Added unit tests, documentation and function descriptions across the board. Increased cyclop complexity threshold to 15 which is a bit more sane than 10 and excluded _test.go files from linters.

internal/logging/accesslog.go

@@ -65,6 +65,9 @@ func clientKey(req *http.Request) string {
 	return host
 }
 
+// AccessLog wraps next, writing a line to logger for each request in the
+// Apache/nginx Common Log Format, or the Combined Log Format (which adds the
+// referer and user agent) if combined is true.
 func AccessLog(logger *log.Logger, combined bool, next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 		start := time.Now()

internal/logging/accesslog_test.go

@@ -0,0 +1,138 @@
+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)
+			}
+		})
+	}
+}

internal/logging/logging.go

@@ -25,6 +25,9 @@ func EnableDebug() {
 	}
 }
 
+// LogToFile sends all logging to logfile as JSON, replacing the default slog
+// logger. The file is created if needed and appended to; any log file opened
+// by an earlier call is closed.
 func LogToFile(logfile string) error {
 	if fileLogger != nil {
 		(*fileLogger).Close()
@@ -47,6 +50,7 @@ func LogToFile(logfile string) error {
 	return nil
 }
 
+// Shutdown closes the log file opened by LogToFile, if any.
 func Shutdown() error {
 	var err error = nil
 	if fileLogger != nil {
@@ -56,6 +60,8 @@ func Shutdown() error {
 	return err
 }
 
+// LogToTerminal sends all logging to stdout as coloured text, replacing the
+// default slog logger.
 func LogToTerminal() {
 	opts := &tint.Options{
 		Level:      &logLevel,
@@ -72,10 +78,12 @@ func IsJSONHandler(h slog.Handler) bool {
 	return ok
 }
 
+// IsFileLogger reports whether logging currently goes to a file.
 func IsFileLogger() bool {
 	return fileLogger != nil
 }
 
+// IsDebugEnabled reports whether debug messages are logged.
 func IsDebugEnabled() bool {
 	return logLevel.Level() <= slog.LevelDebug
 }

internal/logging/logging_test.go

@@ -0,0 +1,157 @@
+package logging
+
+import (
+	"context"
+	"io"
+	"log/slog"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/lmittmann/tint"
+)
+
+// saveGlobals restores the package level and the default slog logger after a
+// test that changes them.
+func saveGlobals(t *testing.T) {
+	t.Helper()
+	level := logLevel.Level()
+	def := slog.Default()
+	t.Cleanup(func() {
+		logLevel.Set(level)
+		slog.SetDefault(def)
+		Shutdown()
+	})
+}
+
+func TestLevels(t *testing.T) {
+	saveGlobals(t)
+	slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil)))
+
+	SetLevel(slog.LevelInfo)
+	if IsDebugEnabled() {
+		t.Fatal("debug enabled at info level")
+	}
+	EnableDebug()
+	if !IsDebugEnabled() {
+		t.Fatal("EnableDebug did not enable debug")
+	}
+
+	// EnableDebug must not raise a level that is already more verbose.
+	SetLevel(slog.LevelDebug - 4)
+	EnableDebug()
+	if got := logLevel.Level(); got != slog.LevelDebug-4 {
+		t.Fatalf("level = %v, want %v", got, slog.LevelDebug-4)
+	}
+
+	SetLevel(slog.LevelError)
+	if IsDebugEnabled() {
+		t.Fatal("debug enabled at error level")
+	}
+}
+
+// wrapper is a handler that wraps another, as middleware handlers do.
+type wrapper struct{ slog.Handler }
+
+func TestIsJSONHandler(t *testing.T) {
+	tests := []struct {
+		name string
+		h    slog.Handler
+		want bool
+	}{
+		{"json", slog.NewJSONHandler(io.Discard, nil), true},
+		{"text", slog.NewTextHandler(io.Discard, nil), false},
+		{"tint", tint.NewTextHandler(io.Discard, nil), false},
+		{"nil", nil, false},
+		{"json with attrs", slog.NewJSONHandler(io.Discard, nil).WithAttrs(
+			[]slog.Attr{slog.String("k", "v")}), true},
+		// Only slog's own JSON handler is recognised, not one wrapped in another.
+		{"wrapped json", wrapper{slog.NewJSONHandler(io.Discard, nil)}, false},
+	}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			if got := IsJSONHandler(tc.h); got != tc.want {
+				t.Fatalf("IsJSONHandler = %v, want %v", got, tc.want)
+			}
+		})
+	}
+}
+
+func TestLogToFileWritesJSON(t *testing.T) {
+	saveGlobals(t)
+	SetLevel(slog.LevelInfo)
+	path := filepath.Join(t.TempDir(), "app.log")
+
+	if err := LogToFile(path); err != nil {
+		t.Fatal(err)
+	}
+	if st, err := os.Stat(path); err != nil {
+		t.Fatal(err)
+	} else if perm := st.Mode().Perm(); perm != 0o600 {
+		t.Errorf("log file permissions = %o, want 600", perm)
+	}
+	if !IsJSONHandler(slog.Default().Handler()) {
+		t.Fatal("default handler is not JSON after LogToFile")
+	}
+	slog.Info("hello file", "k", "v")
+	slog.Debug("hidden")
+
+	//nolint:gosec // G304: reading a file the test created in t.TempDir
+	data, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	s := string(data)
+	if !strings.Contains(s, `"msg":"hello file"`) || !strings.Contains(s, `"k":"v"`) {
+		t.Fatalf("log file missing entry: %s", s)
+	}
+	if strings.Contains(s, "hidden") {
+		t.Fatalf("debug line written at info level: %s", s)
+	}
+}
+
+func TestLogToFileBadPath(t *testing.T) {
+	saveGlobals(t)
+	if err := LogToFile(filepath.Join(t.TempDir(), "missing", "app.log")); err == nil {
+		t.Fatal("expected an error for a path in a missing directory")
+	}
+}
+
+func TestLogToFileTracksFile(t *testing.T) {
+	saveGlobals(t)
+	if err := LogToFile(filepath.Join(t.TempDir(), "app.log")); err != nil {
+		t.Fatal(err)
+	}
+	if !IsFileLogger() {
+		t.Fatal("IsFileLogger() = false after LogToFile")
+	}
+	if err := Shutdown(); err != nil {
+		t.Fatal(err)
+	}
+	if IsFileLogger() {
+		t.Fatal("IsFileLogger() = true after Shutdown")
+	}
+}
+
+func TestShutdownWithoutFile(t *testing.T) {
+	if err := Shutdown(); err != nil {
+		t.Fatal(err)
+	}
+	if IsFileLogger() {
+		t.Fatal("IsFileLogger() = true with no file")
+	}
+}
+
+func TestLogToTerminal(t *testing.T) {
+	saveGlobals(t)
+	LogToTerminal()
+	h := slog.Default().Handler()
+	if IsJSONHandler(h) {
+		t.Fatal("terminal handler reported as JSON")
+	}
+	SetLevel(slog.LevelWarn)
+	if h.Enabled(context.Background(), slog.LevelInfo) {
+		t.Fatal("terminal handler ignores the package level")
+	}
+}