traefik icon indicating copy to clipboard operation
traefik copied to clipboard
Published 4 months ago • verified publisher icon traefik

writeTimeout ignored for http/1.1

Open ringgelerch opened this issue 3 years ago • 11 comments

Welcome!

  • [X] Yes, I've searched similar issues on GitHub and didn't find any.
  • [X] Yes, I've searched similar issues on the Traefik community forum and didn't find any.

What did you do?

Hi, I wanted to use the transport.respondingTimeouts.writeTimeout to limit the processing time of the incoming request. Unfortunately I had some problems with the timeout.

I tested my configuration with two test clients. One was connected via http/1.1 and the other via http/2. I expected that the timeout would be triggered in both scenarios.

What did you see instead?

The result was:

  • http/1.1: configured writeTimeout had no influence and wasn't triggered
  • http/2: writeTimeout was triggered and worked as expected

I have created an minimum example to reproduce this behavior.

What version of Traefik are you using?

Version: 2.8.1 Codename: vacherin Go version: go1.17.11 Built: 2022-07-11T14:06:57Z OS/Arch: linux/amd64

What is your environment & configuration?

My docker-compose.yml looks like this:

version: '3'

services:
  reverse-proxy:
    # The official v2 Traefik docker image
    image: traefik:v2.8
    # Enables the web UI and tells Traefik to listen to docker
    command: --api.insecure=true --providers.docker --entryPoints.web.address=:80 --entryPoints.web.transport.respondingTimeouts.writeTimeout="5s" --log.level=DEBUG --log.filePath=/log/traefik.log --accesslog=true --accesslog.filepath=/log/access.log --entrypoints.websecure.address=:443 --entrypoints.websecure.http.tls.certResolver=leresolver --entrypoints.websecure.transport.respondingTimeouts.writeTimeout="5s"
    ports:
      # The HTTP port
      - "80:80"
      # The Web UI (enabled by --api.insecure=true)
      - "8080:8080"
      - "443:443"
    volumes:
      # So that Traefik can listen to the Docker events
      - /var/run/docker.sock:/var/run/docker.sock
      - ./log:/log
    labels:
      - "traefik.http.routers.api.tls=true"
      - "traefik.http.routers.api.tls.certresolver=DefaultAcmeResolver"

  whoami:
    image: traefik/whoami
    labels:
      - "traefik.http.routers.whoami.rule=Host(`whoami.docker.localhost`)"

To reproduce the issue execute the following steps:

  1. Start the containers
ringgelerch@NB6789:~/traefik$ docker-compose up -d
[+] Running 2/2
⠿ Container traefik-whoami-1         Started                                                                                                                                                                                           0.8s
⠿ Container traefik-reverse-proxy-1  Started                                                                                                                                                                                           0.8s
ringgelerch@NB6789:~/traefik$
  1. Make a HTTP GET with http/1.1
ringgelerch@NB6789:~/traefik$ curl -H Host:whoami.docker.localhost https://127.0.0.1/?wait=7s -v -k --http1.1
*   Trying 127.0.0.1:443...
* Connected to 127.0.0.1 (127.0.0.1) port 443 (#0)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: CN=TRAEFIK DEFAULT CERT
*  start date: Jul 14 15:13:26 2022 GMT
*  expire date: Jul 14 15:13:26 2023 GMT
*  issuer: CN=TRAEFIK DEFAULT CERT
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
> GET /?wait=7s HTTP/1.1
> Host:whoami.docker.localhost
> User-Agent: curl/7.74.0
> Accept: */*
>
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (OUT), TLS alert, bad record mac (532):
* OpenSSL SSL_read: error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac, errno 0
* Closing connection 0
curl: (56) OpenSSL SSL_read: error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac, errno 0
ringgelerch@NB6789:~/traefik$
  1. Make a HTTP GET with http/2
ringgelerch@NB6789:~/traefik$ curl -H Host:whoami.docker.localhost https://127.0.0.1/?wait=7s -v -k --http2
*   Trying 127.0.0.1:443...
* Connected to 127.0.0.1 (127.0.0.1) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: CN=TRAEFIK DEFAULT CERT
*  start date: Jul 14 15:13:26 2022 GMT
*  expire date: Jul 14 15:13:26 2023 GMT
*  issuer: CN=TRAEFIK DEFAULT CERT
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55debcda4b70)
> GET /?wait=7s HTTP/2
> Host:whoami.docker.localhost
> user-agent: curl/7.74.0
> accept: */*
>
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
* HTTP/2 stream 0 was not closed cleanly: INTERNAL_ERROR (err 2)
* stopped the pause stream!
* Connection #0 to host 127.0.0.1 left intact
curl: (92) HTTP/2 stream 0 was not closed cleanly: INTERNAL_ERROR (err 2)
ringgelerch@NB6789:~/traefik$
  1. Check access.log:
ringgelerch@NB6789:~/traefik$ cat log/access.log
172.19.0.1 - - [14/Jul/2022:15:18:53 +0000] "GET /?wait=7s HTTP/1.1" 200 377 "-" "-" 1 "websecure-whoami@docker" "http://172.19.0.3:80" 7008ms
172.19.0.1 - - [14/Jul/2022:15:21:13 +0000] "GET /?wait=7s HTTP/2.0" 499 21 "-" "-" 2 "websecure-whoami@docker" "http://172.19.0.3:80" 5007ms
ringgelerch@NB6789:~/traefik$

The writeTimeouts were set to 5s and the response delay of the whoami service was set to 7s. As you can see in the access.log, the timeout in the http/1.1 scenario wasn't triggered but there is no response as well.

When I reduce delay of the whoami service to 4s the request is processed as expected:

ringgelerch@NB6789:~/traefik$ curl -H Host:whoami.docker.localhost https://127.0.0.1/?wait=4s -v -k --http1.1
*   Trying 127.0.0.1:443...
* Connected to 127.0.0.1 (127.0.0.1) port 443 (#0)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: CN=TRAEFIK DEFAULT CERT
*  start date: Jul 14 15:13:26 2022 GMT
*  expire date: Jul 14 15:13:26 2023 GMT
*  issuer: CN=TRAEFIK DEFAULT CERT
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
> GET /?wait=4s HTTP/1.1
> Host:whoami.docker.localhost
> User-Agent: curl/7.74.0
> Accept: */*
>
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Content-Length: 377
< Content-Type: text/plain; charset=utf-8
< Date: Thu, 14 Jul 2022 15:39:14 GMT
<
Hostname: 36a3f55b7ec7
IP: 127.0.0.1
IP: 172.19.0.3
RemoteAddr: 172.19.0.2:36106
GET /?wait=4s HTTP/1.1
Host: whoami.docker.localhost
User-Agent: curl/7.74.0
Accept: */*
Accept-Encoding: gzip
X-Forwarded-For: 172.19.0.1
X-Forwarded-Host: whoami.docker.localhost
X-Forwarded-Port: 443
X-Forwarded-Proto: https
X-Forwarded-Server: d344518d8b16
X-Real-Ip: 172.19.0.1

* Connection #0 to host 127.0.0.1 left intact
ringgelerch@NB6789:~/traefik$

If applicable, please paste the log output in DEBUG level

ringgelerch@NB6789:~/traefik$ cat log/traefik.log
time="2022-07-14T15:12:29Z" level=info msg="Traefik version 2.8.1 built on 2022-07-11T14:06:57Z"
time="2022-07-14T15:12:29Z" level=debug msg="Static configuration loaded {\"global\":{\"checkNewVersion\":true},\"serversTransport\":{\"maxIdleConnsPerHost\":200},\"entryPoints\":{\"traefik\":{\"address\":\":8080\",\"transport\":{\"lifeCycle\":{\"graceTimeOut\":\"10s\"},\"respondingTimeouts\":{\"idleTimeout\":\"3m0s\"}},\"forwardedHeaders\":{},\"http\":{},\"http2\":{\"maxConcurrentStreams\":250},\"udp\":{\"timeout\":\"3s\"}},\"web\":{\"address\":\":80\",\"transport\":{\"lifeCycle\":{\"graceTimeOut\":\"10s\"},\"respondingTimeouts\":{\"writeTimeout\":\"5s\",\"idleTimeout\":\"3m0s\"}},\"forwardedHeaders\":{},\"http\":{},\"http2\":{\"maxConcurrentStreams\":250},\"udp\":{\"timeout\":\"3s\"}},\"websecure\":{\"address\":\":443\",\"transport\":{\"lifeCycle\":{\"graceTimeOut\":\"10s\"},\"respondingTimeouts\":{\"writeTimeout\":\"5s\",\"idleTimeout\":\"3m0s\"}},\"forwardedHeaders\":{},\"http\":{\"tls\":{\"certResolver\":\"leresolver\"}},\"http2\":{\"maxConcurrentStreams\":250},\"udp\":{\"timeout\":\"3s\"}}},\"providers\":{\"providersThrottleDuration\":\"2s\",\"docker\":{\"watch\":true,\"endpoint\":\"unix:///var/run/docker.sock\",\"defaultRule\":\"Host(`{{ normalize .Name }}`)\",\"exposedByDefault\":true,\"swarmModeRefreshSeconds\":\"15s\"}},\"api\":{\"insecure\":true,\"dashboard\":true},\"log\":{\"level\":\"DEBUG\",\"filePath\":\"/log/traefik.log\",\"format\":\"common\"},\"accessLog\":{\"filePath\":\"/log/access.log\",\"format\":\"common\",\"filters\":{},\"fields\":{\"defaultMode\":\"keep\",\"headers\":{\"defaultMode\":\"drop\"}}},\"pilot\":{\"dashboard\":true}}"
time="2022-07-14T15:12:29Z" level=info msg="\nStats collection is disabled.\nHelp us improve Traefik by turning this feature on :)\nMore details on: https://doc.traefik.io/traefik/contributing/data-collection/\n"
time="2022-07-14T15:12:29Z" level=warning msg="Traefik Pilot is deprecated and will be removed soon. Please check our Blog for migration instructions later this year."
time="2022-07-14T15:12:29Z" level=info msg="Starting provider aggregator aggregator.ProviderAggregator"
time="2022-07-14T15:12:29Z" level=debug msg="Starting TCP Server" entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Starting TCP Server" entryPointName=websecure
time="2022-07-14T15:12:29Z" level=info msg="Starting provider *traefik.Provider"
time="2022-07-14T15:12:29Z" level=debug msg="*traefik.Provider provider configuration: {}"
time="2022-07-14T15:12:29Z" level=info msg="Starting provider *docker.Provider"
time="2022-07-14T15:12:29Z" level=debug msg="*docker.Provider provider configuration: {\"watch\":true,\"endpoint\":\"unix:///var/run/docker.sock\",\"defaultRule\":\"Host(`{{ normalize .Name }}`)\",\"exposedByDefault\":true,\"swarmModeRefreshSeconds\":\"15s\"}"
time="2022-07-14T15:12:29Z" level=debug msg="Starting TCP Server" entryPointName=web
time="2022-07-14T15:12:29Z" level=info msg="Starting provider *acme.ChallengeTLSALPN"
time="2022-07-14T15:12:29Z" level=debug msg="*acme.ChallengeTLSALPN provider configuration: {}"
time="2022-07-14T15:12:29Z" level=debug msg="Configuration received: {\"http\":{\"routers\":{\"api\":{\"entryPoints\":[\"traefik\"],\"service\":\"api@internal\",\"rule\":\"PathPrefix(`/api`)\",\"priority\":2147483646},\"dashboard\":{\"entryPoints\":[\"traefik\"],\"middlewares\":[\"dashboard_redirect@internal\",\"dashboard_stripprefix@internal\"],\"service\":\"dashboard@internal\",\"rule\":\"PathPrefix(`/`)\",\"priority\":2147483645}},\"services\":{\"api\":{},\"dashboard\":{},\"noop\":{}},\"middlewares\":{\"dashboard_redirect\":{\"redirectRegex\":{\"regex\":\"^(http:\\\\/\\\\/(\\\\[[\\\\w:.]+\\\\]|[\\\\w\\\\._-]+)(:\\\\d+)?)\\\\/$\",\"replacement\":\"${1}/dashboard/\",\"permanent\":true}},\"dashboard_stripprefix\":{\"stripPrefix\":{\"prefixes\":[\"/dashboard/\",\"/dashboard\"]}}},\"models\":{\"websecure\":{\"tls\":{\"certResolver\":\"leresolver\"}}},\"serversTransports\":{\"default\":{\"maxIdleConnsPerHost\":200}}},\"tcp\":{},\"udp\":{},\"tls\":{}}" providerName=internal
time="2022-07-14T15:12:29Z" level=debug msg="No default certificate, generating one" tlsStoreName=default
time="2022-07-14T15:12:29Z" level=debug msg="Provider connection established with docker 20.10.14 (API 1.41)" providerName=docker
time="2022-07-14T15:12:29Z" level=error msg="service \"elegant-wright\" error: port is missing" providerName=docker container=elegant-wright-b806c08e1e32ea1c7f39d82e5762dbb03631b55a039eac7bf025390fc89b6a58
time="2022-07-14T15:12:29Z" level=debug msg="Configuration received: {\"http\":{\"routers\":{\"api\":{\"service\":\"reverse-proxy-traefik\",\"rule\":\"Host(`reverse-proxy-traefik`)\",\"tls\":{\"certResolver\":\"DefaultAcmeResolver\"}},\"whoami\":{\"service\":\"whoami-traefik\",\"rule\":\"Host(`whoami.docker.localhost`)\"}},\"services\":{\"reverse-proxy-traefik\":{\"loadBalancer\":{\"servers\":[{\"url\":\"http://172.19.0.3:80\"}],\"passHostHeader\":true}},\"whoami-traefik\":{\"loadBalancer\":{\"servers\":[{\"url\":\"http://172.19.0.2:80\"}],\"passHostHeader\":true}}}},\"tcp\":{},\"udp\":{}}" providerName=docker
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware dashboard@internal" entryPointName=traefik routerName=dashboard@internal middlewareName=tracing middlewareType=TracingForwarder
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" middlewareType=StripPrefix entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_stripprefix@internal
time="2022-07-14T15:12:29Z" level=debug msg="Adding tracing to middleware" routerName=dashboard@internal middlewareName=dashboard_stripprefix@internal entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" middlewareType=RedirectRegex entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_redirect@internal
time="2022-07-14T15:12:29Z" level=debug msg="Setting up redirection from ^(http:\\/\\/(\\[[\\w:.]+\\]|[\\w\\._-]+)(:\\d+)?)\\/$ to ${1}/dashboard/" routerName=dashboard@internal middlewareName=dashboard_redirect@internal middlewareType=RedirectRegex entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Adding tracing to middleware" routerName=dashboard@internal entryPointName=traefik middlewareName=dashboard_redirect@internal
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware api@internal" entryPointName=traefik routerName=api@internal middlewareName=tracing middlewareType=TracingForwarder
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" entryPointName=traefik middlewareName=traefik-internal-recovery middlewareType=Recovery
time="2022-07-14T15:12:29Z" level=debug msg="No entryPoint defined for this router, using the default one(s) instead: [web websecure]" routerName=api
time="2022-07-14T15:12:29Z" level=debug msg="No entryPoint defined for this router, using the default one(s) instead: [web websecure]" routerName=whoami
time="2022-07-14T15:12:29Z" level=debug msg="No default certificate, generating one" tlsStoreName=default
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware dashboard@internal" routerName=dashboard@internal middlewareName=tracing middlewareType=TracingForwarder entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" middlewareName=dashboard_stripprefix@internal middlewareType=StripPrefix entryPointName=traefik routerName=dashboard@internal
time="2022-07-14T15:12:29Z" level=debug msg="Adding tracing to middleware" routerName=dashboard@internal middlewareName=dashboard_stripprefix@internal entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_redirect@internal middlewareType=RedirectRegex
time="2022-07-14T15:12:29Z" level=debug msg="Setting up redirection from ^(http:\\/\\/(\\[[\\w:.]+\\]|[\\w\\._-]+)(:\\d+)?)\\/$ to ${1}/dashboard/" entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_redirect@internal middlewareType=RedirectRegex
time="2022-07-14T15:12:29Z" level=debug msg="Adding tracing to middleware" routerName=dashboard@internal entryPointName=traefik middlewareName=dashboard_redirect@internal
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware api@internal" routerName=api@internal middlewareType=TracingForwarder middlewareName=tracing entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" middlewareName=traefik-internal-recovery middlewareType=Recovery entryPointName=traefik
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" entryPointName=web middlewareName=pipelining middlewareType=Pipelining routerName=whoami@docker serviceName=whoami-traefik
time="2022-07-14T15:12:29Z" level=debug msg="Creating load-balancer" routerName=whoami@docker serviceName=whoami-traefik entryPointName=web
time="2022-07-14T15:12:29Z" level=debug msg="Creating server 0 http://172.19.0.2:80" routerName=whoami@docker serviceName=whoami-traefik serverName=0 entryPointName=web
time="2022-07-14T15:12:29Z" level=debug msg="child http://172.19.0.2:80 now UP"
time="2022-07-14T15:12:29Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware whoami-traefik" middlewareName=tracing middlewareType=TracingForwarder entryPointName=web routerName=whoami@docker
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" middlewareType=Recovery entryPointName=web middlewareName=traefik-internal-recovery
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" routerName=api@docker serviceName=reverse-proxy-traefik middlewareName=pipelining middlewareType=Pipelining entryPointName=web
time="2022-07-14T15:12:29Z" level=debug msg="Creating load-balancer" serviceName=reverse-proxy-traefik entryPointName=web routerName=api@docker
time="2022-07-14T15:12:29Z" level=debug msg="Creating server 0 http://172.19.0.3:80" routerName=api@docker serviceName=reverse-proxy-traefik serverName=0 entryPointName=web
time="2022-07-14T15:12:29Z" level=debug msg="child http://172.19.0.3:80 now UP"
time="2022-07-14T15:12:29Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware reverse-proxy-traefik" routerName=api@docker middlewareName=tracing middlewareType=TracingForwarder entryPointName=web
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" entryPointName=web middlewareName=traefik-internal-recovery middlewareType=Recovery
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" middlewareType=Pipelining serviceName=reverse-proxy-traefik entryPointName=websecure routerName=websecure-api@docker middlewareName=pipelining
time="2022-07-14T15:12:29Z" level=debug msg="Creating load-balancer" serviceName=reverse-proxy-traefik entryPointName=websecure routerName=websecure-api@docker
time="2022-07-14T15:12:29Z" level=debug msg="Creating server 0 http://172.19.0.3:80" entryPointName=websecure routerName=websecure-api@docker serviceName=reverse-proxy-traefik serverName=0
time="2022-07-14T15:12:29Z" level=debug msg="child http://172.19.0.3:80 now UP"
time="2022-07-14T15:12:29Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware reverse-proxy-traefik" entryPointName=websecure routerName=websecure-api@docker middlewareName=tracing middlewareType=TracingForwarder
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" serviceName=whoami-traefik middlewareName=pipelining middlewareType=Pipelining entryPointName=websecure routerName=websecure-whoami@docker
time="2022-07-14T15:12:29Z" level=debug msg="Creating load-balancer" routerName=websecure-whoami@docker serviceName=whoami-traefik entryPointName=websecure
time="2022-07-14T15:12:29Z" level=debug msg="Creating server 0 http://172.19.0.2:80" serviceName=whoami-traefik serverName=0 entryPointName=websecure routerName=websecure-whoami@docker
time="2022-07-14T15:12:29Z" level=debug msg="child http://172.19.0.2:80 now UP"
time="2022-07-14T15:12:29Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:12:29Z" level=debug msg="Added outgoing tracing middleware whoami-traefik" routerName=websecure-whoami@docker middlewareName=tracing middlewareType=TracingForwarder entryPointName=websecure
time="2022-07-14T15:12:29Z" level=debug msg="Creating middleware" entryPointName=websecure middlewareName=traefik-internal-recovery middlewareType=Recovery
time="2022-07-14T15:12:29Z" level=debug msg="Adding route for reverse-proxy-traefik with TLS options default" entryPointName=web
time="2022-07-14T15:12:29Z" level=debug msg="Adding route for reverse-proxy-traefik with TLS options default" entryPointName=websecure
time="2022-07-14T15:12:29Z" level=debug msg="Adding route for whoami.docker.localhost with TLS options default" entryPointName=websecure
time="2022-07-14T15:12:29Z" level=error msg="the router websecure-whoami@docker uses a non-existent resolver: leresolver"
time="2022-07-14T15:12:29Z" level=error msg="the router api@docker uses a non-existent resolver: DefaultAcmeResolver"
time="2022-07-14T15:12:29Z" level=error msg="the router websecure-api@docker uses a non-existent resolver: DefaultAcmeResolver"
time="2022-07-14T15:13:20Z" level=info msg="I have to go..."
time="2022-07-14T15:13:20Z" level=info msg="Stopping server gracefully"
time="2022-07-14T15:13:20Z" level=debug msg="Waiting 10s seconds before killing connections." entryPointName=websecure
time="2022-07-14T15:13:20Z" level=debug msg="Waiting 10s seconds before killing connections." entryPointName=traefik
time="2022-07-14T15:13:20Z" level=debug msg="Waiting 10s seconds before killing connections." entryPointName=web
time="2022-07-14T15:13:20Z" level=error msg="accept tcp [::]:8080: use of closed network connection" entryPointName=traefik
time="2022-07-14T15:13:20Z" level=error msg="accept tcp [::]:443: use of closed network connection" entryPointName=websecure
time="2022-07-14T15:13:20Z" level=error msg="accept tcp [::]:80: use of closed network connection" entryPointName=web
time="2022-07-14T15:13:20Z" level=error msg="close tcp [::]:8080: use of closed network connection" entryPointName=traefik
time="2022-07-14T15:13:20Z" level=error msg="close tcp [::]:443: use of closed network connection" entryPointName=websecure
time="2022-07-14T15:13:20Z" level=debug msg="Entry point traefik closed" entryPointName=traefik
time="2022-07-14T15:13:20Z" level=error msg="close tcp [::]:80: use of closed network connection" entryPointName=web
time="2022-07-14T15:13:20Z" level=debug msg="Entry point websecure closed" entryPointName=websecure
time="2022-07-14T15:13:20Z" level=debug msg="Entry point web closed" entryPointName=web
time="2022-07-14T15:13:20Z" level=info msg="Server stopped"
time="2022-07-14T15:13:20Z" level=info msg="Shutting down"
time="2022-07-14T15:13:25Z" level=info msg="Traefik version 2.8.1 built on 2022-07-11T14:06:57Z"
time="2022-07-14T15:13:25Z" level=debug msg="Static configuration loaded {\"global\":{\"checkNewVersion\":true},\"serversTransport\":{\"maxIdleConnsPerHost\":200},\"entryPoints\":{\"traefik\":{\"address\":\":8080\",\"transport\":{\"lifeCycle\":{\"graceTimeOut\":\"10s\"},\"respondingTimeouts\":{\"idleTimeout\":\"3m0s\"}},\"forwardedHeaders\":{},\"http\":{},\"http2\":{\"maxConcurrentStreams\":250},\"udp\":{\"timeout\":\"3s\"}},\"web\":{\"address\":\":80\",\"transport\":{\"lifeCycle\":{\"graceTimeOut\":\"10s\"},\"respondingTimeouts\":{\"writeTimeout\":\"5s\",\"idleTimeout\":\"3m0s\"}},\"forwardedHeaders\":{},\"http\":{},\"http2\":{\"maxConcurrentStreams\":250},\"udp\":{\"timeout\":\"3s\"}},\"websecure\":{\"address\":\":443\",\"transport\":{\"lifeCycle\":{\"graceTimeOut\":\"10s\"},\"respondingTimeouts\":{\"writeTimeout\":\"5s\",\"idleTimeout\":\"3m0s\"}},\"forwardedHeaders\":{},\"http\":{\"tls\":{\"certResolver\":\"leresolver\"}},\"http2\":{\"maxConcurrentStreams\":250},\"udp\":{\"timeout\":\"3s\"}}},\"providers\":{\"providersThrottleDuration\":\"2s\",\"docker\":{\"watch\":true,\"endpoint\":\"unix:///var/run/docker.sock\",\"defaultRule\":\"Host(`{{ normalize .Name }}`)\",\"exposedByDefault\":true,\"swarmModeRefreshSeconds\":\"15s\"}},\"api\":{\"insecure\":true,\"dashboard\":true},\"log\":{\"level\":\"DEBUG\",\"filePath\":\"/log/traefik.log\",\"format\":\"common\"},\"accessLog\":{\"filePath\":\"/log/access.log\",\"format\":\"common\",\"filters\":{},\"fields\":{\"defaultMode\":\"keep\",\"headers\":{\"defaultMode\":\"drop\"}}},\"pilot\":{\"dashboard\":true}}"
time="2022-07-14T15:13:25Z" level=info msg="\nStats collection is disabled.\nHelp us improve Traefik by turning this feature on :)\nMore details on: https://doc.traefik.io/traefik/contributing/data-collection/\n"
time="2022-07-14T15:13:25Z" level=warning msg="Traefik Pilot is deprecated and will be removed soon. Please check our Blog for migration instructions later this year."
time="2022-07-14T15:13:25Z" level=info msg="Starting provider aggregator aggregator.ProviderAggregator"
time="2022-07-14T15:13:25Z" level=debug msg="Starting TCP Server" entryPointName=web
time="2022-07-14T15:13:25Z" level=debug msg="Starting TCP Server" entryPointName=traefik
time="2022-07-14T15:13:25Z" level=debug msg="Starting TCP Server" entryPointName=websecure
time="2022-07-14T15:13:25Z" level=info msg="Starting provider *traefik.Provider"
time="2022-07-14T15:13:25Z" level=debug msg="*traefik.Provider provider configuration: {}"
time="2022-07-14T15:13:25Z" level=info msg="Starting provider *docker.Provider"
time="2022-07-14T15:13:25Z" level=info msg="Starting provider *acme.ChallengeTLSALPN"
time="2022-07-14T15:13:25Z" level=debug msg="*acme.ChallengeTLSALPN provider configuration: {}"
time="2022-07-14T15:13:25Z" level=debug msg="*docker.Provider provider configuration: {\"watch\":true,\"endpoint\":\"unix:///var/run/docker.sock\",\"defaultRule\":\"Host(`{{ normalize .Name }}`)\",\"exposedByDefault\":true,\"swarmModeRefreshSeconds\":\"15s\"}"
time="2022-07-14T15:13:25Z" level=debug msg="Configuration received: {\"http\":{\"routers\":{\"api\":{\"entryPoints\":[\"traefik\"],\"service\":\"api@internal\",\"rule\":\"PathPrefix(`/api`)\",\"priority\":2147483646},\"dashboard\":{\"entryPoints\":[\"traefik\"],\"middlewares\":[\"dashboard_redirect@internal\",\"dashboard_stripprefix@internal\"],\"service\":\"dashboard@internal\",\"rule\":\"PathPrefix(`/`)\",\"priority\":2147483645}},\"services\":{\"api\":{},\"dashboard\":{},\"noop\":{}},\"middlewares\":{\"dashboard_redirect\":{\"redirectRegex\":{\"regex\":\"^(http:\\\\/\\\\/(\\\\[[\\\\w:.]+\\\\]|[\\\\w\\\\._-]+)(:\\\\d+)?)\\\\/$\",\"replacement\":\"${1}/dashboard/\",\"permanent\":true}},\"dashboard_stripprefix\":{\"stripPrefix\":{\"prefixes\":[\"/dashboard/\",\"/dashboard\"]}}},\"models\":{\"websecure\":{\"tls\":{\"certResolver\":\"leresolver\"}}},\"serversTransports\":{\"default\":{\"maxIdleConnsPerHost\":200}}},\"tcp\":{},\"udp\":{},\"tls\":{}}" providerName=internal
time="2022-07-14T15:13:25Z" level=debug msg="No default certificate, generating one" tlsStoreName=default
time="2022-07-14T15:13:25Z" level=debug msg="Provider connection established with docker 20.10.14 (API 1.41)" providerName=docker
time="2022-07-14T15:13:25Z" level=error msg="service \"elegant-wright\" error: port is missing" providerName=docker container=elegant-wright-b806c08e1e32ea1c7f39d82e5762dbb03631b55a039eac7bf025390fc89b6a58
time="2022-07-14T15:13:25Z" level=debug msg="Configuration received: {\"http\":{\"routers\":{\"api\":{\"service\":\"reverse-proxy-traefik\",\"rule\":\"Host(`reverse-proxy-traefik`)\",\"tls\":{\"certResolver\":\"DefaultAcmeResolver\"}},\"whoami\":{\"service\":\"whoami-traefik\",\"rule\":\"Host(`whoami.docker.localhost`)\"}},\"services\":{\"reverse-proxy-traefik\":{\"loadBalancer\":{\"servers\":[{\"url\":\"http://172.19.0.2:80\"}],\"passHostHeader\":true}},\"whoami-traefik\":{\"loadBalancer\":{\"servers\":[{\"url\":\"http://172.19.0.3:80\"}],\"passHostHeader\":true}}}},\"tcp\":{},\"udp\":{}}" providerName=docker
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware api@internal" middlewareName=tracing middlewareType=TracingForwarder routerName=api@internal entryPointName=traefik
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware dashboard@internal" entryPointName=traefik routerName=dashboard@internal middlewareName=tracing middlewareType=TracingForwarder
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareType=StripPrefix entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_stripprefix@internal
time="2022-07-14T15:13:26Z" level=debug msg="Adding tracing to middleware" entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_stripprefix@internal
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" routerName=dashboard@internal middlewareName=dashboard_redirect@internal middlewareType=RedirectRegex entryPointName=traefik
time="2022-07-14T15:13:26Z" level=debug msg="Setting up redirection from ^(http:\\/\\/(\\[[\\w:.]+\\]|[\\w\\._-]+)(:\\d+)?)\\/$ to ${1}/dashboard/" routerName=dashboard@internal middlewareName=dashboard_redirect@internal middlewareType=RedirectRegex entryPointName=traefik
time="2022-07-14T15:13:26Z" level=debug msg="Adding tracing to middleware" entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_redirect@internal
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareType=Recovery middlewareName=traefik-internal-recovery entryPointName=traefik
time="2022-07-14T15:13:26Z" level=debug msg="No entryPoint defined for this router, using the default one(s) instead: [web websecure]" routerName=whoami
time="2022-07-14T15:13:26Z" level=debug msg="No entryPoint defined for this router, using the default one(s) instead: [web websecure]" routerName=api
time="2022-07-14T15:13:26Z" level=debug msg="No default certificate, generating one" tlsStoreName=default
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware api@internal" routerName=api@internal entryPointName=traefik middlewareName=tracing middlewareType=TracingForwarder
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware dashboard@internal" routerName=dashboard@internal entryPointName=traefik middlewareName=tracing middlewareType=TracingForwarder
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareName=dashboard_stripprefix@internal middlewareType=StripPrefix entryPointName=traefik routerName=dashboard@internal
time="2022-07-14T15:13:26Z" level=debug msg="Adding tracing to middleware" routerName=dashboard@internal entryPointName=traefik middlewareName=dashboard_stripprefix@internal
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareName=dashboard_redirect@internal middlewareType=RedirectRegex entryPointName=traefik routerName=dashboard@internal
time="2022-07-14T15:13:26Z" level=debug msg="Setting up redirection from ^(http:\\/\\/(\\[[\\w:.]+\\]|[\\w\\._-]+)(:\\d+)?)\\/$ to ${1}/dashboard/" middlewareType=RedirectRegex entryPointName=traefik routerName=dashboard@internal middlewareName=dashboard_redirect@internal
time="2022-07-14T15:13:26Z" level=debug msg="Adding tracing to middleware" middlewareName=dashboard_redirect@internal entryPointName=traefik routerName=dashboard@internal
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareType=Recovery entryPointName=traefik middlewareName=traefik-internal-recovery
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" serviceName=whoami-traefik middlewareName=pipelining middlewareType=Pipelining entryPointName=web routerName=whoami@docker
time="2022-07-14T15:13:26Z" level=debug msg="Creating load-balancer" entryPointName=web routerName=whoami@docker serviceName=whoami-traefik
time="2022-07-14T15:13:26Z" level=debug msg="Creating server 0 http://172.19.0.3:80" serviceName=whoami-traefik serverName=0 entryPointName=web routerName=whoami@docker
time="2022-07-14T15:13:26Z" level=debug msg="child http://172.19.0.3:80 now UP"
time="2022-07-14T15:13:26Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware whoami-traefik" middlewareType=TracingForwarder entryPointName=web routerName=whoami@docker middlewareName=tracing
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" entryPointName=web middlewareName=traefik-internal-recovery middlewareType=Recovery
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" entryPointName=web middlewareName=pipelining middlewareType=Pipelining serviceName=reverse-proxy-traefik routerName=api@docker
time="2022-07-14T15:13:26Z" level=debug msg="Creating load-balancer" entryPointName=web serviceName=reverse-proxy-traefik routerName=api@docker
time="2022-07-14T15:13:26Z" level=debug msg="Creating server 0 http://172.19.0.2:80" entryPointName=web serviceName=reverse-proxy-traefik serverName=0 routerName=api@docker
time="2022-07-14T15:13:26Z" level=debug msg="child http://172.19.0.2:80 now UP"
time="2022-07-14T15:13:26Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware reverse-proxy-traefik" middlewareName=tracing middlewareType=TracingForwarder entryPointName=web routerName=api@docker
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" entryPointName=web middlewareName=traefik-internal-recovery middlewareType=Recovery
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareName=pipelining middlewareType=Pipelining routerName=websecure-api@docker entryPointName=websecure serviceName=reverse-proxy-traefik
time="2022-07-14T15:13:26Z" level=debug msg="Creating load-balancer" serviceName=reverse-proxy-traefik routerName=websecure-api@docker entryPointName=websecure
time="2022-07-14T15:13:26Z" level=debug msg="Creating server 0 http://172.19.0.2:80" routerName=websecure-api@docker serverName=0 entryPointName=websecure serviceName=reverse-proxy-traefik
time="2022-07-14T15:13:26Z" level=debug msg="child http://172.19.0.2:80 now UP"
time="2022-07-14T15:13:26Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware reverse-proxy-traefik" middlewareType=TracingForwarder entryPointName=websecure routerName=websecure-api@docker middlewareName=tracing
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" middlewareName=pipelining middlewareType=Pipelining entryPointName=websecure routerName=websecure-whoami@docker serviceName=whoami-traefik
time="2022-07-14T15:13:26Z" level=debug msg="Creating load-balancer" serviceName=whoami-traefik entryPointName=websecure routerName=websecure-whoami@docker
time="2022-07-14T15:13:26Z" level=debug msg="Creating server 0 http://172.19.0.3:80" serviceName=whoami-traefik serverName=0 entryPointName=websecure routerName=websecure-whoami@docker
time="2022-07-14T15:13:26Z" level=debug msg="child http://172.19.0.3:80 now UP"
time="2022-07-14T15:13:26Z" level=debug msg="Propagating new UP status"
time="2022-07-14T15:13:26Z" level=debug msg="Added outgoing tracing middleware whoami-traefik" middlewareName=tracing middlewareType=TracingForwarder entryPointName=websecure routerName=websecure-whoami@docker
time="2022-07-14T15:13:26Z" level=debug msg="Creating middleware" entryPointName=websecure middlewareName=traefik-internal-recovery middlewareType=Recovery
time="2022-07-14T15:13:26Z" level=debug msg="Adding route for reverse-proxy-traefik with TLS options default" entryPointName=web
time="2022-07-14T15:13:26Z" level=debug msg="Adding route for reverse-proxy-traefik with TLS options default" entryPointName=websecure
time="2022-07-14T15:13:26Z" level=debug msg="Adding route for whoami.docker.localhost with TLS options default" entryPointName=websecure
time="2022-07-14T15:13:26Z" level=error msg="the router websecure-whoami@docker uses a non-existent resolver: leresolver"
time="2022-07-14T15:13:26Z" level=error msg="the router api@docker uses a non-existent resolver: DefaultAcmeResolver"
time="2022-07-14T15:13:26Z" level=error msg="the router websecure-api@docker uses a non-existent resolver: DefaultAcmeResolver"
time="2022-07-14T15:18:53Z" level=debug msg="Serving default certificate for request: \"\""
time="2022-07-14T15:18:53Z" level=debug msg="vulcand/oxy/roundrobin/rr: begin ServeHttp on request" Request="{\"Method\":\"GET\",\"URL\":{\"Scheme\":\"\",\"Opaque\":\"\",\"User\":null,\"Host\":\"\",\"Path\":\"/\",\"RawPath\":\"\",\"ForceQuery\":false,\"RawQuery\":\"wait=7s\",\"Fragment\":\"\",\"RawFragment\":\"\"},\"Proto\":\"HTTP/1.1\",\"ProtoMajor\":1,\"ProtoMinor\":1,\"Header\":{\"Accept\":[\"*/*\"],\"User-Agent\":[\"curl/7.74.0\"],\"X-Forwarded-Host\":[\"whoami.docker.localhost\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"d344518d8b16\"],\"X-Real-Ip\":[\"172.19.0.1\"]},\"ContentLength\":0,\"TransferEncoding\":null,\"Host\":\"whoami.docker.localhost\",\"Form\":null,\"PostForm\":null,\"MultipartForm\":null,\"Trailer\":null,\"RemoteAddr\":\"172.19.0.1:34666\",\"RequestURI\":\"/?wait=7s\",\"TLS\":null}"
time="2022-07-14T15:18:53Z" level=debug msg="vulcand/oxy/roundrobin/rr: Forwarding this request to URL" ForwardURL="http://172.19.0.3:80" Request="{\"Method\":\"GET\",\"URL\":{\"Scheme\":\"\",\"Opaque\":\"\",\"User\":null,\"Host\":\"\",\"Path\":\"/\",\"RawPath\":\"\",\"ForceQuery\":false,\"RawQuery\":\"wait=7s\",\"Fragment\":\"\",\"RawFragment\":\"\"},\"Proto\":\"HTTP/1.1\",\"ProtoMajor\":1,\"ProtoMinor\":1,\"Header\":{\"Accept\":[\"*/*\"],\"User-Agent\":[\"curl/7.74.0\"],\"X-Forwarded-Host\":[\"whoami.docker.localhost\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"d344518d8b16\"],\"X-Real-Ip\":[\"172.19.0.1\"]},\"ContentLength\":0,\"TransferEncoding\":null,\"Host\":\"whoami.docker.localhost\",\"Form\":null,\"PostForm\":null,\"MultipartForm\":null,\"Trailer\":null,\"RemoteAddr\":\"172.19.0.1:34666\",\"RequestURI\":\"/?wait=7s\",\"TLS\":null}"
time="2022-07-14T15:19:00Z" level=debug msg="vulcand/oxy/roundrobin/rr: completed ServeHttp on request" Request="{\"Method\":\"GET\",\"URL\":{\"Scheme\":\"\",\"Opaque\":\"\",\"User\":null,\"Host\":\"\",\"Path\":\"/\",\"RawPath\":\"\",\"ForceQuery\":false,\"RawQuery\":\"wait=7s\",\"Fragment\":\"\",\"RawFragment\":\"\"},\"Proto\":\"HTTP/1.1\",\"ProtoMajor\":1,\"ProtoMinor\":1,\"Header\":{\"Accept\":[\"*/*\"],\"User-Agent\":[\"curl/7.74.0\"],\"X-Forwarded-Host\":[\"whoami.docker.localhost\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"d344518d8b16\"],\"X-Real-Ip\":[\"172.19.0.1\"]},\"ContentLength\":0,\"TransferEncoding\":null,\"Host\":\"whoami.docker.localhost\",\"Form\":null,\"PostForm\":null,\"MultipartForm\":null,\"Trailer\":null,\"RemoteAddr\":\"172.19.0.1:34666\",\"RequestURI\":\"/?wait=7s\",\"TLS\":null}"
time="2022-07-14T15:21:13Z" level=debug msg="Serving default certificate for request: \"\""
time="2022-07-14T15:21:13Z" level=debug msg="vulcand/oxy/roundrobin/rr: begin ServeHttp on request" Request="{\"Method\":\"GET\",\"URL\":{\"Scheme\":\"\",\"Opaque\":\"\",\"User\":null,\"Host\":\"\",\"Path\":\"/\",\"RawPath\":\"\",\"ForceQuery\":false,\"RawQuery\":\"wait=7s\",\"Fragment\":\"\",\"RawFragment\":\"\"},\"Proto\":\"HTTP/2.0\",\"ProtoMajor\":2,\"ProtoMinor\":0,\"Header\":{\"Accept\":[\"*/*\"],\"User-Agent\":[\"curl/7.74.0\"],\"X-Forwarded-Host\":[\"whoami.docker.localhost\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"d344518d8b16\"],\"X-Real-Ip\":[\"172.19.0.1\"]},\"ContentLength\":0,\"TransferEncoding\":null,\"Host\":\"whoami.docker.localhost\",\"Form\":null,\"PostForm\":null,\"MultipartForm\":null,\"Trailer\":null,\"RemoteAddr\":\"172.19.0.1:34672\",\"RequestURI\":\"/?wait=7s\",\"TLS\":null}"
time="2022-07-14T15:21:13Z" level=debug msg="vulcand/oxy/roundrobin/rr: Forwarding this request to URL" Request="{\"Method\":\"GET\",\"URL\":{\"Scheme\":\"\",\"Opaque\":\"\",\"User\":null,\"Host\":\"\",\"Path\":\"/\",\"RawPath\":\"\",\"ForceQuery\":false,\"RawQuery\":\"wait=7s\",\"Fragment\":\"\",\"RawFragment\":\"\"},\"Proto\":\"HTTP/2.0\",\"ProtoMajor\":2,\"ProtoMinor\":0,\"Header\":{\"Accept\":[\"*/*\"],\"User-Agent\":[\"curl/7.74.0\"],\"X-Forwarded-Host\":[\"whoami.docker.localhost\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"d344518d8b16\"],\"X-Real-Ip\":[\"172.19.0.1\"]},\"ContentLength\":0,\"TransferEncoding\":null,\"Host\":\"whoami.docker.localhost\",\"Form\":null,\"PostForm\":null,\"MultipartForm\":null,\"Trailer\":null,\"RemoteAddr\":\"172.19.0.1:34672\",\"RequestURI\":\"/?wait=7s\",\"TLS\":null}" ForwardURL="http://172.19.0.3:80"
time="2022-07-14T15:21:18Z" level=debug msg="'499 Client Closed Request' caused by: context canceled"
time="2022-07-14T15:21:18Z" level=debug msg="vulcand/oxy/roundrobin/rr: completed ServeHttp on request" Request="{\"Method\":\"GET\",\"URL\":{\"Scheme\":\"\",\"Opaque\":\"\",\"User\":null,\"Host\":\"\",\"Path\":\"/\",\"RawPath\":\"\",\"ForceQuery\":false,\"RawQuery\":\"wait=7s\",\"Fragment\":\"\",\"RawFragment\":\"\"},\"Proto\":\"HTTP/2.0\",\"ProtoMajor\":2,\"ProtoMinor\":0,\"Header\":{\"Accept\":[\"*/*\"],\"User-Agent\":[\"curl/7.74.0\"],\"X-Forwarded-Host\":[\"whoami.docker.localhost\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"d344518d8b16\"],\"X-Real-Ip\":[\"172.19.0.1\"]},\"ContentLength\":0,\"TransferEncoding\":null,\"Host\":\"whoami.docker.localhost\",\"Form\":null,\"PostForm\":null,\"MultipartForm\":null,\"Trailer\":null,\"RemoteAddr\":\"172.19.0.1:34672\",\"RequestURI\":\"/?wait=7s\",\"TLS\":null}"
ringgelerch@NB6789:~/traefik$

ringgelerch avatar Jul 14 '22 15:07 ringgelerch

Hi @ringgelerch , there might be some confusion here on what timeouts should be configured to match your expectations, or maybe I misread or missed something, let me know then :)

From the request description and the app (whoami) compose file configuration it seems you expect to timeout for requests that don't receive a response for more than 5s, but from the timeout configuration on the transport for Traefik it says "timeout if the response write takes more than 5s".

Maybe what your looking for is to tweak on the service forwarding timeouts instead?

ddtmachado avatar Jul 14 '22 20:07 ddtmachado

Hi @ddtmachado, thank you for the fast response 😃

What I was looking for is a timeout to limit the duration when the traefik receives the request from a client until the response is written to the client. If I understand the documentation correctly, the writeTimeout should be the right choice.

writeTimeout is the maximum duration before timing out writes of the response.

It covers the time from the end of the request header read to the end of the response write. If zero, no timeout exists.

Please correct me if I get something wrong.

Maybe this diagram helps to understand what I mean:

image

I have postponed the whoami's response to indirectly delay the traefik's response to the client.

ringgelerch avatar Jul 15 '22 05:07 ringgelerch

Timeouts can be so confusing as we need to take into account both Client to Traefik and Traefik to Backend as well illustrated in your diagram, thanks for that.

The responding timeouts configuration are pertinent only from Traefik to the Client (green), but the problem here is that Traefik didn't receive an answer from the backend before the timeout expired (red), plus there is no timeout configuration from Traefik to the backend that would be configured with the forwarding timeouts as a linked.

timeouts

Having said that I'm keeping it as a bug possible for further investigation because I believe it's wrong that in both cases, HTTP1.1 and HTTP2, the error that is thrown is not a timeout anyway and of course the fact it behaves differently between them.

ddtmachado avatar Jul 15 '22 13:07 ddtmachado

Sorry but I think I still don't get it completely.

This is written in the docs:

It covers the time from the end of the request header read to the end of the response write. If zero, no timeout exists.

"the end of the request header read" -> I understood that this are the request headers of the request from the client to the Traefik. "the end of the response write" -> I think this is pretty clear. This is the green Response (Traefik to Client) from the upper diagram.

What I don't understand why it's a problem that Traefik didn't receive an answer from the backend before the timeout expired. Maybe you can provide more details on that one. I thought this is the main scenario for which the writeTimeout is useful. The behavior should also be independent if there are no additional forwarding timeouts configured.

ringgelerch avatar Jul 15 '22 14:07 ringgelerch

It shouldn't be a problem, that's why I'm keeping it for investigation, because you've shown a 499 is returned which seems wrong even if the timeout value was respected (for the http2 case).

The complexity lies in the fact Traefik opens a separate connection to the backend, which means the client -> Traefik connection timed out while Traefik was still waiting for the response on the other connection to the backend. That connection had no timeout value, so it was still fine and just waiting but since the client connection timed out we should have returned a timeout 408 instead of a context propagation error. So for me there might be an issue regardless of the use of HTTP1.1 or HTTP/2.

ddtmachado avatar Jul 15 '22 16:07 ddtmachado

Now I understand what you meant. Thank you for the explanation.

I hope there will be a solution soon. It would be a great help for me.

I wish you a good start to the new week 😄.

ringgelerch avatar Jul 18 '22 07:07 ringgelerch

Hello @ringgelerch,

We tried to reproduce the issue step by step (in HTTP1.1) and we did see that the timeouts work as expected, that is to say, the client did receive a 200 when the response time did not exceed the timeout option. Whereas the client errored with an empty response when the response time did exceed the timeout option.

But we did see that the status in the access logs for HTTP1.1 requests is indeed always 200, even though the request has failed because of the timeout configuration, which does not reflect what is actually happening.

Therefore we are going to investigate the access log aspect, but we think that the timeout option works as expected. WDYT?

rtribotte avatar Jul 18 '22 13:07 rtribotte

Thank you. @rtribotte you probably mean:

"we did see that the timeouts work as expected, that is to say, the client did receive a 200 when the response time did not exceed the timeout option. Whereas the client errored with an empty response when the response time did exceed the timeout option."

In this case, good to know that its aparently only a logging issue. We will investigate with some network trace (in the more complicated real scenario) as well.

henningw avatar Jul 18 '22 18:07 henningw

Indeed, thanks. I edited the message for future readers.

Thank you. @rtribotte you probably mean:

"we did see that the timeouts work as expected, that is to say, the client did receive a 200 when the response time did not exceed the timeout option. Whereas the client errored with an empty response when the response time did exceed the timeout option."

In this case, good to know that its aparently only a logging issue. We will investigate with some network trace (in the more complicated real scenario) as well.

mpl avatar Jul 19 '22 08:07 mpl

Some info for those interested.

We investigated a bit more, and it turns out there is indeed a difference in behaviour between HTTP/1.1 and HTTP/2, even though at the end of the day, the goal is achieved (i.e. no response is sent to the client in both cases).

To make things short, in HTTP/1.1 , there's a deadline set on the connection, but it ultimately does not lead in a context cancellation as far as the connection between traefik and the backend is concerned, so there is no RoundTrip error on that side. Which is why we see a 200 in the access logs in that scenario.

In HTTP/2, the aforementioned deadline is actually reset (to avoid messing up the concurrent streams), and there's instead a hook on a timer (see onWriteTimeout in x/net/http2/server.go , which is in charge of sending an error in a frame, which does lead to a cancellation of the RoundTrip, and therefore to the 499 error being surfaced and written to the access logs.

We're not quite sure where we'll go with that information, but that's where we're at right now.

mpl avatar Jul 21 '22 14:07 mpl

Update1: the problem is more serious than we initially thought. We were fooled by the fact that the client does not receive a reply (because the connection has been closed), which made us think that things kinda worked. But it's worse than that: not only is the access log arguably a bit useless (because it gives a 200), but also the client only sees the connection being closed after however long it took for the backend to reply. In other words, with the OP's example, with HTTP/1.1 curl will only return the prompt after 7s, whereas with HTTP/2 it will be 5s (as expected). So yes, in this particular case, the responsiveness goal of using a WriteTimeout is completely defeated, so it basically does not work. Please note that we still think the root cause is within the stdlib.

Update2: it is interesting to note that there's a second class of scenario, where WriteTimeout is appropriate and where it actually works. Imagine that your backend, instead of being a whoami that waits for 8s and then replies, is a server that starts replying immediately but takes a long time to actually finish answering (maybe lots of data, maybe latency, etc). In that scenario, we notice that (even in HTTP/1.1) the connection is indeed interrupted at 2s for the client, which only gets a partial answer. And it also kinda makes sense in that scenario that we see a 200 in the access log, as the client did receive a reply albeit incomplete.

mpl avatar Jul 28 '22 09:07 mpl

Update: since we haven't had time to work more on this, and there have been quite some changes in the meantime, I have double-checked and as of now, both traefik v2 and v3 are still affected.

mpl avatar Apr 06 '23 13:04 mpl