classification
Title: Ignore specific errors when closing ssl connections
Type: Stage: resolved
Components: Extension Modules, Library (Lib) Versions: Python 3.9, Python 3.8, Python 3.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Dima.Tisnek, christian.heimes
Priority: normal Keywords:

Created on 2020-03-13 03:40 by Dima.Tisnek, last changed 2020-04-11 21:17 by SilentGhost.

Messages (4)
msg364071 - (view) Author: Dima Tisnek (Dima.Tisnek) * Date: 2020-03-13 03:40
When a connection wrapped in ssl is closed, sometimes the ssl library reports an error, which I believe should be ignored.

The error code is `291` and the name of the error is either SSL_R_KRB5_S_INIT (KRB5_S_INIT) or SSL_R_APPLICATION_DATA_AFTER_CLOSE_NOTIFY depending on openssl header file.
It's only one code, somehow `ssl.h` (depending on version?) has different symbolic name for the error.
TBH, I consider `KRB5_S_INIT` a misnomer, there's no Kerberos here.

The explanation for openssl reporting this error is here:

https://github.com/openssl/openssl/blob/6d53ad6b5cf726d92860e973d7bc8c1930762086/ssl/record/rec_layer_s3.c#L1657-L1668

> The peer is continuing to send application data, but we have
> already sent close_notify. If this was expected we should have
> been called via SSL_read() and this would have been handled
> above.

This situation is easily achieved, because of network delays. Just because we sent "close notify", doesn't mean the other end has received it, and even if it did, there could still be return data in flight.

Reproducer is here: https://gist.github.com/dimaqq/087c66dd7b4a85a669a00221dc3792ea
msg364073 - (view) Author: Dima Tisnek (Dima.Tisnek) * Date: 2020-03-13 03:52
Reproducer:

""" Reproducer for BPO-39951
We send some data over ssl and close the connection.
The server responds after our openssl considers the connection closed-ish and raises an error.
"""
import asyncio
import ssl

host = "nghttp2.org"
port = 443

ssl_context = ssl.create_default_context()
ssl_context.options |= ssl.OP_NO_TLSv1
ssl_context.options |= ssl.OP_NO_TLSv1_1
ssl_context.set_alpn_protocols(["h2"])

# Captured from an HTTP/2 client
DATA = b'PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n\x00\x00*\x04\x00\x00\x00\x00\x00\x00\x01\x00\x00\x10\x00\x00\x02\x00\x00\x00\x00\x00\x04\x00\x00\xff\xff\x00\x05\x00\x00@\x00\x00\x08\x00\x00\x00\x00\x00\x03\x00\x10\x00\x00\x00\x06\x00\x00\xff\xff\x00\x00\x04\x08\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x04\x01\x00\x00\x00\x00'


async def test():
    r, w = await asyncio.open_connection(host, port, ssl=ssl_context)

    info = w.get_extra_info("ssl_object")
    assert info, "HTTP/2 server is required"
    proto = info.selected_alpn_protocol()
    assert proto == "h2", "Failed to negotiate HTTP/2"

    w.write(DATA)
    w.close()
    await w.wait_closed()


asyncio.run(test())




Test on macOS, using cpython builds from python.org:

… > python3.7 repro-bpo-39951.py
Traceback (most recent call last):
  File "repro-bpo-39951.py", line 34, in <module>
    asyncio.run(test())
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "repro-bpo-39951.py", line 31, in test
    await w.wait_closed()
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/streams.py", line 323, in wait_closed
    await self._protocol._closed
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/sslproto.py", line 530, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 778, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2629)

… > python3.8 repro-bpo-39951.py
Traceback (most recent call last):
  File "repro-bpo-39951.py", line 34, in <module>
    asyncio.run(test())
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "repro-bpo-39951.py", line 31, in test
    await w.wait_closed()
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/streams.py", line 359, in wait_closed
    await self._protocol._get_close_waiter(self)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/sslproto.py", line 529, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/ssl.py", line 948, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2730)

… > python3.9 repro-bpo-39951.py
Traceback (most recent call last):
  File "/.../repro-bpo-39951.py", line 34, in <module>
    asyncio.run(test())
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/.../repro-bpo-39951.py", line 31, in test
    await w.wait_closed()
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/streams.py", line 359, in wait_closed
    await self._protocol._get_close_waiter(self)
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/sslproto.py", line 529, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/ssl.py", line 948, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2730)


Test on Linux (python:3.8.1-alpine3.11):

/ # python repro.py
Traceback (most recent call last):
  File "repro.py", line 33, in <module>
    asyncio.run(test())
  File "/usr/local/lib/python3.8/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 612, in run_until_complete
    return future.result()
  File "repro.py", line 30, in test
    await w.wait_closed()
  File "/usr/local/lib/python3.8/asyncio/streams.py", line 359, in wait_closed
    await self._protocol._get_close_waiter(self)
  File "/usr/local/lib/python3.8/asyncio/sslproto.py", line 529, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/local/lib/python3.8/asyncio/sslproto.py", line 207, in feed_ssldata
    self._sslobj.unwrap()
  File "/usr/local/lib/python3.8/ssl.py", line 948, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2730)
msg365293 - (view) Author: Dima Tisnek (Dima.Tisnek) * Date: 2020-03-30 03:02
Let's close this in favour of https://bugs.python.org/issue39953 which has a pending pull request https://github.com/python/cpython/pull/19082
msg365299 - (view) Author: Dima Tisnek (Dima.Tisnek) * Date: 2020-03-30 05:29
Sorry I was too fast to close this.

39953 is about error codes.

This bug is about having an error at all.

I believe that the code in question should pass without error, even in the presence of network delays.
History
Date User Action Args
2020-04-11 21:17:43SilentGhostsetnosy: + christian.heimes
2020-03-30 05:29:51Dima.Tisneksetstatus: closed -> open
resolution: duplicate ->
messages: + msg365299
2020-03-30 03:02:32Dima.Tisneksetstatus: open -> closed
resolution: duplicate
messages: + msg365293

stage: resolved
2020-03-13 03:52:10Dima.Tisneksetmessages: + msg364073
versions: + Python 3.7
2020-03-13 03:40:01Dima.Tisnekcreate