diff --git a/cmd/mock-fts/main.go b/cmd/mock-fts/main.go index ef5408e..a9bdb16 100644 --- a/cmd/mock-fts/main.go +++ b/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 - if opts.accessLogPath != "-" { - var logFile *os.File - logFile, err = os.OpenFile( - opts.accessLogPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600, - ) - if err != nil { - cancel() - <-workerDone - return fmt.Errorf("opening access log: %w", err) - } - defer func() { - err = errors.Join(err, logFile.Close()) - }() - out = logFile + accessLogger, closeAccessLog, err := logging.OpenAccessLog( + opts.accessLogPath, + ) + if err != nil { + cancel() + <-workerDone + return err } - accessLogger := log.New(out, "", 0) + defer func() { + err = errors.Join(err, closeAccessLog()) + }() rateLimiter := mock.NewRateLimiter(opts.rateLimit, opts.rateWindow) mux := http.NewServeMux() diff --git a/internal/cli/serve/command.go b/internal/cli/serve/command.go index 4eaf5d5..762603d 100644 --- a/internal/cli/serve/command.go +++ b/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") diff --git a/internal/config/README.md b/internal/config/README.md index 938317e..6b93b6d 100644 --- a/internal/config/README.md +++ b/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 diff --git a/internal/config/conf_server.go b/internal/config/conf_server.go index 87fc06c..2db95fe 100644 --- a/internal/config/conf_server.go +++ b/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"` diff --git a/internal/logging/accesslog.go b/internal/logging/accesslog.go index 2352118..20407d1 100644 --- a/internal/logging/accesslog.go +++ b/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 +} diff --git a/internal/logging/accesslog_test.go b/internal/logging/accesslog_test.go index 3efeab0..65a77aa 100644 --- a/internal/logging/accesslog_test.go +++ b/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) + } +} diff --git a/internal/middleware/logging.go b/internal/middleware/logging.go index 642b835..d8f9a4d 100644 --- a/internal/middleware/logging.go +++ b/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 -// logged, as it may carry secrets. It logs to slog.Default() unless given -// WithLogger. +// Logger logs one line per request: at debug level, or at info level for a +// connection hijack (a WebSocket upgrade), as one is logged per connection +// 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( diff --git a/internal/middleware/logging_test.go b/internal/middleware/logging_test.go new file mode 100644 index 0000000..e0977bc --- /dev/null +++ b/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) + } + }) + } +} diff --git a/internal/server/server.go b/internal/server/server.go index 16663ad..45ed89d 100644 --- a/internal/server/server.go +++ b/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 - log *slog.Logger - hooks map[Group][]Middleware - limiters map[Group]limiterHook + conf *config.JSCServer + log *slog.Logger + // accessLog is where the access log is written, or nil for none. + 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 } diff --git a/internal/server/server_test.go b/internal/server/server_test.go index d88e08c..1d3b50b 100644 --- a/internal/server/server_test.go +++ b/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() +}