Downgrade logging of invalid HTTP methods on first request to debug level

[bdraco]

Its common when a client sends non-HTTP or encrypted traffic to an HTTP port for the server to encounter an error parsing the request. This is expected to happen when connected to the public internet (rather frequently) as browsers may try to speak SSL before plain-text. There are a variety of other reasons as well, such users mis-typing the port, bad redirects, etc which generates non HTTP traffic on the first request.

To avoid fill logs with noise, a new exception BadHttpMethod, which inherits from BadStatusLine is now raised internally to distinguish between status lines with invalid versions or status and ones one that start with garbage or an invalid method.

The new exception is logged at debug level on the first request only to avoid filling the log with noise when nothing is actually wrong as the vast majority of these are noise. Bad methods received on keep alive requests will continue to be logged at exception level.

Example of how common spurious errors are downstream: https://github.com/home-assistant/core/issues?q=sort%3Aupdated-desc+is%3Aissue+is%3Aclosed+BadStatusLine https://github.com/home-assistant/core/issues?q=sort%3Aupdated-desc+is%3Aissue+is%3Aopen+BadStatusLine

fixes #8065
fixes #8442
fixes #3287

[bdraco]

I think we can narrow this a bit more. We probably still want exception for cparser.HPE_INVALID_STATUS and cparser.HPE_INVALID_VERSION and only downgrade to debug for cparser.HPE_INVALID_METHOD

aiohttp/aiohttp/_http_parser.pyx

Line 835 in 2e369db

cparser.HPE_INVALID_METHOD,

[codspeed-hq]

CodSpeed Performance Report

Merging #10055 will not alter performance

_{Comparing bad_status_line_logging (fef8c36) with master (2e369db)}

Summary

✅ 44 untouched benchmarks

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 98.73%. Comparing base (2e369db) to head (fef8c36).
Report is 4 commits behind head on master.

✅ All tests successful. No failed tests found.

Additional details and impacted files

@@           Coverage Diff           @@
##           master   #10055   +/-   ##
=======================================
  Coverage   98.73%   98.73%           
=======================================
  Files         121      121           
  Lines       36750    36821   +71     
  Branches     4391     4393    +2     
=======================================
+ Hits        36286    36357   +71     
  Misses        314      314           
  Partials      150      150           

Flag	Coverage Δ
CI-GHA	98.62% <100.00%> (+<0.01%)	⬆️
OS-Linux	98.31% <100.00%> (+<0.01%)	⬆️
OS-Windows	96.15% <100.00%> (+<0.01%)	⬆️
OS-macOS	97.41% <100.00%> (+<0.01%)	⬆️
Py-3.10.11	97.26% <100.00%> (+<0.01%)	⬆️
Py-3.10.15	97.80% <100.00%> (-0.05%)	⬇️
Py-3.11.10	97.85% <100.00%> (-0.01%)	⬇️
Py-3.11.9	97.31% <100.00%> (-0.01%)	⬇️
Py-3.12.7	98.38% <100.00%> (+<0.01%)	⬆️
Py-3.13.0	98.36% <100.00%> (+<0.01%)	⬆️
Py-3.9.13	97.18% <100.00%> (+<0.01%)	⬆️
Py-3.9.20	97.72% <100.00%> (+<0.01%)	⬆️
Py-pypy7.3.16	97.33% <100.00%> (+0.01%)	⬆️
VM-macos	97.41% <100.00%> (+<0.01%)	⬆️
VM-ubuntu	98.31% <100.00%> (+<0.01%)	⬆️
VM-windows	96.15% <100.00%> (+<0.01%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[webknjaz]

Would it maybe make sense to call it something like GibberishOnWireException since it's not REALLY the HTTP method in many cases?

[bdraco]

Would it maybe make sense to call it something like GibberishOnWireException since it's not REALLY the HTTP method in many cases?

We could do something like that with the Py parser, but since the C parser doesn't give an error code other than HPE_INVALID_METHOD we can't distinguish between a non-existent method and gibberish so I went with BadHttpMethod

[bdraco]

Slept on this one. Still happy with it.

Going to do a new patch release since Home Assistant beta is today, and I'll have time to turn fixes for anything that needs to be adjusted this week. Also we will get a lot more testers for 3.11.x in case there is any regressions that were missed.

[patchback]

Backport to 3.11: 💔 cherry-picking failed — conflicts found

❌ Failed to cleanly apply c11fe96 on top of patchback/backports/3.11/c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d/pr-10055

Backporting merged PR #10055 into master

1. Ensure you have a local repo clone of your fork. Unless you cloned it
   from the upstream, this would be your origin remote.
2. Make sure you have an upstream repo added as a remote too. In these
   instructions you'll refer to it by the name upstream. If you don't
   have it, here's how you can add it:

   $ git remote add upstream https://github.com/aio-libs/aiohttp.git

3. Ensure you have the latest copy of upstream and prepare a branch
   that will hold the backported code:

   $ git fetch upstream
   $ git checkout -b patchback/backports/3.11/c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d/pr-10055 upstream/3.11

4. Now, cherry-pick PR Downgrade logging of invalid HTTP methods on first request to debug level #10055 contents into that branch:

   $ git cherry-pick -x c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d

   If it'll yell at you with something like fatal: Commit c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d is a merge but no -m option was given., add -m 1 as follows instead:

   $ git cherry-pick -m1 -x c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d

5. At this point, you'll probably encounter some merge conflicts. You must
   resolve them in to preserve the patch from PR Downgrade logging of invalid HTTP methods on first request to debug level #10055 as close to the
   original as possible.
6. Push this branch to your fork on GitHub:

   $ git push origin patchback/backports/3.11/c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d/pr-10055

7. Create a PR, ensure that the CI is green. If it's not — update it so that
   the tests and any other checks pass. This is it!
   Now relax and wait for the maintainers to process your pull request
   when they have some cycles to do reviews. Don't worry — they'll tell you if
   any improvements are necessary when the time comes!

🤖 @patchback
I'm built with octomachinery and
my source is open — https://github.com/sanitizers/patchback-github-app.

[patchback]

Backport to 3.12: 💔 cherry-picking failed — conflicts found

❌ Failed to cleanly apply c11fe96 on top of patchback/backports/3.12/c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d/pr-10055

Backporting merged PR #10055 into master

1. Ensure you have a local repo clone of your fork. Unless you cloned it
   from the upstream, this would be your origin remote.
2. Make sure you have an upstream repo added as a remote too. In these
   instructions you'll refer to it by the name upstream. If you don't
   have it, here's how you can add it:

   $ git remote add upstream https://github.com/aio-libs/aiohttp.git

3. Ensure you have the latest copy of upstream and prepare a branch
   that will hold the backported code:

   $ git fetch upstream
   $ git checkout -b patchback/backports/3.12/c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d/pr-10055 upstream/3.12

4. Now, cherry-pick PR Downgrade logging of invalid HTTP methods on first request to debug level #10055 contents into that branch:

   $ git cherry-pick -x c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d

   If it'll yell at you with something like fatal: Commit c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d is a merge but no -m option was given., add -m 1 as follows instead:

   $ git cherry-pick -m1 -x c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d

5. At this point, you'll probably encounter some merge conflicts. You must
   resolve them in to preserve the patch from PR Downgrade logging of invalid HTTP methods on first request to debug level #10055 as close to the
   original as possible.
6. Push this branch to your fork on GitHub:

   $ git push origin patchback/backports/3.12/c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d/pr-10055

7. Create a PR, ensure that the CI is green. If it's not — update it so that
   the tests and any other checks pass. This is it!
   Now relax and wait for the maintainers to process your pull request
   when they have some cycles to do reviews. Don't worry — they'll tell you if
   any improvements are necessary when the time comes!

🤖 @patchback
I'm built with octomachinery and
my source is open — https://github.com/sanitizers/patchback-github-app.

[webknjaz]

@bdraco would it be possible to grab the first line of the stream and check it in the error processing branch, re-raising as a gibberish exception?

[bdraco]

@bdraco would it be possible to grab the first line of the stream and check it in the error processing branch, re-raising as a gibberish exception?

I was trying to avoid parsing the raw data in the c parser ... but maybe something like #10067 ?