Title: Duplicated connection_made() call for some SSL connections
Type: behavior Stage: resolved
Components: asyncio Versions: Python 3.6, Python 3.5
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: kyuupichan, xtreak, yselivanov
Priority: normal Keywords:

Created on 2017-04-19 22:36 by kyuupichan, last changed 2019-09-11 16:46 by xtreak. This issue is now closed.

Messages (3)
msg291919 - (view) Author: Neil Booth (kyuupichan) * Date: 2017-04-19 22:36
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, 256 total
2017-04-20 07:22:45.666747500 INFO:ElectrumX:[14756] SSL, 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, 259 total
2017-04-20 07:31:04.434559500 INFO:ElectrumX:[14797] SSL, 259 total
2017-04-20 07:31:05.765178500 INFO:ElectrumX:[14798] SSL, 259 total
2017-04-20 07:31:32.305260500 INFO:ElectrumX:[14799] SSL, 256 total
2017-04-20 07:31:44.731859500 INFO:ElectrumX:[14800] SSL, 255 total
2017-04-20 07:31:45.504245500 INFO:ElectrumX:[14801] SSL, 255 total
2017-04-20 07:31:48.943430500 INFO:ElectrumX:[14802] SSL, 255 total
2017-04-20 07:31:59.967676500 INFO:ElectrumX:[14803] TCP, 256 total
2017-04-20 07:32:03.249780500 INFO:ElectrumX:[14804] SSL, 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".
msg323264 - (view) Author: Neil Booth (kyuupichan) * Date: 2018-08-08 07:02
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
msg351977 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python committer) Date: 2019-09-11 16:46
Closing as per OPs last message. Feel free to reopen if needed. Thanks.
Date User Action Args
2019-09-11 16:46:33xtreaksetstatus: open -> closed

nosy: + xtreak
messages: + msg351977

resolution: out of date
stage: resolved
2018-08-08 07:02:16kyuupichansetmessages: + msg323264
2017-04-19 22:36:46kyuupichancreate