Duplicated connection_made() call for some SSL connections

[kyuupichan]

BPO	30105
Nosy	@1st1, @kyuupichan, @tirkarthi

^{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 2019-09-11.16:46:33.961>
created_at = <Date 2017-04-19.22:36:46.882>
labels = ['type-bug', 'expert-asyncio']
title = 'Duplicated connection_made() call for some SSL connections'
updated_at = <Date 2019-09-11.16:46:33.958>
user = 'https://github.com/kyuupichan'

bugs.python.org fields:

activity = <Date 2019-09-11.16:46:33.958>
actor = 'xtreak'
assignee = 'none'
closed = True
closed_date = <Date 2019-09-11.16:46:33.961>
closer = 'xtreak'
components = ['asyncio']
creation = <Date 2017-04-19.22:36:46.882>
creator = 'kyuupichan'
dependencies = []
files = []
hgrepos = []
issue_num = 30105
keywords = []
message_count = 3.0
messages = ['291919', '323264', '351977']
nosy_count = 3.0
nosy_names = ['yselivanov', 'kyuupichan', 'xtreak']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue30105'
versions = ['Python 3.5', 'Python 3.6']

[kyuupichan]

An asyncio SSL server frequently sees duplicated connection_made() calls for an incoming SSL connection. It does not happen to all SSL connections; perhaps 10-25% of them. It never happens to TCP connections.

Here are some examples of logs from one I run. I see this on MacOSX and DragonflyBSD, others have reported the same on Linux, so I believe it's a quirk in asyncio and not O/S specific. I assume it is a bug in the wrapping of the raw TCP transport with an SSL one.

2017-04-20 07:22:44.676180500 INFO:ElectrumX:[14755] SSL 218.185.137.81:52844, 256 total
2017-04-20 07:22:45.666747500 INFO:ElectrumX:[14756] SSL 218.185.137.81:52847, 256 total

The log is output on a connection_made() callback to a protocol, and not from the protocol's constructor. They are very close together, from the same IP address and ports that are close together. The first connection was closed with connection_lost() before the 2nd connection_made() because the total session count (here 256) did not increase.

Here is another section of my log with 2 more examples. Totals are not monotonic because of course disconnections (not logged) happen all the time.

2017-04-20 07:30:31.529671500 INFO:ElectrumX:[14796] SSL 193.90.12.86:42262, 259 total
2017-04-20 07:31:04.434559500 INFO:ElectrumX:[14797] SSL 70.199.157.209:10851, 259 total
2017-04-20 07:31:05.765178500 INFO:ElectrumX:[14798] SSL 70.199.157.209:10877, 259 total
2017-04-20 07:31:32.305260500 INFO:ElectrumX:[14799] SSL 64.113.32.29:35025, 256 total
2017-04-20 07:31:44.731859500 INFO:ElectrumX:[14800] SSL 188.107.123.236:60867, 255 total
2017-04-20 07:31:45.504245500 INFO:ElectrumX:[14801] SSL 188.107.123.236:60868, 255 total
2017-04-20 07:31:48.943430500 INFO:ElectrumX:[14802] SSL 136.24.49.122:54987, 255 total
2017-04-20 07:31:59.967676500 INFO:ElectrumX:[14803] TCP 113.161.81.136:2559, 256 total
2017-04-20 07:32:03.249780500 INFO:ElectrumX:[14804] SSL 69.121.8.201:63409, 256 total

Another reason I believe this is an asyncio issue on the server side is that someone else's server software that doesn't use asyncio logs in a similar way and does not see duplicated incoming "connections".

[kyuupichan]

Can someone close this please; I submitted this and no longer see it with recent Python versions; I suspect it has been fixed by one of the many SSL fixes in the last 12 months

[tirkarthi]

Closing as per OPs last message. Feel free to reopen if needed. Thanks.