aboutsummaryrefslogtreecommitdiff
path: root/common/safelog/log_test.go
blob: 267538cc606a92865fa445b9e0d1e0c0150fb076 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
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",
		},
		{
			//Make sure it doesn't scrub timestamps
			"2019/05/08 15:37:31 starting",
			"2019/05/08 15:37:31 starting\n",
		},
		{
			//Make sure ipv6 addresses where : are encoded as %3A or %3a are scrubbed
			"error dialing relay: wss://snowflake.torproject.net/?client_ip=6201%3ac8%3A3004%3A%3A1234",
			"error dialing relay: wss://snowflake.torproject.net/?client_ip=[scrubbed]\n",
		},
		{
			// make sure url encoded IPv6 IPs get scrubbed (%3a)
			"http2: panic serving [fd00%3a111%3af000%3a777%3a9999%3abbbb%3affff%3adddd]:58344: xxx",
			"http2: panic serving [scrubbed]: xxx\n",
		},
		{
			// make sure url encoded IPv6 IPs get scrubbed (%3A)
			"http2: panic serving [fd00%3a111%3af000%3a777%3a9999%3abbbb%3affff%3adddd]:58344: xxx",
			"http2: panic serving [scrubbed]: xxx\n",
		},
		{
			// make sure url encoded IPv6 IPs get scrubbed, different URL (%3A)
			"error dialing relay: wss://snowflake.torproject.net/?client_ip=fd00%3A8888%3Abbbb%3Acccc%3Adddd%3Aeeee%3A2222%3A123 = dial tcp xxx",
			"error dialing relay: wss://snowflake.torproject.net/?client_ip=[scrubbed] = dial tcp xxx\n",
		},
		{
			// make sure url encoded IPv6 IPs get scrubbed (%3A), compressed
			"http2: panic serving [1%3A2%3A3%3A%3Ad%3Ae%3Af]:55: xxx",
			"http2: panic serving [scrubbed]: xxx\n",
		},
		{
			// make sure url encoded IPv6 IPs get scrubbed (%3A), compressed
			"error dialing relay: wss://snowflake.torproject.net/?client_ip=1%3A2%3A3%3A%3Ad%3Ae%3Af = dial tcp xxx",
			"error dialing relay: wss://snowflake.torproject.net/?client_ip=[scrubbed] = dial tcp xxx\n",
		},
		{
			// multiple space-separated IP addresses
			"Allowed stations: [10.0.1.1 10.0.1.2 10.0.1.3 10.0.1.4]\n",
			"Allowed stations: [[scrubbed] [scrubbed] [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
		"::f",
		"::d:e:f",
		"1:2:3::",
		"1:2:3::d:e:f",
		"1:2:3:d:e:f::",
		"::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")
		}
	}
}