coverage — ~bigbes/sr-ht-ecore — 3bd158fb — chimw/logger.go

Coverage
97.2% 35/36 statements
Δ
—
Blob
9a419f2
Uncovered L182-L183
1 package chimw
2
3 import (
4 "context"
5 "log/slog"
6 "net/http"
7 "time"
8
9 chimiddleware "github.com/go-chi/chi/v5/middleware"
10
11 "sourcecraft.dev/bigbes/sr-ht-ecore/middleware"
12 )
13
14 // defaultLogMessage is the message of the request record. It is a constant
15 // rather than a formatted sentence because everything that varies is an
16 // attribute: a structured record whose message changed per request would make
17 // the one field a log pipeline groups by useless.
18 const defaultLogMessage = "request"
19
20 // SlogFormatter is chi's middleware.LogFormatter emitting slog records instead
21 // of chi's own line.
22 //
23 // chi's Logger writes through a package-level stdlib log.Logger to *stdout*, in
24 // a colourised human format, with no fields. On this instance that is the
25 // highest-volume line a service emits and the only one that is not structured
26 // and not on stderr: an operator who greps the journal for a request id finds
27 // every panic and every audit line of the daemon, and none of its requests.
28 // Replacing it is the entire point of this type.
29 //
30 // It is a LogFormatter rather than a middleware of our own because chi already
31 // owns the parts that are tedious to get right — wrapping the ResponseWriter so
32 // that status and byte count are observable at all, and writing the entry from a
33 // defer so that a request that panics is still logged. What was missing was
34 // somewhere to send the result.
35 //
36 // The zero value works: records go to slog.Default(), under the message
37 // "request", for every request. Use it as
38 //
39 // r.Use(chimw.RequestLogger(chimw.SlogFormatter{}))
40 type SlogFormatter struct {
41 // Logger is where records go. Nil means slog.Default(), read at write time,
42 // so a service that calls slog.SetDefault after building its router still
43 // gets its own handler — this is middleware.RecoverPanics's rule, for the
44 // reason given in the package doc.
45 Logger *slog.Logger
46
47 // Message overrides the record's message. Empty means "request".
48 Message string
49
50 // Skip decides which requests produce no line. Nil logs everything.
51 //
52 // The decision is the caller's and not this package's, deliberately. The
53 // noise worth dropping is a probe hitting /healthz every second — but
54 // "/healthz" is this instance's spelling, a service may also be polled at
55 // /metrics, at a badge a README embeds, or at a static prefix, and which of
56 // those is noise depends on what the operator is looking for that week. A
57 // list baked in here would silently drop the one line somebody debugging
58 // the probe needs, in a package they would have to read the source of to
59 // find out why. SkipPaths covers the common case in one call.
60 //
61 // It is evaluated once per request, before the handler runs, and it
62 // silences only the request line: a panic on a skipped path is still
63 // reported, because a probe path that panics is not noise.
64 Skip func(r *http.Request) bool
65 }
66
67 // RequestLogger is the middleware for a formatter: chi's RequestLogger with this
68 // package's formatter already in it, so that a service need not import chi's
69 // middleware package to install one.
70 //
71 // It goes outermost, ahead of middleware.RecoverPanics — see the package doc for
72 // why — and after chi's RequestID and RealIP, which must have run before the
73 // entry is built for the record to carry an id and for RemoteAddr to be the
74 // viewer's.
75 20 func RequestLogger(f SlogFormatter) func(http.Handler) http.Handler {
76 20 return chimiddleware.RequestLogger(f)
77 20 }
78
79 // SkipPaths builds a Skip predicate matching a fixed set of exact paths, which
80 // is what a probe endpoint is. It matches on the path alone: a query string
81 // cannot turn /healthz into something worth a line.
82 3 func SkipPaths(paths ...string) func(r *http.Request) bool {
83 3 set := make(map[string]struct{}, len(paths))
84 3 for _, p := range paths {
85 2 set[p] = struct{}{}
86 2 }
87 4 return func(r *http.Request) bool {
88 4 _, ok := set[r.URL.Path]
89 4 return ok
90 4 }
91 }
92
93 // NewLogEntry captures what is known before the handler runs. It implements
94 // chi's middleware.LogFormatter.
95 21 func (f SlogFormatter) NewLogEntry(r *http.Request) chimiddleware.LogEntry {
96 21 ctx := r.Context()
97 21 return &logEntry{
98 21 formatter: f,
99 21 ctx: ctx,
100 21 method: r.Method,
101 21 path: r.URL.Path,
102 21 requestID: chimiddleware.GetReqID(ctx),
103 21 quiet: f.Skip != nil && f.Skip(r),
104 21 }
105 21 }
106
107 // logEntry is one request's record, filled in when the response is done.
108 //
109 // The request itself is not held on to. What is logged is copied out here, at
110 // the top of the chain, where r.Method is still the method that arrived and the
111 // path has not been rewritten by anything mounted below; keeping the *http.Request
112 // would mean logging whatever the last middleware to rewrite it decided.
113 type logEntry struct {
114 formatter SlogFormatter
115 ctx context.Context
116 method string
117 path string
118 requestID string
119 quiet bool
120 }
121
122 // Write emits the request line. chi calls it from a defer, so it runs for a
123 // handler that returned normally, one that panicked, and one whose client hung
124 // up halfway.
125 //
126 // The attributes are the five that answer "what happened to this request" —
127 // method, path, status, bytes, duration — plus the request id when chi's
128 // RequestID middleware is installed above this one, which is the field that ties
129 // the line to the panic report and to whatever the handler logged in between.
130 //
131 // path is r.URL.Path and deliberately not RequestURI: the query string of these
132 // services carries search terms a viewer typed and, on the pages that come back
133 // from an OAuth round trip, parameters nobody wants written to disk twice. The
134 // route pattern is not logged either — it is available from the route context by
135 // the time this runs, but it is derivable from the path by anyone reading, and
136 // the path is the thing an operator has in front of them when a report comes in.
137 //
138 // The header is ignored. It is the response's, it is large, and the two fields
139 // of it worth having (status and length) are already arguments.
140 21 func (e *logEntry) Write(status, bytes int, _ http.Header, elapsed time.Duration, _ any) {
141 21 if e.quiet {
142 2 return
143 2 }
144
145 19 status = e.reportedStatus(status)
146 19
147 19 attrs := make([]slog.Attr, 0, 6)
148 19 attrs = append(attrs,
149 19 slog.String("method", e.method),
150 19 slog.String("path", e.path),
151 19 slog.Int("status", status),
152 19 slog.Int("bytes", bytes),
153 19 slog.Duration("duration", elapsed),
154 19 )
155 19 if e.requestID != "" {
156 1 attrs = append(attrs, slog.String("request_id", e.requestID))
157 1 }
158
159 19 e.logger().LogAttrs(e.ctx, levelFor(status), e.message(), attrs...)
160 }
161
162 // Panic is what chi's Recoverer reports through when a log entry is in context;
163 // without it that report is printed to stdout as a pretty-coloured stack, which
164 // is the same escape from the log this type exists to close.
165 //
166 // It does not double up with middleware.RecoverPanics. That one recovers the
167 // panic and renders a page, so the only panics still travelling when Recoverer
168 // looks are the ones it re-raises deliberately — http.ErrAbortHandler, which
169 // chi's Recoverer re-panics without calling this method.
170 //
171 // Skip does not silence it. A request nobody wanted a line for is still a
172 // request whose panic somebody needs.
173 2 func (e *logEntry) Panic(v any, stack []byte) {
174 2 attrs := make([]slog.Attr, 0, 5)
175 2 attrs = append(attrs,
176 2 slog.String("method", e.method),
177 2 slog.String("path", e.path),
178 2 slog.Any("panic", v),
179 2 slog.String("stack", string(stack)),
180 2 )
181 2 if e.requestID != "" {
182 0 attrs = append(attrs, slog.String("request_id", e.requestID))
183 0 }
184
185 2 e.logger().LogAttrs(e.ctx, slog.LevelError, "panic serving a request", attrs...)
186 }
187
188 // reportedStatus turns chi's "nothing was written" into the status the client
189 // actually saw.
190 //
191 // chi's wrapped writer reports 0 when no WriteHeader and no Write ever happened.
192 // Two things produce that. A handler that returned without touching the writer,
193 // which net/http answers with an empty 200 — so 200 is what the client got, and
194 // logging a 0 would send an operator looking for a bug in a redirect that worked.
195 // And a handler that gave up because the caller was already gone, which is what a
196 // cancelled request context means here: no status line was sent because there was
197 // nobody left to send it to.
198 //
199 // That second case is reported as middleware.StatusClientClosedRequest — nginx's
200 // 499, the code the log pipelines in front of this instance already read as "the
201 // client hung up". It is deliberately not any 5xx, which is what levelFor turns
202 // into an Error record and what the alert rate is written against: a viewer who
203 // navigated away mid-render and a CI job that pressed ^C must not page anybody.
204 // That reasoning is the constant's own (middleware.StatusClientClosedRequest);
205 // this is the place it gets applied to the highest-volume line the service emits.
206 //
207 // A handler that answered 499 itself — the donors' status mapping does, on both
208 // surfaces — needs no help from here: 499 is below 500, so it is already an Info
209 // record, which is the whole reason that number was picked over 500.
210 19 func (e *logEntry) reportedStatus(status int) int {
211 19 if status != 0 {
212 15 return status
213 15 }
214 4 if e.ctx.Err() != nil {
215 1 return middleware.StatusClientClosedRequest
216 1 }
217 3 return http.StatusOK
218 }
219
220 // levelFor picks the level of a request line from its status.
221 //
222 // Everything is Info except a 5xx, which is Error. A request line is not a
223 // finding — it is the record that something was served — so the default is the
224 // level a service's ordinary progress is logged at, and a deployment that
225 // dropped it to Warn would be trading away the only per-request evidence it has.
226 //
227 // A 5xx is promoted because it is the one status the service is confessing to:
228 // nothing the viewer typed produces it, and the record is worth its own line in
229 // an operator's filter without them having to know the field name for status.
230 // 4xx stays at Info on purpose. A 404 is a crawler, a stale bookmark or somebody
231 // mistyping a repository name, a 403 is the visibility rules working, and
232 // promoting either would hand a stranger with a URL bar the ability to set the
233 // warning rate of the instance.
234 //
235 // Nothing here special-cases 499: it is below 500 and lands at Info by the same
236 // rule as a 404, which is what makes it the right code for a client that hung up.
237 19 func levelFor(status int) slog.Level {
238 19 if status >= http.StatusInternalServerError {
239 4 return slog.LevelError
240 4 }
241 15 return slog.LevelInfo
242 }
243
244 21 func (e *logEntry) logger() *slog.Logger {
245 21 if e.formatter.Logger != nil {
246 19 return e.formatter.Logger
247 19 }
248 2 return slog.Default()
249 }
250
251 19 func (e *logEntry) message() string {
252 19 if e.formatter.Message != "" {
253 1 return e.formatter.Message
254 1 }
255 18 return defaultLogMessage
256 }