Intermittent 502 proxy errors when running behind Apache

[panovitch]

Hi there! Was wondering if you have some insight on the following problem:

Long story short

We are running an aiohttp app behind an Apache proxy. Around 20% of requests to the app cause Apache to return 502 Proxy Error.

These happen with requests to all endpoints of the server, and there seems to be no pattern to errors of any kind. The proxy error is returned immediately upon request.
Other servers/apps (built on other frameworks, for example, tornado) run behind the same Apache proxy and do not show the same behavior.

The example of Apache logs:

[Tue Jan 23 12:38:51.050529 2018] [proxy_http:error] [pid <pid>:tid <tid>] (20014)Internal error (specific information not available): [client <IP address>] AH01102: error reading status line from remote server <hostname>

Full error response example:

HTTP/1.1 502 Proxy Error
Connection: Keep-Alive
Content-Length: 502
Content-Type: text/html; charset=iso-8859-1
Date: Tue, 23 Jan 2018 13:47:29 GMT
Keep-Alive: timeout=15, max=100
Server: Apache/2.4.18 (Ubuntu)

502 Proxy Error
The proxy server received an invalid response from an upstream server.
The proxy server could not handle the request.
Reason: Error reading from remote server

Your environment

aiohttp==2.3.9
python 3.6.3
Apache 2.4.18

[samuelcolvin]

Do you see anything in the logs from aiohttp?

How are you running aiohttp? With gunicorn or directly?

I guess debug level logs from aiohttp (and gunicorn if it's running) would help.

Also how is the aiohttp server addressed by apache (by an ip or a hostname)? I've had similar issues that turned out to be DNS problems which were fixed by using static IPs.

[panovitch]

Hi @samuelcolvin,
We are running aiohttp directly.
The Apache addresses the server by a hostname, but I doubt that issue is DNS-related, since other apps also run on the same host and dont have any problems.
There are no records in aiohttp logs for the problematic requests at all.

[asvetlov]

Maybe related to #2682

[aalhour]

Hello @asvetlov,

Do you have any recommendation for us to validate the source of the issue? How can we help you guys resolve this problem?

[asvetlov]

I'm working on it

[asvetlov]

Sorry, after digging in I did not found expected bug.
Cannot reproduce locally.

aiohttp error log is required (with DEBUG level enabled) for getting more information about the problem.

[mariuszluciow]

I'm having something similar, running aiohttp behind zuul proxy. After several good responses, and a while of doing nothing, server starts responding with incorrect response, which starts with \r\nTP/1.1 200 OK instead of HTTP/1.1 200 OK

[asvetlov]

1. Not sure if you have the same problem.
2. I need reliable way for reproducing the error -- otherwise a change for fix is very low. Python test would be awesome.

[panovitch]

Hi @asvetlov,

We tried to check the aiohttp debug logs, that's how we tried to do it, and how we are running the app:

def setup_loggers():
    stream_handler = logging.StreamHandler(stream=sys.stderr) 
    _stream_handler.setLevel(logging.DEBUG)

    loggers = [getLogger('aiohttp.internal'), getLogger('aiohttp.server')]
    for logger in loggers:
        logger.setLevel(logging.DEBUG)
        logger.addHandler(_stream_handler)

def run_app():
    """
    Application runner function.
    """
    setup_loggers()
    app = create_app()
    host = server_option("host")
    port = int(server_option("port"))

    web.run_app(
        app=app, host=host, port=port, access_log=make_logger(is_development=True),
        access_log_format=access_log_format)

We ran the app with this configuration, but were unable to see anything related to the problematic requests - they do not even register in the access log.

I'm posting the Apache config below, hope it might help you reproduce it.

Apache Configuration

apache2.conf

Default config. Nothing special here.

sites-enabled

ServerName mine.localhost.com
ProxyRequests Off

<Location /aiohttp_app/>
ProxyPass http://localhost:8137/ retry=0
ProxyPassReverse http://localhost:8137/
</Location>

Apache Error Logs

[Fri Feb 02 16:05:41.865610 2018] [proxy_http:error] [pid 6146:tid 140638813112064] (20014)Internal error (specific information not available): [client 127.0.0.1:39048] AH01102: error reading status line from remote server localhost:8137
[Fri Feb 02 16:05:41.865899 2018] [proxy:error] [pid 6146:tid 140638813112064] [client 127.0.0.1:39048] AH00898: Error reading from remote server returned by /aiohttp_app/ping
[Fri Feb 02 16:05:41.875609 2018] [proxy_http:error] [pid 6147:tid 140638787933952] (20014)Internal error (specific information not available): [client 127.0.0.1:39050] AH01102: error reading status line from remote server localhost:8137
[Fri Feb 02 16:05:41.875797 2018] [proxy:error] [pid 6147:tid 140638787933952] [client 127.0.0.1:39050] AH00898: Error reading from remote server returned by /aiohttp_app/ping

[asvetlov]

Errors are stored in logger named aiohttp.server.
I suggest calling logging.basicConfig(level=logging.DEBUG) to see all logs.

[mariuszluciow]

I spend few hours to produce some small replicable example with no luck. If anything changes I will let you know, thanks anyway!

[panovitch]

Hi @asvetlov, running the app with logging.basicConfig(level=logging.DEBUG) also doesn't show anything. To help reproduce the problem, I've created this: https://github.com/panovitch/test_aiohttp_502. The repo contains a sample apache config (main config apache.conf, which is not different from the default one AFAIK, and a site config for sites-enabled), a way to test for error, and an app (a copy of the example app really). Please note that error occurs pretty randomly so give the test some time to run.

[panovitch]

Hi everyone,

We eventually managed to solve the problem by adding this to our apache proxy config: disablereuse=on -hope this would be useful!

[pfreixes]

@panovitch do you have the chance to test if the error is reproducible with Aiohttp 3.x?

Regarding the disablereuse=on you are forcing to open a TCP connection at each time. is this stack running in local or are separated pieces within a network?

[lordmauve]

I am seeing this with aiohttp==3.1.3 and Apache 2.4.10.

[rcupic]

Hi everyone,

We eventually managed to solve the problem by adding this to our apache proxy config: disablereuse=on -hope this would be useful!

Hello,
Thank you for letting us know your solution. My question is if there is any downgrade in performance with this setup? I have something like 20-30 requests per minute. This setting sounds like disabling pooled connections which means that every of this 20-30 requests will open new connection for itself even if they are from a same client.
@panovitch

[guillaume-fr]

Running into similar issue with aiohttp + gunicorn + apache2.
The same service was running fine on another Python stack + apache2.

(32)Broken pipe: [client 192.168.8.1:44745] AH01084: pass request body failed to [::1]:80 (localhost)

In my environment, I'm not allowed to change disablereuse. The admin is suspecting an issue with keep-alive/persistent connections.

[asvetlov]

Apache uses multithreaded/multiprocessed workers to process http requests.
What is the point of deployment aiohttp behind this?
The concurrency level is limited by Apache, and the number is small.
In contrast, nginx or haproxy use asynchronous/nonblocking model, they fit with aiohttp pretty well.

Sorry, I've not motivated to support aiohttp+apache combination. If somebody wants to provide a pull request -- you are welcome.
Since it did not happen for 2 years yet, I'm closing the issue.

[webknjaz]

Apache uses multithreaded/multiprocessed workers to process http requests.

FTR this is not entirely true. You can configure it the way nginx works.

[guillaume-fr]

I don't have control over our infrastructure, Apache2 is used as reverse proxy for all our containers. I spent time learning aiohttp, enjoyed it and thanks a lot your work on this project. On my side I think I'll have to work with another stack.

Maybe add a note in documentation on Apache not being currently supported as a reverse proxy?

[asvetlov]

From my understanding, event worker still uses async mode for inactive connections only. Which may work in some scenarios though.
Anyway, this project is volunteer-driven.
If somebody wants to dig into problems with Apache and make a fix -- please do.
Docs update that states that Apache usage is discouraged and not fully supported/tested, use it on own risk, is also acceptable.

[Humbedooh]

Random question, many moons later: what is your transfer-encoding set to?
I discovered a problem where apache would break with a 502 as well, turns out I had transfer-encoding set to chunked with a non-chunked response. Removing that header solved it for me.