Caddy: context canceled and 502

Created on 17 Oct 2017 · 16Comments · Source: caddyserver/caddy

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

0.10.10

2. What are you trying to do?

Proxy an express app.

Seems like caddy responds with 502 and complains when I write the request and close the socket for writing. I'm still available for reading, so caddy should send me the proper response.

Note that request gets proxied just fine (I can see in webapp's logs). If I enter request in nc manually without closing the stdin then I get the right response.

3. What is your entire Caddyfile?

localhost:80
tls off
log stdout
errors stderr
proxy /media imageserver
proxy /api server:3200 {
    keepalive 0
}

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

Docker, abiosoft/caddy image.

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

➜  ~  cat request.txt 
POST /api/graphql HTTP/1.1
Host: localhost:3200
Content-Length: 132
Content-type: application/json
Authorization: Bearer R+VNcynE/pbt5lVgLVGlFVhxQpj5DOjs4dNPWqeGHFGPz41XdD7RFQjbrYDoPesA

{"operationName":"currentUser","variables":{},"query":"query currentUser {\n  viewer {\n    id\n    name\n    __typename\n  }\n}\n"}

➜  ~  nc localhost 3200 < request.txt
HTTP/1.1 502 Bad Gateway
Content-Type: text/plain; charset=utf-8
Server: Caddy
X-Content-Type-Options: nosniff
Date: Tue, 17 Oct 2017 21:06:29 GMT
Content-Length: 16

502 Bad Gateway

6. What did you expect to see?

A proper JSON response.

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

gateway_1     | 172.18.0.1 - - [17/Oct/2017:21:04:30 +0000] "POST /api/graphql HTTP/1.1" 502 16
gateway_1     | 17/Oct/2017:21:04:30 +0000 [ERROR 502 /api/graphql] context canceled

bug

Source

rafales

👍7

Most helpful comment

This can also be forced upon caddy via browser requests. Imagine a backend serving this simple php at localhost:8081 :

<?php
sleep(10);
phpinfo();
?>

And a simple Caddyfile like this:

:8080 {
        log / stdout "{host} {combined} {request_id}"
        errors stderr

        proxy / localhost:8081 {
                transparent
                policy least_conn
                keepalive 5
                fail_timeout 10s
                max_fails 1
                try_duration 1s
        }
}

Point your browser to http://localhost:8080 and wait for the phpinfo to be displayed - works.
Press F5 and while it's loading the ESC button -> you'll see [ERROR 502 /] context canceled message in the log.
Press F5 again within fail_timeout and you'll get 502 bad gateway and [ERROR 502 /] no hosts available upstream in the caddy log. This will persist until fail_timout has passed since the first fail. In the log of the backend (NGINX), I only get a HTTP 499.
2018-03-03T14:24:05+00:00 127.0.0.1 - - localhost/localhost "GET / HTTP/1.1" 499 4.048 374 0 29 1 "-" "-" "Mozilla/5.0 (X11; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
So it seems caddy is misinterpreting the client "error" for a backend error.

In my case I'm currently using a fail_timeout 0 as a workaround or else all my sites go down for fail_timeout.
@mholt This sounds pretty much exploitable for DDoS attacks, doesn't it?

Caddy Version: 0.10.11 (and build from git https://github.com/mholt/caddy/commit/5552dcbbc7f630ada7c7d030b37c2efdce750ace).

ionphractal on 3 Mar 2018

👍7

All 16 comments

Btw this is reproducible every time.

rafales on 17 Oct 2017

I think this is related to #1828 and https://caddy.community/t/error-context-canceled/2034

The request goes through to the backend, but the user gets a 502 Bad Gateway error.

ubergesundheit on 21 Oct 2017

This can also be forced upon caddy via browser requests. Imagine a backend serving this simple php at localhost:8081 :

<?php
sleep(10);
phpinfo();
?>

And a simple Caddyfile like this:

:8080 {
        log / stdout "{host} {combined} {request_id}"
        errors stderr

        proxy / localhost:8081 {
                transparent
                policy least_conn
                keepalive 5
                fail_timeout 10s
                max_fails 1
                try_duration 1s
        }
}

Point your browser to http://localhost:8080 and wait for the phpinfo to be displayed - works.
Press F5 and while it's loading the ESC button -> you'll see [ERROR 502 /] context canceled message in the log.
Press F5 again within fail_timeout and you'll get 502 bad gateway and [ERROR 502 /] no hosts available upstream in the caddy log. This will persist until fail_timout has passed since the first fail. In the log of the backend (NGINX), I only get a HTTP 499.
2018-03-03T14:24:05+00:00 127.0.0.1 - - localhost/localhost "GET / HTTP/1.1" 499 4.048 374 0 29 1 "-" "-" "Mozilla/5.0 (X11; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
So it seems caddy is misinterpreting the client "error" for a backend error.

In my case I'm currently using a fail_timeout 0 as a workaround or else all my sites go down for fail_timeout.
@mholt This sounds pretty much exploitable for DDoS attacks, doesn't it?

Caddy Version: 0.10.11 (and build from git https://github.com/mholt/caddy/commit/5552dcbbc7f630ada7c7d030b37c2efdce750ace).

ionphractal on 3 Mar 2018

👍7

Is this still an issue in 0.10.14?

tobya on 27 Apr 2018

@tobya Just tested it and unfortunately yes, it is still present.

$ ./caddy -version       
Caddy 0.10.14 (non-commercial use only)
$ ./caddy -conf Caddyfile
Activating privacy features... done.
http://:8080
WARNING: File descriptor limit 1024 is too low for production servers. At least 8192 is recommended. Fix with "ulimit -n 8192".
localhost:8080 ::1 - - [27/Apr/2018:12:51:49 +0200] "GET /test.php HTTP/1.1" 200 27868 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:59.0) Gecko/20100101 Firefox/59.0" 
27/Apr/2018:12:51:54 +0200 [ERROR 502 /test.php] context canceled
localhost:8080 ::1 - - [27/Apr/2018:12:51:54 +0200] "GET /test.php HTTP/1.1" 502 16 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:59.0) Gecko/20100101 Firefox/59.0" 
27/Apr/2018:12:51:55 +0200 [ERROR 502 /test.php] no hosts available upstream
localhost:8080 ::1 - - [27/Apr/2018:12:51:55 +0200] "GET /test.php HTTP/1.1" 502 16 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:59.0) Gecko/20100101 Firefox/59.0" 
27/Apr/2018:12:51:56 +0200 [ERROR 502 /test.php] no hosts available upstream

ionphractal on 27 Apr 2018

I'm having the same issue with Caddy 0.11.0.

corny on 11 May 2018

Having this issue too on 0.11.0

How can I solve or at least work around it?

Homer-Sim on 26 May 2018

We stumbled upon this bug as well. Are there any plans to fix it? It has a devastating potential as it can be exploited for a DDoS attack...

tomasdeml on 26 Jun 2018

@tomasdeml

It has a devastating potential as it can be exploited for a DDoS attack...

Do explain...

mholt on 26 Jun 2018

@mholt: It is enough that one evil client will repeatly make request and immediately close connection and caddy will stop proxing for defined fail_timeout time. Even if you set max_fails higher than 1, only one client could easily do cancel that many requests in row. so it is not even DDoS, but more severe DoS attack.

Bobris on 26 Jun 2018

👍2

Hmm, I see. Well, you could for now use fail_timeout of 0 if you're worried about attacks like that; but better would be to have this fixed. I don't have the time right now to do it, but I welcome pull requests, and help reviewing them to get them merged.

mholt on 26 Jun 2018

Setting fail_timeout to 0 will make load balancing proxy useless (it will forward requests to truely failed nodes, all the time), so it is not really option.

Bobris on 27 Jun 2018

I understand that. Feel free to open a pull request for quicker resolution!

mholt on 27 Jun 2018

I suggest tagging this issue as "Bug".

Was original issue fixed by #2297?

magikstm on 3 Feb 2019

Good point; yes, we seem to handle the context cancelled error specially now, so that it does not consider the backend to be down. I believe this is fixed.

mholt on 3 Feb 2019

I've been running into issues with Caddy 0.11.5 constantly stopping, and noticed a lot of these in my log files:

18/Apr/2019:22:44:46 -0500 [ERROR 499 /radarrdoc/signalr/connect] context canceled
18/Apr/2019:22:44:52 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled
18/Apr/2019:22:45:10 -0500 [ERROR 499 /sonarrdoc/signalr/poll] context canceled
18/Apr/2019:22:46:47 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled
18/Apr/2019:22:48:24 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled
18/Apr/2019:22:48:24 -0500 [ERROR 499 /lidarrdoc/signalr/abort] context canceled
18/Apr/2019:22:48:24 -0500 [ERROR 499 /sonarrdoc/signalr/poll] context canceled
18/Apr/2019:22:48:24 -0500 [ERROR 499 /radarrdoc/signalr/poll] context canceled
18/Apr/2019:22:49:56 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled
18/Apr/2019:22:51:44 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled
18/Apr/2019:22:57:44 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled
18/Apr/2019:22:58:07 -0500 [ERROR 499 /lidarrdoc/signalr/poll] context canceled

After a bunch of trial and error with the way I call PHP in my caddyfile it just keeps happening no matter how I call it, or what environment vars I use, which led me to stumbling upon this post. I tested with @ionphractal 's instructions and it seems to still be happening in this version of Caddy.

caddy
Activating privacy features... done.

Serving HTTP on port 8080
http://:8080

18/Apr/2019:23:10:33 -0500 [ERROR 502 /] dial tcp [::1]:8081: connectex: No connection could be made because the target machine actively refused it.
localhost:8080 ::1 - - [18/Apr/2019:23:10:33 -0500] "GET / HTTP/1.1" 502 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:34 -0500 [ERROR 502 /favicon.ico] no hosts available upstream
localhost:8080 ::1 - - [18/Apr/2019:23:10:34 -0500] "GET /favicon.ico HTTP/1.1" 502 16 "http://localhost:8080/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:36 -0500 [ERROR 502 /] no hosts available upstream
localhost:8080 ::1 - - [18/Apr/2019:23:10:36 -0500] "GET / HTTP/1.1" 502 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:39 -0500 [ERROR 502 /] no hosts available upstream
localhost:8080 ::1 - - [18/Apr/2019:23:10:39 -0500] "GET / HTTP/1.1" 502 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:40 -0500 [ERROR 502 /favicon.ico] no hosts available upstream
localhost:8080 ::1 - - [18/Apr/2019:23:10:40 -0500] "GET /favicon.ico HTTP/1.1" 502 16 "http://localhost:8080/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:41 -0500 [ERROR 502 /] no hosts available upstream
localhost:8080 ::1 - - [18/Apr/2019:23:10:41 -0500] "GET / HTTP/1.1" 502 16 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:43 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:43 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:45 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:45 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:47 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:47 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:49 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:49 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:51 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:51 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:53 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:53 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"
18/Apr/2019:23:10:56 -0500 [ERROR 499 /] context canceled
localhost:8080 ::1 - - [18/Apr/2019:23:10:56 -0500] "GET / HTTP/1.1" 499 5 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36"