Skip to content

test_logging: test_config_queue_handler() race condition #93761

Closed
@vstinner

Description

@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)

Metadata

Metadata

Assignees

No one assigned

    Labels

    testsTests in the Lib/test dirtype-bugAn unexpected behavior, bug, or error

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions