"Application data after close notify" regression in 3.5.0 with SSL connection

[K900]

I'm running this code:

import aiohttp
import asyncio

async def main():
    async with aiohttp.ClientSession() as sess:
        async with sess.get('https://api.scryfall.com/cards/random') as resp:
            print(await resp.json())

asyncio.run(main())

With aiohttp 3.5.1 on Arch Linux testing (Python 3.7.2, OpenSSL 1.1.1a).

The request to the same URL goes through correctly with curl, and sometimes (very rarely) with aiohttp, but most of the time aiohttp returns None and produces the following error:

SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7fa5894fc080>
transport: <_SelectorSocketTransport fd=6 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:2605)

Edit: this is a regression between 3.4.4 and 3.5.0

[aio-libs-bot]

GitMate.io thinks the contributor most likely able to help you is @asvetlov.

Possibly related issues are #3052 (SSL with closed connections), #3242 (Error), #2822 (Unexpected SSL error (CERTIFICATE_VERIFY_FAILED)), #2497 (ClientSession keep transferring data after closed), and #370 (Server closes connection before sending data).

[scotloach]

I've been seeing this as well, with some sites most of my https transfers are failing.

[scotloach]

Pin it to 3.4.4 until this gets cleared.

[K900]

Yep, that's what I've done.

[asvetlov]

Thanks for the report.
The strange thing is that aiohttp didn't change SSL related code between 3.4 and 3.5 releases, at least intentionally.

[asvetlov]

After git bisect I've found the problematic commit: b20c740
It is the #3361 issue, PR #3362

[socketpair]

@mnach We have to fix that. Please be involved.

[webknjaz]

@socketpair it looks like after his PR @mnach doesn't have any GH activity. I wouldn't count on him receiving these notifications.

[socketpair]

@webknjaz, @mnach is my colleague :)

Well, seems, I fix your bug, Now, I'm writing tests and so on. Thanks for sample of code to reproduce it. Also, it seems, your server (or servers) sometimes respond with gzipped, and sometimes with plain responses. This could mean wrong server setup or incoherent configuration.

[webknjaz]

@socketpair can you provide a reproducer for inconsistent aiohttp server response compression?

[socketpair]

@K900 Problem is fixed. Please re-check. Thanks for bug report.

[socketpair]

@socketpair can you provide a reproducer for inconsistent aiohttp server response compression?

#3485 (comment)

[yjqiang]

Still showing.
@K900 Sorry to bother you, but I think I met the same problem like your issue, after I updated aiohttp to v3.5.4. So maybe this issue still can't be closed right now.

SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x0000022FA2AA63C8>
transport: <_ProactorSocketTransport fd=2708 read=<_OverlappedFuture pending overlapped=<pending, 0x22fa1907430> cb=[_ProactorReadPipeTransport._loop_reading()]>>
Traceback (most recent call last):
  File "D:\ProgramData\Anaconda3\lib\asyncio\sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "D:\ProgramData\Anaconda3\lib\asyncio\sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "D:\ProgramData\Anaconda3\lib\ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2592)

Python 3.7.1 (default, Dec 10 2018, 22:54:23) [MSC v.1915 64 bit (AMD64)] :: Anaconda, Inc. on win32
OpenSSL 1.1.1a 20 Nov 2018
aiohttp 3.5.4

[Cadair]

I too am still getting this error on 3.5.4.

[socketpair]

:( could you provide sample program that triggers that ?

[socketpair]

As far as I remember, my patch helped. Something new ? I would like to fix again.

[Cadair]

This example recreates it for me:

import asyncio
import aiohttp

print(aiohttp.__version__)

url = "https://github.com/sunpy/sample-data/blob/master/sunpy/v1/AIA20110607_063303_0335_lowres.fits?raw=true"


async def run_example():
    async with aiohttp.ClientSession() as session:
        async with session.get(url) as resp:
            print(resp)

asyncio.run(run_example())

[socketpair]

@Cadair I can not reproduce the bug. I use latest Aiohttp from corresponding branch. I tried many times. The output is always

3.5.4
<ClientResponse(https://media.githubusercontent.com/media/sunpy/sample-data/master/sunpy/v1/AIA20110607_063303_0335_lowres.fits) [200 OK]>
<CIMultiDictProxy('Cache-Control': 'max-age=300', 'Content-Security-Policy': "default-src 'none'", 'Content-Type': 'application/octet-stream', 'Etag': '"29b208b8ee35bfe14c18d7a2923b1f1445ea1f09f9c524a7da06ac798bca495a"', 'Last-Modified': 'Sun, 17 Mar 2019 17:54:36 GMT', 'Strict-Transport-Security': 'max-age=31557600', 'Timing-Allow-Origin': 'https://github.com', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'deny', 'X-Xss-Protection': '1; mode=block', 'X-GitHub-Request-Id': '71AE:1E09:751F4A:82C2FC:5C8E89DB', 'Content-Length': '979200', 'Accept-Ranges': 'bytes', 'Date': 'Sun, 17 Mar 2019 17:55:30 GMT', 'Via': '1.1 varnish', 'Connection': 'keep-alive', 'X-Served-By': 'cache-hhn1525-HHN', 'X-Cache': 'HIT', 'X-Cache-Hits': '1', 'X-Timer': 'S1552845330.227869,VS0,VE0', 'Access-Control-Allow-Origin': '*', 'X-Fastly-Request-ID': 'bc488afaa8da780583be5b36157e5c3c8b7273e9', 'Expires': 'Sun, 17 Mar 2019 18:00:30 GMT', 'Source-Age': '54', 'Vary': 'Authorization,Accept-Encoding')>

But Python version is 3.6.7

[Cadair]

This is on Python 3.7, I will test out a few different environments and see how reliable it is to reproduce it.

[yjqiang]

As far as I remember, my patch helped. Something new ? I would like to fix again.

I met this when I executed a script for about a day. Because the network is not stable, so I met something like timeout, and then that message showed.

[minrk]

@Cadair's example reproduces this issue pretty reliably (25-50% of the time) for me with:

• Python 3.7.2
• openssl 1.1.1b
• macOS 10.14.3

This Python comes via conda-forge.

However, when I run it with homebrew-installed Python 3.7.2, which links openssl 1.0.2r, I don't see the issue. So maybe there is something in openssl 1.1?

[poljar]

@Cadair's example reproduces this for me as well with:

• Python 3.7.3
• openssl 1.1.1b
• ArchLinux
• aiohttp 3.5.4

[frxncisjoseph]

Same issue.

context: {'message': 'SSL error in data received', 'exception': SSLError(1, '[SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2580)'), 'transport': <_SelectorSocketTransport fd=857 read=polling write=<idle, bufsize=0>>, 'protocol': <asyncio.sslproto.SSLProtocol object at 0x7f41646b4978>}
Traceback (most recent call last):
  File "/usr/lib64/python3.7/asyncio/base_events.py", line 1626, in call_exception_handler
    self._exception_handler(self, context)
  File "/usr/local/lib/python3.7/site-packages/pypeln/asyncio_task.py", line 587, in exception_handler
    _handle_async_exception(loop, ctx)
  File "/usr/local/lib/python3.7/site-packages/pypeln/asyncio_task.py", line 556, in _handle_async_exception
    raise ctx["exception"]
  File "/usr/lib64/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/lib64/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/lib64/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:2580)

[socketpair]

Hi all. I still can not reproduce the bug.

@Cadair

$ python3.7 ./qwe.py
3.5.4
<ClientResponse(https://media.githubusercontent.com/media/sunpy/sample-data/master/sunpy/v1/AIA20110607_063303_0335_lowres.fits) [200 OK]>
<CIMultiDictProxy('Cache-Control': 'max-age=300', 'Content-Security-Policy': "default-src 'none'", 'Content-Type': 'application/octet-stream', 'Etag': '"29b208b8ee35bfe14c18d7a2923b1f1445ea1f09f9c524a7da06ac798bca495a"', 'Last-Modified': 'Wed, 03 Apr 2019 16:10:50 GMT', 'Strict-Transport-Security': 'max-age=31557600', 'Timing-Allow-Origin': 'https://github.com', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'deny', 'X-Xss-Protection': '1; mode=block', 'X-GitHub-Request-Id': '2DA4:0D74:132D29:158B8E:5CA4DB09', 'Content-Length': '979200', 'Accept-Ranges': 'bytes', 'Date': 'Wed, 03 Apr 2019 16:11:11 GMT', 'Via': '1.1 varnish', 'Connection': 'keep-alive', 'X-Served-By': 'cache-ams21035-AMS', 'X-Cache': 'HIT', 'X-Cache-Hits': '1', 'X-Timer': 'S1554307872.536458,VS0,VE5', 'Access-Control-Allow-Origin': '*', 'X-Fastly-Request-ID': '17e5e709e2b2de1e6d84914e628b76ed3ae794bc', 'Expires': 'Wed, 03 Apr 2019 16:16:11 GMT', 'Source-Age': '21', 'Vary': 'Authorization,Accept-Encoding')>

$ dpkg -l | fgrep openssl
ii  openssl                                    1.1.0g-2ubuntu4.3                            amd64        Secure Sockets Layer toolkit - cryptographic utility

$ python3.7 --version
Python 3.7.1

[yjqiang]

@socketpair I sometimes met this when the network is not stable. And you might need to execute the script again and again. It is not reproduced easily, but we are sure we saw it.

[davidb1]

I'm getting this when I set timeout to be too low and make a request for a large https image for example, pretty much always reproduces

async with aiohttp.request(method="GET", url=image_url, headers=hdrs, timeout=aiohttp.client.ClientTimeout(total=0.1)) as response:
        return await response.read()

Getting this error:

Traceback (most recent call last):
  File "/home/compute/.conda/envs/mask_rcnn_server/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/home/compute/.conda/envs/mask_rcnn_server/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/home/compute/.conda/envs/mask_rcnn_server/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:2609)

[webknjaz]

@davidb1 I cannot reproduce this following your instructions. If I set a low timeout and download a 100MB file I get TimeoutError raised.

$ ipython
Python 3.7.1 (default, Jan 28 2019, 08:25:13)
Type 'copyright', 'credits' or 'license' for more information
IPython 7.2.0 -- An enhanced Interactive Python. Type '?' for help.

In [1]:

In [2]: aiohttp.__version__
Out[2]: '4.0.0a0'
...
In [20]: import ssl

In [21]: ssl.OPENSSL_VERSION
Out[21]: 'OpenSSL 1.1.0j  20 Nov 2018'

Please verify what openssl version your ssl module is linked against.

[luxunator]

@socketpair I noticed that a common occurrence is that using openssl version 1.1.1b so i downgraded to 1.1.1a and same issue then 1.1.1 and the ssl.SSLError still showed. i couldn't downgrade further without breaking the system. But from seeing on here 1.1.0g and under works. Maybe issue is somewhere above ssl version 1.1.0g?

[socketpair]

Try bisect deeper. Docker ? for example install Ubuntu 16.04 or so.

[asvetlov]

@socketpair yes, OpenSSL changed behavior a little on SSL shutdown stage.

python/cpython#13548 fixes the log output. Maybe I'll fix sslproto.py for not generating the exception at all, but suppressing asyncio logging on OSError is valuable anyway.

[asvetlov]

See also #3535 -- it should be fixed too.