bdeshiandClaude Opus 5
c3125e7ad2
Item 1 of the order of work, and two gaps rather than one polish item. There was no access log. Nothing recorded that a request happened, and the Dockerfile ships the binary alone with the site root mounted (ADR-0010), so a bare deployment produced none at all — which mattered because offline log analysis is this project's answer to analytics: no counter on the read path, no third-party script. web.Logged now writes one Info line per request with method, path, status, bytes and duration. And slog was never configured. conventions.md makes importing `log` instead of log/slog a hard failure while nothing ever set a level, a handler or a format. Two flags now do, rejected at startup if unusable, because a logger quietly less verbose than asked for hides exactly the lines somebody changed the flag to see. JSON is the half that matters: it is what makes a log parseable. The re-levelling was the larger half. Counts were 38 error, 7 warn, 4 info, 0 debug; they are now 7, 40, 6, 0. Almost every one of those errors was ADR-0029's "logged, not fatal" category — a misspelled directive, an asset path climbing out of its bundle, an unreadable picture — where the engine coped and the reader still got a good page. Error used as "somebody should see this" means an operator cannot tell a broken build from a typo. The seven that remain are the five requests that answer 500 and the two inside fatal. A successful rebuild now says so. It swapped silently before, so an operator could see a failed rebuild and never a successful one, which leaves the failures with nothing to be read against. No wrapper package: log/slog is the module, and a layer over it would be an abstraction with one caller. Duration comes from content.Now, since the clock is confined to one file and verify.sh enforces it by filename. The recorder does not forward Flusher or ReaderFrom — nothing here streams, so the cost is one io.Copy fast path on static files, and implementing interfaces no caller needs is the speculation rule 6 forbids. Two things this change owed and paid. content.go's comment still said content problems were "logged at error level", which the re-levelling made false. And the new flags pushed runServe past the function-length advisory, so the site-opening block became opened() — a warning that fires on correct code gets acted on, not tolerated, and that is the whole reason the advisory exists. Evidence, demo site, JSON: rebuilt bundles=31, then serving, then one request line each for a 200, a 404 and robots.txt with real byte counts and durations. At -log-level warn, request lines disappear. An invalid level exits with the reason. 12 files. Core 2913 → 2959 of 3400. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
73 lines
2.6 KiB
Go
73 lines
2.6 KiB
Go
package web
|
|
|
|
import (
|
|
"bytes"
|
|
"log/slog"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"strings"
|
|
"testing"
|
|
)
|
|
|
|
// capture installs a logger writing to a buffer and restores the previous one afterwards.
|
|
func capture(t *testing.T) *bytes.Buffer {
|
|
t.Helper()
|
|
var buf bytes.Buffer
|
|
prev := slog.Default()
|
|
slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil)))
|
|
t.Cleanup(func() { slog.SetDefault(prev) })
|
|
return &buf
|
|
}
|
|
|
|
// One line per request, carrying what an access log is for: what was asked, what was answered, how big and
|
|
// how long. Nothing recorded requests before this, so a bare deployment had no access log at all.
|
|
func TestLoggedRecordsWhatWasAnswered(t *testing.T) {
|
|
buf := capture(t)
|
|
h := Logged(http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
|
|
w.WriteHeader(http.StatusTeapot)
|
|
if _, err := w.Write([]byte("hello")); err != nil {
|
|
t.Error(err)
|
|
}
|
|
}))
|
|
rec := httptest.NewRecorder()
|
|
h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/a/path", nil))
|
|
|
|
line := buf.String()
|
|
for _, want := range []string{"msg=request", "method=GET", "path=/a/path", "status=418", "bytes=5", "took="} {
|
|
if !strings.Contains(line, want) {
|
|
t.Errorf("the access log is missing %q:\n%s", want, line)
|
|
}
|
|
}
|
|
// The wrapper must not alter what the client receives.
|
|
if rec.Code != http.StatusTeapot || rec.Body.String() != "hello" {
|
|
t.Errorf("the wrapper changed the response: %d %q", rec.Code, rec.Body.String())
|
|
}
|
|
}
|
|
|
|
// A handler that writes without calling WriteHeader has sent a 200, which is the common path here — so the
|
|
// recorder must assume it rather than reporting zero.
|
|
func TestLoggedAssumesTwoHundredWhenTheHandlerNeverSaysOtherwise(t *testing.T) {
|
|
buf := capture(t)
|
|
h := Logged(http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
|
|
if _, err := w.Write([]byte("x")); err != nil {
|
|
t.Error(err)
|
|
}
|
|
}))
|
|
h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil))
|
|
if got := buf.String(); !strings.Contains(got, "status=200") {
|
|
t.Errorf("status should default to 200:\n%s", got)
|
|
}
|
|
}
|
|
|
|
// A 404 is a normal answer, not a failure, so it is logged at info like every other request. The level
|
|
// convention reserves error for something the engine could not do (conventions.md).
|
|
func TestLoggedTreatsANotFoundAsAnOrdinaryRequest(t *testing.T) {
|
|
buf := capture(t)
|
|
h := Logged(http.HandlerFunc(http.NotFound))
|
|
h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/missing", nil))
|
|
got := buf.String()
|
|
if !strings.Contains(got, "status=404") || !strings.Contains(got, "level=INFO") {
|
|
t.Errorf("a 404 should be one INFO line:\n%s", got)
|
|
}
|
|
}
|