How to get the logger object back from request object once it's served by handler?

Question

I am trying to learn how to use Middleware in Go. I am successful in sending the logger object with the request context to the handler functions. But once the request is processed and the logger object is filled with the data/errors from handler functions, I want to be able to access the modified object. But as per my current implementation I am getting a nil object.

logger := log.WithFields(log.Fields{
                ReqIdKey: reqId,
                "proto":  r.Proto,
                "method": r.Method,
                "uri":    r.URL.RequestURI(),
                "startTime": time.Now(),
                "body":      t,
                "header":      r.Header,
                "remote-addr": r.RemoteAddr,
            })
            ctx = context.WithValue(ctx, "logger", logger)
//Update as per suggestions recieved.
            r = r.WithContext(ctx)

            m := httpsnoop.CaptureMetrics(next, w, r)
            
//Post this point the internal functions modify the log and add errors etc extra fields which I want to access
//For example:
//logger := logcontext.GetLogCtx(ctx) 
//logger = logger.WithFields(log.Fields{"error": err})

            logger = logger.WithFields(log.Fields{
                "responseTime": m.Duration,
                "status":       m.Code,
            })
            return logger.Info("Request Completed")

Response Recieved:

{"body":null,"header":{"Accept":["*/*"],"Accept-Encoding":["gzip, deflate, br"],"Connection":["keep-alive"],"Postman-Token":["a1ef5d6c-94cb-4b64-b350-700c37eff6b4"],"User-Agent":["PostmanRuntime/7.26.2"]},"level":"info","method":"GET","msg":"Request completed","proto":"HTTP/1.1","remote-addr":"127.0.0.1:36254","responseTime":2463797,"startTime":"2020-07-28T00:31:22.97954465+05:30","status":503,"time":"2020-07-28T00:31:22+05:30","uri":"/api/v1/getSomething/some/xyz/abc/2","x-request-id":"f493a4ad-035c-48a8-9207-64a922c96961"}

Expecting the added "error" field from the handler function.

I am aware that there is some conceptual mistake in this case, but not able to get it.

So basically I want to log everything once, not multiple times, for that need to get the final fields and everything at middleware only.

You already have a reference to the logger in your local variable `logger`, just use that instead of getting it back out of the context. — Adrian, Jul 27 '20 at 14:54
yes, I used it, but it the error fields which are added by the handlers are not visible there. Ideally it should be there, cause the handlers modified the same object and added an extra field via logger.WithError(err) — gaurav1999, Jul 27 '20 at 16:29
After the type conversion you must not use log_p if ok is false, although it is unclear why you call Value in the first place. Just use logger directly (Value cannot possibly return anything else). — Peter, Jul 27 '20 at 18:01
@gaurav1999, when you add fields using `WithFields` the returned logger is a wrapper around the original. Those fields are not added to the original logger, only to the new logger. — Burak Serdar, Jul 27 '20 at 19:06
Not sure if that's the case, because the fields which I previously added are still getting logged, like header, url, etc. — gaurav1999, Jul 27 '20 at 19:18
Looking at the source, they are taking care of the old values and appending the new fields. — gaurav1999, Jul 27 '20 at 19:30

Burak Serdar · Answer 1 · 2020-07-27T15:20:02.067

0

If the purpose is to access the modified logger, then you can simply use the logger instance you created in that middleware instead of getting it back from the response. However, this is the reason why your code is not working:

m := httpsnoop.CaptureMetrics(next, w, r.WithContext(ctx))

WithContext returns a new request with the new context. The old request is unmodified. Do this instead:

r=r.WithContext(ctx)
m := httpsnoop.CaptureMetrics(next, w, r)

This will assign the new request containing the new context to r. Use the new r going forward to access the modified request and the context.

edited Jul 27 '20 at 15:20

answered Jul 27 '20 at 14:49

Burak Serdar

46,455
3
40
59

These two sections of code do the exact same thing. The original line passes the returned request from `r.WithContext` as the request parameter to `CaptureMetrics`; your change just stores it in a local variable to do the same thing. – Adrian Jul 27 '20 at 14:55
@Adrian, This affects the rest of the code that follows. In the original post, the modified request is lost. – Burak Serdar Jul 27 '20 at 14:59
That's fair but not really explained in the answer. Though the easier solution is just to use the reference they've already got instead of pulling it back out of the context for no reason. – Adrian Jul 27 '20 at 15:11
@Adrian, added that to the answer. – Burak Serdar Jul 27 '20 at 15:20
I did :- r = r.WithContext(ctx) m := httpsnoop.CaptureMetrics(next, w, r) logger = logger.WithFields(log.Fields{"responseTime": m.Duration,"status": m.Code,}) So this is about using the same reference, but I am still not able to see the error object in the final logger object. – gaurav1999 Jul 27 '20 at 19:02

How to get the logger object back from request object once it's served by handler?

1 Answers1