log every request, and make error mean something again

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>

internal/content/content.go

@@ -96,12 +96,14 @@ type Problem struct {
 // Scan reads every bundle under content/ in fsys, logging anything it worked around.
 //
 // A bundle that cannot be parsed, or that collides with another on the same key and language, is logged
-// at error level and left out; neither is fatal, because one mistyped colon must not take down a site
-// (ADR-0029). An error is returned only when the walk itself fails.
+// at **warn** and left out; neither is fatal, because one mistyped colon must not take down a site
+// (ADR-0029). Warn rather than error is the whole point of the distinction: the engine coped and the site
+// still serves, so error stays reserved for a request or a build step that actually failed
+// (`conventions.md`). An error is returned only when the walk itself fails.
 func Scan(fsys fs.FS) ([]Bundle, error) {
 	found, problems, err := ScanReport(fsys)
 	for _, p := range problems {
-		slog.Error("content problem", "path", p.Path, "detail", p.Detail)
+		slog.Warn("content problem", "path", p.Path, "detail", p.Detail)
 	}
 	return found, err
 }

internal/content/site.go

@@ -60,7 +60,7 @@ func (s *Site) Problems() []Problem { return s.problems }
 // note records a problem and logs it, so the server says the same thing it always did.
 func (s *Site) note(path, detail string) {
 	s.problems = append(s.problems, Problem{path, detail})
-	slog.Error("content problem", "path", path, "detail", detail)
+	slog.Warn("content problem", "path", path, "detail", detail)
 }
 
 // indexRoutes resolves each key's served path from the slugs its variants declare.

internal/ext/passthrough/passthrough.go

@@ -78,7 +78,7 @@ func Routes(siteFS fs.FS, settings content.Settings) map[string]http.Handler {
 		// A missing directory is the ordinary case for a site that wants none of this, so it is not worth a
 		// line in the log; anything else is.
 		if !errors.Is(err, fs.ErrNotExist) {
-			slog.Error("cannot read the passthrough directory", "dir", Dir, "err", err)
+			slog.Warn("cannot read the passthrough directory", "dir", Dir, "err", err)
 		}
 		return nil
 	}
@@ -98,7 +98,7 @@ func readHeaders(siteFS fs.FS) map[string]map[string]string {
 	if err := yaml.Unmarshal(data, &declared); err != nil {
 		// One bad manifest must not take the site down, so the files still serve with derived types
 		// (ADR-0029).
-		slog.Error("cannot parse the passthrough header manifest, so no declared headers apply",
+		slog.Warn("cannot parse the passthrough header manifest, so no declared headers apply",
 			"file", path.Join(Dir, headersFile), "err", err)
 		return nil
 	}
@@ -117,7 +117,7 @@ type file struct {
 func (f *file) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	data, err := fs.ReadFile(f.siteFS, f.name)
 	if err != nil {
-		slog.Error("a passthrough file vanished between startup and this request", "file", f.name, "err", err)
+		slog.Warn("a passthrough file vanished between startup and this request", "file", f.name, "err", err)
 		http.NotFound(w, r)
 		return
 	}
@@ -127,7 +127,7 @@ func (f *file) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		} else {
 			// The address is promised, and a spec-mandated file answering 404 because of a typo is worse
 			// than one answering with its own source. Logged loudly, served anyway (ADR-0029).
-			slog.Error("a passthrough template did not render, so its source is served instead",
+			slog.Warn("a passthrough template did not render, so its source is served instead",
 				"file", f.name, "err", err)
 		}
 	}

internal/ext/shortcodes/code.go

@@ -118,12 +118,12 @@ func readFence(f *ast.FencedCodeBlock, source []byte, origin render.Origin) *cod
 // template or a dotfile (ADR-0038).
 func fromFile(origin render.Origin, name, span string) ([]byte, int, bool) {
 	if origin.Files == nil || strings.Contains(name, "..") {
-		slog.Error("code block cannot read that file", "file", name)
+		slog.Warn("code block cannot read that file", "file", name)
 		return nil, 0, false
 	}
 	data, err := fs.ReadFile(origin.Files, path.Join(origin.Dir, name))
 	if err != nil {
-		slog.Error("code block cannot read that file", "file", name, "err", err)
+		slog.Warn("code block cannot read that file", "file", name, "err", err)
 		return nil, 0, false
 	}
 	lines := strings.Split(strings.TrimRight(string(data), "\n"), "\n")
@@ -180,7 +180,7 @@ func (f fragments) renderCode(w util.BufWriter, source []byte, n ast.Node, enter
 	}
 	tokens, err := chroma.Coalesce(lexer).Tokenise(nil, string(block.source))
 	if err != nil {
-		slog.Error("cannot highlight", "lang", block.lang, "err", err)
+		slog.Warn("cannot highlight", "lang", block.lang, "err", err)
 		return ast.WalkContinue, nil
 	}
 	options := []html.Option{html.WithClasses(true)}
@@ -192,7 +192,7 @@ func (f fragments) renderCode(w util.BufWriter, source []byte, n ast.Node, enter
 	}
 	var highlighted bytes.Buffer
 	if err := html.New(options...).Format(&highlighted, styles.Fallback, tokens); err != nil {
-		slog.Error("cannot format", "lang", block.lang, "err", err)
+		slog.Warn("cannot format", "lang", block.lang, "err", err)
 		return ast.WalkContinue, nil
 	}
 	args := map[string]string{"lang": block.lang}
@@ -201,7 +201,7 @@ func (f fragments) renderCode(w util.BufWriter, source []byte, n ast.Node, enter
 	}
 	out, err := f.partial(codeFragment, render.Fragment{Args: args, Body: template.HTML(highlighted.String())})
 	if err != nil {
-		slog.Error("skipping code fragment", "err", err)
+		slog.Warn("skipping code fragment", "err", err)
 		out = highlighted.Bytes()
 	}
 	if _, err := w.Write(out); err != nil {

internal/ext/shortcodes/containers.go

@@ -95,7 +95,7 @@ func (b bodies) Transform(doc *ast.Document, reader text.Reader, pc parser.Conte
 		var out bytes.Buffer
 		for child := call.FirstChild(); child != nil; child = child.NextSibling() {
 			if err := b.md.Renderer().Render(&out, reader.Source(), child); err != nil {
-				slog.Error("rendering a container body", "name", call.name, "err", err)
+				slog.Warn("rendering a container body", "name", call.name, "err", err)
 			}
 		}
 		call.body = out.Bytes()
@@ -112,7 +112,7 @@ func (f fragments) renderContainer(w util.BufWriter, source []byte, n ast.Node,
 	call := n.(*container)
 	out, err := f.partial(call.name, render.Fragment{Args: call.args, Lang: call.lang, Body: template.HTML(call.body)})
 	if err != nil {
-		slog.Error("skipping container", "name", call.name, "err", err)
+		slog.Warn("skipping container", "name", call.name, "err", err)
 		out = nil
 	}
 	if len(bytes.TrimSpace(out)) == 0 {
@@ -151,7 +151,7 @@ func Merge(src []byte, origin render.Origin) []byte {
 		}
 		body, err := included(origin, args["file"])
 		if err != nil {
-			slog.Error("skipping include", "file", args["file"], "err", err)
+			slog.Warn("skipping include", "file", args["file"], "err", err)
 			continue
 		}
 		out.Write(withoutIncludes(body))
@@ -168,7 +168,7 @@ func withoutIncludes(body []byte) []byte {
 		line, remainder, found := bytes.Cut(rest, []byte("\n"))
 		rest = remainder
 		if name, _, ok := parse(string(line), opener); ok && name == "include" {
-			slog.Error("ignoring an include inside an included file", "line", string(line))
+			slog.Warn("ignoring an include inside an included file", "line", string(line))
 			continue
 		}
 		out.Write(line)

internal/ext/shortcodes/icons.go

@@ -71,7 +71,7 @@ func (f fragments) renderIcon(w util.BufWriter, source []byte, n ast.Node, enter
 	call := n.(*iconNode)
 	out, err := f.partial(iconFragment, render.Fragment{Args: map[string]string{"name": call.name}, Lang: call.lang})
 	if err != nil {
-		slog.Error("skipping icon", "name", call.name, "err", err)
+		slog.Warn("skipping icon", "name", call.name, "err", err)
 		out = nil
 	}
 	if len(bytes.TrimSpace(out)) == 0 {

internal/ext/shortcodes/images.go

@@ -53,13 +53,13 @@ func Derive(siteFS fs.FS, cacheDir string) (int, error) {
 		}
 		data, err := fs.ReadFile(siteFS, p)
 		if err != nil {
-			slog.Error("skipping unreadable picture", "path", p, "err", err)
+			slog.Warn("skipping unreadable picture", "path", p, "err", err)
 			return nil
 		}
 		n, err := derive(data, p, cacheDir)
 		if err != nil {
 			// One unreadable picture must not stop a site from starting (ADR-0029).
-			slog.Error("skipping picture", "path", p, "err", err)
+			slog.Warn("skipping picture", "path", p, "err", err)
 			return nil
 		}
 		made += n
@@ -166,7 +166,7 @@ func picture(origin render.Origin, file string) (render.Picture, bool) {
 	name := path.Join(origin.Dir, file)
 	info, err := fs.Stat(origin.Files, name)
 	if err != nil {
-		slog.Error("picture unreadable", "path", name, "err", err)
+		slog.Warn("picture unreadable", "path", name, "err", err)
 		return p, true
 	}
 	key := fmt.Sprintf("%s\x00%d\x00%d", name, info.Size(), info.ModTime().UnixNano())
@@ -175,7 +175,7 @@ func picture(origin render.Origin, file string) (render.Picture, bool) {
 	}
 	data, err := fs.ReadFile(origin.Files, name)
 	if err != nil {
-		slog.Error("picture unreadable", "path", name, "err", err)
+		slog.Warn("picture unreadable", "path", name, "err", err)
 		return p, true
 	}
 	cfg, _, err := image.DecodeConfig(bytes.NewReader(data))

internal/ext/shortcodes/shortcodes.go

@@ -112,12 +112,12 @@ func (in includes) Transform(doc *ast.Document, reader text.Reader, pc parser.Co
 	}
 	for _, call := range pending(doc) {
 		if insideInclude {
-			slog.Error("ignoring an include inside an included file", "file", call.args["file"])
+			slog.Warn("ignoring an include inside an included file", "file", call.args["file"])
 			continue
 		}
 		content, err := in.convert(call.args["file"], pc)
 		if err != nil {
-			slog.Error("skipping include", "file", call.args["file"], "err", err)
+			slog.Warn("skipping include", "file", call.args["file"], "err", err)
 			continue
 		}
 		call.content = content
@@ -174,7 +174,7 @@ func pending(doc *ast.Document) []*node {
 		return ast.WalkContinue, nil
 	})
 	if err != nil {
-		slog.Error("walking for includes", "err", err)
+		slog.Warn("walking for includes", "err", err)
 	}
 	return found
 }
@@ -255,7 +255,7 @@ func gallery(pc parser.Context) []render.Picture {
 	}
 	entries, err := fs.ReadDir(origin.Files, origin.Dir)
 	if err != nil {
-		slog.Error("gallery cannot read its bundle directory", "dir", origin.Dir, "err", err)
+		slog.Warn("gallery cannot read its bundle directory", "dir", origin.Dir, "err", err)
 		return nil
 	}
 	var names []string
@@ -315,7 +315,7 @@ func (f fragments) render(w util.BufWriter, source []byte, n ast.Node, entering
 	out, err := f.partial(call.name, render.Fragment{
 		Args: call.args, Pictures: call.pictures, Headings: call.headings, Lang: call.lang})
 	if err != nil {
-		slog.Error("skipping shortcode", "name", call.name, "err", err)
+		slog.Warn("skipping shortcode", "name", call.name, "err", err)
 		return ast.WalkContinue, nil
 	}
 	if _, err := w.Write(out); err != nil {

internal/web/extras.go

@@ -55,9 +55,9 @@ func serveExtras(w http.ResponseWriter, req *http.Request, site *content.Site, r
 	if entry.Kind == "markdown" || entry.Kind == "text" {
 		data, err := fs.ReadFile(siteFS, name)
 		if err != nil {
-			slog.Error("extras entry unreadable", "path", name, "err", err)
+			slog.Warn("extras entry unreadable", "path", name, "err", err)
 		} else if html, err := r.RenderText(entry.Kind, data); err != nil {
-			slog.Error("extras entry unrenderable", "path", name, "err", err)
+			slog.Warn("extras entry unrenderable", "path", name, "err", err)
 		} else {
 			selected.HTML = html
 		}

internal/web/logging.go

@@ -0,0 +1,58 @@
+package web
+
+import (
+	"log/slog"
+	"net/http"
+
+	"khosra/internal/content"
+)
+
+// Logged wraps a handler so every request produces one line.
+//
+// This is the access log the engine did not have. Nothing else recorded that a request happened, and the
+// Dockerfile ships the binary alone with the site root mounted (ADR-0010) — so a bare deployment produced no
+// access log at all, which made offline traffic analysis impossible rather than merely inconvenient. That
+// matters because log analysis is this project's answer to analytics: no counter on the read path, no
+// third-party script.
+//
+// Applied by `cmd` around the finished handler rather than inside Handler, so tests and the demo's coverage
+// test stay quiet and so whether to log is the operator's decision rather than the engine's.
+func Logged(h http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		started := content.Now()
+		rec := &recorder{ResponseWriter: w, status: http.StatusOK}
+		h.ServeHTTP(rec, req)
+		slog.Info("request",
+			"method", req.Method,
+			"path", req.URL.Path,
+			"status", rec.status,
+			"bytes", rec.bytes,
+			"took", content.Now().Sub(started))
+	})
+}
+
+// recorder remembers what the handler answered, because a ResponseWriter tells nobody.
+//
+// status starts at 200: a handler that writes without calling WriteHeader has sent one, and that is the
+// common path here. Duration comes from content.Now, not time.Now — the clock lives in exactly one file and
+// `verify.sh` enforces it by filename.
+//
+// It deliberately does not forward Flusher or ReaderFrom. Nothing in this engine streams or hijacks, so the
+// only cost is losing an io.Copy fast path on static files; implementing optional interfaces that no caller
+// needs would be the speculative kind of code rule 6 forbids.
+type recorder struct {
+	http.ResponseWriter
+	status int
+	bytes  int
+}
+
+func (r *recorder) WriteHeader(status int) {
+	r.status = status
+	r.ResponseWriter.WriteHeader(status)
+}
+
+func (r *recorder) Write(b []byte) (int, error) {
+	n, err := r.ResponseWriter.Write(b)
+	r.bytes += n
+	return n, err
+}

internal/web/logging_test.go

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