pulumi: Flakey python test errors with "Task attached to a different loop"

The TestingWithMocks.test_component test intermittently errors with a Task attached to a different loop error: https://github.com/pulumi/pulumi/runs/2098866118#step:18:1754

Expected behavior

The test should pass every time.

Current behavior

=================================== FAILURES ===================================
_______________________ TestingWithMocks.test_component ________________________

args = (<test_with_mocks.test_testing_with_mocks.TestingWithMocks testMethod=test_component>,)
kwargs = {}

    def wrapper(*args, **kwargs):
        from .. import Output  # pylint: disable=import-outside-toplevel
>       _sync_await(run_pulumi_func(lambda: _sync_await(Output.from_input(fn(*args, **kwargs)).future())))

../pulumi/runtime/mocks.py:37: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
Error: ../pulumi/runtime/sync_await.py:54: in _sync_await
    return loop.run_until_complete(fut)
Error: /opt/hostedtoolcache/Python/3.9.2/x64/lib/python3.9/asyncio/base_events.py:642: in run_until_complete
    return future.result()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

func = <function test.<locals>.wrapper.<locals>.<lambda> at 0x7f68c09c2940>

    async def run_pulumi_func(func: Callable):
        try:
            func()
        finally:
            log.debug("Waiting for outstanding RPCs to complete")
    
            # Pump the event loop, giving all of the RPCs that we just queued up time to fully execute.
            # The asyncio scheduler does not expose a "yield" primitive, so this will have to do.
            #
            # Note that "asyncio.sleep(0)" is the blessed way to do this:
            # python/asyncio/issues/284#issuecomment-154180935
            #
            # We await each RPC in turn so that this loop will actually block rather than busy-wait.
            while True:
                await asyncio.sleep(0)
                rpcs_remaining = len(RPC_MANAGER.rpcs)
                if rpcs_remaining == 0:
                    break
                log.debug(f"waiting for quiescence; {rpcs_remaining} RPCs outstanding")
>               await RPC_MANAGER.rpcs.pop()
E               RuntimeError: Task <Task pending name='Task-70' coro=<run_pulumi_func() running at /home/runner/work/pulumi/pulumi/sdk/python/lib/pulumi/runtime/stack.py:51> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.2/x64/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name='Task-349' coro=<get_resource.<locals>.do_get() running at /home/runner/work/pulumi/pulumi/sdk/python/lib/pulumi/runtime/resource.py:194> wait_for=<Future finished result=return {
E                 fi..."
E                   }
E                 }
E               }
E               > cb=[<TaskWakeupMethWrapper object at 0x7f68bdc7ef40>()]> attached to a different loop

Error: ../pulumi/runtime/stack.py:51: RuntimeError

Steps to reproduce

This is a tricky one to reproduce. I have seen this in automation API as well, but been unable to reproduce it consistently. The thing in common between mocks and automation API is that they are both operating within threads where an event loop may not yet exist and therefore need to be created: https://github.com/pulumi/pulumi/pull/6479/files#diff-7940e0adbdbe429f8fbb220a99ee2c6dac0436a1e01abfd8a4dcb5ec6b4e8235R92-R97

About this issue

Original URL
State: open
Created 3 years ago
Reactions: 2
Comments: 16 (11 by maintainers)

Most upvoted comments

@amitjattan I am still investigating this, but I have a few other things that are taking priority right now. Hoping I’ll be able to get to it in the next few weeks.

komalali on Apr 6, 2021

Facing same issues while running pulumi automation tasks via APIs. Resources are created successfully though.

code: 255 stdout: Updating (itsd-devtest-RajanSQLTestRgD01-azrpmsqld009-SQLTesting01): + pulumi:pulumi:Stack itsd-devtest-itsd-devtest-RajanSQLTestRgD01-azrpmsqld009-SQLTesting01 creating + azure:mssql:Database SQLTesting01 creating + azure:mssql:Database SQLTesting01 created + pulumi:pulumi:Stack itsd-devtest-itsd-devtest-RajanSQLTestRgD01-azrpmsqld009-SQLTesting01 creating error: python inline source runtime error: Task <Task pending name=‘Task-871’ coro=<run_in_stack() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py:83> cb=[_run_until_complete_cb() at /usr/local/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name=‘Task-783’ coro=<register_resource.<locals>.do_register() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/resource.py:358> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4037cafaf0>(), <2 more>, <TaskWakeupMethWrapper object at 0x7f4037caf370>()]> cb=[<TaskWakeupMethWrapper object at 0x7f4037af3df0>()]> attached to a different loop + pulumi:pulumi:Stack itsd-devtest-itsd-devtest-RajanSQLTestRgD01-azrpmsqld009-SQLTesting01 creating error: an unhandled error occurred: python inline source runtime error: Task <Task pending name=‘Task-871’ coro=<run_in_stack() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py:83> cb=[_run_until_complete_cb() at /usr/local/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name=‘Task-783’ coro=<register_resource.<locals>.do_register() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/resource.py:358> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4037cafaf0>(), <2 more>, <TaskWakeupMethWrapper object at 0x7f4037caf370>()]> cb=[<TaskWakeupMethWrapper object at 0x7f4037af3df0>()]> attached to a different loop + pulumi:pulumi:Stack itsd-devtest-itsd-devtest-RajanSQLTestRgD01-azrpmsqld009-SQLTesting01 creating failed 2 errors Diagnostics: pulumi:pulumi:Stack (itsd-devtest-itsd-devtest-RajanSQLTestRgD01-azrpmsqld009-SQLTesting01): error: python inline source runtime error: Task <Task pending name=‘Task-871’ coro=<run_in_stack() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py:83> cb=[_run_until_complete_cb() at /usr/local/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name=‘Task-783’ coro=<register_resource.<locals>.do_register() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/resource.py:358> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4037cafaf0>(), <2 more>, <TaskWakeupMethWrapper object at 0x7f4037caf370>()]> cb=[<TaskWakeupMethWrapper object at 0x7f4037af3df0>()]> attached to a different loop Traceback (most recent call last): File “/usr/local/lib/python3.9/site-packages/pulumi/x/automation/_server.py”, line 64, in Run loop.run_until_complete(run_in_stack(self.program)) File “/usr/local/lib/python3.9/asyncio/base_events.py”, line 642, in run_until_complete return future.result() File “/usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py”, line 83, in run_in_stack await run_pulumi_func(lambda: Stack(func)) File “/usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py”, line 51, in run_pulumi_func await RPC_MANAGER.rpcs.pop() RuntimeError: Task <Task pending name=‘Task-871’ coro=<run_in_stack() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py:83> cb=[_run_until_complete_cb() at /usr/local/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name=‘Task-783’ coro=<register_resource.<locals>.do_register() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/resource.py:358> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4037cafaf0>(), <2 more>, <TaskWakeupMethWrapper object at 0x7f4037caf370>()]> cb=[<TaskWakeupMethWrapper object at 0x7f4037af3df0>()]> attached to a different loop error: an unhandled error occurred: python inline source runtime error: Task <Task pending name=‘Task-871’ coro=<run_in_stack() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py:83> cb=[_run_until_complete_cb() at /usr/local/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name=‘Task-783’ coro=<register_resource.<locals>.do_register() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/resource.py:358> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4037cafaf0>(), <2 more>, <TaskWakeupMethWrapper object at 0x7f4037caf370>()]> cb=[<TaskWakeupMethWrapper object at 0x7f4037af3df0>()]> attached to a different loop Traceback (most recent call last): File “/usr/local/lib/python3.9/site-packages/pulumi/x/automation/_server.py”, line 64, in Run loop.run_until_complete(run_in_stack(self.program)) File “/usr/local/lib/python3.9/asyncio/base_events.py”, line 642, in run_until_complete return future.result() File “/usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py”, line 83, in run_in_stack await run_pulumi_func(lambda: Stack(func)) File “/usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py”, line 51, in run_pulumi_func await RPC_MANAGER.rpcs.pop() RuntimeError: Task <Task pending name=‘Task-871’ coro=<run_in_stack() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/stack.py:83> cb=[_run_until_complete_cb() at /usr/local/lib/python3.9/asyncio/base_events.py:184]> got Future <Task pending name=‘Task-783’ coro=<register_resource.<locals>.do_register() running at /usr/local/lib/python3.9/site-packages/pulumi/runtime/resource.py:358> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f4037cafaf0>(), <2 more>, <TaskWakeupMethWrapper object at 0x7f4037caf370>()]> cb=[<TaskWakeupMethWrapper object at 0x7f4037af3df0>()]> attached to a different loop Resources: + 2 created Duration: 1m47s stderr:

amitjattan on Mar 24, 2021