commit 49042511a3dd8184fe9a5d85d05e8597e0ed21d6 Author: Cecylia Bocovich cohosh@torproject.org Date: Thu Apr 11 14:02:18 2019 -0400

Refactored server log scrubber into package

The server log scrubbing code from ticket #21304 is now refactored into a safelog package, along with the appropriate tests --- common/safelog/log.go | 59 +++++++++++++++++++ common/safelog/log_test.go | 140 +++++++++++++++++++++++++++++++++++++++++++++ server/server.go | 54 +---------------- server/server_test.go | 135 ------------------------------------------- 4 files changed, 201 insertions(+), 187 deletions(-)

diff --git a/common/safelog/log.go b/common/safelog/log.go new file mode 100644 index 0000000..8229584 --- /dev/null +++ b/common/safelog/log.go @@ -0,0 +1,59 @@ +//Package for a safer logging wrapper around the standard logging package + +//import "git.torproject.org/pluggable-transports/snowflake.git/common/safelog" +package safelog + +import ( + "bytes" + "io" + "regexp" +) + +const ipv4Address = `\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}` +const ipv6Address = `(([0-9a-fA-F]{0,4}:){2,7}([0-9a-fA-F]{0,4})?(` + ipv4Address + `))` + + `|(([0-9a-fA-F]{0,4}:){2,7}([0-9a-fA-F]{0,4})?)` +const optionalPort = `(:\d{1,5})?` +const addressPattern = `((` + ipv4Address + `)|([(` + ipv6Address + `)])|(` + ipv6Address + `))` + optionalPort +const fullAddrPattern = `(^|\s|[^\w:])` + addressPattern + `(\s|(:\s)|[^\w:]|$)` + +var scrubberPatterns = []*regexp.Regexp{ + regexp.MustCompile(fullAddrPattern), +} + +var addressRegexp = regexp.MustCompile(addressPattern) + +// An io.Writer that can be used as the output for a logger that first +// sanitizes logs and then writes to the provided io.Writer +type LogScrubber struct { + Output io.Writer + buffer []byte +} + +func scrub(b []byte) []byte { + scrubbedBytes := b + for _, pattern := range scrubberPatterns { + // this is a workaround since go does not yet support look ahead or look + // behind for regular expressions. + scrubbedBytes = pattern.ReplaceAllFunc(scrubbedBytes, func(b []byte) []byte { + return addressRegexp.ReplaceAll(b, []byte("[scrubbed]")) + }) + } + return scrubbedBytes +} + +func (ls *LogScrubber) Write(b []byte) (n int, err error) { + n = len(b) + ls.buffer = append(ls.buffer, b...) + for { + i := bytes.LastIndexByte(ls.buffer, '\n') + if i == -1 { + return + } + fullLines := ls.buffer[:i+1] + _, err = ls.Output.Write(scrub(fullLines)) + if err != nil { + return + } + ls.buffer = ls.buffer[i+1:] + } +} diff --git a/common/safelog/log_test.go b/common/safelog/log_test.go new file mode 100644 index 0000000..0f342de --- /dev/null +++ b/common/safelog/log_test.go @@ -0,0 +1,140 @@ +package safelog + +import ( + "bytes" + "log" + "testing" +) + +//Check to make sure that addresses split across calls to write are still scrubbed +func TestLogScrubberSplit(t *testing.T) { + input := []byte("test\nhttp2: panic serving [2620:101:f000:780:9097:75b1:519f:dbb8]:58344: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n") + + expected := "test\nhttp2: panic serving [scrubbed]: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n" + + var buff bytes.Buffer + scrubber := &LogScrubber{Output: &buff} + n, err := scrubber.Write(input[:12]) //test\nhttp2: + if n != 12 { + t.Errorf("wrong number of bytes %d", n) + } + if err != nil { + t.Errorf("%q", err) + } + if buff.String() != "test\n" { + t.Errorf("Got %q, expected %q", buff.String(), "test\n") + } + + n, err = scrubber.Write(input[12:30]) //panic serving [2620:101:f + if n != 18 { + t.Errorf("wrong number of bytes %d", n) + } + if err != nil { + t.Errorf("%q", err) + } + if buff.String() != "test\n" { + t.Errorf("Got %q, expected %q", buff.String(), "test\n") + } + + n, err = scrubber.Write(input[30:]) //000:780:9097:75b1:519f:dbb8]:58344: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n + if n != (len(input) - 30) { + t.Errorf("wrong number of bytes %d", n) + } + if err != nil { + t.Errorf("%q", err) + } + if buff.String() != expected { + t.Errorf("Got %q, expected %q", buff.String(), expected) + } + +} + +//Test the log scrubber on known problematic log messages +func TestLogScrubberMessages(t *testing.T) { + for _, test := range []struct { + input, expected string + }{ + { + "http: TLS handshake error from 129.97.208.23:38310: ", + "http: TLS handshake error from [scrubbed]: \n", + }, + { + "http2: panic serving [2620:101:f000:780:9097:75b1:519f:dbb8]:58344: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack", + "http2: panic serving [scrubbed]: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n", + }, + { + //Make sure it doesn't scrub fingerprint + "a=fingerprint:sha-256 33:B6:FA:F6:94:CA:74:61:45:4A:D2:1F:2C:2F:75:8A:D9:EB:23:34:B2:30:E9:1B:2A:A6:A9:E0:44:72:CC:74", + "a=fingerprint:sha-256 33:B6:FA:F6:94:CA:74:61:45:4A:D2:1F:2C:2F:75:8A:D9:EB:23:34:B2:30:E9:1B:2A:A6:A9:E0:44:72:CC:74\n", + }, + { + //try with enclosing parens + "(1:2:3:4:c:d:e:f) {1:2:3:4:c:d:e:f}", + "([scrubbed]) {[scrubbed]}\n", + }, + } { + var buff bytes.Buffer + log.SetFlags(0) //remove all extra log output for test comparisons + log.SetOutput(&LogScrubber{Output: &buff}) + log.Print(test.input) + if buff.String() != test.expected { + t.Errorf("%q: got %q, expected %q", test.input, buff.String(), test.expected) + } + } + +} + +func TestLogScrubberGoodFormats(t *testing.T) { + for _, addr := range []string{ + // IPv4 + "1.2.3.4", + "255.255.255.255", + // IPv4 with port + "1.2.3.4:55", + "255.255.255.255:65535", + // IPv6 + "1:2:3:4:c:d:e:f", + "1111:2222:3333:4444:CCCC:DDDD:EEEE:FFFF", + // IPv6 with brackets + "[1:2:3:4:c:d:e:f]", + "[1111:2222:3333:4444:CCCC:DDDD:EEEE:FFFF]", + // IPv6 with brackets and port + "[1:2:3:4:c:d:e:f]:55", + "[1111:2222:3333:4444:CCCC:DDDD:EEEE:FFFF]:65535", + // compressed IPv6 + "::d:e:f", + "1:2:3::", + "1:2:3::d:e:f", + "1111:2222:3333::DDDD:EEEE:FFFF", + // compressed IPv6 with brackets + "[::d:e:f]", + "[1:2:3::]", + "[1:2:3::d:e:f]", + "[1111:2222:3333::DDDD:EEEE:FFFF]", + "[1:2:3:4:5:6::8]", + "[1::7:8]", + // compressed IPv6 with brackets and port + "[1::]:58344", + "[::d:e:f]:55", + "[1:2:3::]:55", + "[1:2:3::d:e:f]:55", + "[1111:2222:3333::DDDD:EEEE:FFFF]:65535", + // IPv4-compatible and IPv4-mapped + "::255.255.255.255", + "::ffff:255.255.255.255", + "[::255.255.255.255]", + "[::ffff:255.255.255.255]", + "[::255.255.255.255]:65535", + "[::ffff:255.255.255.255]:65535", + "[::ffff:0:255.255.255.255]", + "[2001:db8:3:4::192.0.2.33]", + } { + var buff bytes.Buffer + log.SetFlags(0) //remove all extra log output for test comparisons + log.SetOutput(&LogScrubber{Output: &buff}) + log.Print(addr) + if buff.String() != "[scrubbed]\n" { + t.Errorf("%q: Got %q, expected %q", addr, buff.String(), "[scrubbed]\n") + } + } +} diff --git a/server/server.go b/server/server.go index e6b6f10..cb58efa 100644 --- a/server/server.go +++ b/server/server.go @@ -3,7 +3,6 @@ package main

import ( - "bytes" "crypto/tls" "errors" "flag" @@ -16,13 +15,13 @@ import ( "os" "os/signal" "path/filepath" - "regexp" "strings" "sync" "syscall" "time"

"git.torproject.org/pluggable-transports/goptlib.git" + "git.torproject.org/pluggable-transports/snowflake.git/common/safelog" "git.torproject.org/pluggable-transports/websocket.git/websocket" "golang.org/x/crypto/acme/autocert" "golang.org/x/net/http2" @@ -56,55 +55,6 @@ additional HTTP listener on port 80 to work with ACME. flag.PrintDefaults() }

-const ipv4Address = `\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}` -const ipv6Address = `(([0-9a-fA-F]{0,4}:){2,7}([0-9a-fA-F]{0,4})?(` + ipv4Address + `))` + - `|(([0-9a-fA-F]{0,4}:){2,7}([0-9a-fA-F]{0,4})?)` -const optionalPort = `(:\d{1,5})?` -const addressPattern = `((` + ipv4Address + `)|([(` + ipv6Address + `)])|(` + ipv6Address + `))` + optionalPort -const fullAddrPattern = `(^|\s|[^\w:])` + addressPattern + `(\s|(:\s)|[^\w:]|$)` - -var scrubberPatterns = []*regexp.Regexp{ - regexp.MustCompile(fullAddrPattern), -} - -var addressRegexp = regexp.MustCompile(addressPattern) - -// An io.Writer that can be used as the output for a logger that first -// sanitizes logs and then writes to the provided io.Writer -type logScrubber struct { - output io.Writer - buffer []byte -} - -func scrub(b []byte) []byte { - scrubbedBytes := b - for _, pattern := range scrubberPatterns { - // this is a workaround since go does not yet support look ahead or look - // behind for regular expressions. - scrubbedBytes = pattern.ReplaceAllFunc(scrubbedBytes, func(b []byte) []byte { - return addressRegexp.ReplaceAll(b, []byte("[scrubbed]")) - }) - } - return scrubbedBytes -} - -func (ls *logScrubber) Write(b []byte) (n int, err error) { - n = len(b) - ls.buffer = append(ls.buffer, b...) - for { - i := bytes.LastIndexByte(ls.buffer, '\n') - if i == -1 { - return - } - fullLines := ls.buffer[:i+1] - _, err = ls.output.Write(scrub(fullLines)) - if err != nil { - return - } - ls.buffer = ls.buffer[i+1:] - } -} - // An abstraction that makes an underlying WebSocket connection look like an // io.ReadWriteCloser. type webSocketConn struct { @@ -336,7 +286,7 @@ func main() { logOutput = f } //We want to send the log output through our scrubber first - log.SetOutput(&logScrubber{output: logOutput}) + log.SetOutput(&safelog.LogScrubber{Output: logOutput})

if !disableTLS && acmeHostnamesCommas == "" { log.Fatal("the --acme-hostnames option is required") diff --git a/server/server_test.go b/server/server_test.go index fe895d2..84ac7ba 100644 --- a/server/server_test.go +++ b/server/server_test.go @@ -1,8 +1,6 @@ package main

import ( - "bytes" - "log" "net" "strconv" "testing" @@ -49,136 +47,3 @@ func TestClientAddr(t *testing.T) { } } } - -//Check to make sure that addresses split across calls to write are still scrubbed -func TestLogScrubberSplit(t *testing.T) { - input := []byte("test\nhttp2: panic serving [2620:101:f000:780:9097:75b1:519f:dbb8]:58344: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n") - - expected := "test\nhttp2: panic serving [scrubbed]: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n" - - var buff bytes.Buffer - scrubber := &logScrubber{output: &buff} - n, err := scrubber.Write(input[:12]) //test\nhttp2: - if n != 12 { - t.Errorf("wrong number of bytes %d", n) - } - if err != nil { - t.Errorf("%q", err) - } - if buff.String() != "test\n" { - t.Errorf("Got %q, expected %q", buff.String(), "test\n") - } - - n, err = scrubber.Write(input[12:30]) //panic serving [2620:101:f - if n != 18 { - t.Errorf("wrong number of bytes %d", n) - } - if err != nil { - t.Errorf("%q", err) - } - if buff.String() != "test\n" { - t.Errorf("Got %q, expected %q", buff.String(), "test\n") - } - - n, err = scrubber.Write(input[30:]) //000:780:9097:75b1:519f:dbb8]:58344: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n - if n != (len(input) - 30) { - t.Errorf("wrong number of bytes %d", n) - } - if err != nil { - t.Errorf("%q", err) - } - if buff.String() != expected { - t.Errorf("Got %q, expected %q", buff.String(), expected) - } - -} - -//Test the log scrubber on known problematic log messages -func TestLogScrubberMessages(t *testing.T) { - for _, test := range []struct { - input, expected string - }{ - { - "http: TLS handshake error from 129.97.208.23:38310: ", - "http: TLS handshake error from [scrubbed]: \n", - }, - { - "http2: panic serving [2620:101:f000:780:9097:75b1:519f:dbb8]:58344: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack", - "http2: panic serving [scrubbed]: interface conversion: *http2.responseWriter is not http.Hijacker: missing method Hijack\n", - }, - { - //Make sure it doesn't scrub fingerprint - "a=fingerprint:sha-256 33:B6:FA:F6:94:CA:74:61:45:4A:D2:1F:2C:2F:75:8A:D9:EB:23:34:B2:30:E9:1B:2A:A6:A9:E0:44:72:CC:74", - "a=fingerprint:sha-256 33:B6:FA:F6:94:CA:74:61:45:4A:D2:1F:2C:2F:75:8A:D9:EB:23:34:B2:30:E9:1B:2A:A6:A9:E0:44:72:CC:74\n", - }, - { - //try with enclosing parens - "(1:2:3:4:c:d:e:f) {1:2:3:4:c:d:e:f}", - "([scrubbed]) {[scrubbed]}\n", - }, - } { - var buff bytes.Buffer - log.SetFlags(0) //remove all extra log output for test comparisons - log.SetOutput(&logScrubber{output: &buff}) - log.Print(test.input) - if buff.String() != test.expected { - t.Errorf("%q: got %q, expected %q", test.input, buff.String(), test.expected) - } - } - -} - -func TestLogScrubberGoodFormats(t *testing.T) { - for _, addr := range []string{ - // IPv4 - "1.2.3.4", - "255.255.255.255", - // IPv4 with port - "1.2.3.4:55", - "255.255.255.255:65535", - // IPv6 - "1:2:3:4:c:d:e:f", - "1111:2222:3333:4444:CCCC:DDDD:EEEE:FFFF", - // IPv6 with brackets - "[1:2:3:4:c:d:e:f]", - "[1111:2222:3333:4444:CCCC:DDDD:EEEE:FFFF]", - // IPv6 with brackets and port - "[1:2:3:4:c:d:e:f]:55", - "[1111:2222:3333:4444:CCCC:DDDD:EEEE:FFFF]:65535", - // compressed IPv6 - "::d:e:f", - "1:2:3::", - "1:2:3::d:e:f", - "1111:2222:3333::DDDD:EEEE:FFFF", - // compressed IPv6 with brackets - "[::d:e:f]", - "[1:2:3::]", - "[1:2:3::d:e:f]", - "[1111:2222:3333::DDDD:EEEE:FFFF]", - "[1:2:3:4:5:6::8]", - "[1::7:8]", - // compressed IPv6 with brackets and port - "[1::]:58344", - "[::d:e:f]:55", - "[1:2:3::]:55", - "[1:2:3::d:e:f]:55", - "[1111:2222:3333::DDDD:EEEE:FFFF]:65535", - // IPv4-compatible and IPv4-mapped - "::255.255.255.255", - "::ffff:255.255.255.255", - "[::255.255.255.255]", - "[::ffff:255.255.255.255]", - "[::255.255.255.255]:65535", - "[::ffff:255.255.255.255]:65535", - "[::ffff:0:255.255.255.255]", - "[2001:db8:3:4::192.0.2.33]", - } { - var buff bytes.Buffer - log.SetFlags(0) //remove all extra log output for test comparisons - log.SetOutput(&logScrubber{output: &buff}) - log.Print(addr) - if buff.String() != "[scrubbed]\n" { - t.Errorf("%q: Got %q, expected %q", addr, buff.String(), "[scrubbed]\n") - } - } -}