job-search/internal/logging/accesslog_test.go

package logging

import (
	"bytes"
	"log"
	"net/http"
	"net/http/httptest"
	"regexp"
	"strings"
	"testing"
)

func TestLogField(t *testing.T) {
	tests := []struct {
		in, want string
	}{
		{"", "-"},
		{"plain", "plain"},
		{"GET /a?b=c HTTP/1.1", "GET /a?b=c HTTP/1.1"},
		{`say "hi"`, `say \x22hi\x22`},
		{`back\slash`, `back\x5Cslash`},
		{"tab\tnl\n", `tab\x09nl\x0A`},
		{"del\x7f", `del\x7F`},
		{"héllo", "héllo"}, // multi-byte UTF-8 passes through
	}
	for _, tc := range tests {
		if got := logField(tc.in); got != tc.want {
			t.Errorf("logField(%q) = %q, want %q", tc.in, got, tc.want)
		}
	}
}

func TestClientKey(t *testing.T) {
	tests := []struct {
		remote, want string
	}{
		{"192.0.2.1:1234", "192.0.2.1"},
		{"[2001:db8::1]:443", "2001:db8::1"},
		{"no-port", "no-port"},
		{"", ""},
	}
	for _, tc := range tests {
		req := &http.Request{
			RemoteAddr: tc.remote,
		}
		if got := clientKey(req); got != tc.want {
			t.Errorf("clientKey(%q) = %q, want %q", tc.remote, got, tc.want)
		}
	}
}

func TestStatusRecorder(t *testing.T) {
	t.Run("first WriteHeader wins", func(t *testing.T) {
		rec := &statusRecorder{
			ResponseWriter: httptest.NewRecorder(),
		}
		rec.WriteHeader(http.StatusTeapot)
		rec.WriteHeader(http.StatusInternalServerError)
		if rec.status != http.StatusTeapot {
			t.Fatalf("status = %d", rec.status)
		}
	})
	t.Run("Write implies 200 and counts bytes", func(t *testing.T) {
		inner := httptest.NewRecorder()
		rec := &statusRecorder{
			ResponseWriter: inner,
		}
		rec.Write([]byte("hello"))
		rec.Write([]byte(" world"))
		if rec.status != http.StatusOK || rec.bytes != 11 {
			t.Fatalf("status = %d, bytes = %d", rec.status, rec.bytes)
		}
		if inner.Body.String() != "hello world" {
			t.Fatalf("body = %q", inner.Body.String())
		}
	})
}

var clfTime = `\[\d{2}/[A-Z][a-z]{2}/\d{4}:\d{2}:\d{2}:\d{2} [+-]\d{4}\]`

func TestAccessLog(t *testing.T) {
	tests := []struct {
		name     string
		combined bool
		handler  http.HandlerFunc
		setup    func(*http.Request)
		want     string // regexp for the whole line
	}{
		{
			name: "no body defaults to 200 and -",
			handler: func(http.ResponseWriter, *http.Request) {
			},
			want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 -$`,
		},
		{
			name: "status and size",
			handler: func(w http.ResponseWriter, _ *http.Request) {
				w.WriteHeader(http.StatusNotFound)
				w.Write([]byte("nope"))
			},
			want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 404 4$`,
		},
		{
			name: "basic auth user is escaped",
			handler: func(w http.ResponseWriter, _ *http.Request) {
				w.Write([]byte("x"))
			},
			setup: func(r *http.Request) {
				r.SetBasicAuth(`bo"b`, "pw")
			},
			want: `^192\.0\.2\.1 - bo\\x22b ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 1$`,
		},
		{
			name:     "combined adds referer and user agent",
			combined: true,
			handler: func(http.ResponseWriter, *http.Request) {
			},
			setup: func(r *http.Request) {
				r.Header.Set("Referer", "http://ref/")
				r.Header.Set("User-Agent", `ua "1"`)
			},
			want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 - "http://ref/" "ua \\x221\\x22"$`,
		},
		{
			name:     "combined with missing headers",
			combined: true,
			handler: func(http.ResponseWriter, *http.Request) {
			},
			setup: func(r *http.Request) {
				r.Header.Del("User-Agent")
			},
			want: `^192\.0\.2\.1 - - ` + clfTime + ` "GET /path\?q=1 HTTP/1\.1" 200 - "-" "-"$`,
		},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			var buf bytes.Buffer
			logger := log.New(&buf, "", 0)
			req := httptest.NewRequest(http.MethodGet, "/path?q=1", nil)
			req.RemoteAddr = "192.0.2.1:5555"
			if tc.setup != nil {
				tc.setup(req)
			}
			w := httptest.NewRecorder()
			AccessLog(logger, tc.combined, tc.handler).ServeHTTP(w, req)

			line := strings.TrimSuffix(buf.String(), "\n")
			if !regexp.MustCompile(tc.want).MatchString(line) {
				t.Fatalf("log line\n  %s\ndoes not match\n  %s", line, tc.want)
			}
		})
	}
}