ProactorEventLoop raises AssertionError

[twisteroidambassador]

BPO	33833
Nosy	@vstinner, @asvetlov, @1st1, @twisteroidambassador, @miss-islington
PRs	bpo-33833: Fix ProactorSocketTransport AssertionError #7632 bpo-33833: Fix ProactorSocketTransport AssertionError (v2) #7893 [3.7] bpo-33833: Fix ProactorSocketTransport AssertionError (GH-7893) #8575
Files	test_proactor_force_close.py

^{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 2018-07-30.20:14:24.359>
created_at = <Date 2018-06-11.13:47:30.402>
labels = ['3.8', 'type-bug', '3.7', 'expert-asyncio']
title = 'ProactorEventLoop raises AssertionError'
updated_at = <Date 2018-07-30.22:13:58.314>
user = 'https://github.com/twisteroidambassador'

bugs.python.org fields:

activity = <Date 2018-07-30.22:13:58.314>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2018-07-30.20:14:24.359>
closer = 'asvetlov'
components = ['asyncio']
creation = <Date 2018-06-11.13:47:30.402>
creator = 'twisteroid ambassador'
dependencies = []
files = ['47639']
hgrepos = []
issue_num = 33833
keywords = ['patch']
message_count = 8.0
messages = ['319302', '319306', '320584', '320642', '320643', '322685', '322687', '322693']
nosy_count = 5.0
nosy_names = ['vstinner', 'asvetlov', 'yselivanov', 'twisteroid ambassador', 'miss-islington']
pr_nums = ['7632', '7893', '8575']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue33833'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[twisteroidambassador]

Sometimes when a socket transport under ProactorEventLoop is writing while the peer closes the connection, asyncio logs an AssertionError.

Attached is a script that fairly reliably reproduces the behavior on my computer.

This is caused by _ProactorBasePipeTransport._force_close() being called between two invocations of _ProactorBaseWritePipeTransport._loop_writing(), where the latter call asserts self._write_fut has not changed after being set by the former call.

[1st1]

Adding Victor as he's been helping with asyncio/proactor lately.

[vstinner]

Sometimes when a socket transport under ProactorEventLoop is writing while the peer closes the connection, asyncio logs an AssertionError.

Would you mind to add an example of such error in this issue?

[twisteroidambassador]

No problem. Running the attached test script on latest master, Windows 10 1803, several errors like this are logged:

Exception in callback _ProactorBaseWritePipeTransport._loop_writing(<_OverlappedF...events.py:479>)
handle: <Handle _ProactorBaseWritePipeTransport._loop_writing(<_OverlappedF...events.py:479>) created at %USERPROFILE%\source\repos\cpython\lib\asyncio\proactor_events.py:373>
source_traceback: Object created at (most recent call last):
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\base_events.py", line 555, in run_until_complete
    self.run_forever()
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\base_events.py", line 523, in run_forever
    self._run_once()
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\base_events.py", line 1750, in _run_once
    handle._run()
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "..\..\..\..\Documents\python\test_proactor_force_close.py", line 8, in server_callback
    writer.write(b'hello')
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\streams.py", line 305, in write
    self._transport.write(data)
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\proactor_events.py", line 334, in write
    self._loop_writing(data=bytes(data))
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\proactor_events.py", line 373, in _loop_writing
    self._write_fut.add_done_callback(self._loop_writing)
Traceback (most recent call last):
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "%USERPROFILE%\source\repos\cpython\lib\asyncio\proactor_events.py", line 346, in _loop_writing
    assert f is self._write_fut
AssertionError

[twisteroidambassador]

As an aside, I'm wondering whether it makes sense to add a blanket "assert exception handler has not been called" condition to ProactorEventLoop's tests, or even other asyncio tests. It looks like ProactorEventLoop is more prone to dropping exceptions on the floor than SelectorEventLoop.

[asvetlov]

New changeset 9045199 by Andrew Svetlov (twisteroid ambassador) in branch 'master':
bpo-33833: Fix ProactorSocketTransport AssertionError (bpo-7893)
9045199

[miss-islington]

New changeset d5c75be by Miss Islington (bot) in branch '3.7':
bpo-33833: Fix ProactorSocketTransport AssertionError (GH-7893)
d5c75be

[vstinner]

Why not fixing Python 3.6? It is not affected?

[BoilingNine]

I still get this problem when I call asyncio.run from a child thread in a loop

Exception in callback _ProactorBaseWritePipeTransport._loop_writing(<_OverlappedF...hed result=27>)
handle: <Handle _ProactorBaseWritePipeTransport._loop_writing(<_OverlappedF...hed result=27>)>
Traceback (most recent call last):
  File "D:\software\.pyenv\pyenv-win-master\pyenv-win\versions\3.11.9\Lib\asyncio\events.py", line 84, in _run
    self._context.run(self._callback, *self._args)
  File "D:\software\.pyenv\pyenv-win-master\pyenv-win\versions\3.11.9\Lib\asyncio\proactor_events.py", line 381, in _loop_writing
    assert f is self._write_fut
           ^^^^^^^^^^^^^^^^^^^^
AssertionError  ```