This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

Author xtreak
Recipients asvetlov, vstinner, xtreak, yselivanov
Date 2019-03-12.18:33:15
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1552415596.07.0.807032533088.issue35760@roundup.psfhosted.org>
In-reply-to
Content
I have modified the test with help of Victor to have lower sleep delay to reproduce the bug. Since sleep calls call_later with the delay where the Timer object is created time.monotonic() + delay. I have added a print statement to see when the sleep is scheduled.

Modified test with 0.01 for run and 0.001 for finally : 

    def test_async_gen_asyncio_gc_aclose_09(self):
        DONE = 0
        import time

        async def gen():
            nonlocal DONE
            try:
                while True:
                    yield 1
            finally:
                print(time.monotonic(), "finally sleeps 1 ms")
                await asyncio.sleep(0.001)
                print(time.monotonic(), "finally sleeps 1 more ms")
                await asyncio.sleep(0.001)
                DONE = 1
                print(time.monotonic(), "finally: DONE = 1--")

        async def run():
            g = gen()
            await g.__anext__()
            await g.__anext__()
            print(time.monotonic(), "del g")
            del g

            print(time.monotonic(), "run sleeps 10 ms...")
            await asyncio.sleep(0.01)
            print(time.monotonic(), "run exit")

        self.loop.run_until_complete(run())
        self.assertEqual(DONE, 1)


./python.exe -X dev -m test -j4 -F test_asyncgen -m test_async_gen_asyncio_gc_aclose_09

On running the test I can see that sometimes sometimes DONE is set before run exit.

0:00:00 load avg: 1.87 [  1] test_asyncgen passed
0.738210762 del g
0.739222722 run sleeps 10 ms...
0.7625599120000001 0.01
0.757210842 finally sleeps 1 ms
0.76050695 0.001
0.762445572 finally sleeps 1 more ms
0.765119049 0.001
0.765694536 run exit
0.76704106 finally: DONE = 1--

sometimes DONE is set after run exit.

0:00:00 load avg: 1.87 [  2] test_asyncgen passed
0.739718657 del g
0.740647619 run sleeps 10 ms...
0.764014802 0.01
0.759427252 finally sleeps 1 ms
0.762613547 0.001
0.764573796 finally sleeps 1 more ms
0.767242878 0.001
0.767722044 run exit
0.769133638 finally: DONE = 1--


There are cases where run exit is called before second sleep is even called causing failure.

0:00:03 load avg: 1.96 [ 16/1] test_asyncgen failed
0.685123806 del g
0.685635626 run sleeps 10 ms...
0.698605025 0.01
0.69112447 finally sleeps 1 ms
0.700476131 0.001
0.701259052 run exit
0.702733814 finally sleeps 1 more ms
0.70500493 0.001
Task was destroyed but it is pending!
source_traceback: Object created at (most recent call last):

Sometimes the second sleep scheduled time and run exit time are almost the same by 1 ms.

0:00:04 load avg: 1.96 [ 18/2] test_asyncgen failed
0.701280462 del g
0.701810041 run sleeps 10 ms...
0.714906478 0.01
0.707617751 finally sleeps 1 ms
0.713339727 0.001
0.714532967 finally sleeps 1 more ms
0.7167121870000001 0.001
0.716623958 run exit
Task was destroyed but it is pending!


I am not sure at this point if I should further debug this at Lib/asyncio/ or at _asynciomodule.c regarding the control flow change related code when an object is awaited. I suspect there is a race condition here since the test seems to set DONE=1 with different control flows and also where DONE=1 is not even called. This is more easily reproducible at lower resolution of time like using 0.01 and 0.001 for this test so this feels more like the race condition is exposed at lower time levels and thus increasing the time difference between the test doesn't seem to be a good solution. 

The above test also fails in 3.6 but takes a long time before below trace occurs : 

0:00:42 load avg: 4.26 [159] test_asyncgen passed
16775.541152592 del g
16775.541369282 run sleeps 10 ms...
16775.542167311 finally sleeps 1 ms
16775.544090629 finally sleeps 1 more ms
16775.546002851 finally: DONE = 1--
16775.552762612 run exit
0:00:43 load avg: 4.26 [160/1] test_asyncgen failed
16775.529271686 del g
16775.529405 run sleeps 10 ms...
16775.529833951 finally sleeps 1 ms
16775.539453811 finally sleeps 1 more ms
16775.539972874 run exit
Task was destroyed but it is pending!
task: <Task pending coro=<async_generator_athrow()> wait_for=<Future finished result=None>>
test test_asyncgen failed -- Traceback (most recent call last):
  File "/Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_asyncgen.py", line 693, in test_async_gen_asyncio_gc_aclose_09
    self.assertEqual(DONE, 1)
AssertionError: 0 != 1


Yury and Andrew, your thoughts would be helpful in debugging this issue and also to check the actual behavior to be tested in this case.
History
Date User Action Args
2019-03-12 18:33:16xtreaksetrecipients: + xtreak, vstinner, asvetlov, yselivanov
2019-03-12 18:33:16xtreaksetmessageid: <1552415596.07.0.807032533088.issue35760@roundup.psfhosted.org>
2019-03-12 18:33:16xtreaklinkissue35760 messages
2019-03-12 18:33:15xtreakcreate