test_logging: test_config_queue_handler() race condition

[vstinner]

The implementation of test_logging.test_config_queue_handler() uses time.sleep(0.010) as synchronization primitive.

@vsajip: please don't use time.sleep() as sync primitive: https://pythondev.readthedocs.io/unstable_tests.html#don-t-use-sleep-as-synchronization

The test fails when the machine is busy:

$ ./python -m test test_logging -m test_config_queue_handler -F -j10 -v
(...)
0:00:10 load avg: 2.36 [ 48/1] test_logging failed (1 failure)
test_config_queue_handler (test.test_logging.ConfigDictTest.test_config_queue_handler) ... FAIL

======================================================================
FAIL: test_config_queue_handler (test.test_logging.ConfigDictTest.test_config_queue_handler)
----------------------------------------------------------------------
Traceback (most recent call last):
 File "/home/vstinner/python/main/Lib/test/test_logging.py", line 3647, in test_config_queue_handler
 self.do_queuehandler_configuration(qspec, lspec)
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 File "/home/vstinner/python/main/Lib/test/test_logging.py", line 3621, in do_queuehandler_configuration
 self.assertEqual(data, ['foo', 'bar', 'baz'])
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: Lists differ: [] != ['foo', 'bar', 'baz']

Second list contains 3 additional elements.
First extra element 0:
'foo'

- []
+ ['foo', 'bar', 'baz']

----------------------------------------------------------------------
Ran 1 test in 0.466s

FAILED (failures=1)

Extract of the test:

 delay = 0.01
 try:
 self.apply_config(cd)
 qh = logging.getHandlerByName('ah')
 self.assertEqual(sorted(logging.getHandlerNames()), ['ah', 'h1'])
 self.assertIsNotNone(qh.listener)
 qh.listener.start()
 # Need to let the listener thread get started
 time.sleep(delay)
 logging.debug('foo')
 logging.info('bar')
 logging.warning('baz')
 # Need to let the listener thread finish its work
 time.sleep(delay)
 with open(fn, encoding='utf-8') as f:
 data = f.read().splitlines()
 self.assertEqual(data, ['foo', 'bar', 'baz'])
 finally:
 if qh:
 qh.listener.stop()
 h = logging.getHandlerByName('h1')
 if h:
 self.addCleanup(closeFileHandler, h, fn)
 else:
 self.addCleanup(os.remove, fn)

[vstinner]

I suggest to wait until the queue is empty instead (delay variable can also be deleted):

diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index 87b3efa406..da5c68e5d7 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -3609,13 +3609,17 @@ def do_queuehandler_configuration(self, qspec, lspec):
 self.assertEqual(sorted(logging.getHandlerNames()), ['ah', 'h1'])
 self.assertIsNotNone(qh.listener)
 qh.listener.start()
- # Need to let the listener thread get started
- time.sleep(delay)
+
 logging.debug('foo')
 logging.info('bar')
 logging.warning('baz')
- # Need to let the listener thread finish its work
- time.sleep(delay)
+
+ deadline = time.monotonic() + support.LONG_TIMEOUT
+ while not qh.listener.queue.empty():
+ time.sleep(0.010)
+ if time.monotonic() > deadline:
+ self.fail("queue not empty")
+
 with open(fn, encoding='utf-8') as f:
 data = f.read().splitlines()
 self.assertEqual(data, ['foo', 'bar', 'baz'])

[vsajip]

@vstinner Thanks for raising this, Victor, and sorry for not thinking about the buildbots. I will rectify that soon!

[vstinner]

sorry for not thinking about the buildbots

The problem is more generic than buildbots. The test can fail randomly on any machine depending on the system load ;-)

I will rectify that soon!

Great! Thanks.

[vstinner]

Should be fixed by commit 5bcf33d.

[vstinner]

Oh, sadly, the bug still occurs: https://buildbot.python.org/all/#/builders/831/builds/1014

I wrote a fix for the second race condition: #93952