Fast and extensible multi-platform HTTP/1-2-3 web server with automatic HTTPS
Mirrored from https://github.com/Slazee/caddy.git
Synced Nov 11, 06:00 UTC
caddyhttp: surface write timeout errors in access log (#7945)
Co-authored-by: Eugin Francis <13235453+euginfrancis@users.noreply.github.com> Signed-off-by: Faiyaz Rahman <faiyazrahman03@gmail.com>
Faiyaz Rahman committed
Sep 4, 2026 at 20:56 UTC
8e90c9a0e1b5c2c2f7e83a7488fba672b204bdd0
2 files changed
+208
-9
modules/caddyhttp/server.go
+34
-4
@@ -642,9 +642,11 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
642
errLog := s.errorLogger.WithLazy(loggableReq)
643
644
var duration time.Duration
645
+ var wrec ResponseRecorder
646
+ var writeErr error
647
648
if s.shouldLogRequest(r) {
647
- wrec := NewResponseRecorder(w, nil, nil)
649
+ wrec = NewResponseRecorder(w, nil, nil)
650
w = wrec
651
652
// wrap the request body in a LengthReader
@@ -653,7 +655,6 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
655
if r.Body != nil {
656
bodyReader = &lengthReader{Source: r.Body}
657
r.Body = bodyReader
656
-
658
// should always be true, private interface can only be referenced in the same package
659
if setReadSizer, ok := wrec.(interface{ setReadSize(*int) }); ok {
660
setReadSizer.setReadSize(&bodyReader.Length)
@@ -663,7 +664,28 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
664
// capture the original version of the request
665
accLog := s.accessLogger.WithLazy(loggableReq)
666
666
- defer s.logRequest(accLog, r, wrec, &duration, repl, bodyReader, shouldLogCredentials)
667
+ defer s.logRequest(accLog, r, wrec, &duration, &writeErr, repl, bodyReader, shouldLogCredentials)
668
+
669
+ // if the request went past the write timeout, flush so the access log can
670
+ // see the write error. deferred because flushing before the error routes
671
+ // run would commit a 200 and lose the error status. it sits after the
672
+ // access log defer so it still runs first.
673
+ defer func() {
674
+ if s.WriteTimeout <= 0 ||
675
+ r.ProtoMajor != 1 ||
676
+ duration < time.Duration(s.WriteTimeout) {
677
+ return
678
+ }
679
+ // over wrec, not the rc above: this reaches the recorder's
680
+ // FlushError, which skips buffered responses (#6144); rc sits
681
+ // below the recorder and would flush them anyway.
682
+ flushErr := http.NewResponseController(wrec).Flush()
683
+ if flushErr != nil &&
684
+ !errors.Is(flushErr, http.ErrHijacked) &&
685
+ !errors.Is(flushErr, http.ErrNotSupported) {
686
+ writeErr = flushErr
687
+ }
688
+ }()
689
}
690
691
// guarantee ACME HTTP challenges; handle them separately from any user-defined handlers
@@ -1190,7 +1212,7 @@ func (s *Server) logTrace(mh MiddlewareHandler) {
1212
1213
// logRequest logs the request to access logs, unless skipped.
1214
func (s *Server) logRequest(
1193
- accLog *zap.Logger, r *http.Request, wrec ResponseRecorder, duration *time.Duration,
1215
+ accLog *zap.Logger, r *http.Request, wrec ResponseRecorder, duration *time.Duration, writeErr *error,
1216
repl *caddy.Replacer, bodyReader *lengthReader, shouldLogCredentials bool,
1217
) {
1218
ctx := r.Context()
@@ -1240,7 +1262,12 @@ func (s *Server) logRequest(
1262
1263
extra := ctx.Value(ExtraLogFieldsCtxKey).(*ExtraLogFields)
1264
1265
+ hasWriteErr := writeErr != nil && *writeErr != nil
1266
+
1267
fieldCount := 6
1268
+ if hasWriteErr {
1269
+ fieldCount++
1270
+ }
1271
fields = make([]zapcore.Field, 0, fieldCount+len(extra.fields))
1272
fields = append(
1273
fields,
@@ -1254,6 +1281,9 @@ func (s *Server) logRequest(
1281
ShouldLogCredentials: shouldLogCredentials,
1282
}),
1283
)
1284
+ if hasWriteErr {
1285
+ fields = append(fields, zap.NamedError("write_error", *writeErr))
1286
+ }
1287
fields = append(fields, extra.fields...)
1288
}
1289
modules/caddyhttp/server_test.go
+174
-5
@@ -4,25 +4,46 @@ import (
4
"bufio"
5
"bytes"
6
"context"
7
+ "errors"
8
+ "fmt"
9
"io"
10
"net"
11
"net/http"
12
"net/http/httptest"
13
"net/netip"
14
"strings"
15
+ "sync"
16
"testing"
17
"time"
18
19
+ "github.com/caddyserver/caddy/v2"
20
"github.com/stretchr/testify/assert"
21
"github.com/stretchr/testify/require"
22
"go.uber.org/zap"
23
"go.uber.org/zap/zapcore"
24
)
25
26
+type syncBuffer struct {
27
+ mu sync.Mutex
28
+ buf bytes.Buffer
29
+}
30
+
31
type writeFunc func(p []byte) (int, error)
32
33
type nopSyncer writeFunc
34
35
+func (s *syncBuffer) Write(p []byte) (n int, err error) {
36
+ s.mu.Lock()
37
+ defer s.mu.Unlock()
38
+ return s.buf.Write(p)
39
+}
40
+
41
+func (s *syncBuffer) String() string {
42
+ s.mu.Lock()
43
+ defer s.mu.Unlock()
44
+ return s.buf.String()
45
+}
46
+
47
func (n nopSyncer) Write(p []byte) (int, error) {
48
return n(p)
49
}
@@ -64,7 +85,7 @@ func TestServer_LogRequest(t *testing.T) {
85
86
buf := bytes.Buffer{}
87
accLog := testLogger(buf.Write)
67
- s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, shouldLogCredentials)
88
+ s.logRequest(accLog, req, wrec, &duration, nil, repl, bodyReader, shouldLogCredentials)
89
90
assert.JSONEq(t, `{
91
"msg":"handled request", "level":"info", "bytes_read":0,
@@ -92,7 +113,7 @@ func TestServer_LogRequest_WithTrace(t *testing.T) {
113
114
buf := bytes.Buffer{}
115
accLog := testLogger(buf.Write)
95
- s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, shouldLogCredentials)
116
+ s.logRequest(accLog, req, wrec, &duration, nil, repl, bodyReader, shouldLogCredentials)
117
118
assert.JSONEq(t, `{
119
"msg":"handled request", "level":"info", "bytes_read":0,
@@ -121,7 +142,7 @@ func BenchmarkServer_LogRequest(b *testing.B) {
142
accLog := testLogger(buf.Write)
143
144
for b.Loop() {
124
- s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, false)
145
+ s.logRequest(accLog, req, wrec, &duration, nil, repl, bodyReader, false)
146
}
147
}
148
@@ -142,7 +163,7 @@ func BenchmarkServer_LogRequest_NopLogger(b *testing.B) {
163
accLog := zap.NewNop()
164
165
for b.Loop() {
145
- s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, false)
166
+ s.logRequest(accLog, req, wrec, &duration, nil, repl, bodyReader, false)
167
}
168
}
169
@@ -166,7 +187,7 @@ func BenchmarkServer_LogRequest_WithTrace(b *testing.B) {
187
accLog := testLogger(buf.Write)
188
189
for b.Loop() {
169
- s.logRequest(accLog, req, wrec, &duration, repl, bodyReader, false)
190
+ s.logRequest(accLog, req, wrec, &duration, nil, repl, bodyReader, false)
191
}
192
}
193
@@ -1365,3 +1386,151 @@ func TestServer_DetermineTrustedProxy_MatchRightMostUntrustedFirst(t *testing.T)
1386
assert.True(t, trusted)
1387
assert.Equal(t, clientIP, "90.100.110.120")
1388
}
1389
+
1390
+func TestServer_LogRequest_WithWriteError(t *testing.T) {
1391
+ s := &Server{}
1392
+ ctx := context.WithValue(context.Background(), ExtraLogFieldsCtxKey, new(ExtraLogFields))
1393
+ req := httptest.NewRequest(http.MethodGet, "/", nil).WithContext(ctx)
1394
+ rec := httptest.NewRecorder()
1395
+ wrec := NewResponseRecorder(rec, nil, nil)
1396
+ duration := 50 * time.Millisecond
1397
+ repl := NewTestReplacer(req)
1398
+ bodyReader := &lengthReader{Source: req.Body}
1399
+ buf := bytes.Buffer{}
1400
+ accLog := testLogger(buf.Write)
1401
+
1402
+ writeErr := errors.New("write tcp: i/o timeout")
1403
+ s.logRequest(accLog, req, wrec, &duration, &writeErr, repl, bodyReader, false)
1404
+
1405
+ assert.JSONEq(t, `{
1406
+ "msg":"handled request", "level":"info", "bytes_read":0,
1407
+ "duration":"50ms", "resp_headers": {}, "size":0,
1408
+ "status":0, "user_id":"",
1409
+ "write_error":"write tcp: i/o timeout"
1410
+ }`, buf.String())
1411
+}
1412
+
1413
+// newAccessLogTestServer starts a server whose access log is written to the
1414
+// returned buffer. writeTimeout is the write timeout Caddy is configured with,
1415
+// while realWriteTimeout is the deadline net/http actually enforces on the
1416
+// connection (zero means no deadline, so writes always succeed).
1417
+func newAccessLogTestServer(t *testing.T, writeTimeout, realWriteTimeout time.Duration, h HandlerFunc) (*httptest.Server, *syncBuffer) {
1418
+ t.Helper()
1419
+
1420
+ buf := new(syncBuffer)
1421
+ s := &Server{
1422
+ logger: zap.NewNop(),
1423
+ errorLogger: zap.NewNop(),
1424
+ accessLogger: testLogger(buf.Write),
1425
+ Logs: &ServerLogConfig{},
1426
+ WriteTimeout: caddy.Duration(writeTimeout),
1427
+ primaryHandlerChain: h,
1428
+ }
1429
+
1430
+ ts := httptest.NewUnstartedServer(http.HandlerFunc(s.ServeHTTP))
1431
+ ts.Config.WriteTimeout = realWriteTimeout
1432
+ ts.Start()
1433
+ t.Cleanup(ts.Close)
1434
+
1435
+ return ts, buf
1436
+}
1437
+
1438
+// eventuallyLogged waits for the access log entry to be written, since it is
1439
+// emitted from a defer that runs after the client has already seen the response.
1440
+func eventuallyLogged(t *testing.T, buf *syncBuffer, contains ...string) {
1441
+ t.Helper()
1442
+
1443
+ assert.Eventually(t, func() bool {
1444
+ logOutput := buf.String()
1445
+ for _, want := range contains {
1446
+ if !strings.Contains(logOutput, want) {
1447
+ return false
1448
+ }
1449
+ }
1450
+ return true
1451
+ }, 1*time.Second, 10*time.Millisecond, "expected log entry containing %q, got %q", contains, buf.String())
1452
+}
1453
+
1454
+func TestServer_ServeHTTP_WriteTimeoutLogsWriteError(t *testing.T) {
1455
+ ts, buf := newAccessLogTestServer(t, 150*time.Millisecond, 150*time.Millisecond,
1456
+ func(w http.ResponseWriter, r *http.Request) error {
1457
+ time.Sleep(300 * time.Millisecond)
1458
+ fmt.Fprint(w, "XX")
1459
+ return nil
1460
+ })
1461
+
1462
+ client := &http.Client{Timeout: 2 * time.Second}
1463
+ resp, err := client.Get(ts.URL)
1464
+ if err == nil {
1465
+ resp.Body.Close() // close immediately since we don't need body contents
1466
+ }
1467
+
1468
+ eventuallyLogged(t, buf, `"write_error"`, "i/o timeout", `"status":200`)
1469
+}
1470
+
1471
+// A handler that takes longer than the configured write timeout but whose
1472
+// response is still written successfully must not be reported as a write error.
1473
+func TestServer_ServeHTTP_DelayedSuccessLogsNoWriteError(t *testing.T) {
1474
+ ts, buf := newAccessLogTestServer(t, 10*time.Millisecond, 0,
1475
+ func(w http.ResponseWriter, r *http.Request) error {
1476
+ time.Sleep(50 * time.Millisecond)
1477
+ fmt.Fprint(w, "hello")
1478
+ return nil
1479
+ })
1480
+
1481
+ client := &http.Client{Timeout: 2 * time.Second}
1482
+ resp, err := client.Get(ts.URL)
1483
+ require.NoError(t, err)
1484
+ body, err := io.ReadAll(resp.Body)
1485
+ resp.Body.Close()
1486
+ require.NoError(t, err)
1487
+
1488
+ assert.Equal(t, http.StatusOK, resp.StatusCode)
1489
+ assert.Equal(t, "hello", string(body))
1490
+
1491
+ eventuallyLogged(t, buf, `"status":200`, `"size":5`)
1492
+ assert.NotContains(t, buf.String(), "write_error")
1493
+}
1494
+
1495
+// The flush probe must not commit a response before the handler error has been
1496
+// turned into a response, otherwise the error status is lost (both on the wire
1497
+// and in the access log).
1498
+func TestServer_ServeHTTP_DelayedHandlerErrorWritesErrorStatus(t *testing.T) {
1499
+ for _, tc := range []struct {
1500
+ name string
1501
+ handler HandlerFunc
1502
+ }{
1503
+ {
1504
+ name: "error without writing",
1505
+ handler: func(w http.ResponseWriter, r *http.Request) error {
1506
+ time.Sleep(50 * time.Millisecond)
1507
+ return Error(http.StatusTeapot, errors.New("delayed failure"))
1508
+ },
1509
+ },
1510
+ {
1511
+ // 1xx responses are informational and pass straight through to the
1512
+ // client, which puts the recorder in streaming mode; flushing at that
1513
+ // point would commit a 200 before the error status can be written.
1514
+ name: "error after informational response",
1515
+ handler: func(w http.ResponseWriter, r *http.Request) error {
1516
+ w.WriteHeader(http.StatusEarlyHints)
1517
+ time.Sleep(50 * time.Millisecond)
1518
+ return Error(http.StatusTeapot, errors.New("delayed failure"))
1519
+ },
1520
+ },
1521
+ } {
1522
+ t.Run(tc.name, func(t *testing.T) {
1523
+ ts, buf := newAccessLogTestServer(t, 10*time.Millisecond, 0, tc.handler)
1524
+
1525
+ client := &http.Client{Timeout: 2 * time.Second}
1526
+ resp, err := client.Get(ts.URL)
1527
+ require.NoError(t, err)
1528
+ resp.Body.Close()
1529
+
1530
+ assert.Equal(t, http.StatusTeapot, resp.StatusCode)
1531
+
1532
+ eventuallyLogged(t, buf, `"status":418`)
1533
+ assert.NotContains(t, buf.String(), "write_error")
1534
+ })
1535
+ }
1536
+}