classification
Title: asyncio SSL contexts leak sockets after calling close with certain Apache servers
Type: resource usage Stage: patch review
Components: asyncio Versions: Python 3.7, Python 3.6, Python 3.5
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Mariatta, fafhrd, fafhrd91, grzgrzgrz3, gvanrossum, haypo, ned.deily, rthr, thehesiod, yselivanov
Priority: critical Keywords: patch

Created on 2017-02-01 00:39 by thehesiod, last changed 2017-06-19 17:24 by fafhrd.

Files
File name Uploaded Description Edit
scratch_1.py thehesiod, 2017-02-01 00:42 asyncio SSL socket leak after close
ssl_shutdown_timeout.patch fafhrd91, 2017-02-01 04:35
Pull Requests
URL Status Linked Edit
PR 409 merged fafhrd91, 2017-03-03 23:25
PR 981 merged misg, 2017-04-03 17:11
PR 2062 merged yselivanov, 2017-06-10 04:08
PR 2063 merged yselivanov, 2017-06-10 04:10
PR 2111 merged yselivanov, 2017-06-11 14:17
PR 2112 merged yselivanov, 2017-06-11 14:20
PR 2113 merged yselivanov, 2017-06-11 14:27
PR 2269 open fafhrd91, 2017-06-18 21:45
Messages (25)
msg286573 - (view) Author: Alexander Mohr (thehesiod) * Date: 2017-02-01 00:39
with the attached code note how HttpClient.connection_lost callback is never called for the madis server. The madis server is an apache server, I tried with the OSX apache server and could not reproduce the issue so it seems something particular about their apache version or configuration.  This is a pretty critical issue as close() does not release the socket.
msg286574 - (view) Author: Alexander Mohr (thehesiod) * Date: 2017-02-01 00:42
updating to make default the error case (madis)
msg286586 - (view) Author: Nikolay Kim (fafhrd91) * Date: 2017-02-01 04:35
madis-data.ncep.noaa.gov side does not complete ssl shutdown process.
msg286664 - (view) Author: Alexander Mohr (thehesiod) * Date: 2017-02-01 17:22
Thanks so much for the patch!

may want to change spelling of what was supposed to be "shutdown" =)  Also think it's worth a comment stating why it's needed?  Like certain Apache servers were noticed to not complete the SSL shutdown process.
msg288841 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-03-02 23:48
Can you guys create a PR on github.com/python/cpython?
msg295588 - (view) Author: Mariatta Wijaya (Mariatta) * (Python committer) Date: 2017-06-09 22:14
There are two PRs for this issue. Is one depending on the other?

PR 409 has merge conflict that needs to be resolved.
msg295589 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-09 22:25
> There are two PRs for this issue. Is one depending on the other?

No, they all address slightly different bugs. All need to be merged though.

> PR 409 has merge conflict that needs to be resolved.

Yes, it seems that it's based on 3.6 branch. I asked the author to rebase it.
msg295605 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-10 04:04
New changeset a608d2d5a7f1aabe9bcbfc220135c5e126189390 by Yury Selivanov (Nikolay Kim) in branch 'master':
bpo-29406: asyncio SSL contexts leak sockets after calling close with certain servers (#409)
https://github.com/python/cpython/commit/a608d2d5a7f1aabe9bcbfc220135c5e126189390
msg295636 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-10 14:00
New changeset 6e14fd2a14cef6ea0709ad234ab41198c2195591 by Yury Selivanov in branch '3.6':
[3.6] bpo-29406: asyncio SSL contexts leak sockets after calling close with certain servers (GH-409) (#2062)
https://github.com/python/cpython/commit/6e14fd2a14cef6ea0709ad234ab41198c2195591
msg295637 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-10 14:01
New changeset 1395c58ef7b98f087d1d5d50962fe7a8c032f34d by Yury Selivanov in branch '3.5':
[3.5] bpo-29406: asyncio SSL contexts leak sockets after calling close with certain servers (GH-409) (#2063)
https://github.com/python/cpython/commit/1395c58ef7b98f087d1d5d50962fe7a8c032f34d
msg295659 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2017-06-10 19:31
While testing current 3.6 top of trunk, I noticed spurious error messages being reported that were not causing the tests to fail.  Investigating further, I found the culprit to be this issue's 6e14fd2a14cef6ea0709ad234ab41198c2195591.  Curiously, the errors aren't showing up on buildbots although I can reproduce 100% on both platforms I've tried: Debian Linux and macOS 10.12.  For some reason that needs to be explored, using -W on regrtest causes the messages to be suppressed and the buildbots use -w by default.

$ ./python
Python 3.6.1+ (remotes/upstream/3.6:76eabd3a21, Jun 10 2017, 15:20:44)
[GCC 6.3.0 20170516] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>>

# without -w or -W
$ ./python -m test test_asyncio
Run tests sequentially
0:00:00 [1/1] test_asyncio
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb55423b4>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb5542504>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb639f8bc>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb6126f84>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb6392fbc>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb671dedc>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
1 test OK.

Total duration: 13 sec
Tests result: SUCCESS

# with -w
$ ./python -m test -w test_asyncio
Run tests sequentially
0:00:00 [1/1] test_asyncio
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb4b15b5c>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb581f264>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb53f068c>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb65faf14>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb5816c04>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0xb582dea4>
transport: None
Traceback (most recent call last):
  File "/py/3x/unix/source/Lib/asyncio/sslproto.py", line 660, in _process_write_backlog
    self._transport.write(chunk)
AttributeError: 'NoneType' object has no attribute 'write'
1 test OK.

Total duration: 13 sec
Tests result: SUCCESS

# with -W -> no messages
$ ./python -m test -W test_asyncio
Run tests sequentially
0:00:00 [1/1] test_asyncio
1 test OK.

Total duration: 13 sec
Tests result: SUCCESS
msg295660 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2017-06-10 19:32
Er, "For some reason that needs to be explored, using -W on regrtest causes the messages to be suppressed and the buildbots use -w by default."

That should be "use -W by default".
msg295661 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2017-06-10 19:39
FTR, same behavior with master (3.7) top of trunk.
msg295670 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-10 21:14
Nikolay, can you please take a look?
msg295671 - (view) Author: Nikolay Kim (fafhrd91) * Date: 2017-06-10 21:18
yes, i am on it
msg295690 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 07:36
> yes, i am on it

Nick, have you been able to find what the problem is? If not, we'll need to pull this change out of 3.6.2.
msg295691 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 07:57
> > yes, i am on it

> Nick, have you been able to find what the problem is? If not, we'll need to pull this change out of 3.6.2.

It's interesting to see how `_process_write_backlog` gets called after `_finalize`. One option would be to simply guard `transport.write` with `if transport is not None`, but I'm afraid that we'll only mask the bug then.
msg295692 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 07:58
> It's interesting to see how `_process_write_backlog` gets called after `_finalize`. One option would be to simply guard `transport.write` with `if transport is not None`, but I'm afraid that we'll only mask the bug then.

OTOH we weren't setting the transport to None before, we were just closing it. Is setting it to None really necessary?
msg295714 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 14:28
Alright, let's play it safe. I'm going to be reverting the change from all branches. Nick, if you are able to figure this out please create a new PR.
msg295715 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 14:46
New changeset 09663de203396b28483a570bb268c130b59639cf by Yury Selivanov in branch 'master':
Revert "bpo-29406: asyncio SSL contexts leak sockets after calling close with certain servers (#409)" (#2111)
https://github.com/python/cpython/commit/09663de203396b28483a570bb268c130b59639cf
msg295716 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 14:46
New changeset 83d30bd667924549bacf1428ac3e475cdf9792ae by Yury Selivanov in branch '3.6':
Revert "[3.6] bpo-29406: asyncio SSL contexts leak sockets after calling close with certain servers (GH-409) (#2062)" (#2112)
https://github.com/python/cpython/commit/83d30bd667924549bacf1428ac3e475cdf9792ae
msg295717 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-11 14:46
New changeset 4e9dfe214dff000c5b5ad0d8bd8a393feed1d3cf by Yury Selivanov in branch '3.5':
Revert "[3.5] bpo-29406: asyncio SSL contexts leak sockets after calling close with certain servers (GH-409) (#2063)" (#2113)
https://github.com/python/cpython/commit/4e9dfe214dff000c5b5ad0d8bd8a393feed1d3cf
msg295765 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-06-12 10:43
See also issue 29970.
msg296359 - (view) Author: Grzegorz Grzywacz (grzgrzgrz3) * Date: 2017-06-19 17:21
This is not problem with madis-data.ncep.noaa.gov not doing ssl shutdown, this is problem with asyncio not doing it.

Patch from this #30698 issue fix this too.
msg296360 - (view) Author: Nikolay Kim (fafhrd) Date: 2017-06-19 17:24
Let’s close this issue then. I don’t like it anyway.

> On Jun 19, 2017, at 10:21 AM, Grzegorz Grzywacz <report@bugs.python.org> wrote:
> 
> 
> Grzegorz Grzywacz added the comment:
> 
> This is not problem with madis-data.ncep.noaa.gov not doing ssl shutdown, this is problem with asyncio not doing it.
> 
> Patch from this #30698 issue fix this too.
> 
> ----------
> nosy: +grzgrzgrz3
> 
> _______________________________________
> Python tracker <report@bugs.python.org>
> <http://bugs.python.org/issue29406>
> _______________________________________
History
Date User Action Args
2017-06-19 17:24:50fafhrdsetnosy: + fafhrd
messages: + msg296360
2017-06-19 17:21:03grzgrzgrz3setnosy: + grzgrzgrz3
messages: + msg296359
2017-06-18 21:45:35fafhrd91setpull_requests: + pull_request2319
2017-06-13 10:12:59rthrsetnosy: + rthr
2017-06-12 10:43:37yselivanovsetmessages: + msg295765
2017-06-11 14:46:55yselivanovsetmessages: + msg295717
2017-06-11 14:46:48yselivanovsetmessages: + msg295716
2017-06-11 14:46:38yselivanovsetmessages: + msg295715
2017-06-11 14:28:45yselivanovsetmessages: + msg295714
2017-06-11 14:27:53yselivanovsetpull_requests: + pull_request2166
2017-06-11 14:20:31yselivanovsetpull_requests: + pull_request2165
2017-06-11 14:17:47yselivanovsetpull_requests: + pull_request2164
2017-06-11 07:58:53yselivanovsetmessages: + msg295692
2017-06-11 07:57:29yselivanovsetmessages: + msg295691
2017-06-11 07:36:56yselivanovsetmessages: + msg295690
2017-06-10 21:18:57fafhrd91setmessages: + msg295671
2017-06-10 21:14:30yselivanovsetmessages: + msg295670
2017-06-10 19:39:26ned.deilysetnosy: + haypo
messages: + msg295661
2017-06-10 19:32:46ned.deilysetmessages: + msg295660
2017-06-10 19:31:16ned.deilysetpriority: normal -> critical
nosy: + ned.deily
messages: + msg295659

2017-06-10 14:01:19yselivanovsetmessages: + msg295637
2017-06-10 14:00:47yselivanovsetmessages: + msg295636
2017-06-10 04:10:53yselivanovsetpull_requests: + pull_request2125
2017-06-10 04:08:59yselivanovsetpull_requests: + pull_request2124
2017-06-10 04:04:41yselivanovsetmessages: + msg295605
2017-06-09 22:25:43yselivanovsetmessages: + msg295589
2017-06-09 22:14:21Mariattasetnosy: + Mariatta
messages: + msg295588
2017-06-09 22:04:03Mariattasetstage: patch review
versions: + Python 3.7
2017-04-03 17:11:06misgsetpull_requests: + pull_request1154
2017-03-03 23:25:45fafhrd91setpull_requests: + pull_request371
2017-03-02 23:48:45yselivanovsetmessages: + msg288841
2017-02-01 17:22:29thehesiodsetmessages: + msg286664
2017-02-01 04:35:54fafhrd91setversions: + Python 3.6
2017-02-01 04:35:25fafhrd91setfiles: + ssl_shutdown_timeout.patch

nosy: + fafhrd91
messages: + msg286586

keywords: + patch
2017-02-01 00:42:25thehesiodsetfiles: - scratch_1.py
2017-02-01 00:42:01thehesiodsetfiles: + scratch_1.py

messages: + msg286574
2017-02-01 00:39:05thehesiodcreate