How to debug random RemoteProtocolError: illegal request line: bytearray(b'{\"foo\": \"bar\"}POST /v1/api/x HTTP/1.1')" }

[sevaho]

Checklist

• The bug is reproducible against the latest release or master.
• There are no similar issues or pull requests to fix it yet.

Describe the bug

Today I stumbled on a really weird error with httpx and uvicorn. Unable to reproduce locally, have some clues, but can't figure it out... So I decided to create a bug report here.

I am running micro services on EKS with following setup:

Nginx Ingress -> Service 1 -> Service 2

Service 1 will call Service 2 with httpx, Service 2 serves a fastapi app with uvicorn.

When I call Service 1 that calls Service 2 ~ 1/3 calls results in a 500 RemoteProtocolError. Super weird.

I call with following script:

import requests

while True:
    r = requests.post("https://<api>/v1/api/x", json={"foo": "bar"})
    print(r.text)

My script produces the following:

{"msg":"SERVER_ERROR","code":500}
{"status":"OK"}
{"msg":"SERVER_ERROR","code":500}
{"status":"OK"}
{"status":"OK"}
{"msg":"SERVER_ERROR","code":500}
{"msg":"SERVER_ERROR","code":500}
{"status":"OK"}
{"status":"OK"}
{"msg":"SERVER_ERROR","code":500}
{"status":"OK"}
{"status":"OK"}
{"status":"OK"}
{"status":"OK"}
{"msg":"SERVER_ERROR","code":500}

Service 1 error logs:

{"asctime": "2022-01-31 17:28:41", "levelname": "WARNING", "module": "h11_impl", "funcName": "handle_events", "lineno": 139, "message": "Invalid HTTP request received.", "exc_info": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py\", line 136, in handle_events\n    event = self.conn.next_event()\n  File \"/usr/local/lib/python3.9/site-packages/h11/_connection.py\", line 443, in next_event\n    exc._reraise_as_remote_protocol_error()\n  File \"/usr/local/lib/python3.9/site-packages/h11/_util.py\", line 76, in _reraise_as_remote_protocol_error\n    raise self\n  File \"/usr/local/lib/python3.9/site-packages/h11/_connection.py\", line 425, in next_event\n    event = self._extract_next_receive_event()\n  File \"/usr/local/lib/python3.9/site-packages/h11/_connection.py\", line 367, in _extract_next_receive_event\n    event = self._reader(self._receive_buffer)\n  File \"/usr/local/lib/python3.9/site-packages/h11/_readers.py\", line 72, in maybe_read_from_IDLE_client\n    matches = validate(\n  File \"/usr/local/lib/python3.9/site-packages/h11/_util.py\", line 88, in validate\n    raise LocalProtocolError(msg)\nh11._util.RemoteProtocolError: illegal request line: bytearray(b'{\"foo\": \"bar\"}POST /v1/api/x HTTP/1.1')"}

Service 2 spits out:

{
    "asctime": "2022-01-31 17:28:41",
    "levelname": "WARNING",
    "module": "h11_impl",
    "funcName": "handle_events",
    "lineno": 139,
    "message": "Invalid HTTP request received.",
    "exc_info": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py\", line 136, in handle_events\n    event = self.conn.next_event()\n  File \"/usr/local/lib/python3.9/site-packages/h11/_connection.py\", line 443, in next_event\n    exc._reraise_as_remote_protocol_error()\n  File \"/usr/local/lib/python3.9/site-packages/h11/_util.py\", line 76, in _reraise_as_remote_protocol_error\n    raise self\n  File \"/usr/local/lib/python3.9/site-packages/h11/_connection.py\", line 425, in next_event\n    event = self._extract_next_receive_event()\n  File \"/usr/local/lib/python3.9/site-packages/h11/_connection.py\", line 367, in _extract_next_receive_event\n    event = self._reader(self._receive_buffer)\n  File \"/usr/local/lib/python3.9/site-packages/h11/_readers.py\", line 72, in maybe_read_from_IDLE_client\n    matches = validate(\n  File \"/usr/local/lib/python3.9/site-packages/h11/_util.py\", line 88, in validate\n    raise LocalProtocolError(msg)\nh11._util.RemoteProtocolError: illegal request line: bytearray(b'{\"foo\": \"bar\"}POST /v1/api/x HTTP/1.1')"
}

I tried the following to try and reproduce:

• running both services on my machine (Arch Linux 5.15.13) - no result
• running both services in docker on my machine - no result
• running Service 1 on my machine and port forwarding Service 2 (kubefwd) - no result

So it has something to do with Service 1 running in Kuberentes? The odd thing is that I ran Service 2 with hypercorn and no random 500s everything works fine. So it has something to do with Service 2?

Conclusion, I am asking for help on ways to debug this anomaly. Any recommendations?

Steps to reproduce the bug

None, sorry. Cannot reproduce locally.

Expected behavior

No response

Actual behavior

No response

Debugging material

Running latest httpx, uvicorn, Python3.9, python:3.9-slim docker.

Environment

ENTRYPOINT ["/usr/bin/tini", "--"]
CMD ["uvicorn", "centurion.app:app", "--workers=1", "--log-level", "info", "--log-config", "logger.conf", "--port", "5000", "--host", "0.0.0.0"]

Additional context

No response

[sevaho]

I've done some checks with previous uvicorn releases, and I get no errors with 0.17.0, but get errors with 0.17.1 . Changes: https://github.com/encode/uvicorn/releases/tag/0.17.1 .

Changes between 0.17.0..0.17.1

• Move all data handling logic to protocol and ensure connection is closed. (Fix ensure http connection is closed #1332) 28/01/22
• Change spec_version field from "2.1" to "2.3", as Uvicorn is compliant with that version of the ASGI specifications. (Fix spec_version value from WebSocket and HTTP connection scopes #1337) 25/01/22

[zpz]

hey, looks similar to my issue. I've just asked on SO a moment ago https://stackoverflow.com/q/70965672/6178706

[tomchristie]

Should now be resolved in 0.17.2 - #1356