Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

test_logging: test_config_queue_handler() race condition #93761

Open
vstinner opened this issue Jun 13, 2022 · 3 comments
Open

test_logging: test_config_queue_handler() race condition #93761

vstinner opened this issue Jun 13, 2022 · 3 comments
Labels
tests type-bug

Comments

@vstinner
Copy link
Member

@vstinner vstinner commented Jun 13, 2022

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 vstinner added the type-bug label Jun 13, 2022
@vstinner
Copy link
Member Author

@vstinner vstinner commented Jun 13, 2022

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'])

@AlexWaygood AlexWaygood added the tests label Jun 13, 2022
@vsajip
Copy link
Member

@vsajip vsajip commented Jun 13, 2022

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

@vstinner
Copy link
Member Author

@vstinner vstinner commented Jun 13, 2022

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
tests type-bug
Projects
None yet
Development

No branches or pull requests

3 participants