Skip to content

Commit 7fae5fb

Browse files
committed
Downgrade ErrorCtx to Warn on canceled context
A client disconnecting or aborting a request cancels the request context; code further down the call chain often surfaces that as an error (failed query, failed decode) and logs it via ErrorCtx. That's not a server-side failure, so log it at Warn instead. Deadline exceeded is left at Error since it more often points at a real problem (slow query, downstream latency). Signed-off-by: Bryan Frimin <bryan@probo.com>
1 parent 9ec60a0 commit 7fae5fb

2 files changed

Lines changed: 47 additions & 1 deletion

File tree

‎log/log.go‎

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ package log
1818

1919
import (
2020
"context"
21+
"errors"
2122
"fmt"
2223
"io"
2324
"log/slog"
@@ -256,8 +257,15 @@ func (l *Logger) Named(name string, options ...Option) *Logger {
256257
}
257258

258259
// Log logs a message at the specified level with optional attributes,
259-
// adding trace and span IDs if the context has a span.
260+
// adding trace and span IDs if the context has a span. An Error
261+
// logged against a context canceled by its caller (e.g. a client
262+
// disconnect) is downgraded to Warn, since it reflects the caller
263+
// going away rather than a failure on our end.
260264
func (l *Logger) Log(ctx context.Context, level Level, msg string, args ...Attr) {
265+
if level == LevelError && errors.Is(context.Cause(ctx), context.Canceled) {
266+
level = LevelWarn
267+
}
268+
261269
if l.match != nil && l.match(level, msg, args) {
262270
return
263271
}

‎log/log_test.go‎

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -299,6 +299,44 @@ func TestCtxConvenienceMethods(t *testing.T) {
299299
}
300300
}
301301

302+
func TestErrorCtxDowngradesOnCanceledContext(t *testing.T) {
303+
var buf bytes.Buffer
304+
l := NewLogger(WithOutput(&buf))
305+
306+
ctx, cancel := context.WithCancel(context.Background())
307+
cancel()
308+
309+
l.ErrorCtx(ctx, "client went away")
310+
311+
m := parseJSONLog(t, &buf)
312+
assert.Equal(t, "WARN", m["level"])
313+
assert.Equal(t, "client went away", m["msg"])
314+
}
315+
316+
func TestErrorCtxKeepsErrorOnDeadlineExceeded(t *testing.T) {
317+
var buf bytes.Buffer
318+
l := NewLogger(WithOutput(&buf))
319+
320+
ctx, cancel := context.WithTimeout(context.Background(), 0)
321+
defer cancel()
322+
<-ctx.Done()
323+
324+
l.ErrorCtx(ctx, "slow downstream call")
325+
326+
m := parseJSONLog(t, &buf)
327+
assert.Equal(t, "ERROR", m["level"])
328+
}
329+
330+
func TestErrorCtxKeepsErrorOnLiveContext(t *testing.T) {
331+
var buf bytes.Buffer
332+
l := NewLogger(WithOutput(&buf))
333+
334+
l.ErrorCtx(context.Background(), "real failure")
335+
336+
m := parseJSONLog(t, &buf)
337+
assert.Equal(t, "ERROR", m["level"])
338+
}
339+
302340
func TestConvenienceMethodsWithAttrs(t *testing.T) {
303341
var buf bytes.Buffer
304342
l := NewLogger(WithOutput(&buf))

0 commit comments

Comments
 (0)