test_asyncio hanging for 1 hour (AIX version, hangs in test_subprocess_interactive)

[DavidEdelsohn]

BPO	19293
Nosy	@gvanrossum, @tim-one, @db3l, @ncoghlan, @pitrou, @vstinner, @larryhastings, @skrah, @florentx
Files	issue19293.patch: Skip some signal tests in test_events.py asyncio_signal.diff sockpair.diff issue19293.patch2 issue19293.patch3 aixfix2.diff

^{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 = 'https://github.com/gvanrossum'
closed_at = <Date 2013-10-22.04:30:21.433>
created_at = <Date 2013-10-19.04:20:34.913>
labels = ['type-bug', 'tests']
title = 'test_asyncio hanging for 1 hour (AIX version, hangs in test_subprocess_interactive)'
updated_at = <Date 2013-10-22.04:31:54.977>
user = 'https://bugs.python.org/DavidEdelsohn'

bugs.python.org fields:

activity = <Date 2013-10-22.04:31:54.977>
actor = 'David.Edelsohn'
assignee = 'gvanrossum'
closed = True
closed_date = <Date 2013-10-22.04:30:21.433>
closer = 'gvanrossum'
components = ['Tests']
creation = <Date 2013-10-19.04:20:34.913>
creator = 'David.Edelsohn'
dependencies = []
files = ['32225', '32232', '32284', '32289', '32290', '32292']
hgrepos = []
issue_num = 19293
keywords = ['patch']
message_count = 72.0
messages = ['200364', '200372', '200374', '200426', '200433', '200435', '200437', '200438', '200440', '200449', '200452', '200456', '200461', '200463', '200466', '200470', '200475', '200487', '200494', '200505', '200510', '200513', '200514', '200516', '200518', '200520', '200521', '200525', '200530', '200531', '200532', '200533', '200534', '200541', '200543', '200544', '200547', '200551', '200552', '200553', '200582', '200589', '200597', '200598', '200599', '200615', '200666', '200671', '200672', '200689', '200713', '200720', '200745', '200791', '200794', '200806', '200808', '200811', '200814', '200860', '200861', '200867', '200868', '200869', '200872', '200873', '200874', '200876', '200879', '200880', '200881', '200882']
nosy_count = 13.0
nosy_names = ['gvanrossum', 'tim.peters', 'db3l', 'ncoghlan', 'pitrou', 'vstinner', 'larry', 'skrah', 'flox', 'neologix', 'python-dev', 'sbt', 'David.Edelsohn']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue19293'
versions = ['Python 3.4']

[DavidEdelsohn]

test_asyncio times out after one hour on AIX and leaves a process consuming 100% of a thread.

[145/382/3] test_asyncio
Timeout (1:00:00)!
Thread 0x00000001:
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/selectors.py", line 265 in select
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/asyncio/base_events.py", line 576 in _run_once
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/asyncio/base_events.py", line 153 in run_forever
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/asyncio/base_events.py", line 172 in run_until_complete
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/test_asyncio/test_events.py", line 1012 in test_subprocess_interactive
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/case.py", line 571 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/case.py", line 610 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/suite.py", line 117 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/suite.py", line 79 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/suite.py", line 117 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/suite.py", line 79 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/suite.py", line 117 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/suite.py", line 79 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/unittest/runner.py", line 168 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/support/init.py", line 1661 in _run_suite
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/support/init.py", line 1695 in run_unittest
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/test_asyncio/init.py", line 26 in test_main
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/regrtest.py", line 1276 in runtest_inner
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/regrtest.py", line 965 in runtest
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/regrtest.py", line 761 in main
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/regrtest.py", line 1560 in main_in_temp_cwd
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/test/main.py", line 3 in <module>
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/runpy.py", line 73 in _run_code
File "/home/shager/cpython-buildarea/3.x.edelsohn-aix-ppc64/build/Lib/runpy.py", line 160 in _run_module_as_main
make: 1254-004 The error code from the last command is 1.

[gvanrossum]

Is that traceback upside down compared to normal Python tracebacks?

[gvanrossum]

Assuming it is, it is hanging in the poll() syscall, here:
http://hg.python.org/cpython/file/f3a2dab1623b/Lib/selectors.py#265

Could you see if it works better with select()? Comment out lines 402, 403 in that file.

[DavidEdelsohn]

Commenting out poll in selectors.py does not help.

AIX has its own epoll/kqueue efficient I/O event polling feature "pollset", which I will open as a separate enhancement request issue.

Some of the subprocess tests in test_asyncio/test_events.py related to signals are hanging on AIX: test_subprocess_interactive, test_subprocess_kill and test_subprocess_send_signal all hang. This probably is related to Issue bpo-18238 and the tests skipped in test_signal.py.

The attached patch skips those tests on AIX.

[python-dev]

New changeset 41a841fac7fb by Guido van Rossum in branch 'default':
Disable some subprocess tests that hang on AIX.
http://hg.python.org/cpython/rev/41a841fac7fb

[gvanrossum]

Thanks for the investigation and the patch.

As to the deeper issue, I'm not sure I understand what's going on -- is this a bug in Python or in AIX? Is there a better work-around than disabling the test? The bpo-18238 that you mention seems to be closed by disabling tests too, but that seems unsatisfactory.

Is the real issue that select() and poll() on AIX cannot be interrupted by signals? That sounds really sad.

[neologix]

Does AIX have an equivalent to Linux's strace?
If yes, having a sample output would be helpful.

Otherwise, maybe just adding manual debug traces to PollSelector.select() would help to see which events are reported.

[skrah]

I think the failure is not only on AIX. The FreeBSD bots had similar
failures, and here is one on PPC Linux:

http://buildbot.python.org/all/builders/PPC64%20PowerLinux%203.x/builds/881/steps/test/logs/stdio

Timeout (1:00:00)!
Thread 0x0000008074e46670:
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/selectors.py", line 313 in select
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/asyncio/base_events.py", line 576 in _run_once
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/asyncio/base_events.py", line 153 in run_forever
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/asyncio/base_events.py", line 172 in run_until_complete
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/test_asyncio/test_events.py", line 1078 in test_subprocess_close_after_finish
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/case.py", line 571 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/case.py", line 610 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/suite.py", line 117 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/suite.py", line 79 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/suite.py", line 117 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/suite.py", line 79 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/suite.py", line 117 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/suite.py", line 79 in __call__
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/unittest/runner.py", line 168 in run
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/support/init.py", line 1661 in _run_suite
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/support/init.py", line 1695 in run_unittest
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/test_asyncio/init.py", line 26 in test_main
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/regrtest.py", line 1276 in runtest_inner
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/regrtest.py", line 965 in runtest
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/regrtest.py", line 761 in main
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/regrtest.py", line 1560 in main_in_temp_cwd
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/test/main.py", line 3 in <module>
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/runpy.py", line 73 in _run_code
File "/home/shager/cpython-buildarea/3.x.edelsohn-powerlinux-ppc64/build/Lib/runpy.py", line 160 in _run_module_as_main
make: *** [buildbottest] Error 1

[gvanrossum]

[Off-topic: Heck, another one of those upside-down tracebacks. WHY???]

I'll need a lot of help from folks on the affected platforms in debugging this, since these tests work fine when I run them on the platforms to which I have access (Ubuntu and OS X).

I would also like to point out http://code.google.com/p/tulip/issues/detail?id=67 (and the thread referenced in my last message there) as well as http://code.google.com/p/tulip/issues/detail?id=68. Perhaps there are clues there.

I hope that we'll be able to sort this out before the beta release.

[DavidEdelsohn]

My understanding of the issue is POSIX and The Open Group specification are ambiguous about the handling of Unix socket API calls when interrupted by a signal. Linux implements a more liberal, accommodating behavior and the Python Async I/O implementation is assuming those semantics. AIX inherited a lot from OSF, Mac OS X/Darwin inherited a lot from FreeBSD, both of which adopted more "unforgiving behavior".

The following web page seems to summarize the issue:

http://www.madore.org/~david/computers/connect-intr.html

I don't know if the description still is accurate for BSDs, but AIX likely implemented more pedantic, unforgiving semantics.

The standard seems to allow the behavior seen in AIX and FreeBSD, regardless of whether it is less useful / pleasant. From a pedantic standpoint, I think this is a bug in the Python implementation of Async I/O because it assumes behavior (implemented by Linux) not required by an implementation that conforms to the POSIX and Open Group specifications.

[DavidEdelsohn]

Also, the Python buildbot for AIX is running on a POWER AIX 7.1 system at OSU OSL that is a member of the "GCC Compile Farm" cluster on which FOSS developers can obtain free accounts. If you want access to an AIX system for testing, it's available.