[tor-commits] [snowflake/master] Modified log scrubber to handle split lines

[cohosh at torproject.org]

commit c6a4a4191f2031abc744013d63f536612c37b512
Author: Cecylia Bocovich <cohosh at torproject.org>
Date:   Mon Mar 25 10:51:47 2019 -0400

    Modified log scrubber to handle split lines
    
    Log scrubber now scrubs addresses even in the case where they are split
    across calls to the scrubber's output io.Writer.
    
    Added test cases to test that the writer behaves correctly across split
    lines.
---
 server/server.go      | 24 +++++++++++++++++++++---
 server/server_test.go | 47 +++++++++++++++++++++++++++++++++++++++++++++--
 2 files changed, 66 insertions(+), 5 deletions(-)

diff --git a/server/server.go b/server/server.go
index decfed4..539d0e1 100644
--- a/server/server.go
+++ b/server/server.go
@@ -3,6 +3,7 @@
 package main
 
 import (
+	"bytes"
 	"crypto/tls"
 	"errors"
 	"flag"
@@ -66,15 +67,32 @@ var scrubberPatterns = []*regexp.Regexp{
 // sanitizes logs and then writes to the provided io.Writer
 type logScrubber struct {
 	output io.Writer
+	buffer []byte
 }
 
-func (ls *logScrubber) Write(b []byte) (n int, err error) {
+func scrub(b []byte) []byte {
 	scrubbedBytes := b
 	for _, pattern := range scrubberPatterns {
 		scrubbedBytes = pattern.ReplaceAll(scrubbedBytes, []byte("[scrubbed]"))
 	}
+	return scrubbedBytes
+}
 
-	return ls.output.Write(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
@@ -308,7 +326,7 @@ func main() {
 		logOutput = f
 	}
 	//We want to send the log output through our scrubber first
-	log.SetOutput(&logScrubber{logOutput})
+	log.SetOutput(&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 cfe4653..846d95e 100644
--- a/server/server_test.go
+++ b/server/server_test.go
@@ -50,7 +50,50 @@ func TestClientAddr(t *testing.T) {
 	}
 }
 
-func TestLogScrubber(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]:58344: 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)
+	}
+
+}
+
+func TestLogScrubberFormats(t *testing.T) {
 	for _, test := range []struct {
 		input, expected string
 	}{
@@ -98,7 +141,7 @@ func TestLogScrubber(t *testing.T) {
 	} {
 		var buff bytes.Buffer
 		log.SetFlags(0) //remove all extra log output for test comparisons
-		log.SetOutput(&logScrubber{&buff})
+		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)