Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Error when handling HTTP requests with HTTP2 related "Upgrade: h2c" in header #6446

Open
1 task done
pwuertz opened this issue Dec 21, 2021 · 19 comments
Open
1 task done
Labels
enhancement reproducer: present This PR or issue contains code, which reproduce the problem described or clearly understandable STR server

Comments

@pwuertz
Copy link
Contributor

pwuertz commented Dec 21, 2021

Describe the bug

I'm experiencing problems when trying to handle HTTP requests sent by Qt6 clients. It looks like Qt now sends additional HTTP2 related headers by default. HTTP servers based on aiohttp 3.6 and python http.server are handling those requests just fine, but aiohttp 3.7 and 3.8 are showing irregularities in the parsed headers, are unable to read request bodies, and fail to send replies.

Test code and examples for good/bad observations are attached to this issue.

To Reproduce

Qt6 / Qt5 client test code:

#include <QtCore/QCoreApplication>
#include <QtNetwork/QNetworkAccessManager>
#include <QtNetwork/QNetworkReply>


int main(int argc, char *argv[])
{
  QCoreApplication a(argc, argv);
  QNetworkAccessManager qnam;

  QUrl requestUrl("http://localhost:9000/");
  QNetworkRequest request(requestUrl);
  // --- WORKAROUND: aiohttp only processes Qt6 requests with Http2Allowed set to false ---
  // request.setAttribute(QNetworkRequest::Attribute::Http2AllowedAttribute, false);
  request.setHeader(QNetworkRequest::ContentTypeHeader, "text/plain;charset=UTF-8");
  QByteArray queryData("Hello World");
  auto* reply = qnam.post(request, queryData);

  QObject::connect(reply, &QNetworkReply::finished, [&]() {
    if(reply->error() == QNetworkReply::NoError) {
      QString contents = QString::fromUtf8(reply->readAll());
      qDebug() << "Reply Ok" << contents;
    }
    else {
      QString err = reply->errorString();
      qDebug() << "Reply Error" << err;
    }
    reply->deleteLater();
    a.quit();
  });

  return a.exec();
}

Aiohttp test server:

from aiohttp import web

async def post_handler(request: web.Request):
    body = await request.read()
    n_expected, n_read = request.headers.get('Content-Length'), len(body)
    print(f"Received request, body expected {n_expected}, body read {n_read}")
    headers = "\n".join(f"  {k}: {v}" for k, v in request.headers.items())
    print(f"Headers\n{headers}")
    return web.Response(body=body)

app = web.Application()
app.add_routes([web.post('/', post_handler)])
web.run_app(app, port=9000)

Expected behavior

aiohttp server should be able to handle the requests.

Logs/tracebacks

Good result with aiohttp 3.6:

Received request, body expected 11, body read 11
Headers
  Host: localhost:9000
  Content-Type: text/plain;charset=UTF-8
  Content-Length: 11
  Accept-Encoding: gzip, deflate
  Accept-Language: en-US,*
  User-Agent: Mozilla/5.0
  Connection: Keep-Alive, Upgrade, HTTP2-Settings
  Upgrade: h2c
  HTTP2-Settings: AAIAAAAA

Bad result with aiohttp 3.7 and 3.8:

Received request, body expected 11, body read 0
Headers
  Host: localhost:9000
  Content-Type: text/plain;charset=UTF-8
  Content-Length: 11
  Accept-Encoding: gzip, deflate
  Accept-Language: en-US,*
  User-Agent: Mozilla/5.0
  Connection: Keep-Alive, Upgrade, HTTP2-Settings, Upgrade, HTTP2-Settings
  Upgrade: h2c
  HTTP2-Settings: AAIAAAAA
Unhandled exception
Traceback (most recent call last):
  File "/home/pwuertz/.local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 514, in start
    resp, reset = await task
  File "/home/pwuertz/.local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 460, in _handle_request
    reset = await self.finish_response(request, resp, start_time)
  File "/home/pwuertz/.local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 599, in finish_response
    self._request_parser.feed_data(self._message_tail)
  File "aiohttp/_http_parser.pyx", line 551, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: 400, message="Bad status line 'Invalid method encountered'"

Python Version

Python 3.9.7

aiohttp Version

Version: 3.8.1

multidict Version

Version: 4.7.6

yarl Version

Version: 1.5.1

OS

Ubuntu 21.10

Related component

Server

Additional context

No response

Code of Conduct

  • I agree to follow the aio-libs Code of Conduct
@pwuertz pwuertz added the bug label Dec 21, 2021
@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 21, 2021

Also got some TCP dumps from the good and bad test case:

aiohttp 3.6, good

$ sudo tcpdump -A -s 0 'tcp port 9000' -i lo
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on lo, link-type EN10MB (Ethernet), snapshot length 262144 bytes
11:25:44.653129 IP localhost.47218 > localhost.9000: Flags [S], seq 648149401, win 65495, options [mss 65495,sackOK,TS val 4120277942 ecr 0,nop,wscale 7], length 0
E..<.y@.@..@.........r#(&............0.........
..s.........
11:25:44.653136 IP localhost.9000 > localhost.47218: Flags [S.], seq 1401724688, ack 648149402, win 65483, options [mss 65495,sackOK,TS val 4120277942 ecr 4120277942,nop,wscale 7], length 0
E..<..@.@.<.........#(.rS...&........0.........
..s...s.....
11:25:44.653144 IP localhost.47218 > localhost.9000: Flags [.], ack 1, win 512, options [nop,nop,TS val 4120277942 ecr 4120277942], length 0
E..4.z@.@..G.........r#(&...S........(.....
..s...s.
11:25:44.653269 IP localhost.47218 > localhost.9000: Flags [P.], seq 1:285, ack 1, win 512, options [nop,nop,TS val 4120277942 ecr 4120277942], length 284
E..P.{@.@..*.........r#(&...S........D.....
..s...s.POST / HTTP/1.1
Host: localhost:9000
Content-Type: text/plain;charset=UTF-8
Content-Length: 11
Accept-Encoding: gzip, deflate
Accept-Language: en-US,*
User-Agent: Mozilla/5.0
Connection: Keep-Alive, Upgrade, HTTP2-Settings
Upgrade: h2c
HTTP2-Settings: AAIAAAAA

Hello World
11:25:44.653273 IP localhost.9000 > localhost.47218: Flags [.], ack 285, win 510, options [nop,nop,TS val 4120277942 ecr 4120277942], length 0
E..4 T@.@..n........#(.rS...&........(.....
..s...s.
11:25:44.653708 IP localhost.9000 > localhost.47218: Flags [P.], seq 1:151, ack 285, win 512, options [nop,nop,TS val 4120277942 ecr 4120277942], length 150
E... U@.@...........#(.rS...&..............
..s...s.HTTP/1.1 200 OK
Content-Length: 11
Content-Type: application/octet-stream
Date: Tue, 21 Dec 2021 10:25:44 GMT
Server: Python/3.9 aiohttp/3.6.0


11:25:44.653715 IP localhost.47218 > localhost.9000: Flags [.], ack 151, win 511, options [nop,nop,TS val 4120277942 ecr 4120277942], length 0
E..4.|@.@..E.........r#(&...S........(.....
..s...s.
11:25:44.653731 IP localhost.9000 > localhost.47218: Flags [P.], seq 151:162, ack 285, win 512, options [nop,nop,TS val 4120277942 ecr 4120277942], length 11
E..? V@.@..a........#(.rS...&........3.....
..s...s.Hello World
11:25:44.653734 IP localhost.47218 > localhost.9000: Flags [.], ack 162, win 511, options [nop,nop,TS val 4120277942 ecr 4120277942], length 0
E..4.}@.@..D.........r#(&...S........(.....
..s...s.
11:25:44.653956 IP localhost.47218 > localhost.9000: Flags [F.], seq 285, ack 162, win 512, options [nop,nop,TS val 4120277943 ecr 4120277942], length 0
E..4.~@.@..C.........r#(&...S........(.....
..s...s.
11:25:44.654020 IP localhost.9000 > localhost.47218: Flags [F.], seq 162, ack 286, win 512, options [nop,nop,TS val 4120277943 ecr 4120277943], length 0
E..4 W@.@..k........#(.rS...&........(.....
..s...s.
11:25:44.654027 IP localhost.47218 > localhost.9000: Flags [.], ack 163, win 512, options [nop,nop,TS val 4120277943 ecr 4120277943], length 0
E..4..@.@..B.........r#(&...S........(.....
..s...s.
^C
12 packets captured
24 packets received by filter
0 packets dropped by kernel

aiohttp >= 3.7, bad

$ sudo tcpdump -A -s 0 'tcp port 9000' -i lo
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on lo, link-type EN10MB (Ethernet), snapshot length 262144 bytes
11:28:15.060735 IP localhost.47220 > localhost.9000: Flags [S], seq 933826246, win 65495, options [mss 65495,sackOK,TS val 4120428349 ecr 0,nop,wscale 7], length 0
E..<..@.@.?..........t#(7............0.........
...=........
11:28:15.060746 IP localhost.9000 > localhost.47220: Flags [S.], seq 2668135700, ack 933826247, win 65483, options [mss 65495,sackOK,TS val 4120428349 ecr 4120428349,nop,wscale 7], length 0
E..<..@.@.<.........#(.t....7........0.........
...=...=....
11:28:15.060754 IP localhost.47220 > localhost.9000: Flags [.], ack 1, win 512, options [nop,nop,TS val 4120428349 ecr 4120428349], length 0
E..4..@.@.?..........t#(7............(.....
...=...=
11:28:15.060877 IP localhost.47220 > localhost.9000: Flags [P.], seq 1:285, ack 1, win 512, options [nop,nop,TS val 4120428350 ecr 4120428349], length 284
E..P..@.@.>..........t#(7............D.....
...>...=POST / HTTP/1.1
Host: localhost:9000
Content-Type: text/plain;charset=UTF-8
Content-Length: 11
Accept-Encoding: gzip, deflate
Accept-Language: en-US,*
User-Agent: Mozilla/5.0
Connection: Keep-Alive, Upgrade, HTTP2-Settings
Upgrade: h2c
HTTP2-Settings: AAIAAAAA

Hello World
11:28:15.060882 IP localhost.9000 > localhost.47220: Flags [.], ack 285, win 510, options [nop,nop,TS val 4120428350 ecr 4120428350], length 0
E..4t.@.@...........#(.t....7........(.....
...>...>
11:28:15.061779 IP localhost.9000 > localhost.47220: Flags [F.], seq 1, ack 285, win 512, options [nop,nop,TS val 4120428350 ecr 4120428350], length 0
E..4t.@.@...........#(.t....7........(.....
...>...>
11:28:15.061804 IP localhost.47220 > localhost.9000: Flags [F.], seq 285, ack 2, win 512, options [nop,nop,TS val 4120428351 ecr 4120428350], length 0
E..4..@.@.?..........t#(7............(.....
...?...>
11:28:15.061812 IP localhost.9000 > localhost.47220: Flags [.], ack 286, win 512, options [nop,nop,TS val 4120428351 ecr 4120428351], length 0
E..4t.@.@...........#(.t....7........(.....
...?...?
11:28:15.061875 IP localhost.47222 > localhost.9000: Flags [S], seq 632459119, win 65495, options [mss 65495,sackOK,TS val 4120428351 ecr 0,nop,wscale 7], length 0
E..<.S@.@..f.........v#(%..o.........0.........
...?........
11:28:15.061878 IP localhost.9000 > localhost.47222: Flags [S.], seq 401720488, ack 632459120, win 65483, options [mss 65495,sackOK,TS val 4120428351 ecr 4120428351,nop,wscale 7], length 0
E..<..@.@.<.........#(.v....%..p.....0.........
...?...?....
11:28:15.061881 IP localhost.47222 > localhost.9000: Flags [.], ack 1, win 512, options [nop,nop,TS val 4120428351 ecr 4120428351], length 0
E..4.T@.@..m.........v#(%..p.........(.....
...?...?
11:28:15.061924 IP localhost.47222 > localhost.9000: Flags [P.], seq 1:310, ack 1, win 512, options [nop,nop,TS val 4120428351 ecr 4120428351], length 309
E..i.U@.@..7.........v#(%..p.........].....
...?...?POST / HTTP/1.1
Host: localhost:9000
Content-Type: text/plain;charset=UTF-8
Content-Length: 11
Accept-Encoding: gzip, deflate
Accept-Language: en-US,*
User-Agent: Mozilla/5.0
Connection: Keep-Alive, Upgrade, HTTP2-Settings, Upgrade, HTTP2-Settings
Upgrade: h2c
HTTP2-Settings: AAIAAAAA

Hello World
11:28:15.061927 IP localhost.9000 > localhost.47222: Flags [.], ack 310, win 510, options [nop,nop,TS val 4120428351 ecr 4120428351], length 0
E..4..@.@...........#(.v....%........(.....
...?...?
11:28:15.062145 IP localhost.9000 > localhost.47222: Flags [F.], seq 1, ack 310, win 512, options [nop,nop,TS val 4120428351 ecr 4120428351], length 0
E..4..@.@...........#(.v....%........(.....
...?...?
11:28:15.062162 IP localhost.47222 > localhost.9000: Flags [F.], seq 310, ack 2, win 512, options [nop,nop,TS val 4120428351 ecr 4120428351], length 0
E..4.V@.@..k.........v#(%............(.....
...?...?
11:28:15.062167 IP localhost.9000 > localhost.47222: Flags [.], ack 311, win 512, options [nop,nop,TS val 4120428351 ecr 4120428351], length 0
E..4..@.@...........#(.v....%........(.....
...?...?
^C
16 packets captured
32 packets received by filter
0 packets dropped by kernel

@pwuertz pwuertz changed the title Error when handling HTTP requests from Qt6 Error when handling HTTP requests with HTTP2 related "Upgrade: h2c" in header Dec 21, 2021
@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 21, 2021

All right, it seems that this problem is solely triggered by this line in the request header:

Upgrade: h2c

When this header is present, aiohttp to fails and drops the connection.

@webknjaz
Copy link
Member

HTTP/2 is not supported at the moment. But you could contribute it: #5999.

@Dreamsorcerer
Copy link
Member

Dreamsorcerer commented Dec 21, 2021

HTTP/2 is not supported at the moment. But you could contribute it: #5999.

Description said that the connection works with aiohttp 3.6. So there is presumably some kind of regression that is not related to supporting HTTP/2.

@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 21, 2021

HTTP/2 is not supported at the moment. But you could contribute it: #5999.

Missing HTTP/2 support is not the issue here. The client did send a perfectly valid HTTP/1.1 request with the suggestion of switching to another protocol the server may or may not support.

If the server supports and agrees to switching to a suggested protocol, the server replies with a HTTP/1.1 101 Switching Protocols response. If the server doesn't support the protocol (or doesn't want to switch) it should just continue talking to the client using the already established HTTP/1.1 protocol in an orderly fashion (i.e. not just drop the connection).

The server doesn't decide if a protocol upgrade is mandatory. It's the clients decision to either continue using the non-upgraded protocol or to drop the connection and report the absence of a 101 reply as sort of a MissingProtocolError.

@webknjaz
Copy link
Member

Well, then it would be useful to get a PR with a failing regression test.

@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 22, 2021

Here is a minimal aiohttp.test_utils based test that triggers the observed behavior on aiohttp >= 3.7

from aiohttp import web, test_utils

async def test_unsupported_upgrade() -> None:
    # don't fail if a client probes for an unsupported protocol upgrade
    # https://github.com/aio-libs/aiohttp/issues/6446#issuecomment-999032039
    async def post_handler(request: web.Request):
        return web.Response(body=await request.read())

    upgrade_headers = {"Connection": "Upgrade", "Upgrade": "unsupported_proto"}
    app = web.Application()
    app.add_routes([web.post("/", post_handler)])
    async with test_utils.TestServer(app) as server:
        async with test_utils.TestClient(server) as cli:
            resp = await cli.post("/", data=b"Test", headers=upgrade_headers)
            assert resp.status == 200
            assert (await resp.read()) == b"Test"

# asyncio.run(test_unsupported_upgrade()) or similar

Oddly enough, no error is triggered when running this function as part of the aiohttp tests, e.g. by adding it to aiohttp/tests/test_web_server.py. The aiohttp testing environment appears to differ from the 'real' environment in some significant way.

@webknjaz
Copy link
Member

Could you submit that as a pull request? It'd give us visibility into the behavior in multiple envs, not just your laptop.

As for the difference, it is possible that you're running the tests with pure-Python fallback parser implementation which may be different from the Cython-based one. If this is true, we'd need to make sure to make the behavior equivalent too.

@Dreamsorcerer
Copy link
Member

Oddly enough, no error is triggered when running this function as part of the aiohttp tests, e.g. by adding it to aiohttp/tests/test_web_server.py. The aiohttp testing environment appears to differ from the 'real' environment in some significant way.

Maybe also double check what versions you are testing with. Maybe the issue is not present on master, but only in the 3.8/3.9 branches..

@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 22, 2021

Maybe also double check what versions you are testing with. Maybe the issue is not present on master, but only in the 3.8/3.9 branches..

Right, I assumed this could be the case, but I'm pretty sure I excluded this possibility by checking out 3.8.1 (still no error in tests) + installing from source and running the code (error is triggered) 🤷

@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 23, 2021

Could you submit that as a pull request? It'd give us visibility into the behavior in multiple envs, not just your laptop.

Added PR #6451 for the regression test. Sorry, I didn't understand the need for PR earlier because the snippet in #6446 (comment) already provided visibility beyond my PC, while the testing framework doesn't seem to do the 'right' thing at this time.

As for the difference, it is possible that you're running the tests with pure-Python fallback parser implementation which may be different from the Cython-based one. If this is true, we'd need to make sure to make the behavior equivalent too.

Oh, that sounds reasonable, that difference kept me bamboozled for quite some time.

@pwuertz
Copy link
Contributor Author

pwuertz commented Dec 23, 2021

As for the difference, it is possible that you're running the tests with pure-Python fallback parser implementation which may be different from the Cython-based one. If this is true, we'd need to make sure to make the behavior equivalent too.

Oh, that is exactly what happened here! The tests were performed against aiohttp from the source tree, so they used the pure-python implementation. After copying over all .so files from build the compiled parsers are picked up and the test does indeed fail now.

@webknjaz
Copy link
Member

After copying over all .so files from build the compiled parsers are picked up and the test does indeed fail now.

FYI it should be enough to run make cythonize + make test to that the C-extensions built.

Meanwhile, I've approved the CI run and we should soon have the logs of how it fails there. If everything goes as expected, that test can be marked as xfail and merged per https://pganssle-talks.github.io/xfail-lightning.

@Dreamsorcerer
Copy link
Member

So, I think the change that caused this is probably switching to llhttp for the parsing. I'm not familiar with this, so not sure if the bug needs to be reported upstream to llhttp or if there's something we can fix here.

Maybe @derlih might know more.

@webknjaz
Copy link
Member

So, I think the change that caused this is probably switching to llhttp for the parsing.

I don't think so. The reporter claims that the error started happening in aiohttp 3.7 but the switch hasn't happened until aiohttp 3.8.

@webknjaz
Copy link
Member

Here's the log from the CI failure for history:

=================================== FAILURES ===================================
_______________________ test_unsupported_upgrade[pyloop] _______________________

aiohttp_raw_server = <function aiohttp_raw_server.<locals>.go at 0x7f077f28ec80>
aiohttp_client = <function aiohttp_client.<locals>.go at 0x7f077f28e0d0>

    async def test_unsupported_upgrade(aiohttp_raw_server, aiohttp_client) -> None:
        # don't fail if a client probes for an unsupported protocol upgrade
        # aio-libs/aiohttp/issues/6446#issuecomment-999032039
        async def handler(request: web.Request):
            return web.Response(body=await request.read())
    
        upgrade_headers = {"Connection": "Upgrade", "Upgrade": "unsupported_proto"}
        server = await aiohttp_raw_server(handler)
        cli = await aiohttp_client(server)
        test_data = b"Test"
>       resp = await cli.post("/path/to", data=test_data, headers=upgrade_headers)

aiohttp_client = <function aiohttp_client.<locals>.go at 0x7f077f28e0d0>
aiohttp_raw_server = <function aiohttp_raw_server.<locals>.go at 0x7f077f28ec80>
cli        = <aiohttp.test_utils.TestClient object at 0x7f077f2dd7f0>
handler    = <function test_unsupported_upgrade.<locals>.handler at 0x7f077f28e510>
server     = <aiohttp.test_utils.RawTestServer object at 0x7f077f03f4e0>
test_data  = b'Test'
upgrade_headers = {'Connection': 'Upgrade', 'Upgrade': 'unsupported_proto'}

tests/test_web_server.py:31: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
aiohttp/test_utils.py:324: in _request
    resp = await self._session.request(method, self.make_url(path), **kwargs)
        kwargs     = {'data': b'Test',
 'headers': {'Connection': 'Upgrade', 'Upgrade': 'unsupported_proto'}}
        method     = 'POST'
        path       = '/path/to'
        self       = <aiohttp.test_utils.TestClient object at 0x7f077f2dd7f0>
aiohttp/client.py:559: in _request
    await resp.start(conn)
        all_cookies = <SimpleCookie: >
        allow_redirects = True
        auth       = None
        auth_from_url = None
        chunked    = None
        compress   = None
        conn       = Connection<ConnectionKey(host='127.0.0.1', port=42413, is_ssl=False, ssl=None, proxy=None, proxy_auth=None, proxy_headers_hash=None)>
        cookies    = None
        data       = b'Test'
        expect100  = False
        fingerprint = None
        handle     = None
        headers    = <CIMultiDict('Connection': 'Upgrade', 'Upgrade': 'unsupported_proto')>
        history    = []
        json       = None
        max_redirects = 10
        method     = 'POST'
        params     = None
        proxy      = None
        proxy_auth = None
        proxy_headers = <CIMultiDict()>
        raise_for_status = None
        read_bufsize = 65536
        read_until_eof = True
        real_timeout = ClientTimeout(total=300, connect=None, sock_read=None, sock_connect=None)
        redirects  = 0
        req        = <aiohttp.client_reqrep.ClientRequest object at 0x7f077f2dd4a8>
        resp       = <ClientResponse(http://127.0.0.1:42413/path/to) [None None]>
None

        self       = <aiohttp.client.ClientSession object at 0x7f077f2dd320>
        skip_auto_headers = None
        skip_headers = set()
        ssl        = None
        ssl_context = None
        str_or_url = URL('http://127.0.0.1:42413/path/to')
        timeout    = <object object at 0x7f0785b8d6d0>
        timer      = <aiohttp.helpers.TimerContext object at 0x7f077f2ddc50>
        tm         = <aiohttp.helpers.TimeoutHandle object at 0x7f077f2dda90>
        trace_request_ctx = None
        traces     = []
        url        = URL('http://127.0.0.1:42413/path/to')
        verify_ssl = None
        version    = HttpVersion(major=1, minor=1)
aiohttp/client_reqrep.py:896: in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
        connection = Connection<ConnectionKey(host='127.0.0.1', port=42413, is_ssl=False, ssl=None, proxy=None, proxy_auth=None, proxy_headers_hash=None)>
        protocol   = <aiohttp.client_proto.ResponseHandler object at 0x7f077f087ce0>
        self       = <ClientResponse(http://127.0.0.1:42413/path/to) [None None]>
None

_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <aiohttp.client_proto.ResponseHandler object at 0x7f077f087ce0>

    async def read(self) -> _T:
        if not self._buffer and not self._eof:
            assert not self._waiter
            self._waiter = self._loop.create_future()
            try:
>               await self._waiter
E               aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected

self       = <aiohttp.client_proto.ResponseHandler object at 0x7f077f087ce0>

aiohttp/streams.py:616: ServerDisconnectedError
------------------------------ Captured log call -------------------------------
ERROR    aiohttp.server:web_protocol.py:405 Unhandled exception
Traceback (most recent call last):
  File "/home/runner/work/aiohttp/aiohttp/aiohttp/web_protocol.py", line 514, in start
    resp, reset = await task
  File "/home/runner/work/aiohttp/aiohttp/aiohttp/web_protocol.py", line 460, in _handle_request
    reset = await self.finish_response(request, resp, start_time)
  File "/home/runner/work/aiohttp/aiohttp/aiohttp/web_protocol.py", line 599, in finish_response
    self._request_parser.feed_data(self._message_tail)
  File "aiohttp/_http_parser.pyx", line 551, in aiohttp._http_parser.HttpParser.feed_data
    raise ex
aiohttp.http_exceptions.BadStatusLine: 400, message="Bad status line 'Invalid method encountered'"

It shows that the server seems to attempt sending HTTP 400 (BadStatusLine exception) but somehow ends up sending a reset on a lower level (supposedly TCP RST). And on the client-side, it gets translated to the ServerDisconnectedError exception. This makes me wonder if there's some sort of a race condition that decides that the transport layer needs to drop the connection...

@Dreamsorcerer
Copy link
Member

Ah, OK. I just looked at the last line:

  File "aiohttp/_http_parser.pyx", line 551, in aiohttp._http_parser.HttpParser.feed_data
    raise ex
aiohttp.http_exceptions.BadStatusLine: 400, message="Bad status line 'Invalid method encountered'"

And noticed that it comes from some llhttp thing a few lines earlier (plus the error doesn't occur without extensions): https://github.com/aio-libs/aiohttp/blob/master/aiohttp/_http_parser.pyx#L531

So, I thought that was it.

@Dreamsorcerer
Copy link
Member

Dreamsorcerer commented Dec 23, 2021

It shows that the server seems to attempt sending HTTP 400 (BadStatusLine exception) but somehow ends up sending a reset on a lower level (supposedly TCP RST). And on the client-side, it gets translated to the ServerDisconnectedError exception.

Actually, isn't that 2 separate issues? If the connection works correctly in aiohttp 3.6, then raising a BadStatusLine is a regression. Then failing to send the 400 response is another issue.

webknjaz added a commit that referenced this issue Dec 23, 2021
… (#6451)

Co-authored-by: Sviatoslav Sydorenko <webknjaz@redhat.com>
patchback bot pushed a commit that referenced this issue Dec 23, 2021
… (#6451)

Co-authored-by: Sviatoslav Sydorenko <webknjaz@redhat.com>
(cherry picked from commit a60e8a5)
webknjaz pushed a commit to webknjaz/aiohttp that referenced this issue Dec 23, 2021
…libs#6446) (aio-libs#6451)

Co-authored-by: Sviatoslav Sydorenko <webknjaz@redhat.com>
(cherry picked from commit a60e8a5)
@webknjaz
Copy link
Member

Yep, maybe it's two issues. I don't have time to look into that right now but I've taken care of adding the xfailing test to the supported branches. The original PR added it to 3.8 but it's of course necessary in 3.9 and master which should get auto merged soon.

@webknjaz webknjaz added reproducer: missing This PR or issue lacks code, which reproduce the problem described or clearly understandable STR reproducer: present This PR or issue contains code, which reproduce the problem described or clearly understandable STR and removed reproducer: missing This PR or issue lacks code, which reproduce the problem described or clearly understandable STR labels Dec 23, 2021
webknjaz added a commit that referenced this issue Dec 23, 2021
…orted Upgrade requests (issue #6446) (#6455)

Co-authored-by: Sviatoslav Sydorenko <webknjaz@redhat.com>
Co-authored-by: Peter Würtz <pwuertz@gmail.com>
webknjaz added a commit that referenced this issue Dec 28, 2021
…upported Upgrade requests (issue #6446) (#6456)

Co-authored-by: Sviatoslav Sydorenko <webknjaz@redhat.com>
Co-authored-by: Peter Würtz <pwuertz@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement reproducer: present This PR or issue contains code, which reproduce the problem described or clearly understandable STR server
Projects
None yet
Development

No branches or pull requests

3 participants