gitlab.com/gitlab-org/labkit@v1.21.0/log/access_logger_test.go

package log

import (
	"bytes"
	"fmt"
	"io"
	"net/http"
	"net/http/httptest"
	"testing"
	"time"

	"github.com/stretchr/testify/require"
)

func TestAccessLogger(t *testing.T) {
	tests := []struct {
		name            string
		urlSuffix       string
		body            string
		logMatchers     []string
		options         []AccessLoggerOption
		requestHeaders  map[string]string
		responseHeaders map[string]string
		handler         http.Handler
	}{
		{
			name: "trivial",
			body: "hello",
			logMatchers: []string{
				`\btime=\"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}`,
				`\blevel=info`,
				`\bmsg=access`,
				`\bcorrelation_id=\s+`,
				`\bduration_ms=\d+`,
				`\bhost="127.0.0.1:\d+"`,
				`\bmethod=GET`,
				`\bproto=HTTP/1.1`,
				`\breferrer=\s+`,
				`\bremote_addr="127.0.0.1:\d+"`,
				`\bremote_ip=127.0.0.1`,
				`\bstatus=200`,
				`\bsystem=http`,
				`\buri=/`,
				`\buser_agent=Go`,
				`\bwritten_bytes=5`,
				`\bcontent_type=\s+`,
			},
		},
		{
			name:      "senstitive_params",
			urlSuffix: "?password=123456",
			logMatchers: []string{
				`\buri=\"/\?password=\[FILTERED\]\"`,
			},
		},
		{
			name: "extra_fields",
			options: []AccessLoggerOption{
				WithExtraFields(func(r *http.Request) Fields {
					return Fields{"testfield": "testvalue"}
				}),
			},
			logMatchers: []string{
				`\btestfield=testvalue\b`,
			},
		},
		{
			name: "excluded_fields",
			options: []AccessLoggerOption{
				WithFieldsExcluded(defaultEnabledFields),
			},
			logMatchers: []string{
				`^time=\"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.*level=info msg=access\n$`,
			},
		},
		{
			name: "x_forwarded_for",
			requestHeaders: map[string]string{
				"X-Forwarded-For": "196.7.0.238",
			},
			logMatchers: []string{
				`\bremote_ip=196.7.0.238\b`,
			},
		},
		{
			name: "x_forwarded_for_incorrect",
			requestHeaders: map[string]string{
				"X-Forwarded-For": "gitlab.com",
			},
			logMatchers: []string{
				`\bremote_ip=127.0.0.1\b`,
			},
		},
		{
			name: "x_forwarded_for_incorrect",
			requestHeaders: map[string]string{
				"X-Forwarded-For": "196.7.238, 197.7.8.9",
			},
			logMatchers: []string{
				`\bremote_ip=197.7.8.9\b`,
			},
		},
		{
			name: "x_forwarded_for_not_allowed",
			options: []AccessLoggerOption{
				WithXFFAllowed(func(sip string) bool { return false }),
			},
			requestHeaders: map[string]string{
				"X-Forwarded-For": "196.7.0.238",
			},
			logMatchers: []string{
				`\bremote_ip=127.0.0.1\b`,
			},
		},
		{
			name: "empty body",
			logMatchers: []string{
				`\bstatus=200\b`,
			},
		},
		{
			name: "content type",
			body: "hello",
			responseHeaders: map[string]string{
				"Content-Type": "text/plain",
			},
			logMatchers: []string{
				`\bcontent_type=text/plain`,
			},
		},
		{
			name: "time to the first byte",
			body: "ok",
			logMatchers: []string{
				`\bttfb_ms=\d+`,
			},
		},
		{
			name: "time to the first byte, with long delay",
			body: "yo",
			logMatchers: []string{
				// we expect the delay to be around `10ms`
				`\bttfb_ms=1\d\b`,
			},
			handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
				time.Sleep(10 * time.Millisecond)
				fmt.Fprint(w, "yo")
			}),
		},
		{
			name: "time to the first byte, with a slow data transfer",
			body: "yo",
			logMatchers: []string{
				// we expect the delay to be lower than `10ms`
				`\bttfb_ms=\d\b`,
			},
			handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
				w.WriteHeader(http.StatusInternalServerError)
				time.Sleep(10 * time.Millisecond)
				fmt.Fprint(w, "yo")
			}),
		},
		{
			name: "time to the first byte, with a long processing and slow data transfer",
			body: "yo",
			logMatchers: []string{
				// we expect the delay to be around `10ms`
				`\bttfb_ms=1\d\b`,
			},
			handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
				time.Sleep(10 * time.Millisecond)
				w.WriteHeader(http.StatusInternalServerError)
				time.Sleep(20 * time.Millisecond)
				fmt.Fprint(w, "yo")
			}),
		},
	}
	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			buf := &bytes.Buffer{}

			logger := New()
			_, err := Initialize(WithLogger(logger), WithWriter(buf))
			require.NoError(t, err)

			handler := tt.handler

			if handler == nil {
				handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
					for k, v := range tt.responseHeaders {
						w.Header().Add(k, v)
					}
					// This if-statement provides test coverage for the case where the
					// handler never calls Write or WriteHeader.
					if len(tt.body) > 0 {
						fmt.Fprint(w, tt.body)
					}
				})
			}

			opts := []AccessLoggerOption{WithAccessLogger(logger)}
			opts = append(opts, tt.options...)
			handler = AccessLogger(handler, opts...)

			ts := httptest.NewTLSServer(handler)
			defer ts.Close()

			client := ts.Client()
			req, err := http.NewRequest("GET", ts.URL+tt.urlSuffix, nil)
			require.NoError(t, err)

			for k, v := range tt.requestHeaders {
				req.Header.Add(k, v)
			}

			res, err := client.Do(req)
			require.NoError(t, err)

			gotBody, err := io.ReadAll(res.Body)
			res.Body.Close()

			require.NoError(t, err)
			require.Equal(t, tt.body, string(gotBody))

			logString := buf.String()
			for _, v := range tt.logMatchers {
				require.Regexp(t, v, logString)
			}
		})
	}
}

func TestAccessLoggerPanic(t *testing.T) {
	buf := &bytes.Buffer{}

	logger := New()
	_, err := Initialize(WithLogger(logger), WithWriter(buf))
	require.NoError(t, err)

	var handler http.Handler
	handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		panic("see how the logger handles a panic")
	})

	opts := []AccessLoggerOption{WithAccessLogger(logger)}
	handler = AccessLogger(handler, opts...)

	ts := httptest.NewTLSServer(handler)
	defer ts.Close()

	client := ts.Client()
	req, err := http.NewRequest("GET", ts.URL+"/", nil)
	require.NoError(t, err)

	_, err = client.Do(req)
	require.Error(t, err, "panic should cause the request to fail with a closed connection")

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

func TestUnwrap(t *testing.T) {
	rw := httptest.NewRecorder()
	lrw := &loggingResponseWriter{rw: rw}

	require.Same(t, rw, lrw.Unwrap())
}