1package log
2
3import (
4	"bytes"
5	"fmt"
6	"io/ioutil"
7	"net/http"
8	"net/http/httptest"
9	"testing"
10	"time"
11
12	"github.com/stretchr/testify/require"
13)
14
15func TestAccessLogger(t *testing.T) {
16	tests := []struct {
17		name            string
18		urlSuffix       string
19		body            string
20		logMatchers     []string
21		options         []AccessLoggerOption
22		requestHeaders  map[string]string
23		responseHeaders map[string]string
24		handler         http.Handler
25	}{
26		{
27			name: "trivial",
28			body: "hello",
29			logMatchers: []string{
30				`\btime=\"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}`,
31				`\blevel=info`,
32				`\bmsg=access`,
33				`\bcorrelation_id=\s+`,
34				`\bduration_ms=\d+`,
35				`\bhost="127.0.0.1:\d+"`,
36				`\bmethod=GET`,
37				`\bproto=HTTP/1.1`,
38				`\breferrer=\s+`,
39				`\bremote_addr="127.0.0.1:\d+"`,
40				`\bremote_ip=127.0.0.1`,
41				`\bstatus=200`,
42				`\bsystem=http`,
43				`\buri=/`,
44				`\buser_agent=Go`,
45				`\bwritten_bytes=5`,
46				`\bcontent_type=\s+`,
47			},
48		},
49		{
50			name:      "senstitive_params",
51			urlSuffix: "?password=123456",
52			logMatchers: []string{
53				`\buri=\"/\?password=\[FILTERED\]\"`,
54			},
55		},
56		{
57			name: "extra_fields",
58			options: []AccessLoggerOption{
59				WithExtraFields(func(r *http.Request) Fields {
60					return Fields{"testfield": "testvalue"}
61				}),
62			},
63			logMatchers: []string{
64				`\btestfield=testvalue\b`,
65			},
66		},
67		{
68			name: "excluded_fields",
69			options: []AccessLoggerOption{
70				WithFieldsExcluded(defaultEnabledFields),
71			},
72			logMatchers: []string{
73				`^time=\"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.*level=info msg=access\n$`,
74			},
75		},
76		{
77			name: "x_forwarded_for",
78			requestHeaders: map[string]string{
79				"X-Forwarded-For": "196.7.0.238",
80			},
81			logMatchers: []string{
82				`\bremote_ip=196.7.0.238\b`,
83			},
84		},
85		{
86			name: "x_forwarded_for_incorrect",
87			requestHeaders: map[string]string{
88				"X-Forwarded-For": "gitlab.com",
89			},
90			logMatchers: []string{
91				`\bremote_ip=127.0.0.1\b`,
92			},
93		},
94		{
95			name: "x_forwarded_for_incorrect",
96			requestHeaders: map[string]string{
97				"X-Forwarded-For": "196.7.238, 197.7.8.9",
98			},
99			logMatchers: []string{
100				`\bremote_ip=197.7.8.9\b`,
101			},
102		},
103		{
104			name: "x_forwarded_for_not_allowed",
105			options: []AccessLoggerOption{
106				WithXFFAllowed(func(sip string) bool { return false }),
107			},
108			requestHeaders: map[string]string{
109				"X-Forwarded-For": "196.7.0.238",
110			},
111			logMatchers: []string{
112				`\bremote_ip=127.0.0.1\b`,
113			},
114		},
115		{
116			name: "empty body",
117			logMatchers: []string{
118				`\bstatus=200\b`,
119			},
120		},
121		{
122			name: "content type",
123			body: "hello",
124			responseHeaders: map[string]string{
125				"Content-Type": "text/plain",
126			},
127			logMatchers: []string{
128				`\bcontent_type=text/plain`,
129			},
130		},
131		{
132			name: "time to the first byte",
133			body: "ok",
134			logMatchers: []string{
135				`\bttfb_ms=\d+`,
136			},
137		},
138		{
139			name: "time to the first byte, with long delay",
140			body: "yo",
141			logMatchers: []string{
142				// we expect the delay to be around `10ms`
143				`\bttfb_ms=1\d\b`,
144			},
145			handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
146				time.Sleep(10 * time.Millisecond)
147				fmt.Fprint(w, "yo")
148			}),
149		},
150		{
151			name: "time to the first byte, with a slow data transfer",
152			body: "yo",
153			logMatchers: []string{
154				// we expect the delay to be lower than `10ms`
155				`\bttfb_ms=\d\b`,
156			},
157			handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
158				w.WriteHeader(http.StatusInternalServerError)
159				time.Sleep(10 * time.Millisecond)
160				fmt.Fprint(w, "yo")
161			}),
162		},
163		{
164			name: "time to the first byte, with a long processing and slow data transfer",
165			body: "yo",
166			logMatchers: []string{
167				// we expect the delay to be around `10ms`
168				`\bttfb_ms=1\d\b`,
169			},
170			handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
171				time.Sleep(10 * time.Millisecond)
172				w.WriteHeader(http.StatusInternalServerError)
173				time.Sleep(20 * time.Millisecond)
174				fmt.Fprint(w, "yo")
175			}),
176		},
177	}
178	for _, tt := range tests {
179		t.Run(tt.name, func(t *testing.T) {
180			buf := &bytes.Buffer{}
181
182			logger := New()
183			_, err := Initialize(WithLogger(logger), WithWriter(buf))
184			require.NoError(t, err)
185
186			handler := tt.handler
187
188			if handler == nil {
189				handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
190					for k, v := range tt.responseHeaders {
191						w.Header().Add(k, v)
192					}
193					// This if-statement provides test coverage for the case where the
194					// handler never calls Write or WriteHeader.
195					if len(tt.body) > 0 {
196						fmt.Fprint(w, tt.body)
197					}
198				})
199			}
200
201			opts := []AccessLoggerOption{WithAccessLogger(logger)}
202			opts = append(opts, tt.options...)
203			handler = AccessLogger(handler, opts...)
204
205			ts := httptest.NewTLSServer(handler)
206			defer ts.Close()
207
208			client := ts.Client()
209			req, err := http.NewRequest("GET", ts.URL+tt.urlSuffix, nil)
210			require.NoError(t, err)
211
212			for k, v := range tt.requestHeaders {
213				req.Header.Add(k, v)
214			}
215
216			res, err := client.Do(req)
217			require.NoError(t, err)
218
219			gotBody, err := ioutil.ReadAll(res.Body)
220			res.Body.Close()
221
222			require.NoError(t, err)
223			require.Equal(t, tt.body, string(gotBody))
224
225			logString := buf.String()
226			for _, v := range tt.logMatchers {
227				require.Regexp(t, v, logString)
228			}
229		})
230	}
231}
232
233func TestAccessLoggerPanic(t *testing.T) {
234	buf := &bytes.Buffer{}
235
236	logger := New()
237	_, err := Initialize(WithLogger(logger), WithWriter(buf))
238	require.NoError(t, err)
239
240	var handler http.Handler
241	handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
242		panic("see how the logger handles a panic")
243	})
244
245	opts := []AccessLoggerOption{WithAccessLogger(logger)}
246	handler = AccessLogger(handler, opts...)
247
248	ts := httptest.NewTLSServer(handler)
249	defer ts.Close()
250
251	client := ts.Client()
252	req, err := http.NewRequest("GET", ts.URL+"/", nil)
253	require.NoError(t, err)
254
255	_, err = client.Do(req)
256	require.Error(t, err, "panic should cause the request to fail with a closed connection")
257
258	require.Regexp(t, `\bstatus=0\b`, buf.String(), "if the handler panics before writing a response header, the status code is undefined, so we expect code 0")
259}
260