Ignore specific errors when closing ssl connections

[dimaqq]

BPO	39951
Nosy	@tiran, @fantix, @asvetlov, @dimaqq, @1st1, @kumaraditya303

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2022-03-12.14:03:27.004>
created_at = <Date 2020-03-13.03:40:00.997>
labels = ['expert-SSL', 'type-bug', '3.9', '3.10', '3.11', 'expert-asyncio']
title = 'Ignore specific errors when closing ssl connections'
updated_at = <Date 2022-03-12.14:03:27.004>
user = 'https://github.com/dimaqq'

bugs.python.org fields:

activity = <Date 2022-03-12.14:03:27.004>
actor = 'asvetlov'
assignee = 'none'
closed = True
closed_date = <Date 2022-03-12.14:03:27.004>
closer = 'asvetlov'
components = ['asyncio', 'SSL']
creation = <Date 2020-03-13.03:40:00.997>
creator = 'Dima.Tisnek'
dependencies = []
files = []
hgrepos = []
issue_num = 39951
keywords = []
message_count = 13.0
messages = ['364071', '364073', '365293', '365299', '379902', '386513', '386514', '386515', '386516', '386518', '386520', '414794', '414798']
nosy_count = 6.0
nosy_names = ['christian.heimes', 'fantix', 'asvetlov', 'Dima.Tisnek', 'yselivanov', 'kumaraditya']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue39951'
versions = ['Python 3.9', 'Python 3.10', 'Python 3.11']

[dimaqq]

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

[dimaqq]

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)

[dimaqq]

Let's close this in favour of https://bugs.python.org/issue39953 which has a pending pull request #19082

[dimaqq]

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.

[dimaqq]

https://bugs.python.org/issue39953 has landed and the errors are now more sensible:
(that patch was not backported to 3.7, because it's not a security issue).

Python 3.7.8 [SSL: KRB5_S_INIT] application data after close notify
Python 3.8.5 [SSL: APPLICATION_DATA_AFTER_CLOSE_NOTIFY] application data after close notify
Python 3.9.0 [SSL: APPLICATION_DATA_AFTER_CLOSE_NOTIFY] application data after close notify
Python 3.10.0a1 [SSL: APPLICATION_DATA_AFTER_CLOSE_NOTIFY] application data after close notify

I guess I shall work on a patch to ignore this specific error when closing the connection.

I would appreciate guidance on half-closed state that, it seems, is possible since TLS 1.3 🤔

[fantix]

This should/will be fixed by #62175 I think - like suggested in the OpenSSL comments, the proposed change will always try to run SSL_read() before SSL_shutdown(), even after the close_notify is sent.

[dimaqq]

@fantix alas, no:

~/cpython (asvetlov--new-ssl|✚1) [1] > ./python.exe ~/repro-39951.py
Traceback (most recent call last):
  File "/Users/dima.tisnek/repro-39951.py", line 33, in <module>
    asyncio.run(test())
  File "/Users/dima.tisnek/cpython/Lib/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Users/dima.tisnek/cpython/Lib/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/Users/dima.tisnek/repro-39951.py", line 30, in test
    await w.wait_closed()
  File "/Users/dima.tisnek/cpython/Lib/asyncio/streams.py", line 359, in wait_closed
    await self._protocol._get_close_waiter(self)
  File "/Users/dima.tisnek/cpython/Lib/asyncio/sslproto.py", line 638, in _do_shutdown
    self._sslobj.unwrap()
  File "/Users/dima.tisnek/cpython/Lib/ssl.py", line 948, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2730)

[dimaqq]

Added 3.10 target.

[tiran]

3.7 is in security fix-only mode.

APPLICATION_DATA_AFTER_CLOSE_NOTIFY is a protocol violation in any TLS version. It's not related to TLS 1.3. The error occurs when one side wants to close the connection, but the other sides keeps sending user data. It's bug in higher level application could. The ssl module cannot ignore this error condition.

https://github.com/openssl/openssl/blob/76624df15fef0725f28a8b9d0f31256946669b1a/ssl/record/rec_layer_s3.c#L1635-L1648

[dimaqq]

Thank you, Christian, for removing 3.7 target, I was not up to date on Python support schedule.

Regarding protocol violation, let me explain what I've dug up so far... I am not an expert, please feel free to correct me.

TLS up to 1.2
Closing a connection (sending close notifies) closes both directions at once.
However, something like a data race is possible:
Let's say "our" side sent close notify at t0, which arrives at "their" side at t1, and the packet that "their" sent at "t1" arrives back to "us"
at t2.
"Their" side can legitimately continue to send data during t0..t1, as it has not received the close notify yet.
This data can arrive at "our" side anywhere within t0...t2 period.
Current implementation treats this data as protocol violation.
I don't believe it should, because the data was legitimate at the time it was sent. It should most likely be discarded though.

TLS 1.3 and later
Closing a connection only closes one half of the connection, the other half is closed after the round trip. (I'm not clear whether that's always the case, or if that's an option).
Current implementation is simply unprepared for half-closed connections (I think) and thus in a way, unprepared for TLS 1.3

[tiran]

TLS 1.2 has one-way close notify. For example typical HTTP clients like curl send a close_notify and then shut down the TCP connection. HTTP servers may not reply with close_notify or may not wait for the client to confirm the server-side close notify.

Python's ssl module does not support one-way close yet. It's an unfortunate limitation of the API that predates my involvement in the ssl module. The unwrap() methods always performs a blocking two-way shutdown. unwrap() calls SSL_shutdown() twice to downgrade a TLS connection to a plain TCP connection. The unwrap() API also requires cooperation from both parties.

https://tools.ietf.org/html/rfc5246#section-7.2.1
https://www.openssl.org/docs/manmaster/man3/SSL_shutdown.html

[kumaraditya303]

@asvetlov This has been fixed on main branch with bpo-44011. This can be closed now.

[tiran]

The bug should be fixed in 3.9 and 3.10 maintenance branches, too.