🎯 Prevent Duplicate Log Entries on Request Context Cancellation during Graceful Shutdown

[rachelealicek]

📝 Description

During graceful server shutdown or abrupt client disconnections, if an active request's context is canceled while the handler is still executing, the logging middleware (middleware.Logger / middleware.RequestLogger) emits two completion log entries for the same request.

This behavior results in duplicate structured logs, which inflates request metrics (e.g., error rates, throughput) and causes ingestion anomalies in downstream log processing and monitoring systems. The duplication only occurs when the request context is canceled (context.Canceled) before the handler completes its execution lifecycle.

🎯 Acceptance Criteria

• Exactly one log entry must be emitted per HTTP request, regardless of whether the request completes successfully, panics, or is canceled/interrupted.
• If a request is canceled due to client disconnect or server shutdown, the single emitted log should accurately reflect the cancellation (e.g., logging a status code like 499 Client Closed Request or recording the context cancellation error).
• The fix must not introduce race conditions. The mechanism to prevent double-logging must be thread-safe.
• Standard logging behavior for normal request completion must remain unaffected.

🛠️ Technical Specifications & Context

In the go-chi/chi architecture (specifically within the rachelealicek/chi repository), the logging middleware is located in the middleware/ directory:

• Key Files: middleware/logger.go and potentially middleware/wrap_writer.go.

Root Cause Analysis

The issue typically occurs because:

1. The logging middleware defers a write/log operation at the start of the handler chain.
2. A separate goroutine or context watcher (e.g., monitoring r.Context().Done()) detects the cancellation during shutdown and prematurely writes a log entry or response status.
3. When the handler chain finally unwinds, the deferred logging function executes anyway, writing a second log entry.

Proposed Solution

To resolve this, we should introduce a state check (e.g., using a thread-safe flag or sync.Once) to ensure the log entry is written exactly once.

1. Introduce a Guard Flag:
   In the custom ResponseWriter wrapper or the LogEntry recorder, implement a thread-safe mechanism (such as atomic.CompareAndSwapInt32 or sync.Once) to track whether the log has already been written.

   type responseLogger struct {
       // ... existing fields
       logged int32
   }
   
   func (l *responseLogger) WriteLog(status int, bytes int, elapsed time.Duration) {
       if atomic.CompareAndSwapInt32(&l.logged, 0, 1) {
           // Perform actual logging
       }
   }

2. Handle Context Cancellation Gracefully:
   Ensure that if the context is canceled, the logger captures the cancellation state, marks the log as written, and prevents the deferred execution from writing a duplicate entry.

🧪 Verification & Testing

Automated Test Case

Add a test in middleware/logger_test.go that simulates a canceled request:

1. Start a test server using the logging middleware.
2. Send a request that blocks inside the handler.
3. Cancel the request's context (or close the client connection) to trigger the cancellation path.
4. Allow the handler to finish.
5. Assert that the custom log buffer/mock logger received exactly one log entry.

Example test structure:

func TestLogger_ContextCancellation_SingleLog(t *testing.T) {
    var buf bytes.Buffer
    // Initialize logger with buf...

    r := chi.NewRouter()
    r.Use(middleware.RequestLogger(&middleware.DefaultLogFormatter{Logger: log.New(&buf, "", 0)}))
    
    r.Get("/cancel", func(w http.ResponseWriter, r *http.Request) {
        // Simulate work, then context cancellation
        ctx, cancel := context.WithCancel(r.Context())
        cancel() // Cancel context immediately
        <-ctx.Done()
    })

    // Execute request and verify buf contains exactly one log entry
}

Manual Verification

• Run the test suite with the race detector enabled:

  go test -race ./middleware/...

---

---

This repo is using Opire - what does it mean? 👇

💵 Everyone can add rewards for this issue commenting /reward 100 (replace 100 with the amount).
🕵️‍♂️ If someone starts working on this issue to earn the rewards, they can comment /try to let everyone know!
🙌 And when they open the PR, they can comment /claim #1 either in the PR description or in a PR's comment.

🪙 Also, everyone can tip any user commenting /tip 20 @rachelealicek (replace 20 with the amount, and @rachelealicek with the user to tip).

📖 If you want to learn more, check out our documentation.

[rachelealicek]

/reward 10

[opirebot]

😅 Ups... you cannot create a reward of $10.00. It needs to be at least $20.00

[1RB]

/try

Check if you're the only one trying 👇

You're the first one to try to solve this issue, go for it! 😉

[tnknick14]

I've reviewed the issue. The duplicate log entry occurs because the middleware's deferred logging logic executes both on normal handler completion and on context cancellation (via the request context's Done channel), without coordinating between these paths.

I can fix this by wrapping the log emission in a sync.Once (or a guarded boolean) within the middleware's per-request state, ensuring exactly one log entry regardless of whether completion is triggered by handler return, panic recovery, or context cancellation.

Before I implement: should the cancellation case use status code 499 (Nginx convention), or do you prefer a different representation (e.g., logging context.Canceled explicitly with the original status code that would have been written)?

I'll submit a PR once I have your preference on the status code handling

[freeEasyLoope]

Suggested fix — 2026-07-23 22:05

```json
{
  "type": "code",
  "language": "Go",
  "code": "// 在中间件中添加状态跟踪以防止重复日志\nfunc PreventDuplicateLogMiddleware(next http.Handler) http.Handler {\n    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {\n        // 使用 sync.Once 确保日志只记录一次\n        var logOnce sync.Once\n        \n        // 包装 ResponseWriter 以捕获状态码\n        lrw := &loggingResponseWriter{ResponseWriter: w, st

_{Auto-generated, review before merge}

[wasim-builds]

/opire try

[MercornKing]

Proposed Fix: Context Cancellation Check in Logger Middleware

Hi! Duplicate logs occur because both the timeout handler and the logger middleware independently log the cancellation.

Fix Implementation

We can prevent the logger from writing a duplicate entry if the context was intentionally canceled.

func LoggerMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        next.ServeHTTP(w, r)
        if r.Context().Err() == context.Canceled {
            // Prevent duplicate logging for canceled requests
            return 
        }
        log.Printf("Handled %s %s", r.Method, r.URL.Path)
    })
}

Let me know if you want a PR for this!