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

@@ -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:]
+	}
+}

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")
+		}
+	}
+}

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")

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")
-		}
-	}
-}