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

Prevent ResponseHandler from parsing unexpected payloads #3979

Open
wants to merge 6 commits into
base: master
Choose a base branch
from

Conversation

NicolasAubry
Copy link

@NicolasAubry NicolasAubry commented Aug 14, 2019

What do these changes do?

They fix an edge-case bug causing high memory consumption that occurs when sending requests to a few specific Web hosts.

We use aiohttp for our scanning tools that run in docker containers. While they work perfectly most of the time, we sometimes experienced repeated OOM cycles that caused the container to be killed over and over again because its memory usage spiked to the 2GB limit as soon as a scan started.

We discovered that some of the host we scan sends more than one response per request, usually around 100-200, but sometimes up to a few thousands, resulting in high memory consumption.

For example, making a GET request to one of those hosts with this simple script:

async def make_request(url):
   async with ClientSession() as session:
       response = await session.get(url, ssl=False)
       print(response.headers)
       print(response.content)

produces the following output:

<CIMultiDictProxy('Date': 'Wed, 14 Aug 2019 13:28:35 GMT', 'Vary': 'Accept-Encoding', 'Content-Encoding': 'gzip', 'Content-Length': '229', 'Content-Type': 'text/html; charset=iso-8859-1')>
<StreamReader 270 bytes eof>

The response headers and the content is what we expect.

The TCP dump for this single request, however, is more surprising:

08:49:00.017346 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [S], seq 3383878192, win 64240, options [mss 1460,sackOK,TS val 1699102928 ecr 0,nop,wscale 7], length 0
08:49:00.039166 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [S.], seq 2185886896, ack 3383878193, win 4140, options [mss 1380,nop,nop,TS val 2418844289 ecr 1699102928,sackOK,eol], length 0
08:49:00.039195 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 1, win 64240, options [nop,nop,TS val 1699102950 ecr 2418844289], length 0
08:49:00.040917 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [P.], seq 1:518, ack 1, win 64240, options [nop,nop,TS val 1699102951 ecr 2418844289], length 517
08:49:00.062071 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], ack 518, win 4657, options [nop,nop,TS val 2418844312 ecr 1699102951], length 0
08:49:00.071556 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 1:1449, ack 518, win 4657, options [nop,nop,TS val 2418844321 ecr 1699102951], length 1448
08:49:00.071581 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 1449, win 62792, options [nop,nop,TS val 1699102982 ecr 2418844321], length 0
08:49:00.071591 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 1449:2897, ack 518, win 4657, options [nop,nop,TS val 2418844321 ecr 1699102951], length 1448
08:49:00.071593 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 2897, win 61344, options [nop,nop,TS val 1699102982 ecr 2418844321], length 0
08:49:00.071597 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 2897:4345, ack 518, win 4657, options [nop,nop,TS val 2418844321 ecr 1699102951], length 1448
08:49:00.071600 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 4345, win 59896, options [nop,nop,TS val 1699102982 ecr 2418844321], length 0
08:49:00.071602 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 4345:4437, ack 518, win 4657, options [nop,nop,TS val 2418844321 ecr 1699102951], length 92
08:49:00.071603 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 4437, win 59804, options [nop,nop,TS val 1699102982 ecr 2418844321], length 0
08:49:00.072255 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [P.], seq 518:864, ack 4437, win 62928, options [nop,nop,TS val 1699102983 ecr 2418844321], length 346
08:49:00.093318 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], ack 864, win 5003, options [nop,nop,TS val 2418844343 ecr 1699102983], length 0
08:49:00.103297 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 4437:4443, ack 864, win 5003, options [nop,nop,TS val 2418844353 ecr 1699102983], length 6
08:49:00.103875 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 4443:4516, ack 864, win 5003, options [nop,nop,TS val 2418844354 ecr 1699102983], length 73
08:49:00.104004 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 4516, win 62928, options [nop,nop,TS val 1699103014 ecr 2418844353], length 0
08:49:00.104719 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [P.], seq 864:1033, ack 4516, win 62928, options [nop,nop,TS val 1699103015 ecr 2418844353], length 169
08:49:00.126148 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], ack 1033, win 5172, options [nop,nop,TS val 2418844375 ecr 1699103015], length 0
08:49:00.127417 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 4516:4973, ack 1033, win 5172, options [nop,nop,TS val 2418844377 ecr 1699103015], length 457
08:49:00.127437 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 4973:5430, ack 1033, win 5172, options [nop,nop,TS val 2418844377 ecr 1699103015], length 457
08:49:00.127441 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 5430:5887, ack 1033, win 5172, options [nop,nop,TS val 2418844377 ecr 1699103015], length 457
08:49:00.127443 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 5887:6344, ack 1033, win 5172, options [nop,nop,TS val 2418844377 ecr 1699103015], length 457
08:49:00.127445 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 6344:6801, ack 1033, win 5172, options [nop,nop,TS val 2418844377 ecr 1699103015], length 457
08:49:00.127449 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 6801:7258, ack 1033, win 5172, options [nop,nop,TS val 2418844377 ecr 1699103015], length 457
08:49:00.127451 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 7258:7715, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.127454 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 7715:8172, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.127562 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 8172, win 62928, options [nop,nop,TS val 1699103038 ecr 2418844377], length 0
08:49:00.128084 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 8172:8629, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.128093 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 8629:9086, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.128096 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 9086:9543, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.128291 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 9543:10000, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.128299 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 10000:10457, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.128302 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 10457:10914, ack 1033, win 5172, options [nop,nop,TS val 2418844378 ecr 1699103015], length 457
08:49:00.128703 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 10914:11371, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.128711 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 11371:11828, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.128713 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 11828:12285, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.128958 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [P.], seq 1033:1090, ack 12285, win 58815, options [nop,nop,TS val 1699103039 ecr 2418844378], length 57
08:49:00.129326 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 12285:12742, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.130154 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 12742:13199, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.130162 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 13199:13656, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.130165 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 13656:14113, ack 1033, win 5172, options [nop,nop,TS val 2418844379 ecr 1699103015], length 457
08:49:00.130167 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 14113:14570, ack 1033, win 5172, options [nop,nop,TS val 2418844380 ecr 1699103015], length 457
[110 similar lines omitted]
08:49:00.144643 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 65754:66211, ack 1033, win 5172, options [nop,nop,TS val 2418844395 ecr 1699103015], length 457
08:49:00.144647 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 66211:66668, ack 1033, win 5172, options [nop,nop,TS val 2418844395 ecr 1699103015], length 457
08:49:00.144970 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 66668:67125, ack 1033, win 5172, options [nop,nop,TS val 2418844395 ecr 1699103015], length 457
08:49:00.144979 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 67125:67444, ack 1033, win 5172, options [nop,nop,TS val 2418844395 ecr 1699103015], length 319
08:49:00.148758 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 67444:69410, ack 1033, win 5172, options [nop,nop,TS val 2418844398 ecr 1699103038], length 1966
08:49:00.148767 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 69410:70324, ack 1033, win 5172, options [nop,nop,TS val 2418844398 ecr 1699103038], length 914
08:49:00.148770 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 70324:71100, ack 1033, win 5172, options [nop,nop,TS val 2418844399 ecr 1699103038], length 776
08:49:00.149937 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], ack 1090, win 5229, options [nop,nop,TS val 2418844400 ecr 1699103039], length 0
08:49:00.170997 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 71100, win 0, options [nop,nop,TS val 1699103081 ecr 2418844379], length 0
08:49:01.192772 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [.], ack 71100, win 62928, options [nop,nop,TS val 1699104103 ecr 2418844379], length 0
08:49:01.192978 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [F.], seq 1090, ack 71100, win 62928, options [nop,nop,TS val 1699104103 ecr 2418844379], length 0
08:49:01.213965 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 71100:72152, ack 1090, win 5229, options [nop,nop,TS val 2418845463 ecr 1699104103], length 1052
08:49:01.213995 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [R], seq 3383879282, win 0, length 0
08:49:01.214012 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], seq 72152:76256, ack 1090, win 5229, options [nop,nop,TS val 2418845463 ecr 1699104103], length 4104
08:49:01.214015 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [R], seq 3383879282, win 0, length 0
08:49:01.214835 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], seq 76256:110456, ack 1090, win 5229, options [nop,nop,TS val 2418845463 ecr 1699104103], length 34200
08:49:01.214842 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [R], seq 3383879282, win 0, length 0
08:49:01.215341 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [P.], seq 110456:133390, ack 1090, win 5229, options [nop,nop,TS val 2418845463 ecr 1699104103], length 22934
08:49:01.215347 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [R], seq 3383879282, win 0, length 0
08:49:01.215351 IP www.example.com.https > nicolas-laptop.localdomain.38734: Flags [.], ack 1091, win 5229, options [nop,nop,TS val 2418845464 ecr 1699104103], length 0
08:49:01.215353 IP nicolas-laptop.localdomain.38734 > www.example.com.https: Flags [R], seq 3383879283, win 0, length 0

The server (www.example.com) sends the same response over and over again. Those additional payloads aren't tied to a ClientResponse and stay there, filling memory. As we do thousands of requests, those payloads take a lot of memory.

Putting a print at line 189 in aiohttp/client_proto.py, as shown below, produce the following output:

    def data_received(self, data: bytes) -> None:
        if not data:
            return

        print("Data received")
        # custom payload parser
        if self._payload_parser is not None:
            eof, tail = self._payload_parser.feed_data(data)
Data received
Data received
Data received
Data received
Data received
Data received
Data received
Data received
<StreamReader 270 bytes eof>

There is more payload than what is added to the ClientResponse the user gets.
When a lot of requests is performed and even more data is received for some requests, the memory usage becomes an issue.

Are there changes in behavior for the user?

Hopefully, none apart from reduced memory consumption when hitting this strange server-side behavior. We have tested this fix internally for more than a week, and it fixed this particular problem without causing any noticeable undesired behaviors.

Related issue number

None that I'm aware of.

Checklist

  • I think the code is well written
  • Unit tests for the changes exist
  • Documentation reflects the changes
  • If you provide code modification, please add yourself to CONTRIBUTORS.txt
    • The format is <Name> <Surname>.
    • Please keep alphabetical order, the file is sorted by names.
  • Add a new news fragment into the CHANGES folder
    • name it <issue_id>.<type> for example (588.bugfix)
    • if you don't have an issue_id change it to the pr id after creating the pr
    • ensure type is one of the following:
      • .feature: Signifying a new feature.
      • .bugfix: Signifying a bug fix.
      • .doc: Signifying a documentation improvement.
      • .removal: Signifying a deprecation or removal of public API.
      • .misc: A ticket has been closed, but it is not of interest to users.
    • Make sure to use full sentences with correct case and punctuation, for example: "Fix issue with non-ascii contents in doctest text files."

@psf-chronographer psf-chronographer bot added the bot:chronographer:provided There is a change note present in this PR label Aug 14, 2019
@lgtm-com
Copy link
Contributor

lgtm-com bot commented Aug 14, 2019

This pull request fixes 1 alert when merging 0672191 into c5a80c8 - view on LGTM.com

fixed alerts:

  • 1 for Except block handles 'BaseException'

@codecov-io
Copy link

codecov-io commented Aug 14, 2019

Codecov Report

Merging #3979 into master will decrease coverage by 0.01%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #3979      +/-   ##
==========================================
- Coverage   97.77%   97.75%   -0.02%     
==========================================
  Files          43       43              
  Lines        8763     8778      +15     
  Branches     1375     1377       +2     
==========================================
+ Hits         8568     8581      +13     
- Misses         83       84       +1     
- Partials      112      113       +1
Impacted Files Coverage Δ
aiohttp/client_proto.py 96.95% <100%> (+0.3%) ⬆️
aiohttp/web_fileresponse.py 96.59% <0%> (-1.14%) ⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update c5a80c8...0672191. Read the comment docs.

@socketpair
Copy link
Contributor

This patch may break case when we have not read completely the first response, but someone has sent second request in the same connection from other coroutine, and next we may see two responses. I don't know if it is possible.

@NicolasAubry
Copy link
Author

@socketpair Based on my understanding of the code, I think the case you describe is possible, as connections are released and can be reused when an EOF is received, and the buffer is read after that.

@webknjaz webknjaz changed the title Prevent ResponseHandler to parse unexpected payloads. Prevent ResponseHandler from parsing unexpected payloads Sep 18, 2019
@@ -0,0 +1 @@
Prevent ResponseHandler to parse unexpected payloads.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
Prevent ResponseHandler to parse unexpected payloads.
Prevent ResponseHandler from parsing unexpected payloads.

@webknjaz
Copy link
Member

@NicolasAubry I'd like to see a test for what @socketpair described and also some negative tests.

@lphuberdeau
Copy link
Contributor

Sending a request before the previous response is fully read would qualify as HTTP pipelining.

Documentation is quite clear on this subject:

aiohttp does not support HTTP/HTTPS pipelining.

@CLAassistant

This comment has been minimized.

@asvetlov asvetlov closed this Nov 20, 2020
@asvetlov asvetlov reopened this Nov 20, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bot:chronographer:provided There is a change note present in this PR
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

7 participants