classification
Title: False timeout log message on proactor close
Type: behavior Stage: resolved
Components: asyncio Versions: Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: John Nelson2, asvetlov, johnboy2, matrixise, vstinner, yselivanov
Priority: normal Keywords: patch, patch, patch

Created on 2018-08-02 22:50 by johnboy2, last changed 2019-01-15 12:06 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
repro.py johnboy2, 2018-08-02 22:50
Pull Requests
URL Status Linked Edit
PR 11494 merged vstinner, 2019-01-10 00:52
PR 11494 merged vstinner, 2019-01-10 00:52
PR 11494 merged vstinner, 2019-01-10 00:52
PR 11555 merged vstinner, 2019-01-14 16:32
PR 11555 merged vstinner, 2019-01-14 16:32
PR 11555 merged vstinner, 2019-01-14 16:32
PR 11565 merged vstinner, 2019-01-15 11:39
PR 11565 merged vstinner, 2019-01-15 11:39
Messages (8)
msg322994 - (view) Author: John Nelson (johnboy2) * Date: 2018-08-02 22:50
Repro:
 1. Run the attached script ('repro.py')

Expected output:

2018-07-31 16:39:57,069 - asyncio - DEBUG - Using proactor: IocpProactor
2018-07-31 16:39:57,084 - root - INFO - Starting
2018-07-31 16:39:58,100 - root - INFO - Sleep done
2018-07-31 16:39:58,100 - root - INFO - Loop closed

Actual output:

2018-07-31 16:37:58,583 - asyncio - DEBUG - Using proactor: IocpProactor
2018-07-31 16:37:58,599 - root - INFO - Starting
2018-07-31 16:37:59,614 - root - INFO - Sleep done
2018-07-31 16:37:59,614 - asyncio - DEBUG - taking long time to close proactor
2018-07-31 16:37:59,614 - root - INFO - Loop closed
msg322995 - (view) Author: John Nelson (johnboy2) * Date: 2018-08-02 22:55
I *suspect* the issue is down to a discrepancy between:
- IocpProactor.close(), and
- IocpProactor._poll()

When the former calls the latter, it seems to be expecting a truth value response from _poll() to indicate that no timeout occurred. However, the latter only ever returns None.

Of note is that `ms != 0` whenever a timeout occurs, potentially giving a simple test point.
msg323035 - (view) Author: Stéphane Wirtel (matrixise) * (Python triager) Date: 2018-08-03 07:08
Hi johnboy2,

thank you for your issue, but could you send us more information about your platform?

thank you
msg323428 - (view) Author: John Nelson (John Nelson2) Date: 2018-08-12 04:56
Python 3.5.4 (v3.5.4:3f56838, Aug  8 2017, 02:17:05) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import platform, sys
>>> platform.win32_ver()
('2012ServerR2', '6.3.9600', 'SP0', 'Multiprocessor Free')
>>> sys.version_info
sys.version_info(major=3, minor=5, micro=4, releaselevel='final', serial=0)
msg333673 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-15 10:48
New changeset b1e45739d832e1e402a563c6727defda92e193b7 by Victor Stinner in branch 'master':
bpo-34323: Enhance IocpProactor.close() log (GH-11555)
https://github.com/python/cpython/commit/b1e45739d832e1e402a563c6727defda92e193b7
msg333681 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-15 11:41
Oops, I used the wrong bpo number for my second change in master:

New changeset b91140fdb17472d03a7b7971f143c08a40fde923 by Victor Stinner in branch 'master':
bpo-11555: Enhance IocpProactor.close() log again (GH-11563)
https://github.com/python/cpython/commit/b91140fdb17472d03a7b7971f143c08a40fde923
msg333688 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-15 12:05
New changeset d5a6adf6285ec8892b977a32c22143ebd1025b50 by Victor Stinner in branch '3.7':
[3.7] bpo-34323: Enhance IocpProactor.close() log (GH-11565)
https://github.com/python/cpython/commit/d5a6adf6285ec8892b977a32c22143ebd1025b50
msg333689 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-01-15 12:06
Ok, the bug is now fixed. Thanks for your bug report John Nelson!
History
Date User Action Args
2019-01-15 12:09:20vstinnerlinkissue35599 superseder
2019-01-15 12:06:28vstinnersetstatus: open -> closed
messages: + msg333689

keywords: patch, patch, patch
resolution: fixed
stage: patch review -> resolved
2019-01-15 12:05:34vstinnersetmessages: + msg333688
2019-01-15 11:41:05vstinnersetkeywords: patch, patch, patch

messages: + msg333681
2019-01-15 11:39:16vstinnersetpull_requests: + pull_request11226
2019-01-15 11:39:05vstinnersetpull_requests: + pull_request11225
2019-01-15 10:48:02vstinnersetnosy: + vstinner
messages: + msg333673
2019-01-14 16:33:08vstinnersetpull_requests: + pull_request11192
2019-01-14 16:32:57vstinnersetpull_requests: + pull_request11191
2019-01-14 16:32:45vstinnersetpull_requests: + pull_request11190
2019-01-10 00:53:05vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request11015
2019-01-10 00:52:55vstinnersetkeywords: + patch
stage: (no value)
pull_requests: + pull_request11014
2019-01-10 00:52:45vstinnersetkeywords: + patch
stage: (no value)
pull_requests: + pull_request11013
2018-08-12 04:56:09John Nelson2setnosy: + John Nelson2
messages: + msg323428
2018-08-03 07:08:00matrixisesetnosy: + matrixise
messages: + msg323035
2018-08-02 22:55:55johnboy2setmessages: + msg322995
2018-08-02 22:50:13johnboy2create