Redirect generate wrong access logs

[jdel]

Do you want to request a feature or report a bug?

Reporting a bug

What did you do?

Run traefik with http redirected to https and examine access logs.

What did you expect to see?

A single curl on nginx1 generates 1 line in the access log:

172.17.0.1 - - [13/Dec/2017:19:49:27 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 34 "Host-nginx1-test-tld-3" "http://172.17.0.3:80" 0ms

A single curl on nginx2 generates 1 line in the access log:

172.17.0.1 - - [13/Dec/2017:19:50:41 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 42 "Host-nginx2-test-tld-2" "http://172.17.0.4:80" 0ms

What did you see instead?

A single curl on nginx1 generates 2 lines in the access log:

172.17.0.1 - - [13/Dec/2017:19:49:27 +0000] "GET / HTTP/1.1" - - - "curl/7.54.0" 33 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [13/Dec/2017:19:49:27 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 34 "Host-nginx1-test-tld-3" "http://172.17.0.3:80" 0ms

Now a curl on nginx2 shows a erroneous output in the first line:

172.17.0.1 - - [13/Dec/2017:19:50:41 +0000] "GET / HTTP/1.1" - - - "curl/7.54.0" 41 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [13/Dec/2017:19:50:41 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 42 "Host-nginx2-test-tld-2" "http://172.17.0.4:80" 0ms

Output of traefik version: (What version of Traefik are you using?)

docker run --rm traefik:v1.4 version
Version:      v1.4.5
Codename:     roquefort
Go version:   go1.9.2
Built:        2017-12-06_10:16:48AM
OS/Arch:      linux/amd64

What is your environment & configuration (arguments, toml, provider, platform, ...)?

defaultEntryPoints = ["http", "https"]
logLevel = "ERROR"
InsecureSkipVerify = true

[accessLog]
filePath = "/var/log/traefik/access.log"

################################################################
# Web configuration backend
################################################################
[web]
address = ":8080"
[web.statistics]
recentErrors = 20

################################################################
# Docker configuration backend
################################################################
[docker]
domain = "test.tld"
watch = true

[entryPoints]
  [entryPoints.http]
  address = ":80"
    [entryPoints.http.redirect]
    entryPoint = "https"
  [entryPoints.https]
  address = ":8443"

Traefik run with:

docker rm -fv traefik; docker run --detach \
    --name       traefik \
    --publish    8080:8080 \
    --publish    8880:80 \
    --publish    8443:443 \
    --volume     /Users/jdel/data/traefik/logs/:/var/log/traefik/:rw \
    --volume     /Users/jdel/data/traefik/traefik.toml:/etc/traefik/traefik.toml:ro \
    --volume     /var/run/docker.sock:/var/run/docker.sock:ro \
    --memory     300m \
    traefik:v1.4 --web

Now run 3 nginx:

docker run -d --name nginx1 nginx:stable-alpine
docker run -d --name nginx2 nginx:stable-alpine
docker run -d --name nginx3 nginx:stable-alpine

A single curl on nginx1 generates 2 lines in the access log:

172.17.0.1 - - [13/Dec/2017:19:49:27 +0000] "GET / HTTP/1.1" - - - "curl/7.54.0" 33 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [13/Dec/2017:19:49:27 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 34 "Host-nginx1-test-tld-3" "http://172.17.0.3:80" 0ms

Now a curl on nginx2 shows a weird behaviour:

172.17.0.1 - - [13/Dec/2017:19:50:41 +0000] "GET / HTTP/1.1" - - - "curl/7.54.0" 41 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [13/Dec/2017:19:50:41 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 42 "Host-nginx2-test-tld-2" "http://172.17.0.4:80" 0ms

The first lime says we're hitting Host-nginx1-test-tld-3 which is not correct.

Same goes with nginx3:

172.17.0.1 - - [13/Dec/2017:19:52:07 +0000] "GET / HTTP/1.1" - - - "curl/7.54.0" 43 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [13/Dec/2017:19:52:07 +0000] "GET / HTTP/1.1" 200 612 - "curl/7.54.0" 44 "Host-nginx3-test-tld-1" "http://172.17.0.5:80" 0ms

[jdel]

I haven't looked at the code yet. I'll see if I can pin down the issue.

[mmatur]

@jdel Thanks for your interest on Træfik.

To me it is not an issue. Because with your example it is normal to have two lines of log.

You send a request on the entrypoint who listen on port 8880, you have configured this entrypoint to redirect to the https entrypoint who listen on 8443. So when Træfik receives the request it responses with a 302 Found and you client will do an other request on the value of the Location headers in the response.
You client does two requests on Træfik

$ curl -ILs -H 'Host:nginx1.test.tld'  http://127.0.0.1:8880/
HTTP/1.1 302 Found
Location: http://nginx1.test.tld:8443/
Date: Tue, 02 Jan 2018 15:17:53 GMT
Content-Length: 5
Content-Type: text/plain; charset=utf-8

HTTP/1.1 200 OK
Accept-Ranges: bytes
Content-Length: 612
Content-Type: text/html
Date: Tue, 02 Jan 2018 15:17:53 GMT
Etag: "5a21d078-264"
Last-Modified: Fri, 01 Dec 2017 21:58:16 GMT
Server: nginx/1.12.2

[jdel]

Hello @mmatur, Thanks for looking into this.

Indeed, due to the weird first line in the log, I assumed the redirection was done internally for some reason and I didn't even check. My bad.

It does make sense to have two entries in the log but then the first one should be formed properly, show the status code 302 and the correct frontend name.

If you look at my test case above, currently, the first line always shows the same front end name.

The following curl commands (without following redirection):

curl -Is --resolve 'nginx1.test.tld:8880:127.0.0.1' nginx1.test.tld:8880
curl -Is --resolve 'nginx2.test.tld:8880:127.0.0.1' nginx2.test.tld:8880
curl -Is --resolve 'nginx3.test.tld:8880:127.0.0.1' nginx3.test.tld:8880

Generate the following access logs

172.17.0.1 - - [03/Jan/2018:11:36:27 +0000] "HEAD / HTTP/1.1" - - - "curl/7.54.0" 9 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [03/Jan/2018:11:36:27 +0000] "HEAD / HTTP/1.1" - - - "curl/7.54.0" 10 "Host-nginx1-test-tld-3" - 0ms
172.17.0.1 - - [03/Jan/2018:11:36:27 +0000] "HEAD / HTTP/1.1" - - - "curl/7.54.0" 11 "Host-nginx1-test-tld-3" - 0ms

It always shows Host-nginx1-test-tld-3 when it's not alwazs the case.

Eventually, some info about the entrypoint would be nice too in order to filter the logs.

[mmatur]

Hello @jdel,

I can confirmed that there is an issue with the host name. Nice catch

Like explained here it is normal that the 302 status is not present

// OriginStatus is the map key used for the HTTP status code returned by the origin server.
// If the request was handled by this Traefik instance (e.g. with a redirect), then this value will be absent.

[jdel]

Yes that's what I assumed, there is some internal things going on there.

Is there any technical reason not to have the original status in the access log ?

I might be the only one using the access log feature with a log analyzer to parse the logs, but to me this seems fundamental, as an empty status code will basically be treated as invalid by most log analyzers.

[mmatur]

Thanks for your feedback.

I am working on a fix

[jdel]

Thanks a lot. My Go is not good enough to attempt a fix myself, but I can do tests if it's any help.