test_logging: "OSError: [Errno 9] Bad file descriptor" logged on FreeBSD

[vstinner]

BPO	43842
Nosy	@vstinner
PRs	bpo-43842: Fix race condition in test_logging SMTP test #25436 [3.9] bpo-43842: Fix race condition in test_logging SMTP test (GH-25436) #25437 [3.8] bpo-43842: Fix race condition in test_logging SMTP test (GH-25436) (GH-25437) #25440

^{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 2021-04-16.14:37:42.297>
created_at = <Date 2021-04-14.11:15:16.829>
labels = ['3.8', 'tests', '3.9', '3.10']
title = 'test_logging: "OSError: [Errno 9] Bad file descriptor" logged on FreeBSD'
updated_at = <Date 2021-04-16.14:37:42.297>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-04-16.14:37:42.297>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2021-04-16.14:37:42.297>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2021-04-14.11:15:16.829>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 43842
keywords = ['patch']
message_count = 5.0
messages = ['391057', '391186', '391187', '391200', '391204']
nosy_count = 1.0
nosy_names = ['vstinner']
pr_nums = ['25436', '25437', '25440']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue43842'
versions = ['Python 3.8', 'Python 3.9', 'Python 3.10']

[vstinner]

Random error seen on FreeBSD:

0:05:54 load avg: 5.75 [340/427/1] test_logging passed -- running: test_pydoc (34.4 sec)

Exception in thread Thread-25 (serve_forever):
Traceback (most recent call last):
  File "/usr/home/vstinner/python/master/Lib/threading.py", line 990, in _bootstrap_inner
    self.run()
  File "/usr/home/vstinner/python/master/Lib/threading.py", line 928, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/home/vstinner/python/master/Lib/test/test_logging.py", line 863, in serve_forever
    asyncore.loop(poll_interval, map=self._map)
  File "/usr/home/vstinner/python/master/Lib/asyncore.py", line 203, in loop
    poll_fun(timeout, map)
  File "/usr/home/vstinner/python/master/Lib/asyncore.py", line 144, in poll
    r, w, e = select.select(r, w, e, timeout)
OSError: [Errno 9] Bad file descriptor

[vstinner]

There is a race condition. The main thread closes a file descriptor which is part of the asyncore loop "map", a thread polls on the asyncore "map" file descriptors.

-- Main thread --

Close a socket:

File "/usr/home/vstinner/python/master/Lib/test/test_logging.py", line 1072, in test_basic
server.stop()
File "/usr/home/vstinner/python/master/Lib/test/test_logging.py", line 870, in stop
self.close()

-- TestSMTPServer thread --

Wait in asyncore.loop():
                      
Exception in thread Thread-1 (serve_forever):                                                                                                                  
Traceback (most recent call last):                                             
  File "/usr/home/vstinner/python/master/Lib/threading.py", line 990, in _bootstrap_inner                                                                      
    self.run()                                                                 
  File "/usr/home/vstinner/python/master/Lib/threading.py", line 928, in run                                                                                   
    self._target(*self._args, **self._kwargs)                                  
  File "/usr/home/vstinner/python/master/Lib/test/test_logging.py", line 863, in serve_forever                                                                 
    asyncore.loop(poll_interval, map=self._map)                                
  File "/usr/home/vstinner/python/master/Lib/asyncore.py", line 211, in loop                                                                                   
    poll_fun(timeout, map)                                                     
  File "/usr/home/vstinner/python/master/Lib/asyncore.py", line 145, in poll                                                                                   
    r, w, e = select.select(r, w, e, timeout)                                  
OSError: [Errno 9] Bad file descriptor

[vstinner]

New changeset 75ec103 by Victor Stinner in branch 'master':
bpo-43842: Fix race condition in test_logging SMTP test (GH-25436)
75ec103

[vstinner]

New changeset e1903e1 by Victor Stinner in branch '3.9':
bpo-43842: Fix race condition in test_logging SMTP test (GH-25436) (GH-25437)
e1903e1

[vstinner]

New changeset 816da33 by Victor Stinner in branch '3.8':
bpo-43842: Fix race condition in test_logging SMTP test (GH-25436) (GH-25437) (GH-25440)
816da33