[tor-commits] [snowflake/master] Refactored server log scrubber into package
cohosh at torproject.org
cohosh at torproject.org
Tue Apr 16 17:01:09 UTC 2019
commit 49042511a3dd8184fe9a5d85d05e8597e0ed21d6
Author: Cecylia Bocovich <cohosh at 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")
- }
- }
-}
More information about the tor-commits
mailing list