[Proxy] 502 context canceled

[zaolin]

1. What version of Caddy are you using (caddy -version)?

0.16.0

2. What are you trying to do?

Caddy <-> Nginx <-> Phusion Passenger <-> Web application

Using caddy as transparent reverse proxy for nginx.

3. What is your entire Caddyfile?

www.domain.com {
  header / Strict-Transport-Security "max-age=31536000; includeSubDomains; preload"
    tls email@domain.com {
      max_certs 50
    }
  gzip
  redir {
    if {mitm} is true
    / https://mitm.domain.com
  }
  proxy / vm_domain_name:80 {
      transparent
  }
  errors /var/lib/caddy/domain-errors.log
  log /var/lib/caddy/domain-access.log
}

4. How did you run Caddy (give the full command and describe the execution environment)?

caddy -conf /etc/caddy/caddy.conf -agree -http2=false

5. Please paste any relevant HTTP request(s) here.

• Preparing request to https://www.domain.com/
• Enable automatic URL encoding
• Enable SSL validation
• Enable cookie sending with jar of 1 cookie
• Connection 0 seems to be dead!
• Closing connection 0
• Trying ...
• TCP_NODELAY set
• Connected to ... port 443 (adding support for php including clean urls and wordpress permalinks #1)
• mbedTLS: Connecting to www.domain.com:443
• mbedTLS: Set min SSL version to TLS 1.0
• mbedTLS: Handshake complete, cipher is TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384
• Dumping cert info:
• • cert. version : 3
• • serial number : 03:29:20:B3:2F:AA:78:89:02:B1:1B:66:39:8B:BB:9F:76:82
• • issuer name : C=US, O=Let's Encrypt, CN=Let's Encrypt Authority X3
• • subject name : CN=www.domain.com
• • issued on : 2017-08-15 01:32:00
• • expires on : 2017-11-13 01:32:00
• • signed using : RSA with SHA-256
• • RSA key size : 2048 bits
• • basic constraints : CA=false
• • subject alt name : www.domain.com
• • key usage : Digital Signature, Key Encipherment
• • ext key usage : TLS Web Server Authentication, TLS Web Client Authentication
• SSL connected

GET / HTTP/1.1
Host: www.domain.com
User-Agent: insomnia/5.5.2
Accept: /
Accept-Encoding: deflate, gzip
Cookie: domain-3_session=QlYxZFppU2hmR1VDbVhCL1BjSENBTU02V1cyRFJxUFhrWnJLMGEvODlaQ2ZHcWF0cEdtcXNDSFFPMWh4T0txRHd3SjRZV2xtRG9VbWJnUWl4dmllN1ZKa3Fxd3U3T2puT2hPcUZiWEZLUzJDSUFDT2pvYnpCUmFKVGM5UjlQYjc5OGhCV2RkRWxlUEtZdS9DR2g2M2VBPT0tLVVHTE1EZTR6cTM5aU1pVmpOaGc1d0E9PQ%3D%3D--68c716127c1ed309f23860dcfc409ad1f4e1a74b
Content-Type: application/json
PRIVATE-TOKEN: P8i-CJzZgokXisHQpk9
Content-Length: 0
< HTTP/1.1 200 OK
< Cache-Control: max-age=0, private, must-revalidate
< Content-Encoding: gzip
< Content-Type: text/html; charset=utf-8
< Date: Tue, 15 Aug 2017 15:58:30 GMT
< Etag: W/"6b254e60bfd19265757715b518b38e11"
< Server: Caddy
< Server: nginx/1.10.3 + Phusion Passenger 5.1.6

• Replaced cookie _domain-3_session="dDFjM2c2cUJZNjRIeHF6K05TRUd6NjAyZ3BycGRoczhwQWlCNHJXUzgxQ2RtOXV3RjI3empwdVlHMkZ6QXZWOEdZUThGbmh3UnJNR2pBME5MQnY3Vjc3UEtVUnMrbHhlOERjdmNCcFRSWExoYTU1ekxUUnZFdFU1VDR3bGJqZXVVbFhOQzlQbFNpVGJYbGFXN1JzczB3PT0tLWZNcWRoUnBkUzFKVmIvTzhxTGpBalE9PQ%3D%3D--154a10b7fedc901b56af64f0fb68576d7dee5ee3" for domain www.domain.com, path /, expire 0
  < Set-Cookie: _domain-3_session=dDFjM2c2cUJZNjRIeHF6K05TRUd6NjAyZ3BycGRoczhwQWlCNHJXUzgxQ2RtOXV3RjI3empwdVlHMkZ6QXZWOEdZUThGbmh3UnJNR2pBME5MQnY3Vjc3UEtVUnMrbHhlOERjdmNCcFRSWExoYTU1ekxUUnZFdFU1VDR3bGJqZXVVbFhOQzlQbFNpVGJYbGFXN1JzczB3PT0tLWZNcWRoUnBkUzFKVmIvTzhxTGpBalE9PQ%3D%3D--154a10b7fedc901b56af64f0fb68576d7dee5ee3; path=/; HttpOnly
  < Status: 200 OK
  < Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
  < Vary: Accept-Encoding
  < X-Content-Type-Options: nosniff
  < X-Frame-Options: SAMEORIGIN
  < X-Powered-By: Phusion Passenger 5.1.6
  < X-Request-Id: 27a2b427-3da1-4c62-9140-3e8e782c2b7e
  < X-Runtime: 1.357073
  < X-Xss-Protection: 1; mode=block
  < Transfer-Encoding: chunked

• Received 199 B chunk

• Received 2.2 KB chunk

• Received 528 B chunk

• Received 3.8 KB chunk

• Received 3.8 KB chunk

• Received 3.8 KB chunk

• Received 3.3 KB chunk

• Connection adding support for php including clean urls and wordpress permalinks #1 to host www.domain.com left intact

• Saved 1 cookie

6. What did you expect to see?

I am getting errors on the log but the web application seems to work.
But I am not sure we have 20 incoming connections per second and
the 502 error shows up sometimes.

7. What did you see instead (give full error messages and/or log)?

15/Aug/2017:18:30:03 +0200 [ERROR 502 /berufe/flugbegleiter/] context canceled
15/Aug/2017:18:30:15 +0200 [ERROR 502 /ajax/main_search/] context canceled
15/Aug/2017:18:30:27 +0200 [ERROR 502 /] context canceled

8. How can someone who is starting from scratch reproduce the bug as minimally as possible?

Maybe I can provide a test environment. But I need to check that option.

[mholt]

Thanks for the detailed report. That log message usually just means the client stopped loading the resource before it was finished. Generally nothing to worry about, especially if things are working. :) Let us know if there's anything else!

[zaolin]

Okay. Good to know. I was a little bit confused because it's logged as error message. Would be good to have client/server messages split in order to get a better understanding of what is going on.

[mholt]

Yeah, I agree, although it's hard to tell which kind of message it is unless I add special exceptions for the text of the error value - as far as I know. And the text string can probably change, so it's not a robust way of doing it.

[mholt]

@sporkmonger

We're seeing really significant volumes of 502s coming from our caddy proxy w/ a context canceled message in the logs. These are with non-browser clients (iOS/Android apps). I am seeing them every few seconds in our logs, from a large number of different IP addresses and client types, both browser and non-browser. I think there's a legit bug here.

Can you boil it down to a reproducible test case for us to verify and experiment with?

[sporkmonger]

I deleted the comment because a co-worker provided some additional information suggesting it's likely we're cancelling requests in some of the non-browser clients after all.

[sporkmonger]

There is a general sentiment, FWIW, that "502" doesn't seem quite right since it's a situation caused by the client. Basically, we think of 5xx as something caused by a problem inside the proxy or with something upstream. We think of 4xx as something that originates downstream. If the request was canceled, the client isn't really looking at the response anymore, but for logging purposes, something 4xx seems like it would be more informative.

[mholt]

Gotcha, that makes sense. Sorry, I got your comment in an email, which doesn't get deleted when a comment here is deleted. :P

We can look into changing the response status if we can determine that a context cancelled is what is happening.