Fabio: access logging

[rutchkiwi]

Hi!

First off, thank you for making this, it's a really cool project!

My question is quite simple, does fabio support access logging? nginx for instance can print all requests passing through and their responses to stdout or a file. Would be quite useful to me, since I'd then would not need to implement this in all downstream services.

[magiconair]

Not yet but certainly doable. Just log to local disk?

[rutchkiwi]

thx for the quick reply!
In my case I'd like to log to stdout, since I'm running the docker image and all my other containers send their logs off to a log aggregation service using a docker log driver.

[magiconair]

so access log to stdout, normal log to stderr?

[rutchkiwi]

That would be perfect for me

[magiconair]

Any preference on the format?

[rutchkiwi]

No strong preference really, but json would be easy to parse. The data I capture in other places would be

• the http method/hostname/path
• the response time & status
• which (upstream) server it got routed to
• the local time
• the user agent

Of course for a first version it would be really nice just having the first two! Let me know if there is anything I could do to help with this. :)

[osigida]

I guess, the format should be configurable, say we'd like to have some headers as well.

Here is implementation from logback, might be useful: http://logback.qos.ch/access.html

[sfleiter]

What is still missing to be able to merge this?
Looking forward to the feature.

[magiconair]

There was quite a bit of work to do AFAIR. I'm on vacation for another week and should have time to pick some of the slack early December.

[sfleiter]

Thanks a lot for your fast feedback Frank,
hope you have a wonderful vacation!

[sielaq]

+1 for access logs, also to a file too

[sielaq]

[ElliotG]

Also wanted to add that access logging would be super awesome.

[leprechau]

I'm not sure I see the rationale to have this goto a file natively. Running fabio under systemd, upstart or in a docker container allows you to easily get any stdout/stderr into a file with standard tools.

[magiconair]

Lets first get this working. Writing to a file is trivial but I agree with @leprechau that this shouldn't be necessary in this day and age.

[magiconair]

OK, here is access logging support for fabio. The code supports the common and combined log file format out of the box with common being the default. To enable access logging you have to set proxy.log.target=stdout.

You can also configure a custom log format. Check fabio.properties for details. You'll also find examples on how the common and combined log file formats are defined.

I've spent some time writing the code in a way so that it doesn't alloc since fabio sits in the hot-path.

For everybody interested in this feature: Testing is highly appreciated. I'm especially interested in whether the values are correct and whether all the fields you're looking for are covered. This branch is based on master but I'll rebase it once 1.4 is out.

[magiconair]

Rebased the patch on the new 1.4 release which is on master now.

[magiconair]

Just in case someone wonders why I didn't just use text/template for the log line format (I just did for example). I wrote a short benchmark to get an idea.

Here are the results

$ go test -v -benchmem -bench Log -run lxjdlf
BenchmarkLog/my_parser-8             1000000          2337 ns/op           0 B/op          0 allocs/op
BenchmarkLog/go_text/template-8       100000         19035 ns/op         848 B/op         76 allocs/op
PASS
ok      github.com/eBay/fabio/logger    4.480s

And here the code

func BenchmarkLog(b *testing.B) {
    t1 := time.Date(2016, 1, 1, 0, 0, 0, 0, time.UTC)
    t2 := t1.Add(100 * time.Millisecond)
    req := &http.Request{
        RequestURI: "/?q=x",
        Header: http.Header{
            "User-Agent":      {"Mozilla Firefox"},
            "Referer":         {"http://foo.com/"},
            "X-Forwarded-For": {"3.3.3.3"},
        },
        RemoteAddr: "2.2.2.2:666",
        Host:       "foo.com",
        URL: &url.URL{
            Path:     "/",
            RawQuery: "?q=x",
            Host:     "proxy host",
        },
        Method: "GET",
        Proto:  "HTTP/1.1",
    }

    resp := &http.Response{
        StatusCode:    200,
        ContentLength: 1234,
        Header:        http.Header{"foo": []string{"bar"}},
        Request: &http.Request{
            RemoteAddr: "5.6.7.8:1234",
        },
    }

    b.Run("my parser", func(b *testing.B) {
        var keys []string
        for k := range fields {
            keys = append(keys, k)
        }
        sort.Strings(keys)
        format := strings.Join(keys, " ")

        l, err := New(ioutil.Discard, format)
        if err != nil {
            b.Fatal(err)
        }

        b.ResetTimer()
        for i := 0; i < b.N; i++ {
            l.Log(t1, t2, resp, req)
        }
    })
    b.Run("go text/template", func(b *testing.B) {
        tmpl := ""
        for i := 0; i < len(fields); i++ {
            tmpl += "{{.Req.RemoteAddr}}"
        }
        t := template.Must(template.New("log").Parse(tmpl))
        d := &struct {
            Req  *http.Request
            Resp *http.Response
        }{req, resp}

        b.ResetTimer()
        for i := 0; i < b.N; i++ {
            t.Execute(ioutil.Discard, d)
        }
    })
}

[holtwilkins]

Hey @magiconair thanks for getting this going! I tried it out, and most of the fields look right to me, but the $upstream_* fields seem to be logging the remote fields, not the upstream fields.

[magiconair]

@holtwilkins Indeed. Thanks for finding this. This should be fixed now. Could you have another look, please?

[magiconair]

Fixed nil pointer panic in proxy/http_proxy.go:93

[magiconair]

Rebased to master after travis test failure fix.

[holtwilkins]

I can confirm that $upstream_addr looks right now, thanks!

[magiconair]

Cool and thanks @holtwilkins for taking another look. @sielaq has also found the nil pointer issue so I think the code is in good shape. I'll sit on this for a couple more days since I don't like the config options yet because they clash a bit with the proxy.log.routes option I've added lately and then there is PR #246 for a remote logging backend which should be integrated later.

[ak66982]

$upstream_host logs protocol pre-pended to the host, $upstream_port leaves slash after the port:
Is this intentional ?

proxy.log.format = addr:"$upstream_addr" host:"$upstream_host" port:"$upstream_port"

Mar 28 23:33:14 30383225-ce3b-42ec-a292-8b770212d5b9 fabio: addr:"http://10.1.6.227:1991/" host:"http://10.1.6.227" port:"1991/"

[magiconair]

@ak66982 No, of course not. Should have written a full integration test :( I'll fix it.

[magiconair]

@ak66982 Fixed.

[magiconair]

This produces now: addr:"127.0.0.1:5000" host:"127.0.0.1" port:"5000"

I've added a couple of additional fields:

//   request_scheme          - request scheme
//   request_url             - request URL
//   upstream_request_scheme - upstream request scheme
//   upstream_request_uri    - upstream request URI
//   upstream_request_url    - upstream request URL

The full list is:

//   header.<name>           - request http header (name: [a-zA-Z0-9-]+)
//   remote_addr             - host:port of remote client
//   remote_host             - host of remote client
//   remote_port             - port of remote client
//   request                 - request <method> <uri> <proto>
//   request_args            - request query parameters
//   request_host            - request host header (aka server name)
//   request_method          - request method
//   request_scheme          - request scheme
//   request_uri             - request URI
//   request_url             - request URL
//   request_proto           - request protocol
//   response_body_size      - response body size in bytes
//   response_status         - response status code
//   response_time_ms        - response time in S.sss format
//   response_time_us        - response time in S.ssssss format
//   response_time_ns        - response time in S.sssssssss format
//   time_rfc3339            - log timestamp in YYYY-MM-DDTHH:MM:SSZ format
//   time_rfc3339_ms         - log timestamp in YYYY-MM-DDTHH:MM:SS.sssZ format
//   time_rfc3339_us         - log timestamp in YYYY-MM-DDTHH:MM:SS.ssssssZ format
//   time_rfc3339_ns         - log timestamp in YYYY-MM-DDTHH:MM:SS.sssssssssZ format
//   time_unix_ms            - log timestamp in unix epoch ms
//   time_unix_us            - log timestamp in unix epoch us
//   time_unix_ns            - log timestamp in unix epoch ns
//   time_common             - log timestamp in DD/MMM/YYYY:HH:MM:SS -ZZZZ
//   upstream_addr           - host:port of upstream server
//   upstream_host           - host of upstream server
//   upstream_port           - port of upstream server
//   upstream_request_scheme - upstream request scheme
//   upstream_request_uri    - upstream request URI
//   upstream_request_url    - upstream request URL

[ak66982]

By the way, thanks for the wonderful piece of software!

$response_body_size sometimes logs '-1' instead of proper size (redacted):

Mar 29 21:19:56 local fabio: 2017-03-29T21:19:56.415Z [remote]:44876 [host] 10.1.7.195:1991 6.852 200 -1 "POST [URI] HTTP/1.1" "[DATA]"
Mar 29 21:19:56 local fabio: 2017-03-29T21:19:56.598Z [remote]:44876 [host] 10.1.7.195:1991 0.175 200 -1 "GET [URI] HTTP/1.1" "[DATA]"
Mar 29 21:19:57 local fabio: 2017-03-29T21:19:57.222Z [remote]:44876 [host] 10.1.6.75:1991 0.084 200 -1 "PUT [URI] HTTP/1.1" "[DATA]"

proxy.log.format = $time_rfc3339_ms $remote_addr $request_host $upstream_addr $response_time_ms $response_status $response_body_size "$request" "$request_args"

I checked the tcpdump, there was nothing strange in these requests. Content-Length is missing from reply, but $response_body_size was logged correctly in other requests with content-length missing.

[magiconair]

@ak66982 Thank you. I'm glad you like it.

Right now, I'm getting the content length from the http response generated by the Go reverse proxy. i didn't dig into how it retrieves it but I'll have a look.

[magiconair]

Added a full integration tests which generates the log output through the proxy with a real request. This uncovered two bugs in the $upstream_request_uri and $upstream_request_url fields which did not contain the upstream uri paths and args since this magic was happening somewhere in the httputil.NewSingleHostReverseProxy() code.

The other thing I've discovered was that the request object got modified through the reverse proxy code which made the $request_url, $request_scheme and $request_args fields invalid or incomplete. This has been fixed.

@ak66982 I still don't have a test for the -1 value in the $response_body_size so it would be helpful if you could try to narrow this down further.

[magiconair]

I've renamed the log parameters as follows:

log.access.format
log.access.target
log.routes.format (replaces proxy.log.routes)

This should also make integration with PR #246 more consistent. If there are no objections then I'm going to merge this and release version 1.4.1.

[magiconair]

Published release v1.4.1 with access logging support. Thanks for your help.