classification
Title: test_asyncio: ProactorEventLoopTests sendfile tests leak references on Windows
Type: Stage: resolved
Components: asyncio Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, giampaolo.rodola, miss-islington, vstinner, yselivanov
Priority: normal Keywords: patch, patch, patch

Created on 2018-01-29 12:43 by vstinner, last changed 2019-01-11 14:11 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
test_aiosend.py vstinner, 2019-01-08 03:07
Pull Requests
URL Status Linked Edit
PR 11461 merged vstinner, 2019-01-07 22:35
PR 11461 merged vstinner, 2019-01-07 22:35
PR 11461 merged vstinner, 2019-01-07 22:35
PR 11469 merged vstinner, 2019-01-08 13:03
PR 11469 merged vstinner, 2019-01-08 13:03
PR 11469 merged vstinner, 2019-01-08 13:03
PR 11471 merged miss-islington, 2019-01-08 13:23
PR 11471 merged miss-islington, 2019-01-08 13:23
PR 11471 merged miss-islington, 2019-01-08 13:23
PR 11489 merged vstinner, 2019-01-10 00:17
PR 11489 merged vstinner, 2019-01-10 00:17
PR 11489 merged vstinner, 2019-01-10 00:17
PR 11519 merged miss-islington, 2019-01-11 13:35
PR 11519 merged miss-islington, 2019-01-11 13:35
PR 11519 merged miss-islington, 2019-01-11 13:35
Messages (17)
msg311116 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:43
AMD64 Windows8.1 Refleaks 3.x:
http://buildbot.python.org/all/#/builders/80/builds/118

test_asyncio leaked [4, 4, 3] memory blocks, sum=11

I reproduced the issue. I'm running test.bisect to try to isolate this bug.
msg311122 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-01-29 12:56
It seems to be related to sendfile():

C:\vstinner\python\master>python -m test -R 3:3 test_asyncio -m test.test_asyncio.test_events.ProactorEventLoopTests.test_sendfile_close_peer_in_middle_of_receiving
Running Debug|x64 interpreter...
Run tests sequentially
0:00:00 [1/1] test_asyncio
beginning 6 repetitions
123456
......
test_asyncio leaked [1, 2, 1] memory blocks, sum=4
test_asyncio failed

1 test failed:
    test_asyncio

Total duration: 1 sec
Tests result: FAILURE
msg311151 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-01-29 17:04
Andrew, please take a look.  I'll have very limited (to no at all) time to work on Python in the next 2 weeks.
msg315727 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-04-25 13:24
The test is still leaking memory blocks. Any progress on investigating the issue?
msg320157 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-06-21 11:00
Oh, I found again this bug while working on my PR 7827 (detect handle leaks on Windows in regrtest).
msg321007 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-03 22:59
See also bpo-33735: my commit 23401fb960bb94e6ea62d2999527968d53d3fc65 fixes a false alarm in regrtest when hunting leaks in test_multiprocessing_spawn or test_multiprocessing_forkserver.
msg333188 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-07 22:56
New changeset df8e1fb4e388e18430a9be8c6ceeb03c330f166c by Victor Stinner in branch 'master':
bpo-32710: test_asyncio: test_sendfile reset policy (GH-11461)
https://github.com/python/cpython/commit/df8e1fb4e388e18430a9be8c6ceeb03c330f166c
msg333193 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-08 01:08
Update:

* test.test_asyncio.test_sendfile.ProactorEventLoopTests.test_sendfile_close_peer_in_the_middle_of_receiving leaks 1 reference per run: this bug is caused by bpo-35682 and fixed by PR 11462
* test.test_asyncio.test_sendfile.ProactorEventLoopTests.test_sendfile_fallback_close_peer_in_the_middle_of_receiving leaks 1 reference per run: I don't understand why.

I spent a lot of time to investigate test_sendfile_fallback_close_peer_in_the_middle_of_receiving() leak and I don't understand the issue. The main loop is BaseEventLoop._sendfile_fallback(). For the specific case of this test, the loop can be simplified to:

        proto = _SendfileFallbackProtocol(transp)
        try:
            while True:
                data = b'x' * (1024 * 64)
                await proto.drain()
                transp.write(data)
        finally:
            await proto.restore()

The server closes the connection after it gets 1024 bytes. The client socket gets a ConnectionAbortedError exception in _ProactorBaseWritePipeTransport._loop_writing() which calls _fatal_error():

        except OSError as exc:
            self._fatal_error(exc, 'Fatal write error on pipe transport')

_fatal_error() calls _force_close() which sets _closing to True and calls protocol.connection_lost(). In the meanwhile, drain() raises ConnectionError because is_closing() is true:

    async def drain(self):
        if self._transport.is_closing():
            raise ConnectionError("Connection closed by peer")
        ...
msg333198 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-08 01:48
Interesting commit. No idea if it's related.

commit 79790bc35fe722a49977b52647f9b5fe1deda2b7
Author: Victor Stinner <vstinner@redhat.com>
Date:   Fri Jun 8 00:25:52 2018 +0200

    bpo-33694: Fix race condition in asyncio proactor (GH-7498)
    
    The cancellation of an overlapped WSARecv() has a race condition
    which causes data loss because of the current implementation of
    proactor in asyncio.
    
    No longer cancel overlapped WSARecv() in _ProactorReadPipeTransport
    to work around the race condition.
    
    Remove the optimized recv_into() implementation to get simple
    implementation of pause_reading() using the single _pending_data
    attribute.
    
    Move _feed_data_to_bufferred_proto() to protocols.py.
    
    Remove set_protocol() method which became useless.
msg333207 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-08 03:07
Attached test_aiosend.py is a simplified version of test to trigger the reference leak. Copy it to Lib/test/ and run:

vstinner@WIN C:\vstinner\python\master>python -m test test_aiosend -R 3:3
Running Debug|x64 interpreter...
Run tests sequentially
0:00:00 [1/1] test_aiosend
beginning 6 repetitions
123456
......
test_aiosend leaked [1, 1, 1] references, sum=3
test_aiosend leaked [1, 2, 1] memory blocks, sum=4
test_aiosend failed

== Tests result: FAILURE ==

1 test failed:
    test_aiosend

Total duration: 548 ms
Tests result: FAILURE
msg333227 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-08 13:12
It took me 1 year, a few sleepless nights, multiple attempts to understand the leak, but I eventually found it! WSASend() doesn't release the memory if it fails immediately. I wrote PR 11469 to fix the memory leak. ReadFile() has the same bug, I also fixed it.

By the way, the _overlapped.Overlapped type has no traverse function: it may help the garbage collector to add once, since asyncio is famous for building reference cycles by design (Future.set_exception()).
msg333228 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-08 13:23
New changeset a234e148394c2c7419372ab65b773d53a57f3625 by Victor Stinner in branch 'master':
bpo-32710: Fix leak in Overlapped_WSASend() (GH-11469)
https://github.com/python/cpython/commit/a234e148394c2c7419372ab65b773d53a57f3625
msg333229 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-08 13:33
I ran test_asyncio refleak hunting on Windows, and there is no more leak!

vstinner@WIN C:\vstinner\python\master>python -m test test_asyncio -R 3:3 
(...)
Total duration: 13 min 24 sec
Tests result: SUCCESS

I will close this PR once the 3.7 backport is merged.
msg333230 - (view) Author: miss-islington (miss-islington) Date: 2019-01-08 13:40
New changeset 88ad48bc98980a40591cc5521703dbb0ad3a9b17 by Miss Islington (bot) in branch '3.7':
bpo-32710: Fix leak in Overlapped_WSASend() (GH-11469)
https://github.com/python/cpython/commit/88ad48bc98980a40591cc5521703dbb0ad3a9b17
msg333467 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-11 13:35
New changeset 5485085b324a45307c1ff4ec7d85b5998d7d5e0d by Victor Stinner in branch 'master':
bpo-32710: Fix _overlapped.Overlapped memory leaks (GH-11489)
https://github.com/python/cpython/commit/5485085b324a45307c1ff4ec7d85b5998d7d5e0d
msg333470 - (view) Author: miss-islington (miss-islington) Date: 2019-01-11 14:01
New changeset 059997d78ed1a1a5a364b1846ac972c98c704927 by Miss Islington (bot) in branch '3.7':
bpo-32710: Fix _overlapped.Overlapped memory leaks (GH-11489)
https://github.com/python/cpython/commit/059997d78ed1a1a5a364b1846ac972c98c704927
msg333472 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-11 14:11
Ok, _overlapped.Overlapped should now have a few less memory leaks :-)
History
Date User Action Args
2019-01-11 14:11:20vstinnersetkeywords: patch, patch, patch

messages: + msg333472
2019-01-11 14:01:53miss-islingtonsetmessages: + msg333470
2019-01-11 13:35:55miss-islingtonsetpull_requests: + pull_request11094
2019-01-11 13:35:47miss-islingtonsetpull_requests: + pull_request11093
2019-01-11 13:35:38miss-islingtonsetpull_requests: + pull_request11092
2019-01-11 13:35:17vstinnersetmessages: + msg333467
2019-01-10 00:18:10vstinnersetpull_requests: + pull_request11006
2019-01-10 00:18:01vstinnersetpull_requests: + pull_request11005
2019-01-10 00:17:52vstinnersetpull_requests: + pull_request11004
2019-01-08 13:46:28vstinnersetkeywords: patch, patch, patch
status: open -> closed
resolution: fixed
stage: patch review -> resolved
2019-01-08 13:40:52miss-islingtonsetnosy: + miss-islington
messages: + msg333230
2019-01-08 13:33:15vstinnersetkeywords: patch, patch, patch

messages: + msg333229
2019-01-08 13:23:51miss-islingtonsetpull_requests: + pull_request10967
2019-01-08 13:23:42miss-islingtonsetpull_requests: + pull_request10966
2019-01-08 13:23:33miss-islingtonsetpull_requests: + pull_request10965
2019-01-08 13:23:19vstinnersetmessages: + msg333228
2019-01-08 13:12:47vstinnersetkeywords: patch, patch, patch

messages: + msg333227
2019-01-08 13:03:49vstinnersetpull_requests: + pull_request10964
2019-01-08 13:03:40vstinnersetpull_requests: + pull_request10963
2019-01-08 13:03:34vstinnersetpull_requests: + pull_request10962
2019-01-08 03:07:28vstinnersetkeywords: patch, patch, patch
files: + test_aiosend.py
messages: + msg333207
2019-01-08 01:48:44vstinnersetkeywords: patch, patch, patch

messages: + msg333198
2019-01-08 01:08:40vstinnersetkeywords: patch, patch, patch

messages: + msg333193
2019-01-08 00:58:10vstinnersetkeywords: patch, patch, patch
title: test_asyncio: ProactorEventLoopTests.test_sendfile_close_peer_in_middle_of_receiving() leaked [4, 4, 3] memory blocks on AMD64 Windows8.1 Refleaks 3.x -> test_asyncio: ProactorEventLoopTests sendfile tests leak references on Windows
2019-01-07 22:56:10vstinnersetmessages: + msg333188
2019-01-07 22:35:24vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request10939
2019-01-07 22:35:15vstinnersetkeywords: + patch
stage: (no value)
pull_requests: + pull_request10938
2019-01-07 22:35:08vstinnersetkeywords: + patch
stage: (no value)
pull_requests: + pull_request10937
2018-07-03 22:59:50vstinnersetmessages: + msg321007
2018-07-03 22:58:18vstinnersettitle: test_asyncio leaked [4, 4, 3] memory blocks, sum=11 on AMD64 Windows8.1 Refleaks 3.x -> test_asyncio: ProactorEventLoopTests.test_sendfile_close_peer_in_middle_of_receiving() leaked [4, 4, 3] memory blocks on AMD64 Windows8.1 Refleaks 3.x
2018-06-21 11:00:03vstinnersetmessages: + msg320157
2018-05-23 13:05:05giampaolo.rodolasetnosy: + giampaolo.rodola
2018-04-25 13:24:27vstinnersetversions: + Python 3.8
2018-04-25 13:24:17vstinnersetmessages: + msg315727
2018-01-29 17:04:09yselivanovsetmessages: + msg311151
2018-01-29 12:56:37vstinnersetmessages: + msg311122
2018-01-29 12:43:38vstinnercreate