Access logging fails in combination with proxy gzipping

[tino]

With fabio 1.5.8 I've set:

FABIO_log_access_target = "stdout"
FABIO_log_access_format = "combined"

and can see that fabio uses that after restart.

The only logs it output (besides route changes and errors are like this):

2018/03/04 14:44:55 [INFO] consul: Registered fabio with address "10.0.0.57" 
2018/03/04 14:44:55 [INFO] consul: Registered fabio with tags "" 
2018/03/04 14:44:55 [INFO] consul: Registered fabio with health check to "http://[10.0.0.57]:9998/health" 
invalid log msg: 2018/03/04 14:45:41 Unsolicited response received on idle HTTP channel starting with "{\"status\": \"OK\", \"version\": \"2018.8.5\"}"; err=<nil> 
invalid log msg: 2018/03/04 14:46:41 Unsolicited response received on idle HTTP channel starting with "{\"status\": \"OK\", \"version\": \"2018.8.5\"}"; err=<nil> 
invalid log msg: 2018/03/04 14:47:41 Unsolicited response received on idle HTTP channel starting with "{\"status\": \"OK\", \"version\": \"2018.8.5\"}"; err=<nil> 
invalid log msg: 2018/03/04 14:48:41 Unsolicited response received on idle HTTP channel starting with "{\"status\": \"OK\", \"version\": \"2018.8.5\"}"; err=<nil> 
invalid log msg: 2018/03/04 14:49:41 Unsolicited response received on idle HTTP channel starting with "{\"status\": \"OK\", \"version\": \"2018.8.5\"}"; err=<nil> invalid 

The json you see in there is the response of one of my service /status/ urls, which is used for health checking, also remotely through fabio.

It does work when I run it locally like: docker run --rm -it -p 9999:9999 -p 9998:9998 -e FABIO_registry_consul_addr=10.0.0.12:8500 -e FABIO_log_access_target="stdout" fabiolb/fabio.

Any idea what the culprit could be?

[magiconair]

No idea. Let me have a look.

[magiconair]

After looking at golang/go#19895 I think there could be an issue with the way your service responds to health checks. It seems to be sending data after it has responded to the health check.

[tino]

True, I see that response on a HEAD request, where it shouldn't return that.

However, would that block all logging? I don't see any other log besides those health checks that produce invalid logs, while fabio is routing a lot of traffic.

Running fabio locally (against the production Consul) I get:

172.17.0.1 - - [06/Mar/2018:08:59:20 +0000] "GET /status/ HTTP/1.1" 200 117
invalid log msg: 2018/03/06 08:59:30 Unsolicited response received on idle HTTP channel starting with "{\"services\": {\"mysql\": \"green\", \"postgresql\": \"green\", \"rabbitmq\": \"green\", \"redis\": \"green\"}, \"version\": \"2018.8.5\"}"; err=<nil>
172.17.0.1 - - [06/Mar/2018:08:59:30 +0000] "HEAD /status/ HTTP/1.1" 200 117

which was 1 GET and 1 HEAD request. So then they both show up.

Also, the healtch checks that occur are actually GET requests (generated by Nomad), so I don't think the HEAD part is the problem?

[magiconair]

The access log should go to stdout and the normal log to stderr via the leveled logger so they should not interfere with each other.

The leveled logger looks at the first two bytes of the log line to determine the level and if that isn't in the right format prints invalid log msg:.

[tino]

Okay, found the culprit!
FABIO_proxy_gzip_contenttype = "^(text/.*|application/(javascript|json|font-woff|xml)|.*\+(json|xml))(;.*)?$"

Removing that makes it work :). Tried other regexes but that didn't make a difference.

Renamed the issue.

Ps. thanks for making fabio start so fast, tried a lot of different configs 😊

[magiconair]

Cool. Is this the default regex from the properties file? I’m glad you like it 🙂 — Frank Schröder

…

On 6. Mar 2018, at 16:53, Tino de Bruijn ***@***.***> wrote: Okay, found the culprit! FABIO_proxy_gzip_contenttype = "^(text/.*|application/(javascript|json|font-woff|xml)|.*\+(json|xml))(;.*)?$" Removing that makes it work :). Tried other regexes but that didn't make a difference. Ps. thanks for making fabio start so fast, tried a lot of different configs 😊 — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[tino]

Yes, it is. But ^(text/.*)(;.*)?$ didn't work either. And when I break the regex fabio will crash so that shouldn't be the case.

[tino]

Okay, I'm getting somewhere. If I apply this patch, it still doesn't log (so this doesn't change the handler, but just wraps it):

diff --git a/proxy/gzip/gzip_handler.go b/proxy/gzip/gzip_handler.go
index 9cdf70d..0bc6ad3 100644
--- a/proxy/gzip/gzip_handler.go
+++ b/proxy/gzip/gzip_handler.go
@@ -11,6 +11,7 @@ import (
        "bufio"
        "compress/gzip"
        "errors"
+       "fmt"
        "io"
        "net"
        "net/http"
@@ -36,17 +37,23 @@ var gzipWriterPool = sync.Pool{
 // body if the client supports it (via the Accept-Encoding header) and the
 // response Content-Type matches the contentTypes expression.
 func NewGzipHandler(h http.Handler, contentTypes *regexp.Regexp) http.Handler {
-       return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-               w.Header().Add(headerVary, headerAcceptEncoding)
+       fmt.Printf("Old handler: %z\n", h)
+       nh := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+               // w.Header().Add(headerVary, headerAcceptEncoding)

                if acceptsGzip(r) {
-                       gzWriter := NewGzipResponseWriter(w, contentTypes)
-                       defer gzWriter.Close()
-                       h.ServeHTTP(gzWriter, r)
+                       fmt.Println("GZIPPED")
+                       // gzWriter := NewGzipResponseWriter(w, contentTypes)
+                       // defer gzWriter.Close()
+                       h.ServeHTTP(w, r)
+                       // fmt.Printf("GZIPPED", )
                } else {
+                       fmt.Println("NOT GZIPPED")
                        h.ServeHTTP(w, r)
                }
        })
+       fmt.Printf("New handler: %z\n", nh)
+       return nh
 }

 type GzipResponseWriter struct {

Output:

New handler: %!z(http.HandlerFunc=0x1363f90)
GZIPPED
Old handler: &{%!z(func(*http.Request)=0x136cb80) %!z(*proxy.transport=&{0xc42013e0f0 <nil> <nil>}) %!z(time.Duration=0) %!z(*log.Logger=<nil>) <nil> %!z(func(*http.Response) error=<nil>)}

If I just make NewGzipHandler return h, logging works.

So appearently the new handler is making the logging change? Nvm, proxy.HTTPProxy.ServeHTTP actually exits at line 200, because h is not a direct httputil.ReverseProxy anymore but a http.Handler. I fail to see how the *httputil.ReverseProxy return value from proxy.newHTTPProxy becomes a http.Handler and couldn't figure out a way to prevent this.

Any suggestions on how to tackle this?

[magiconair]

Ah, damn. The ugly hack for getting the response rears its head... I'll comment on the PR. That's a good catch. Thanks a lot for finding this!

[magiconair]

@tino Could you try #470 ?