fix: prevent duplicate log entries on request context cancellation by 1RB · Pull Request #2 · rachelealicek/chi

1RB · 2026-07-23T08:30:43Z

Fix: Prevent Duplicate Log Entries on Request Context Cancellation

Fixes #1

Problem

During graceful server shutdown or client disconnections, if a request's context is canceled while the handler is still executing, the logging middleware emits two completion log entries — one from the context-cancellation watcher and one from the deferred handler unwind. This inflates request metrics and causes log ingestion anomalies.

Solution

Introduced an atomic CAS guard (atomic.CompareAndSwapInt32) in responseLogger.WriteLog() that ensures exactly one log entry is written per request, regardless of how many times WriteLog is called:

func (rl *responseLogger) WriteLog(err error) {
    if !atomic.CompareAndSwapInt32(&rl.logged, 0, 1) {
        return // already logged — prevent duplicate
    }
    // ... perform logging
}

Both the cancellation-watcher goroutine and the deferred completion log call WriteLog() — whichever fires first wins, the other is a no-op.

Behavior

Normal completion → one log entry with handler's status code (200, etc.)
Context canceled → one log entry with status 499 + error
Context deadline exceeded → one log entry with status 499 + error
Thread-safe → CAS guard works under concurrent access (verified with -race)

Test coverage (6 tests, all passing with `-race`)

✓ TestLogger_ContextCancellation_SingleLog — exactly 1 entry on cancel
✓ TestLogger_NormalCompletion_SingleLog — exactly 1 entry on success
✓ TestLogger_ContextCanceled_LogsError — logs 499 on cancellation
✓ TestLogger_NormalCompletion_Logs200 — logs 200 on success
✓ TestResponseLogger_WriteLog_ThreadSafe — 10 concurrent calls → 1 entry
✓ TestLogger_MultipleRequests_EachOneLog — 5 requests → 5 entries

/attempt #1

When a request's context is canceled (client disconnect or server shutdown), the logging middleware now emits exactly one log entry instead of two. Changes: - Add responseLogger with atomic.CompareAndSwapInt32 guard (thread-safe) - WriteLog() uses CAS to ensure only the first caller logs — prevents duplicate entries from the deferred handler unwind + cancellation watcher - Context cancellation watcher goroutine logs with 499 status - DefaultLogger maps context.Canceled/DeadlineExceeded to status 499 - Normal completion still logs with the handler's status code Test coverage (6 tests, all passing with -race): - Exactly one log entry on context cancellation - Exactly one log entry on normal completion - Canceled request logs 499 status - Normal request logs 200 status - Thread safety: 10 concurrent WriteLog calls produce exactly 1 entry - Multiple requests each produce exactly one log entry Fixes rachelealicek#1

Copilot

Pull request overview

This PR aims to prevent duplicate request-completion log entries when an HTTP request context is canceled (e.g., client disconnects / graceful shutdown) by guarding logging so it only happens once per request.

Changes:

Replaced the prior main.go “hello world” with a custom logging middleware and responseLogger that uses an atomic CAS guard to prevent duplicate logs.
Added a new main_test.go with tests asserting single-log behavior under cancellation and concurrency.
Added a go.mod for the module.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 7 comments.

File	Description
main.go	Adds a response-wrapping logger + middleware with an atomic guard to prevent double logging on cancellation.
main_test.go	Adds tests covering cancellation, normal completion, concurrency, and multiple-request scenarios.
go.mod	Introduces module definition and Go language version directive.

Comments suppressed due to low confidence (4)

main_test.go:84

This time.Sleep is unnecessary: the deferred log call runs before mw.ServeHTTP returns, so logCount can be asserted immediately. Removing sleeps keeps tests fast and reduces timing sensitivity.

	time.Sleep(10 * time.Millisecond)

main_test.go:115

This time.Sleep is unnecessary for the same reason as above: logging happens before ServeHTTP returns in these tests. Consider removing it to avoid slowing down the test suite.

	time.Sleep(10 * time.Millisecond)

main_test.go:139

This time.Sleep is unnecessary: WriteLog runs before ServeHTTP returns in this test, so the output can be checked immediately.

	time.Sleep(10 * time.Millisecond)

main_test.go:204

This time.Sleep is unnecessary: each request’s deferred log runs before mw.ServeHTTP returns inside the loop, so logCount is already final after the loop. Removing the sleep speeds up the test and avoids timing sensitivity.

	time.Sleep(50 * time.Millisecond)

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

+func (rl *responseLogger) Write(b []byte) (int, error) {
+	n, err := rl.w.Write(b)
+	rl.bytes += n
+	return n, err
+}


+	// Give the deferred log time to run
+	time.Sleep(10 * time.Millisecond)
+


+// LoggerMiddleware wraps the handler with logging that guarantees exactly
+// one log entry per request, even when the request context is canceled.
+func LoggerMiddleware(logger Logger, next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		rl := newResponseLogger(w, logger, r.Method, r.URL.Path)


+func (rl *responseLogger) WriteLog(err error) {
+	if !atomic.CompareAndSwapInt32(&rl.logged, 0, 1) {
+		return // already logged — prevent duplicate
+	}
+	rl.logger.Log(LogEntry{
+		Method:  rl.method,
+		Path:    rl.path,
+		Status:  rl.status,
+		Bytes:   rl.bytes,
+		Elapsed: time.Since(rl.start),
+		Err:     err,
+	})
+}


+		// Watch for context cancellation in a goroutine — if the client
+		// disconnects or server shuts down mid-handler, log the cancellation.
+		go func() {
+			<-r.Context().Done()
+			rl.WriteLog(r.Context().Err())
+		}()
+
+		// Defer the normal completion log. WriteLog's atomic CAS guard
+		// ensures only one entry is written — whichever fires first wins.
+		defer func() {
+			// If context was canceled, use that error; otherwise nil (normal completion)
+			err := r.Context().Err()
+			rl.WriteLog(err)
+		}()


@@ -1,7 +1,139 @@
 package main


+	method   string
+	path     string
+	start    time.Time
+	cancelMu sync.Mutex


…e leak, remove sleeps - Default status to 200 in WriteLog only when err==nil (handler wrote body without WriteHeader). On context cancellation, status 0 flows to DefaultLogger.Log which maps it to 499. - Add sync.Mutex (rl.mu) to protect rl.status and rl.bytes reads/writes, fixing race between cancellation goroutine and handler writes. - Fix goroutine leak: add done channel so context-watcher exits when handler finishes, not just when r.Context().Done() fires. Defer waits for goroutineDone before calling WriteLog. - Remove unused cancelMu field from responseLogger struct. - Remove all time.Sleep calls after mw.ServeHTTP in tests — WriteLog runs synchronously via defer before ServeHTTP returns. - Add func main() {} back to main.go (package main requires it).

Copilot AI review requested due to automatic review settings July 23, 2026 08:30

Copilot started reviewing on behalf of 1RB July 23, 2026 08:31 View session

Copilot AI reviewed Jul 23, 2026

View reviewed changes

Navigation Menu

fix: prevent duplicate log entries on request context cancellation - #2

fix: prevent duplicate log entries on request context cancellation#2
1RB wants to merge 2 commits into
rachelealicek:mainfrom
1RB:fix/duplicate-log-on-cancel

1RB commented Jul 23, 2026

Uh oh!

Copilot AI left a comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

		// Give the deferred log time to run
		time.Sleep(10 * time.Millisecond)

Conversation

1RB commented Jul 23, 2026