AddCustomAttributes does not work when using some middlewares

[codybuell]

I've got a handler that is adding some custom attributes to be logged with slogchi.AddCustomAttributes(). This works as expected for most routes however if I use a middleware that adds something to the request context the custom attributes are no longer showing on the log. An example middleware that breaks it:

type contextKey string

const ExampleContextKey contextKey = "someKey"

func ExampleMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		ctx := context.WithValue(r.Context(), ClientContextKey, "example")
		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

If I modify the middleware to update the request in place the custom attributes are logged.

type contextKey string

const ExampleContextKey contextKey = "someKey"

func ExampleMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		*r = *r.WithContext(context.WithValue(r.Context(), ClientContextKey, "example"))
		next.ServeHTTP(w, r)
	})
}

Is there a way to get custom attributes to work with the first approach? Some chi middlewares like middleware.Timeout() use r.WithContext(ctx) and it would be great if they were compatible. Thanks for this project!

[samber]

hi @codybuell

Did you check the middleware chain order?

slogchi -> ExampleMiddleware -> handler

is different than

ExampleMiddleware -> slogchi -> handler

next.ServeHTTP(w, r.WithContext(ctx)) injects the context in the child handlers. *r=r.WithContext(ctx) injects the context globally (parent and child handlers, but might lead to unexpected behavior.

[codybuell]

Hi @samber, yeah here's what I'm seeing:

slogchi first:
slogchi  ->  *r=r.WithContext(ctx)  ->  handler w/AddCustAttr  =  attrs ARE logged
slogchi  ->  next. ServeHTTP(w, r.WithContext(ctx))  ->  handler w/AddCustAttr  =  attrs NOT logged

examplemiddleware first:
*r=r.WithContext(ctx)  ->  slogchi  ->  handler w/AddCustAttr  =  attrs ARE logged
next.ServeHTTP(w, r.WithContext(ctx))  ->  slogchi  ->  handler w/AddCustAttr  =  attrs ARE logged 

So does slogchi need to always be last in the middleware chain? For my setup I am trying to add ExampleMiddleware only to a subset of routes like so:

router := chi.NewRouter

router.Use(middleware.Timeout(60 * time.Second))    // <-- this guy uses next.ServeHTTP(w, r.WithContext(ctx))
router.Use(slogchi.New(logger))

router.Route("/api", func(router chi.Router) {
    router.Use(ExampleMiddleware)

    router.Get("/version", Version)
})

router.Get("/other", Other)                // don't want the ExampleMiddleware

slogchi appears to be using the *r=r.WithContext(ctx) approach to add the slog attrs to the context, guessing that is necessary as something critical is getting dropped with the shallow copy done by (http.Request).WithContext()? Are there any drawbacks to using that approach in ExampleMiddleware as a workaound?

[samber]

Linking samber/slog-http#4