Description

vstinner

opened on Jun 13, 2022

Issue body actions

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)

Activity

1. vstinner

   added

   type-bugAn unexpected behavior, bug, or errorAn unexpected behavior, bug, or error

   on Jun 13, 2022
2. vstinner commented on Jun 13, 2022

   

   vstinner

   on Jun 13, 2022

   MemberAuthor

   More actions

   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'])
3. AlexWaygood

   added

   testsTests in the Lib/test dirTests in the Lib/test dir

   on Jun 13, 2022
4. vsajip commented on Jun 13, 2022

   

   vsajip

   on Jun 13, 2022

   Member

   More actions

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

   added a commit that references this issue on Jun 13, 2022

   pythongh-93761: Fix test to avoid simple delay when synchronizing.

   6e5b7cb
6. vstinner commented on Jun 13, 2022

   

   vstinner

   on Jun 13, 2022

   MemberAuthor

   More actions

   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.
7. vsajip

   added a commit that references this issue on Jun 14, 2022

   gh-93761: Fix test to avoid simple delay when synchronizing. (GH-93779)

   5bcf33d
8. vstinner commented on Jun 17, 2022

   

   vstinner

   on Jun 17, 2022

   MemberAuthor

   More actions

   Should be fixed by commit 5bcf33d.
9. vstinner

   closed this as completedon Jun 17, 2022
10. vstinner commented on Jun 17, 2022

    

    vstinner

    on Jun 17, 2022

    MemberAuthor

    More actions

    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
11. vstinner

    added a commit that references this issue on Jun 19, 2022

    gh-93761: Fix test_logging test_config_queue_handler() race condition (…

    dba3fa5
12. serhiy-storchaka

    added a commit that references this issue on Jun 26, 2022

    Revert 30935 defer bpo45162 to 312 (#94285)

    1ffde3e

Issue actions