~bigbes/sr-ht-ecore

ref: 9a97b126e5a4f23591b42da7d75b0bb843c31521 sr-ht-ecore/chimw/logger.go -rw-r--r-- 10.4 KiB
9a97b126 — Eugene Blikh ecore: the gaps the third adoption pass found 9 days ago
                                                                                
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
package chimw

import (
	"context"
	"log/slog"
	"net/http"
	"time"

	chimiddleware "github.com/go-chi/chi/v5/middleware"

	"sourcecraft.dev/bigbes/sr-ht-ecore/middleware"
)

// defaultLogMessage is the message of the request record. It is a constant
// rather than a formatted sentence because everything that varies is an
// attribute: a structured record whose message changed per request would make
// the one field a log pipeline groups by useless.
const defaultLogMessage = "request"

// SlogFormatter is chi's middleware.LogFormatter emitting slog records instead
// of chi's own line.
//
// chi's Logger writes through a package-level stdlib log.Logger to *stdout*, in
// a colourised human format, with no fields. On this instance that is the
// highest-volume line a service emits and the only one that is not structured
// and not on stderr: an operator who greps the journal for a request id finds
// every panic and every audit line of the daemon, and none of its requests.
// Replacing it is the entire point of this type.
//
// It is a LogFormatter rather than a middleware of our own because chi already
// owns the parts that are tedious to get right — wrapping the ResponseWriter so
// that status and byte count are observable at all, and writing the entry from a
// defer so that a request that panics is still logged. What was missing was
// somewhere to send the result.
//
// The zero value works: records go to slog.Default(), under the message
// "request", for every request. Use it as
//
//	r.Use(chimw.RequestLogger(chimw.SlogFormatter{}))
type SlogFormatter struct {
	// Logger is where records go. Nil means slog.Default(), read at write time,
	// so a service that calls slog.SetDefault after building its router still
	// gets its own handler — this is middleware.RecoverPanics's rule, for the
	// reason given in the package doc.
	Logger *slog.Logger

	// Message overrides the record's message. Empty means "request".
	Message string

	// Skip decides which requests produce no line. Nil logs everything.
	//
	// The decision is the caller's and not this package's, deliberately. The
	// noise worth dropping is a probe hitting /healthz every second — but
	// "/healthz" is this instance's spelling, a service may also be polled at
	// /metrics, at a badge a README embeds, or at a static prefix, and which of
	// those is noise depends on what the operator is looking for that week. A
	// list baked in here would silently drop the one line somebody debugging
	// the probe needs, in a package they would have to read the source of to
	// find out why. SkipPaths covers the common case in one call.
	//
	// It is evaluated once per request, before the handler runs, and it
	// silences only the request line: a panic on a skipped path is still
	// reported, because a probe path that panics is not noise.
	Skip func(r *http.Request) bool
}

// RequestLogger is the middleware for a formatter: chi's RequestLogger with this
// package's formatter already in it, so that a service need not import chi's
// middleware package to install one.
//
// It goes outermost, ahead of middleware.RecoverPanics — see the package doc for
// why — and after chi's RequestID and RealIP, which must have run before the
// entry is built for the record to carry an id and for RemoteAddr to be the
// viewer's.
func RequestLogger(f SlogFormatter) func(http.Handler) http.Handler {
	return chimiddleware.RequestLogger(f)
}

// SkipPaths builds a Skip predicate matching a fixed set of exact paths, which
// is what a probe endpoint is. It matches on the path alone: a query string
// cannot turn /healthz into something worth a line.
func SkipPaths(paths ...string) func(r *http.Request) bool {
	set := make(map[string]struct{}, len(paths))
	for _, p := range paths {
		set[p] = struct{}{}
	}
	return func(r *http.Request) bool {
		_, ok := set[r.URL.Path]
		return ok
	}
}

// NewLogEntry captures what is known before the handler runs. It implements
// chi's middleware.LogFormatter.
func (f SlogFormatter) NewLogEntry(r *http.Request) chimiddleware.LogEntry {
	ctx := r.Context()
	return &logEntry{
		formatter: f,
		ctx:       ctx,
		method:    r.Method,
		path:      r.URL.Path,
		requestID: chimiddleware.GetReqID(ctx),
		quiet:     f.Skip != nil && f.Skip(r),
	}
}

// logEntry is one request's record, filled in when the response is done.
//
// The request itself is not held on to. What is logged is copied out here, at
// the top of the chain, where r.Method is still the method that arrived and the
// path has not been rewritten by anything mounted below; keeping the *http.Request
// would mean logging whatever the last middleware to rewrite it decided.
type logEntry struct {
	formatter SlogFormatter
	ctx       context.Context
	method    string
	path      string
	requestID string
	quiet     bool
}

// Write emits the request line. chi calls it from a defer, so it runs for a
// handler that returned normally, one that panicked, and one whose client hung
// up halfway.
//
// The attributes are the five that answer "what happened to this request" —
// method, path, status, bytes, duration — plus the request id when chi's
// RequestID middleware is installed above this one, which is the field that ties
// the line to the panic report and to whatever the handler logged in between.
//
// path is r.URL.Path and deliberately not RequestURI: the query string of these
// services carries search terms a viewer typed and, on the pages that come back
// from an OAuth round trip, parameters nobody wants written to disk twice. The
// route pattern is not logged either — it is available from the route context by
// the time this runs, but it is derivable from the path by anyone reading, and
// the path is the thing an operator has in front of them when a report comes in.
//
// The header is ignored. It is the response's, it is large, and the two fields
// of it worth having (status and length) are already arguments.
func (e *logEntry) Write(status, bytes int, _ http.Header, elapsed time.Duration, _ any) {
	if e.quiet {
		return
	}

	status = e.reportedStatus(status)

	attrs := make([]slog.Attr, 0, 6)
	attrs = append(attrs,
		slog.String("method", e.method),
		slog.String("path", e.path),
		slog.Int("status", status),
		slog.Int("bytes", bytes),
		slog.Duration("duration", elapsed),
	)
	if e.requestID != "" {
		attrs = append(attrs, slog.String("request_id", e.requestID))
	}

	e.logger().LogAttrs(e.ctx, levelFor(status), e.message(), attrs...)
}

// Panic is what chi's Recoverer reports through when a log entry is in context;
// without it that report is printed to stdout as a pretty-coloured stack, which
// is the same escape from the log this type exists to close.
//
// It does not double up with middleware.RecoverPanics. That one recovers the
// panic and renders a page, so the only panics still travelling when Recoverer
// looks are the ones it re-raises deliberately — http.ErrAbortHandler, which
// chi's Recoverer re-panics without calling this method.
//
// Skip does not silence it. A request nobody wanted a line for is still a
// request whose panic somebody needs.
func (e *logEntry) Panic(v any, stack []byte) {
	attrs := make([]slog.Attr, 0, 5)
	attrs = append(attrs,
		slog.String("method", e.method),
		slog.String("path", e.path),
		slog.Any("panic", v),
		slog.String("stack", string(stack)),
	)
	if e.requestID != "" {
		attrs = append(attrs, slog.String("request_id", e.requestID))
	}

	e.logger().LogAttrs(e.ctx, slog.LevelError, "panic serving a request", attrs...)
}

// reportedStatus turns chi's "nothing was written" into the status the client
// actually saw.
//
// chi's wrapped writer reports 0 when no WriteHeader and no Write ever happened.
// Two things produce that. A handler that returned without touching the writer,
// which net/http answers with an empty 200 — so 200 is what the client got, and
// logging a 0 would send an operator looking for a bug in a redirect that worked.
// And a handler that gave up because the caller was already gone, which is what a
// cancelled request context means here: no status line was sent because there was
// nobody left to send it to.
//
// That second case is reported as middleware.StatusClientClosedRequest — nginx's
// 499, the code the log pipelines in front of this instance already read as "the
// client hung up". It is deliberately not any 5xx, which is what levelFor turns
// into an Error record and what the alert rate is written against: a viewer who
// navigated away mid-render and a CI job that pressed ^C must not page anybody.
// That reasoning is the constant's own (middleware.StatusClientClosedRequest);
// this is the place it gets applied to the highest-volume line the service emits.
//
// A handler that answered 499 itself — the donors' status mapping does, on both
// surfaces — needs no help from here: 499 is below 500, so it is already an Info
// record, which is the whole reason that number was picked over 500.
func (e *logEntry) reportedStatus(status int) int {
	if status != 0 {
		return status
	}
	if e.ctx.Err() != nil {
		return middleware.StatusClientClosedRequest
	}
	return http.StatusOK
}

// levelFor picks the level of a request line from its status.
//
// Everything is Info except a 5xx, which is Error. A request line is not a
// finding — it is the record that something was served — so the default is the
// level a service's ordinary progress is logged at, and a deployment that
// dropped it to Warn would be trading away the only per-request evidence it has.
//
// A 5xx is promoted because it is the one status the service is confessing to:
// nothing the viewer typed produces it, and the record is worth its own line in
// an operator's filter without them having to know the field name for status.
// 4xx stays at Info on purpose. A 404 is a crawler, a stale bookmark or somebody
// mistyping a repository name, a 403 is the visibility rules working, and
// promoting either would hand a stranger with a URL bar the ability to set the
// warning rate of the instance.
//
// Nothing here special-cases 499: it is below 500 and lands at Info by the same
// rule as a 404, which is what makes it the right code for a client that hung up.
func levelFor(status int) slog.Level {
	if status >= http.StatusInternalServerError {
		return slog.LevelError
	}
	return slog.LevelInfo
}

func (e *logEntry) logger() *slog.Logger {
	if e.formatter.Logger != nil {
		return e.formatter.Logger
	}
	return slog.Default()
}

func (e *logEntry) message() string {
	if e.formatter.Message != "" {
		return e.formatter.Message
	}
	return defaultLogMessage
}