Added access log to server and modified mock-fts to use it

cmd/mock-fts/main.go

@@ -23,7 +23,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
 	"log/slog"
 	"net/http"
 	"os"
@@ -286,23 +285,17 @@ func run(ctx context.Context, opts *options) (err error) {
 	}()
 
 	// Serve the API.
-	out := os.Stdout
+	accessLogger, closeAccessLog, err := logging.OpenAccessLog(
-	if opts.accessLogPath != "-" {
+		opts.accessLogPath,
-		var logFile *os.File
+	)
-		logFile, err = os.OpenFile(
+	if err != nil {
-			opts.accessLogPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600,
+		cancel()
-		)
+		<-workerDone
-		if err != nil {
+		return err
-			cancel()
-			<-workerDone
-			return fmt.Errorf("opening access log: %w", err)
-		}
-		defer func() {
-			err = errors.Join(err, logFile.Close())
-		}()
-		out = logFile
 	}
-	accessLogger := log.New(out, "", 0)
+	defer func() {
+		err = errors.Join(err, closeAccessLog())
+	}()
 
 	rateLimiter := mock.NewRateLimiter(opts.rateLimit, opts.rateWindow)
 	mux := http.NewServeMux()

internal/cli/serve/command.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log"
 	"log/slog"
 	"os"
 	"os/signal"
@@ -14,6 +15,7 @@ import (
 	"github.com/spf13/cobra"
 
 	"git.avsdev.uk/Go/job-search/internal/cli"
+	"git.avsdev.uk/Go/job-search/internal/logging"
 	"git.avsdev.uk/Go/job-search/internal/server"
 )
 
@@ -32,13 +34,14 @@ WebSocket endpoint under /ws.`,
 			slog.Debug("command persistent post-run", "command", "serve")
 		},
 		Args: cobra.NoArgs,
-		RunE: func(cmd *cobra.Command, _ []string) error {
+		RunE: func(cmd *cobra.Command, _ []string) (err error) {
 			slog.Debug("command run", "command", "serve")
 
 			addrOverride, _ := cmd.Flags().GetString("listen")
 			hostOverride, _ := cmd.Flags().GetString("host")
 			portOverride, _ := cmd.Flags().GetInt("port")
 			foreground, _ := cmd.Flags().GetBool("foreground")
+			accessLogOverride, _ := cmd.Flags().GetString("access-log")
 
 			if addrOverride != "" {
 				listenParts := strings.Split(addrOverride, ":")
@@ -47,12 +50,11 @@ WebSocket endpoint under /ws.`,
 						"--listen should be in the format of 127.0.0.1:9393",
 					)
 				}
-				port, err := strconv.Atoi(listenParts[1])
+				portOverride, err = strconv.Atoi(listenParts[1])
 				if err != nil {
 					return fmt.Errorf("failed to parse --listen port: %w", err)
 				}
 				hostOverride = listenParts[0]
-				portOverride = port
 			}
 
 			conf, err := opts.RunSetup(cmd, true, foreground)
@@ -66,6 +68,27 @@ WebSocket endpoint under /ws.`,
 			if hostOverride != "" {
 				conf.Server.Host = hostOverride
 			}
+			if cmd.Flags().Changed("access-log") {
+				conf.Server.AccessLog = accessLogOverride
+			}
+
+			var options []server.Option
+			if conf.Server.AccessLog != "" {
+				var (
+					accessLog      *log.Logger
+					closeAccessLog func() error
+				)
+				accessLog, closeAccessLog, err = logging.OpenAccessLog(
+					conf.Server.AccessLog,
+				)
+				if err != nil {
+					return err
+				}
+				defer func() {
+					err = errors.Join(err, closeAccessLog())
+				}()
+				options = append(options, server.WithAccessLog(accessLog))
+			}
 
 			// ctx is cancelled on the first SIGINT (Ctrl+C) or SIGTERM.
 			ctx, stop := signal.NotifyContext(
@@ -80,7 +103,7 @@ WebSocket endpoint under /ws.`,
 				stop()
 			}()
 
-			appServer, err := server.New(&conf.Server)
+			appServer, err := server.New(&conf.Server, options...)
 			if err != nil {
 				return err
 			}
@@ -98,6 +121,12 @@ WebSocket endpoint under /ws.`,
 	)
 	flags.Int("port", 0, "listen address (default from config, 9393)")
 	flags.Bool("foreground", false, "run in the foreground")
+	flags.String(
+		"access-log",
+		"",
+		`access log file, or "-" for stdout; "" for none `+
+			"(default from config, server.access_log)",
+	)
 	cmd.MarkFlagsMutuallyExclusive("listen", "host")
 	cmd.MarkFlagsMutuallyExclusive("listen", "port")
 

internal/config/README.md

@@ -101,6 +101,7 @@ The `server` section is split into a number of sub-sections:
 | `server.port` | int | `9393` | Port to listen on; `0`: any free port |
 | `server.max_header_bytes` | byte size | `8KB` | Largest request header block; `0B` for 8KB. `-1` (no limit) is rejected, as the HTTP server always has one |
 | `server.max_body_bytes` | byte size | `1MB` | Largest request body; `0B` for 1MB, `-1` for no limit |
+| `server.access_log` | string | | File the access log is appended to, one line per request in the Combined Log Format; `-`: stdout; empty: no access log. `serve --access-log` overrides it |
 
 #### Timeouts
 

internal/config/conf_server.go

@@ -15,11 +15,15 @@ const JSCKServer string = "server"
 // port). MaxHeaderBytes is the largest request header block; 0 means the
 // default (8KB), and -1 (no limit) is rejected (see validate). MaxBodyBytes is
 // the largest request body; 0 means the default (1MB) and -1 no limit.
+// AccessLog is the file the access log is appended to, one line per request
+// in the Combined Log Format; "-" means stdout, and empty means no access
+// log.
 type JSCServer struct {
 	Host           string              `cfg:"host"             default:"127.0.0.1"`
 	Port           int                 `cfg:"port"             default:"9393"`
 	MaxHeaderBytes util.ByteSize       `cfg:"max_header_bytes" default:"8KB"`
 	MaxBodyBytes   util.ByteSize       `cfg:"max_body_bytes"   default:"1MB"`
+	AccessLog      string              `cfg:"access_log"`
 	Timeouts       JSCServerTimeouts   `cfg:"timeouts"`
 	RateLimits     JSCServerRateLimits `cfg:"rate_limits"`
 	Proxy          JSCServerProxy      `cfg:"proxy"`

internal/logging/accesslog.go

@@ -5,6 +5,8 @@ import (
 	"log"
 	"net"
 	"net/http"
+	"os"
+	"path/filepath"
 	"strconv"
 	"strings"
 	"time"
@@ -26,12 +28,20 @@ func (s *statusRecorder) WriteHeader(code int) {
 	s.ResponseWriter.WriteHeader(code)
 }
 
+// Unwrap returns the wrapped ResponseWriter, so that http.ResponseController
+// can reach its Hijack and Flush: a WebSocket upgrade hijacks the connection.
+func (s *statusRecorder) Unwrap() http.ResponseWriter {
+	return s.ResponseWriter
+}
+
 func (s *statusRecorder) Write(data []byte) (int, error) {
 	if s.status == 0 {
 		s.status = http.StatusOK
 	}
+
 	written, err := s.ResponseWriter.Write(data)
 	s.bytes += written
+
 	return written, err
 }
 
@@ -108,3 +118,23 @@ func AccessLog(
 		logger.Println(line)
 	})
 }
+
+// OpenAccessLog opens the access log at path for appending, creating it if
+// needed, or stdout for "-", for AccessLog. It returns a logger writing to it
+// and a function that closes it (doing nothing for stdout).
+func OpenAccessLog(path string) (*log.Logger, func() error, error) {
+	if path == "-" {
+		return log.New(os.Stdout, "", 0), func() error {
+			return nil
+		}, nil
+	}
+
+	file, err := os.OpenFile(
+		filepath.Clean(path), os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600,
+	)
+	if err != nil {
+		return nil, nil, fmt.Errorf("opening access log: %w", err)
+	}
+
+	return log.New(file, "", 0), file.Close, nil
+}

internal/logging/accesslog_test.go

@@ -5,9 +5,13 @@ import (
 	"log"
 	"net/http"
 	"net/http/httptest"
+	"os"
+	"path/filepath"
 	"regexp"
 	"strings"
+	"sync"
 	"testing"
+	"time"
 )
 
 func TestLogField(t *testing.T) {
@@ -152,3 +156,96 @@ func TestAccessLog(t *testing.T) {
 		})
 	}
 }
+
+// A handler behind AccessLog can hijack the connection through
+// http.ResponseController, as a WebSocket upgrade does, and the request is
+// still logged.
+func TestAccessLogHijack(t *testing.T) {
+	var buffer lockedBuffer
+	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		conn, readWriter, err := http.NewResponseController(w).Hijack()
+		if err != nil {
+			t.Errorf("hijack: %v", err)
+			return
+		}
+		defer conn.Close()
+		readWriter.WriteString("HTTP/1.1 204 No Content\r\n\r\n")
+		readWriter.Flush()
+	})
+	server := httptest.NewServer(AccessLog(log.New(&buffer, "", 0), true, handler))
+	defer server.Close()
+
+	res, err := http.Get(server.URL + "/hijacked")
+	if err != nil {
+		t.Fatal(err)
+	}
+	res.Body.Close()
+	if res.StatusCode != http.StatusNoContent {
+		t.Errorf("status = %d; want 204 from the hijacked connection", res.StatusCode)
+	}
+
+	// The line is written when the handler returns, after the client has its
+	// response.
+	deadline := time.Now().Add(time.Second)
+	for !strings.Contains(buffer.String(), `"GET /hijacked HTTP/1.1"`) {
+		if time.Now().After(deadline) {
+			t.Fatalf("request not logged: %q", buffer.String())
+		}
+		time.Sleep(5 * time.Millisecond)
+	}
+}
+
+// lockedBuffer is a bytes.Buffer safe to write from the server's goroutine
+// while the test reads it.
+type lockedBuffer struct {
+	mu     sync.Mutex
+	buffer bytes.Buffer
+}
+
+func (b *lockedBuffer) Write(data []byte) (int, error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buffer.Write(data)
+}
+
+func (b *lockedBuffer) String() string {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buffer.String()
+}
+
+// An access log file is created if needed and appended to; "-" is stdout.
+func TestOpenAccessLog(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "access.log")
+	os.WriteFile(path, []byte("earlier line\n"), 0o600)
+
+	logger, closeLog, err := OpenAccessLog(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	logger.Print("new line")
+	if err := closeLog(); err != nil {
+		t.Fatal(err)
+	}
+
+	data, err := os.ReadFile(filepath.Clean(path))
+	if err != nil {
+		t.Fatal(err)
+	}
+	if got := string(data); got != "earlier line\nnew line\n" {
+		t.Errorf("access log = %q; want the new line appended", got)
+	}
+
+	logger, closeLog, err = OpenAccessLog("-")
+	if err != nil || logger.Writer() != os.Stdout {
+		t.Errorf("OpenAccessLog(-) = %v, %v; want stdout", logger, err)
+	}
+	if err := closeLog(); err != nil {
+		t.Errorf("closing stdout's access log: %v", err)
+	}
+
+	_, _, err = OpenAccessLog(filepath.Join(t.TempDir(), "missing", "a.log"))
+	if err == nil || !strings.Contains(err.Error(), "opening access log") {
+		t.Errorf("missing directory: %v; want an error", err)
+	}
+}

internal/middleware/logging.go

@@ -120,9 +120,11 @@ func isRequestIDChar(char byte) bool {
 	return char == '-' || char == '_' || char == '.'
 }
 
-// Logger logs one line per request. The query string is deliberately not
+// Logger logs one line per request: at debug level, or at info level for a
-// logged, as it may carry secrets. It logs to slog.Default() unless given
+// connection hijack (a WebSocket upgrade), as one is logged per connection
-// WithLogger.
+// rather than per request; a 4xx response is logged at warn level and a 5xx
+// at error level. The query string is deliberately not logged, as it may
+// carry secrets. It logs to slog.Default() unless given WithLogger.
 func Logger(opts ...Option) func(http.Handler) http.Handler {
 	settings := applyOptions(opts)
 	return func(next http.Handler) http.Handler {
@@ -138,12 +140,14 @@ func Logger(opts ...Option) func(http.Handler) http.Handler {
 					status = http.StatusOK
 				}
 
-				level := slog.LevelInfo
+				level := slog.LevelDebug
 				switch {
 				case status >= 500:
 					level = slog.LevelError
 				case status >= 400:
 					level = slog.LevelWarn
+				case recorder.hijacked:
+					level = slog.LevelInfo
 				}
 
 				settings.logger("http").LogAttrs(

internal/middleware/logging_test.go

@@ -0,0 +1,96 @@
+package middleware
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"sync"
+	"testing"
+	"time"
+)
+
+// lockedBuffer is a bytes.Buffer safe to write from the server's goroutine
+// while the test reads it.
+type lockedBuffer struct {
+	mu     sync.Mutex
+	buffer bytes.Buffer
+}
+
+func (b *lockedBuffer) Write(data []byte) (int, error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buffer.Write(data)
+}
+
+func (b *lockedBuffer) String() string {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buffer.String()
+}
+
+// A request is logged at debug level, a hijacked connection at info, a 4xx
+// response at warn and a 5xx at error.
+func TestLoggerLevels(t *testing.T) {
+	tests := []struct {
+		name    string
+		handler http.HandlerFunc
+		want    string
+	}{
+		{"ok", func(w http.ResponseWriter, r *http.Request) {
+			w.WriteHeader(http.StatusOK)
+		}, "DEBUG"},
+		{"not found", func(w http.ResponseWriter, r *http.Request) {
+			w.WriteHeader(http.StatusNotFound)
+		}, "WARN"},
+		{"server error", func(w http.ResponseWriter, r *http.Request) {
+			w.WriteHeader(http.StatusInternalServerError)
+		}, "ERROR"},
+		{"hijacked", func(w http.ResponseWriter, r *http.Request) {
+			conn, readWriter, err := http.NewResponseController(w).Hijack()
+			if err != nil {
+				t.Errorf("hijack: %v", err)
+				return
+			}
+			defer conn.Close()
+			readWriter.WriteString("HTTP/1.1 204 No Content\r\n\r\n")
+			readWriter.Flush()
+		}, "INFO"},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var buffer lockedBuffer
+			logger := slog.New(slog.NewJSONHandler(&buffer, &slog.HandlerOptions{
+				Level: slog.LevelDebug,
+			}))
+			server := httptest.NewServer(
+				Logger(WithLogger(logger))(tt.handler),
+			)
+			defer server.Close()
+
+			res, err := http.Get(server.URL)
+			if err != nil {
+				t.Fatal(err)
+			}
+			res.Body.Close()
+
+			// The line is written when the handler returns, which may be after
+			// the client has its response.
+			deadline := time.Now().Add(time.Second)
+			for buffer.String() == "" && time.Now().Before(deadline) {
+				time.Sleep(5 * time.Millisecond)
+			}
+			var entry struct {
+				Level string `json:"level"`
+				Msg   string `json:"msg"`
+			}
+			if err := json.Unmarshal([]byte(buffer.String()), &entry); err != nil {
+				t.Fatalf("log line %q: %v", buffer.String(), err)
+			}
+			if entry.Msg != "request" || entry.Level != tt.want {
+				t.Errorf("logged %+v; want a request at %s", entry, tt.want)
+			}
+		})
+	}
+}

internal/server/server.go

@@ -6,6 +6,7 @@ import (
 	"crypto/tls"
 	"errors"
 	"fmt"
+	"log"
 	"log/slog"
 	"net"
 	"net/http"
@@ -17,6 +18,7 @@ import (
 	"github.com/pires/go-proxyproto"
 
 	"git.avsdev.uk/Go/job-search/internal/config"
+	"git.avsdev.uk/Go/job-search/internal/logging"
 	"git.avsdev.uk/Go/job-search/internal/middleware"
 	"git.avsdev.uk/Go/job-search/internal/util"
 	"git.avsdev.uk/Go/job-search/internal/websocket"
@@ -49,6 +51,16 @@ func WithLogger(logger *slog.Logger) Option {
 	}
 }
 
+// WithAccessLog makes the server write a line to logger for every request, in
+// the Combined Log Format (see logging.AccessLog), as well as the request
+// lines it logs with slog. The line is written when the request ends, and
+// covers requests that middleware refuses.
+func WithAccessLog(logger *log.Logger) Option {
+	return func(s *Server) {
+		s.accessLog = logger
+	}
+}
+
 // WithMiddleware appends middleware to a group. This is the generic hook
 // (auth, metrics, tracing, custom header rules, ...).
 func WithMiddleware(group Group, middlewares ...Middleware) Option {
@@ -82,10 +94,12 @@ type limiterHook struct {
 
 // Server is the application server.
 type Server struct {
-	conf     *config.JSCServer
+	conf *config.JSCServer
-	log      *slog.Logger
+	log  *slog.Logger
-	hooks    map[Group][]Middleware
+	// accessLog is where the access log is written, or nil for none.
-	limiters map[Group]limiterHook
+	accessLog *log.Logger
+	hooks     map[Group][]Middleware
+	limiters  map[Group]limiterHook
 
 	// trusted are the proxies whose forwarding headers are believed.
 	trusted []netip.Prefix
@@ -156,6 +170,9 @@ func New(conf *config.JSCServer, opts ...Option) (*Server, error) {
 		server.backgroundCancel()
 		return nil, err
 	}
+	if server.accessLog != nil {
+		server.handler = logging.AccessLog(server.accessLog, true, server.handler)
+	}
 
 	return server, nil
 }

internal/server/server_test.go

@@ -1,13 +1,16 @@
 package server
 
 import (
+	"bytes"
 	"context"
 	"encoding/json"
+	"log"
 	"log/slog"
 	"net/http"
 	"net/http/cookiejar"
 	"net/http/httptest"
 	"strings"
+	"sync"
 	"testing"
 	"time"
 
@@ -218,3 +221,89 @@ func TestNoLimitIfUnset(t *testing.T) {
 		}
 	}
 }
+
+// With WithAccessLog, each request, including one refused by middleware, is
+// written to the access log in the Combined Log Format.
+func TestAccessLog(t *testing.T) {
+	var buffer bytes.Buffer
+	ts := newTestServer(t, func(conf *config.JSCServer) {
+		conf.Headers.AllowedHosts = []string{"example.com"}
+	}, WithAccessLog(log.New(&buffer, "", 0)))
+
+	req, _ := http.NewRequest("GET", ts.URL+"/api/health", nil)
+	req.Host = "example.com"
+	req.Header.Set("User-Agent", "test-agent")
+	res, err := http.DefaultClient.Do(req)
+	if err != nil {
+		t.Fatal(err)
+	}
+	res.Body.Close()
+
+	// A Host that isn't allowed is refused by RequestChecks.
+	res, err = http.Get(ts.URL + "/api/health")
+	if err != nil {
+		t.Fatal(err)
+	}
+	res.Body.Close()
+
+	lines := strings.Split(strings.TrimSpace(buffer.String()), "\n")
+	if len(lines) != 2 {
+		t.Fatalf("access log has %d lines; want 2:\n%s", len(lines), &buffer)
+	}
+	if !strings.Contains(lines[0], `"GET /api/health HTTP/1.1" 200`) ||
+		!strings.Contains(lines[0], `"test-agent"`) {
+		t.Errorf("first line = %q; want a 200 with the user agent", lines[0])
+	}
+	if !strings.Contains(lines[1], `"GET /api/health HTTP/1.1" 421`) {
+		t.Errorf("second line = %q; want the refused request's 421", lines[1])
+	}
+}
+
+// With WithAccessLog, a WebSocket upgrade still hijacks the connection: the
+// client gets its welcome, and the upgrade is logged with 101.
+func TestAccessLogWebSocket(t *testing.T) {
+	var buffer syncBuffer
+	ts := newTestServer(t, nil, WithAccessLog(log.New(&buffer, "", 0)))
+	ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
+	defer cancel()
+
+	wsURL := "ws" + strings.TrimPrefix(ts.URL, "http") + "/ws"
+	conn, _, err := websocket.Dial(ctx, wsURL, nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	var welcome ws.Envelope
+	err = wsjson.Read(ctx, conn, &welcome)
+	if err != nil || welcome.Type != ws.TypeWelcome {
+		t.Fatalf("want welcome, got %+v, %v", welcome, err)
+	}
+	conn.Close(websocket.StatusNormalClosure, "")
+
+	// The line is written when the connection's handler returns.
+	deadline := time.Now().Add(time.Second)
+	for !strings.Contains(buffer.String(), `"GET /ws HTTP/1.1" 101`) {
+		if time.Now().After(deadline) {
+			t.Fatalf("upgrade not logged with 101: %q", buffer.String())
+		}
+		time.Sleep(5 * time.Millisecond)
+	}
+}
+
+// syncBuffer is a bytes.Buffer safe to write from one goroutine while
+// another reads it.
+type syncBuffer struct {
+	mu     sync.Mutex
+	buffer bytes.Buffer
+}
+
+func (b *syncBuffer) Write(data []byte) (int, error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buffer.Write(data)
+}
+
+func (b *syncBuffer) String() string {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buffer.String()
+}