Logger middleware: support gzipped responses from graphite-web

[fkaleo]

graphite-web can (and in my testing does) gzip compress its responses. When it errors and we want to log that error, metrictank needs to unzip the body.

Caveat: detecting gzip compression is done based on the Content-Encoding header which sometimes is set too early by the gziper middleware before compression has happened. We handle that case by logging the uncompressed error when decompression fails.

[woodsaj]

which sometimes is set too early by the gziper middleware before compression has happened

This sounds like the order the gziper and log middlerware handlers are being loaded is wrong.

the gzipper middleware sets the content-type header only when w.WriteHeader(int) is called. Then when w.Write([]byte) the data is compressed and passed through to the underlying responseWriter.

So it sounds like the following is happening.

Gzip middlerware wraps ResponseWriter as gzipResponseWriter
Logging middleware wraps gzipResponseWriter as loggedResponseWriter

When the response results in an error:

• loggedResponseWriter.WriteHeader(500) is called
• gzipResponseWriter.WriteHeader(500) is called
• content-type is set to gzip
• ResponseWriter.WriteHeader(500) is called
• loggedResponseWriter.Write(body) is called
• body is logged, but body has not yet been compressed
• gzipResponseWriter.Write(body) is called
• body is compressed and ResponseWriter.Write(compressedBody) is called.

to fix this, i think that r.Use(middleware.Logger())

metrictank/api/routes.go

Line 21 in 43d0f40

r.Use(middleware.Logger())

needs to be called before any of the the other middleware handlers.

This will ensure that logs are last thin to happen before response data is pushed to the client.

[Dieterbe]

might make more sense to make awoods the reviewer of this. I'm gonna be OOO for about a week and he knows this code much better.

[woodsaj]

see my comments in PR #1694 #1694 (review)

[woodsaj]

This shouldnt be done here. We should just store the compressed payload in rw.errBody and do the decompress when we write the log message.

The client wont get their response until we call the rw.responseWriter(b), so we should call it as soon as possible.

The log message is not written until after the request has been completely sent to the client, so spending the time to decompress the data their wont impact request latency (yes, failed responses are likely only going to have small payloads and so it probably wont matter where we do the decompress)

[fkaleo]

Fixed in ff4b0e5

[woodsaj]

rw.Write(b) might be called multiple times. This will result in the errBody only containing the end of the data.
If response resulted in an Error and the payload is really large, we probably dont want all of it, but we will want the first part of it.

[fkaleo]

Fixed with ff4b0e5 by buffering up all the entire response. For now I think we can store it all. Having it all might be necessary in the gzip case.

[fkaleo]

which sometimes is set too early by the gziper middleware before compression has happened

This sounds like the order the gziper and log middlerware handlers are being loaded is wrong.

the gzipper middleware sets the content-type header only when w.WriteHeader(int) is called. Then when w.Write([]byte) the data is compressed and passed through to the underlying responseWriter.

So it sounds like the following is happening.

Gzip middlerware wraps ResponseWriter as gzipResponseWriter
Logging middleware wraps gzipResponseWriter as loggedResponseWriter

When the response results in an error:

* loggedResponseWriter.WriteHeader(500) is called

* gzipResponseWriter.WriteHeader(500) is called

* content-type is set to gzip

* ResponseWriter.WriteHeader(500) is called

* loggedResponseWriter.Write(body) is called

* body is logged, but body has not yet been compressed

* gzipResponseWriter.Write(body) is called

* body is compressed and ResponseWriter.Write(compressedBody) is called.

to fix this, i think that r.Use(middleware.Logger())

metrictank/api/routes.go

Line 21 in 43d0f40

r.Use(middleware.Logger())

needs to be called before any of the the other middleware handlers.

This will ensure that logs are last thin to happen before response data is pushed to the client.

Reordered the middlewares to follow your advice in 8356c6f.
Logging is wrapping first (good for timing) and called after gziper which ensures it receives a gzipped response if the Content-Encoding header is set to gzip.

[woodsaj]

I think we should make a few more improvements here, though they are slightly out of scope.

1. both the logging and tracing middleware are capturing the responseBody if the request status >= 400. we dont need two copies of the body.
2. I really think we should set a cap on the number of bytes to capture. if the something goes wrong and a really large response is written we are going to cause problems for our logging and tracing platforms if we try and write 100's of KB or larger.

to address these i suggest

1. merge the tracing and logging middleware into one, or use a shared responseWriter wrapper.
   for a shared responseWriter you can just check if current responseWriter is already a 'CaptureErrorResponseWriter' or not to see if you need to updated it. eg

  var wrappedRW *CaptureErrorResponseWriter
  if wrappedRW, ok := ctx.Resp.(*CaptureErrorResponseWriter); !ok {
      wrappedRW = &CaptureErrorResponseWriter{ResponseWriter: ctx.Resp
  }
  ....
  errBody := wrappedRW.ErrorBody()

2. only put up to 1k of data into the captured errBody, and then additionally if we need to decompress it, only return the first 1k of data after decompression. this will work fine with gzip. It will decompress what it can then return an error. So if you get decoded data back, just ignore the error.

[fkaleo]

I think we should make a few more improvements here, though they are slightly out of scope.

1. both the logging and tracing middleware are capturing the responseBody if the request status >= 400.  we dont need two copies of the body.

2. I really think we should set a cap on the number of bytes to capture.  if the something goes wrong and a really large response is written we are going to cause problems for our logging and tracing platforms if we try and write 100's of KB or larger.

to address these i suggest

1. merge the tracing and logging middleware into one, or use a shared responseWriter wrapper.
   for a shared responseWriter you can just check if current responseWriter is already a 'CaptureErrorResponseWriter' or not to see if you need to updated it.  eg

  var wrappedRW *CaptureErrorResponseWriter
  if wrappedRW, ok := ctx.Resp.(*CaptureErrorResponseWriter); !ok {
      wrappedRW = &CaptureErrorResponseWriter{ResponseWriter: ctx.Resp
  }
  ....
  errBody := wrappedRW.ErrorBody()

1. only put up to 1k of data into the captured errBody, and then additionally if we need to decompress it, only return the first 1k of data after decompression.  this will work fine with gzip. It will decompress what it can then return an error.  So if you get decoded data back, just ignore the error.

Fair points. Can I do that in a separate PR?

[woodsaj]

Fair points. Can I do that in a separate PR?

Yes