fabio icon indicating copy to clipboard operation
fabio copied to clipboard

Published 20 hours ago • verified publisher icon fabiolb

Sporadic 502 errors in Fabio logs

Open echo-xu opened this issue 5 years ago • 9 comments

Hi,

We are seeing sporadic 502 errors in Fabio logs, and we see 2 kinds of error messages that match the 502 occurrences:

$ grep 'proxy error' fabio.stderr.5
invalid log msg: 2019/10/26 02:22:34 http: proxy error: read tcp IP:33374->IP:24218: read: connection reset by peer
invalid log msg: 2019/10/26 14:10:12 http: proxy error: EOF

IP1 - IP2:Port - [27/Oct/2019:01:53:48 +0000] "POST /some_api HTTP/1.1" 502 0 0.017

I don't see anything abnormal in our API service that could contribute to the 502 response - and from the logs we found the failed request did not reach the API, so I think maybe Fabio is going wrong somewhere, any ideas to troubleshoot this kind of issue in Fabio? Thanks.

echo-xu avatar Oct 28 '19 19:10 echo-xu

might be related to https://github.com/fabiolb/fabio/issues/336

echo-xu avatar Nov 13 '19 21:11 echo-xu

Hi @echo-xu, were you able to resolve this?

ansrivas avatar Nov 18 '19 09:11 ansrivas

@ansrivas Not yet. I assume this is a Fabio issue.

echo-xu avatar Dec 02 '19 19:12 echo-xu

Having this same issue on 1.5.11 and 1.5.13. Just random 502s in load test, like .8-1.5% of traffic. If I hit the app container directly, no errors. If I test with haproxy in front of the container (just as a sort of side by side test), no errors either.

Mar 26 13:16:20 server01 fabio: 192.168.1.92:37952 - - [26/Mar/2020:18:16:20 +0000] "POST /testapp HTTP/1.1" 200 1319 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37868 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 200 1259 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: invalid log msg: 2020/03/26 18:16:21 http: proxy error: EOF
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37954 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 502 0 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37944 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 200 1314 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37938 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 200 1278 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37864 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 200 1313 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37876 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 200 1323 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:21 server01 fabio: 192.168.1.92:37872 - - [26/Mar/2020:18:16:21 +0000] "POST /testapp HTTP/1.1" 200 1284 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:22 server01 fabio: 192.168.1.92:37862 - - [26/Mar/2020:18:16:22 +0000] "POST /testapp HTTP/1.1" 200 1274 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:22 server01 fabio: 192.168.1.92:37948 - - [26/Mar/2020:18:16:22 +0000] "POST /testapp HTTP/1.1" 200 1249 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:22 server01 fabio: 192.168.1.92:37858 - - [26/Mar/2020:18:16:22 +0000] "POST /testapp HTTP/1.1" 200 1284 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:22 server01 fabio: invalid log msg: 2020/03/26 18:16:22 http: proxy error: EOF
Mar 26 13:16:22 server01 fabio: 192.168.1.92:37896 - - [26/Mar/2020:18:16:22 +0000] "POST /testapp HTTP/1.1" 502 0 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:22 server01 fabio: 192.168.1.92:37940 - - [26/Mar/2020:18:16:22 +0000] "POST /testapp HTTP/1.1" 200 1323 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"
Mar 26 13:16:22 server01 fabio: 192.168.1.92:37926 - - [26/Mar/2020:18:16:22 +0000] "POST /testapp HTTP/1.1" 200 1285 "" "python-requests/2.22.0" "" "192.168.1.15:24675" "testapp"

codyja avatar Mar 26 '20 21:03 codyja

I took a packet capture between fabio and the backend container. When the 502 happens, fabio sends a SYN to the backend, the backend responds with a SYN ACK, and then fabio responds with a RST and closes the connection. Wanted to see if @leprechau had any ideas on this one. Thanks!

image

codyja avatar Mar 27 '20 14:03 codyja

I wanted to circle back here and say that our intermittent 502s were actually app problems with the backends that fabio was routing to. In more packet captures, we realized that fabio was trying to send more connections to ports that the app was trying to shutdown. We then realized that the app was sending back an invalid http header (connection: Closed, versus connection: close). Once we fixed that, we stopped seeing our particular issue.

codyja avatar Apr 08 '20 21:04 codyja

I wanted to circle back here and say that our intermittent 502s were actually app problems with the backends that fabio was routing to. In more packet captures, we realized that fabio was trying to send more connections to ports that the app was trying to shutdown. We then realized that the app was sending back an invalid http header (connection: Closed, versus connection: close). Once we fixed that, we stopped seeing our particular issue.

@codyja Hey, we are seeing the same issue on our Node app behind Fabio. Could you please provide more details about how you fix this in your app? Which REST framework are you using and how did you correct the invalid http header return by your APP? As far as I know, the http header returned by my APP seems default by the framework I use. I'm not sure if and how to change that.

zelong430 avatar Jun 01 '20 16:06 zelong430

While I see a number of issues with the "context cancelled" log message, in our case, we also see 502's without those. For example, here are logs from 2 requests spaced minutes apart:

invalid log msg: 2022/04/25 15:07:41 http: proxy error: context canceled
invalid log msg: 2022/04/25 15:13:54 http: proxy error: EOF

For the second request, is that saying the remote backend failed or what should I determine based on these logs?

We see <1% of all requests thru fabio end with 502, but it's consistent and I'm not sure if it's fabio or the backend.

ketzacoatl avatar Apr 25 '22 15:04 ketzacoatl

fwiw: we chased down our 502's internally and it ended up just being about shutdown timing during redeploys. This tweet is a tidy summary of our solution: https://twitter.com/ProgrammerDude/status/1660238268863066114

maxmcd avatar Jun 13 '23 14:06 maxmcd