Add http.time_ms to all logs #49
Conversation
There was a problem hiding this comment.
Looks fine overall just some nit to bring more inline to the grpc middleware so that we keep a consistent approach across all projects.
Have a look at https://github.com/grpc-ecosystem/go-grpc-middleware/blob/master/logging/logrus/server_interceptors.go how the grpc work has been done.
| @@ -86,6 +87,7 @@ func newServerRequestFields(req *http.Request) logrus.Fields { | |||
| "http.request.user_agent": req.Header.Get("User-Agent"), | |||
| "http.request.length_bytes": req.ContentLength, | |||
| "http.request.referer": req.Referer(), | |||
| "http.start_time": startTime, | |||
There was a problem hiding this comment.
If we use time.Format, we have to then Parse it from the Hook, which could (?) yield an un-handable error. I'm not opposed to it but Time already has a String() function which is mostly human readable.
| @@ -21,12 +21,14 @@ var ( | |||
| // | |||
| // All handlers will have a Logrus logger in their context, which can be fetched using `ctxlogrus.Extract`. | |||
| func Middleware(entry *logrus.Entry, opts ...Option) httpwares.Middleware { | |||
| entry.Logger.Hooks.Add(&timeHook{}) | |||
There was a problem hiding this comment.
would prefer to just do this inline ... rather than adding hooks
There was a problem hiding this comment.
From the PR context and offline discussion, I can't think of a good way of doing this without hooks.
| return func(nextHandler http.Handler) http.Handler { | ||
| options := evaluateMiddlewareOpts(opts) | ||
| return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { | ||
| wrappedResp := httpwares.WrapResponseWriter(resp) | ||
|
|
||
| requestFields := appendFields(newServerRequestFields(req), options.requestFieldExtractor(req)) | ||
| startTime := time.Now() | ||
| requestFields := appendFields(newServerRequestFields(req, startTime), options.requestFieldExtractor(req)) |
There was a problem hiding this comment.
whilst were in could we change this to use ctxLogrus the post call uses it but for some reason not pre call.
Currently, this http middleware adds a
time_msfield to the log once the request handling is finished. However, we want to be able to get time since the beginning of the request in all logs - including the ones logged in the handler that the middleware is wrapping.I couldn't find an easy way of doing this. My options were
http_ms, but this is checking an internal behaviour fromgo-httpwaresthat is error-prone.http_msat every logging. Because you need to provide the logger to the middleware, as long as you use the same logger from your handler you will have all the fields included by the middleware.The best option here seemed to be 3), which is implemented in this PR.