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

false-negative indicator end_of_HTTP_chunk in readchunk #3362

Merged
merged 1 commit into from
Nov 24, 2018
Merged

false-negative indicator end_of_HTTP_chunk in readchunk #3362

merged 1 commit into from
Nov 24, 2018

Conversation

mnacharov
Copy link
Contributor

@mnacharov mnacharov commented Oct 24, 2018

What do these changes do?

fix a race-condition bug #3361 by:

  • waking up an await self._wait('readchunk') when on_chunk_complete called
  • return ("", True) in readchunk when buffer is empty, but _http_chunk_splits isn't and the end user already has a full chunk of data pos==cursor (on_chunk_complete called recently)

Are there changes in behavior for the user?

Related issue number

#3361

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."

@codecov-io
Copy link

codecov-io commented Oct 24, 2018

Codecov Report

Merging #3362 into master will decrease coverage by 0.03%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #3362      +/-   ##
==========================================
- Coverage   98.01%   97.97%   -0.04%     
==========================================
  Files          44       44              
  Lines        8396     8402       +6     
  Branches     1374     1376       +2     
==========================================
+ Hits         8229     8232       +3     
- Misses         69       71       +2     
- Partials       98       99       +1
Impacted Files Coverage Δ
aiohttp/streams.py 99.22% <100%> (+0.01%) ⬆️
aiohttp/tcp_helpers.py 90% <0%> (-6.67%) ⬇️
aiohttp/client_reqrep.py 97.28% <0%> (-0.16%) ⬇️

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 49261c1...09a7f1f. Read the comment docs.

@mnacharov
Copy link
Contributor Author

tests added

@mnacharov
Copy link
Contributor Author

@webknjaz @asvetlov review needed

@asvetlov
Copy link
Member

I can find a time tomorrow only

@mnacharov
Copy link
Contributor Author

ok. thanks

@webknjaz
Copy link
Member

Deferring review to @asvetlov

@asvetlov asvetlov mentioned this pull request Nov 8, 2018
@mnacharov
Copy link
Contributor Author

@asvetlov ping

@asvetlov
Copy link
Member

On my radar

@asvetlov asvetlov merged commit b20c740 into aio-libs:master Nov 24, 2018
@asvetlov
Copy link
Member

Perfect! Thanks!

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

@mnach the PR introduces the #3362 bug FYI

@K900
Copy link

K900 commented Jan 4, 2019

#3477, not #3362

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

Streams code is too complex to fit in my brain.
It should be reimplemented in a more straightforward and maintainable way.
If nobody will come up with the fix -- I'm going to revert the change in a day or two, sorry.

@socketpair
Copy link
Contributor

socketpair commented Jan 4, 2019

@asvetlov Everything covered with tests. Please do not revert. We thoroughly tested it during bug fixing. Yes, it is complex. Yes it should be re-implemented. But do not revert, maybe I will help

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

With the PR the following snippet never passes all 100 iterations.
It can fail on 5th or 20th but never finishes.
Reverting the PR "fixes" the problem.

If you or @mnach want to work on it -- it would be fine.
I can wait for a while but we need to publish a bugfix release either with the fix or with the rollback.

import aiohttp
import asyncio
import sys


async def main():
    async with aiohttp.ClientSession() as sess:
        for i in range(100):
            async with sess.get('https://api.scryfall.com/cards/random') as resp:
                ret = await resp.json()
                if ret is None:
                    print('Fail', i)
                    return 123
    return 0

sys.exit(asyncio.run(main()))

@socketpair
Copy link
Contributor

Yes, I want to work on this bproblem.

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

Perfect!
Thank you!
Reverting is not my preference, better to find a fix. I've tried and failed :(

@socketpair
Copy link
Contributor

never passes all 100 iterations.

with SSL-related traceback ? or just 123 ?

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

It depends:

andrew•~/projects/aiohttp(master⚡)» python fail_ssl.py                                             (aiohttp)  [13:32:49]
Fail 8
andrew•~/projects/aiohttp(master⚡)» python fail_ssl.py                                             (aiohttp)  [13:57:06]
Fail 1
andrew•~/projects/aiohttp(master⚡)» python fail_ssl.py                                             (aiohttp)  [13:57:10]
Fail 3
andrew•~/projects/aiohttp(master⚡)» python fail_ssl.py                                             (aiohttp)  [13:57:13]
Fail 3
SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f279c0b9160>
transport: <_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib/python3.7/ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2592)

@socketpair
Copy link
Contributor

socketpair commented Jan 4, 2019

Some debug:

Seems, bug happen when we receive chunked, gzipped content, and when a chunk contains some gzipped data, that is not resolved to any user-visible data since that data is not enough for gzip decoder FSM to output anything.

Seems code is not ready for situation, when some chunk arrived, but no data added to the internal buffer for reading.

Continuing investigation.

@socketpair
Copy link
Contributor

The problem: we can not distiguish between last empty chunk, and generic chunk that yields no data when gzip is used. (!) that's why everything fail.

@asvetlov unrelated problem: why .json() retuns None when no data was read ? There should be exception.

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

Are you sure about gzipped content? I don't see Content-Encoding in return headers:

andrew•neuromation/platform-api-clients/python(refactor-storage-api⚡)» curl -vvv https://api.scryfall.com/cards/random
*   Trying 54.152.127.232...
* TCP_NODELAY set
* Connected to api.scryfall.com (54.152.127.232) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: none
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: CN=api.scryfall.com
*  start date: Dec 25 23:42:57 2018 GMT
*  expire date: Mar 25 23:42:57 2019 GMT
*  subjectAltName: host "api.scryfall.com" matched cert's "api.scryfall.com"
*  issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
*  SSL certificate verify ok.
> GET /cards/random HTTP/1.1
> Host: api.scryfall.com
> User-Agent: curl/7.61.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Date: Fri, 04 Jan 2019 13:12:38 GMT
< Connection: keep-alive
< X-Frame-Options: DENY
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Download-Options: noopen
< X-Permitted-Cross-Domain-Policies: none
< Referrer-Policy: strict-origin-when-cross-origin
< Server: Scryfall API
< Access-Control-Allow-Origin: *
< Access-Control-Allow-Methods: GET, POST, DELETE, OPTIONS
< Access-Control-Allow-Headers: Accept, Accept-Charset, Accept-Language, Authorization, Cache-Control, Content-Language, Content-Type, DNT, Host, If-Modified-Since, Keep-Alive, Origin, Referer, User-Agent, X-Requested-With
< Access-Control-Max-Age: 300
< Cache-Control: no-cache, no-store
< X-Robots-Tag: none
< X-Scryfall-Card-Image: https://img.scryfall.com/cards/large/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.jpg?1543699973
< X-Scryfall-Card: https://scryfall.com/card/aer/104/aetherwind-basker?utm_source=api
< Content-Type: application/json; charset=utf-8
< Content-Disposition: inline
< Content-Transfer-Encoding: binary
< Vary: Accept-Encoding
< Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
< Transfer-Encoding: chunked
< Via: 1.1 vegur
< 
{"object":"card","id":"fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9","oracle_id":"d9ec9a4f-0644-47c5-bc09-1201d5251bde","multiverse_ids":[423771],"mtgo_id":62797,"mtgo_foil_id":62798,"arena_id":64687,"tcgplayer_id":126345,"name":"Aetherwind Basker","lang":"en","released_at":"2017-01-20","uri":"https://api.scryfall.com/cards/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9","scryfall_uri":"https://scryfall.com/card/aer/104/aetherwind-basker?utm_source=api","layout":"normal","highres_image":true,"image_uris":{"small":"https://img.scryfall.com/cards/small/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.jpg?1543699973","normal":"https://img.scryfall.com/cards/normal/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.jpg?1543699973","large":"https://img.scryfall.com/cards/large/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.jpg?1543699973","png":"https://img.scryfall.com/cards/png/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.png?1543699973","art_crop":"https://img.scryfall.com/cards/art_crop/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.jpg?1543699973","border_crop":"https://img.scryfall.com/cards/border_crop/front/f/a/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9.jpg?1543699973"},"mana_cost":"{4}{G}{G}{G}","cmc":7.0,"type_line":"Creature — Lizard","oracle_text":"Trample\nWhenever Aetherwind Basker enters the battlefield or attacks, you get {E} (an energy counter) for each creature you control.\nPay {E}: Aetherwind Basker gets +1/+1 until end of turn.","power":"7","toughness":"7","colors":["G"],"color_identity":["G"],"legalities":{"standard":"not_legal","future":"not_legal","frontier":"legal","modern":"legal","legacy":"legal","pauper":"not_legal","vintage":"legal","penny":"legal","commander":"legal","1v1":"legal","duel":"legal","brawl":"not_legal"},"games":["mtgo","paper"],"reserved":false,"foil":true,"nonfoil":true,"oversized":false,"promo":false,"reprint":false,"set":"aer","set_name":"Aether Revolt","set_uri":"https://api.scryfall.com/sets/a4a0db50-8826-4e73-833c-3fd934375f96","set_search_uri":"https://api.scryfall.com/cards/search?order=set\u0026q=e%3Aaer\u0026unique=prints","scryfall_set_uri":"https://scryfall.com/sets/aer?utm_source=api","rulings_uri":"https://api.scryfall.com/cards/fa04d5fa-6ba2-4833-8ea0-1941a03bd3e9/rulings","prints_search_uri":"https://api.scryfall.com/cards/search?order=released\u0026q=oracleid%3Ad9ec9a4f-0644-47c5-bc09-1201d5251bde\u0026unique=prints","collector_number":"104","digital":false,"rarity":"mythic","flavor_text":"Its frill inspired the design of efficient aether collectors.","illustration_id":"39e4d6ff-afe7-4036-946f-193ba3749228","artist":"Svetlin Velinov","border_color":"black","frame":"2015","frame_effect":"","full_art":false,"story_spotlight":false,"edhrec_rank":5071,"usd":"0.32","eur":"0.33","tix":"0.01","related_uris":{"gatherer":"http://gatherer.wizards.com/Pages/Card/Details.aspx?multiverseid=423771","tcgplayer_decks":"https://decks.tcgplayer.com/magic/deck/search?contains=Aetherwind+Basker\u0026page=1\u0026partner=Scryfall\u0026utm_campaign=affiliate\u0026utm_medium=scryfall\u0026utm_source=scryfall","e* Connection #0 to host api.scryfall.com left intact
dhrec":"http://edhrec.com/route/?cc=Aetherwind+Basker","mtgtop8":"http://mtgtop8.com/search?MD_check=1\u0026SB_check=1\u0026cards=Aetherwind+Basker"},"purchase_uris":{"tcgplayer":"https://shop.tcgplayer.com/magic/aether-revolt/aetherwind-basker?partner=Scryfall\u0026utm_campaign=affiliate\u0026utm_medium=scryfall\u0026utm_source=scryfall","cardmarket":"https://www.cardmarket.com/en/Magic/Products/Singles/Aether-Revolt/Aetherwind-Basker?referrer=scryfall","cardhoarder":"https://www.cardhoarder.com/cards/62797?affiliate_id=scryfall\u0026ref=card-profile\u0026utm_campaign=affiliate\u0026utm_medium=card\u0026utm_source=scryfall"}}%  

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

None is returned by my commit 6a19364
Honestly, I don't recall the reason.
Maybe we should be more strict in this and don't strip data (json.loads('\n{}\n') works perfectly fine).

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

@socketpair we can don't emit empty chunks if EOF is not reached.
feed_eof() can be used for this (may require parser changes)

@socketpair
Copy link
Contributor

I have to go, but I think I will fix it today. I have enough debug information.

@socketpair
Copy link
Contributor

socketpair commented Jan 4, 2019

@asvetlov it seems, that server SOMETIMES return gzipped response:

Starting request -------------------------------------
client_proto: feed_data: b'HTTP/1.1 200 OK\r\nDate: Fri, 04 Jan 2019 13:39:13 GMT\r\nConnection: keep-alive\r\nX-Frame-Options: DENY\r\nX-Xss-Protection: 1; mode=block\r\nX-Content-Type-Options: nosniff\r\nX-Download-Options: noopen\r\nX-Permitted-Cross-Domain-Policies: none\r\nReferrer-Policy: strict-origin-when-cross-origin\r\nServer: Scryfall API\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Allow-Methods: GET, POST, DELETE, OPTIONS\r\nAccess-Control-Allow-Headers: Accept, Accept-Charset, Accept-Language, Authorization, Cache-Control, Content-Language, Content-Type, DNT, Host, If-Modified-Since, Keep-Alive, Origin, Referer, User-Agent, X-Requested-With\r\nAccess-Control-Max-Age: 300\r\nCache-Control: no-cache, no-store\r\nX-Robots-Tag: none\r\nX-Scryfall-Card-Image: https://img.scryfall.com/cards/large/en/w17/18.jpg?1517813031\r\nX-Scryfall-Card: https://scryfall.com/card/w17/18/raise-dead?utm_source=api\r\nContent-Type: application/json; charset=utf-8\r\nContent-Disposition: inline\r\nContent-Transfer-Encoding: binary\r\nVary: Accept-Encoding\r\nContent-Encoding: gzip\r\nStrict-Transport-Security: max-age=31536000; includeSubDomains; preload\r\nTransfer-Encoding: chunked\r\nVia: 1.1 vegur\r\n\r\n'

@webknjaz
Copy link
Member

webknjaz commented Jan 4, 2019

@socketpair server returns gzipped response only if the request says that it'd accept it with Accept-Encoding: gzip:

$ while :; do curl -vvv https://api.scryfall.com/cards/random 2>&1 | grep -i gzip; sleep 0.1; done                           
^C%

$ while :; do curl -vvv -H 'Accept-Encoding: gzip' https://api.scryfall.com/cards/random 2>&1 | grep -i gzip; sleep 0.1; done
> Accept-Encoding: gzip
< Content-Encoding: gzip
> Accept-Encoding: gzip
< Content-Encoding: gzip
> Accept-Encoding: gzip
< Content-Encoding: gzip
^C%

@socketpair
Copy link
Contributor

socketpair commented Jan 4, 2019

@asvetlov I have fixed #3477. It actually was not connected with this one. It was added before in e7c9390 . It was masked :)

@asvetlov
Copy link
Member

asvetlov commented Jan 4, 2019

@socketpair cool!
Thanks

@socketpair
Copy link
Contributor

socketpair commented Jan 4, 2019

@asvetlov, In the end, after my fix all 100 iterations of your program run without any troubles.

@lock
Copy link

lock bot commented Jan 4, 2020

This thread has been automatically locked since there has not been
any recent activity after it was closed. Please open a new issue for
related bugs.

If you feel like there's important points made in this discussion,
please include those exceprts into that new issue.

@lock lock bot added the outdated label Jan 4, 2020
@lock lock bot locked as resolved and limited conversation to collaborators Jan 4, 2020
@psf-chronographer psf-chronographer bot added the bot:chronographer:provided There is a change note present in this PR label Jan 4, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bot:chronographer:provided There is a change note present in this PR outdated
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants