test_read_pty_output() of test_asyncio hangs on macOS 10.13.2 (darwin 17.3.0)

[vstinner]

BPO	32517
Nosy	@ronaldoussoren, @vstinner, @ned-deily, @asvetlov, @1st1, @n8henrie, @mattbillenstein, @miss-islington
PRs	bpo-32517: fix test_read_pty_output() hangs on macOS 10.13.2+ #6037 [3.7] bpo-32517: fix test_read_pty_output() hangs on macOS 10.13.2+ (GH-6037) #6038 bpo-32517: re-enable test_read_pty_output on macOS #6112 bpo-32517: fix test_read_pty_output() hangs on macOS 10.13.2+ (GH-6037) #6113

^{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-03-27.21:19:53.424>
created_at = <Date 2018-01-07.23:03:38.358>
labels = ['OS-mac', '3.8', '3.7', 'tests', 'expert-asyncio']
title = 'test_read_pty_output() of test_asyncio hangs on macOS 10.13.2 (darwin 17.3.0)'
updated_at = <Date 2018-03-27.21:19:53.423>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2018-03-27.21:19:53.423>
actor = 'ned.deily'
assignee = 'none'
closed = True
closed_date = <Date 2018-03-27.21:19:53.424>
closer = 'ned.deily'
components = ['macOS', 'Tests', 'asyncio']
creation = <Date 2018-01-07.23:03:38.358>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 32517
keywords = ['patch']
message_count = 14.0
messages = ['309650', '309665', '309690', '309727', '310274', '310276', '313014', '313473', '313491', '313492', '313812', '313813', '314550', '314551']
nosy_count = 8.0
nosy_names = ['ronaldoussoren', 'vstinner', 'ned.deily', 'asvetlov', 'yselivanov', 'n8henrie', 'mattbillenstein', 'miss-islington']
pr_nums = ['6037', '6038', '6112', '6113']
priority = None
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue32517'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[vstinner]

On buildbot x86-64 Sierra 3.6, since build 163, test_read_pty_output() of test_asyncio started to hang:

http://buildbot.python.org/all/#/builders/20/builds/163/steps/4/logs/stdio

0:22:40 load avg: 1.73 [329/406/1] test_asyncio crashed (Exit code 1)
Timeout (0:15:00)!
Thread 0x00007fffb5eee340 (most recent call first):
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/selectors.py", line 577 in select
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/asyncio/base_events.py", line 1396 in _run_once
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/asyncio/base_events.py", line 422 in run_forever
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/asyncio/base_events.py", line 455 in run_until_complete
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/test/test_asyncio/test_events.py", line 1536 in test_read_pty_output
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/test/support/init.py", line 555 in wrapper
File "/Users/buildbot/buildarea/3.6.billenstein-sierra/build/Lib/test/support/init.py", line 600 in wrapper
(...)

Difference between pythoninfo of build 162 and 163:

-os.login: buildbot
+os.login: _timed

-os.uname: posix.uname_result(sysname='Darwin', nodename='mattb-mbp2.local', release='17.2.0', version='Darwin Kernel Version 17.2.0: Fri Sep 29 18:27:05 PDT 2017; root:xnu-4570.20.62~3/RELEASE_X86_64', machine='x86_64')
+os.uname: posix.uname_result(sysname='Darwin', nodename='mattb-mbp2.local', release='17.3.0', version='Darwin Kernel Version 17.3.0: Thu Nov 9 18:09:22 PST 2017; root:xnu-4570.31.3~1/RELEASE_X86_64', machine='x86_64')

-platform.platform: Darwin-17.2.0-x86_64-i386-64bit
+platform.platform: Darwin-17.3.0-x86_64-i386-64bit

-sys.version: 3.6.4+ (heads/3.6:aea95c2fbd, Jan 2 2018, 00:22:06) [GCC 4.2.1 Compatible Apple LLVM 9.0.0 (clang-900.0.39.2)]
+sys.version: 3.6.4+ (heads/3.6:a70d5ff992, Jan 4 2018, 01:35:13) [GCC 4.2.1 Compatible Apple LLVM 9.0.0 (clang-900.0.39.2)]

-sysconfig[HOST_GNU_TYPE]: x86_64-apple-darwin17.2.0
+sysconfig[HOST_GNU_TYPE]: x86_64-apple-darwin17.3.0

The os.login change is interesting and curious, and it also looks like a macOS upgrade from Darwin 17.2.0 to 17.3.0.

[ronaldoussoren]

The darwin version change is likely due to an upgrade from macOS 10.13.1 to 10.13.2.

The user change can be due to the introduction of a new system user, but I don't know when user _timed was introduced and don't have 10.3 VMs other than one running 10.13.2. User _timed does not exist on 10.12.6, and is hence a fairly recent addition.

The buildbot operator could verify this by checking the UID for user buildbot, this likely conflicts with user _timed. The fix for that would be the give user buildbot a new UID and chown all files in the buildbot tree to the new UID.

[mattbillenstein]

I don't see a conflict in the uids:

mattb@mattb-mbp2:~ $ id -u buildbot
506
mattb@mattb-mbp2:~ $ id -u _timed
266
mattb@mattb-mbp2:~ $ grep _timed /etc/passwd
_timed:*:266:266:Time Sync Daemon:/var/db/timed:/usr/bin/false
mattb@mattb-mbp2:~ $ grep 506 /etc/passwd
mattb@mattb-mbp2:~ $

Buildbot is started via launchd:

mattb@mattb-mbp2:~ $ sudo cat /Library/LaunchDaemons/net.buildbot.slave.plist
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd"\>
<plist version="1.0">
<dict>
<key>Label</key>
<string>net.buildbot.slave</string>
<key>UserName</key>
<string>buildbot</string>
<key>WorkingDirectory</key>
<string>/Users/buildbot/buildarea</string>
<key>ProgramArguments</key>
<array>
<string>/Users/buildbot/bin/run_slave.sh</string>
</array>
<key>StandardOutPath</key>
<string>twistd.log</string>
<key>StandardErrorPath</key>
<string>twistd.log</string>
<key>KeepAlive</key>
<true/>
<key>SessionCreate</key>
<true/>
</dict>
</plist>

[mattbillenstein]

Note, I can repro running it by hand from the cli. And I cannot repro on 3.x, only 3.6 on the same machine.

[vstinner]

bpo-32578 has been marked as a duplicate of this issue.

[n8henrie]

I can reproduce on my local machine.

MacOS 10.13.2, trying to build 3.6.4. Waited for up to 6 hours for it to fail or finish, never does, just hangs at test_asyncio.

[ned-deily]

Since this is still happening on current macOS 10.13.3, we should get a fix for this in before 3.6.5rc1. PR's welcome!

[n8henrie]

It seems to work if you close proto.transport (as is done in test_write_pty()).

[1st1]

New changeset 12f74d8 by Yury Selivanov (Nathan Henrie) in branch '3.6':
bpo-32517: fix test_read_pty_output() hangs on macOS 10.13.2+ (GH-6037)
12f74d8

[miss-islington]

New changeset 3c39beb by Miss Islington (bot) in branch '3.7':
bpo-32517: fix test_read_pty_output() hangs on macOS 10.13.2+ (GH-6037)
3c39beb