Fabio 100% CPU usage due to logging

[scalp42]

Hi folks,

We have a simple Docker container deployed (kennethreitz/httpbin:latest) through Nomad with the urlprefix-/httpbin.

Fabio is listening on 9999 and trying to curl the httpbin service works as intended from Fabio host or anywhere:

root@fabio-i-0dec89141f864a92c [dev-usw2-dev1] ~ # curl fabio.service.consul:9999/httpbin/headers
{
  "headers": {
    "Accept": "*/*",
    "Accept-Encoding": "gzip",
    "Forwarded": "for=10.22.202.212; proto=http; by=10.22.202.212; httpproto=http/1.1",
    "Host": "fabio.service.consul:9999",
    "User-Agent": "curl/7.58.0",
    "X-Fabio-Id": "5612028f-0fb1-f2c3-18f8-682957232962",
    "X-Forwarded-Host": "fabio.service.consul:9999",
    "X-Forwarded-Prefix": "/httpbin"
  }
}

We have an Application Load Balancer (ALB) in front of it forwarding requests to Fabio:

Now, we have a CNAME record for www.example.com for the ALB public DNS:

dig www.example.com +short                                                                                                                                  
dev1-fabio-alb-public-1145129295.us-west-2.elb.amazonaws.com.
52.37.27.235
54.191.105.184
54.186.250.249
52.11.238.59

We would like to have www.example.com forward requests to the httpbin service through Fabio, so we set up a basic route in Consul KV:

route add www.example.com www.example.com http://fabio.service.consul:9999/httpbin opts "strip=/httpbin"

We can see the route added to the logs in Fabio as expected:

Jul 12 21:17:12 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: # --- fabio/dev-usw2-dev1/httpbin
Jul 12 21:17:12 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: route add www.example.com  www.example.com http://fabio.service.consul:9999/httpbin opts "strip=/httpbin"

Now if we try to curl from anywhere www.example.com:

$> curl --verbose https://www.example.com

* Rebuilt URL to: https://www.example.com/
*   Trying 53.11.238.59...
* TCP_NODELAY set
* Connected to www.example.com (52.11.238.59) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/cert.pem
  CApath: none
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: OU=Domain Control Validated; CN=*.example.com
*  start date: Jun 21 10:32:34 2019 GMT
*  expire date: Aug 20 23:19:38 2020 GMT
*  subjectAltName: host "www.example.com" matched cert's "*.example.com"
*  issuer: C=US; ST=Arizona; L=Scottsdale; O=GoDaddy.com, Inc.; OU=http://certs.godaddy.com/repository/; CN=Go Daddy Secure Certificate Authority - G2
*  SSL certificate verify ok.
* 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 0x7f8e10009400)
> GET / HTTP/2
> Host: www.example.com
> User-Agent: curl/7.54.0
> Accept: */*
>
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
^C

It just hangs while Fabio writing thousands of lines per seconds in the log:

Jul 12 21:30:39 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: invalid log msg: 2019/07/12 21:30:39 http: proxy error: context canceled
Jul 12 21:30:39 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: 10.22.219.216 - - [12/Jul/2019:21:30:39 +0000] "GET / HTTP/1.1" 502 0 "" "curl/7.54.0"
Jul 12 21:30:39 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: invalid log msg: 2019/07/12 21:30:39 http: proxy error: context canceled
Jul 12 21:30:39 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: 10.22.202.212 - - [12/Jul/2019:21:30:39 +0000] "GET / HTTP/1.1" 502 0 "" "curl/7.54.0"
Jul 12 21:30:39 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: invalid log msg: 2019/07/12 21:30:39 http: proxy error: context canceled
Jul 12 21:30:39 fabio-i-0dec89141f864a92c.dev-usw2-dev1 fabio[27318]: 10.22.202.212 - - [12/Jul/2019:21:30:39 +0000] "GET / HTTP/1.1" 502 0 "" "curl/7.54.0"

Version: fabio-1.5.11-go1.11.5

Our use case should be straightforward (pretty much want to remove the /httpbin path when hitting www.example.com instead of www.example.com/httpbin)

Any help would be much appreciated @pschultz @pires @leprechau 🤞

[scalp42]

The end result is a 502 from ALB:

GET / HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: www.example.com
User-Agent: HTTPie/1.0.2



HTTP/1.1 502 Bad Gateway
Connection: keep-alive
Content-Length: 138
Content-Type: text/html
Date: Fri, 12 Jul 2019 21:41:59 GMT
Server: awselb/2.0

<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
</body>
</html>

[scalp42]

Here's the full Fabio trace happening in the logs after a while also: https://gist.github.com/scalp42/975b9288f1304f7b25a2f7a0f635d3c4

[scalp42]

It appears to be a "Fabio-to-Fabio" issue.

This doesn't work:

route add www.example.com www.example.com http://fabio.service.consul:9999/httpbin opts "strip=/httpbin"

But if we skip Fabio, it works fine:

route add www.example.com www.example.com http://httpbin.service.consul:23356/httpbin opts "strip=/httpbin"

The issue is that we have many containers not just 23356 which is the reason for Fabio in the first place.

[tino]

Yeah if you route fabio back to fabio you create an endless loop!

The second route add command you posted above is the correct one. It doesn't "skip" fabio. If you have multiple services that you want to split traffic over, you'll have to add multiple route add statements. However, if you are already using consul it is probably easier to register each service with a urlprefix-www.example.com/httpbin opts "strip=/httpbin tag. That way you don't have to manually register the correct ports.