Exception in coroutines are not reported

eldee · February 25, 2021, 10:20pm

It seems that if a coroutine raises an exception when running in a task, the exception is silently discarded, see this small example :

async def embedded():
    print("EMBEDDED")

async def test_async():
    print("BEFORE")
    raise Exception()
    print("AFTER")
    await embedded()

def test(task):
    print("BEFORE")
    raise Exception()
    print("AFTER")
    return task.done

def add_task():
    print("CREATE")
    taskMgr.add(test_async(), 'ex_test')
    print("DONE")

import direct.directbase.DirectStart

add_task()
base.run()

The output is :

Using deprecated DirectStart interface.
Known pipe types:
  glxGraphicsPipe
(all display modules loaded.)
CREATE
DONE
BEFORE

If I run the same code but with vanilla task, the exception is correctly reported :

Using deprecated DirectStart interface.
Known pipe types:
  glxGraphicsPipe
(all display modules loaded.)
CREATE
DONE
BEFORE
Traceback (most recent call last):
  File "tests/test_async_ex.py", line 12, in test
    raise Exception()
Exception
:task(error): Exception occurred in PythonTask ex_test
Traceback (most recent call last):
  File "tests/test_async_ex.py", line 24, in 
    base.run()
  File "/usr/share/panda3d/direct/showbase/ShowBase.py", line 3319, in run
    self.taskMgr.run()
  File "/usr/share/panda3d/direct/task/Task.py", line 541, in run
    self.step()
  File "/usr/share/panda3d/direct/task/Task.py", line 495, in step
    self.mgr.poll()
  File "tests/test_async_ex.py", line 12, in test
    raise Exception()
Exception

Am I missing something or is it a bug ?

rdb · February 26, 2021, 9:34am

I get this when I run it your code:

:task(error): PythonTask ex_test exception was never retrieved:
Traceback (most recent call last):
  File "/tmp/test.py", line 6, in test_async
    raise Exception()
Exception

However, it only prints the exception, and doesn’t interrupt the task manager. Do you think it should?

It might be interesting to check what asyncio does in this case.

eldee · February 26, 2021, 10:28am

Thanks for testing! It’s getting weird again : with an official build of Panda3D the exception is raised, but with my own build of Panda3D, based on 1.10.8 but with double precision floats and a couple of cherry-picked bugfixes, the exception is not reported… Same behaviour on Linux and macOS, so it’s not a compiler issue this time.

(Also there are almost no notification dumped, even with spam level)

With asyncio, if a task is killed due to an exception, the other tasks in the loop keep running.

rdb · February 26, 2021, 10:34am

The error message is disabled if you build with --optimize 4, perhaps that is what is going on?

eldee · February 26, 2021, 10:35am

Yes, that’s what I just thought and currently testing I always forgot that optimise level 4 is pretty aggressive !

rdb · February 26, 2021, 10:36am

Come to think of it, this is probably what you do want to see in a log file if such a failure happens in a distributed game, so maybe we should just keep this one in in opt-4 level builds.

eldee · February 26, 2021, 10:36am

Indeed, with optimise level 4 the exception is not reported at all

eldee · February 26, 2021, 10:47am

Yes, that was actually my implicit assumption, uncaught exception should always be reported. Otherwise, especially in a distributed app, part of the game could suddenly stop working without any indication that something when wrong and caused one of the tasks to be killed. And that would be a nightmare to troubleshoot.

rdb · February 26, 2021, 12:33pm

OK, changed for 1.10.9.

eldee · February 26, 2021, 12:54pm

And it works like a charm, thank you !

eldee · May 20, 2021, 9:56pm

Weirdly it seems that with latest Panda3D master, even though you fix is indeed present in PythonTask destructor, the exception is still not reported (and the task keep running).

The output is again (and the program never stops) :

Using deprecated DirectStart interface.
Known pipe types:
  glxGraphicsPipe
(all display modules loaded.)
CREATE
DONE
BEFORE

eldee · May 25, 2021, 8:47pm

I’ve got another strange occurrence, due to a mistake in my code, a worker task is raising an exception (It’s an AttributeError, but I don’t believe it matters). After a few failed execution of the worker, I suddenly got these line and the whole program ended :

:task(error): PythonTask ShapeObject.patch_task exception was never retrieved:
SystemError: PyEval_EvalFrameEx returned NULL without setting an error
:task(error): PythonTask ShapeObject.patch_task exception was never retrieved:
SystemError: PyEval_EvalFrameEx returned NULL without setting an error

(And it seems the traceback related to the exception is printed before the :task(error): )

With 1.10.9 the worker keeps crashing as expected but I never get the above error nor the program stops.

rdb · May 27, 2021, 8:56am

Is this again only happening with NDEBUG?

Which version of Python?

eldee · May 27, 2021, 9:20am

Is this again only happening with NDEBUG?

I’m always using optimize level 3 now to avoid such problems, but I will check what is the actual configuration of NDEBUG to be on the safe side.

Which version of Python?

It’s Python 3.8 but I will check which version later today.

eldee · May 27, 2021, 9:28pm

The actual Python version is 3.8.5 and NDEBUG is not defined (–optimize=3), the version is 1.11.0 (571946739ecb3c9140afa1e5a64da26b3b849a65)

Here is the log with notify-level-event spam and notify-level-task spam

:task(spam): Adding PythonTask eventManager with sort 0 to chain default with current_sort -2147483647
CREATE
:task(debug): Adding PythonTask ex_test
:event(debug): Throwing event TaskManager-addTask(PythonTask)
:task(spam): Adding PythonTask ex_test with sort 0 to chain default with current_sort -2147483647
DONE
:task(spam): Servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Done servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Servicing PythonTask dataLoop in MainThread Main
:task(spam): Done servicing PythonTask dataLoop in MainThread Main
:task(spam): Servicing PythonTask eventManager in MainThread Main
:task(spam): Done servicing PythonTask eventManager in MainThread Main
:task(spam): Servicing PythonTask ex_test in MainThread Main
BEFORE
:task(debug): PythonTask ex_test received exception from coroutine.
:task(spam): AsyncTaskManager TaskManager task chain default; 9 tasks: cleanup_task(PythonTask ex_test, 1, 1)
:event(debug): Throwing event TaskManager-removeTask(PythonTask)
:task(spam): Done servicing PythonTask ex_test in MainThread Main
:task(spam): Servicing PythonTask ivalLoop in MainThread Main
:task(spam): Done servicing PythonTask ivalLoop in MainThread Main
:task(spam): Servicing PythonTask collisionLoop in MainThread Main
:task(spam): Done servicing PythonTask collisionLoop in MainThread Main
:task(spam): Servicing PythonTask garbageCollectStates in MainThread Main
:task(spam): Done servicing PythonTask garbageCollectStates in MainThread Main
:task(spam): Servicing PythonTask igLoop in MainThread Main
:event(debug): Throwing event window-event(glxGraphicsWindow)
:event(spam): Throwing event NewFrame()
:task(spam): Done servicing PythonTask igLoop in MainThread Main
:task(spam): Servicing PythonTask audioLoop in MainThread Main
:task(spam): Done servicing PythonTask audioLoop in MainThread Main
:task(spam): AsyncTaskManager TaskManager task chain default; 8 tasks: next epoch
:task(spam): No more tasks on sleeping queue.
:task(spam): Servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Done servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Servicing PythonTask dataLoop in MainThread Main
:task(spam): Done servicing PythonTask dataLoop in MainThread Main
:task(spam): Servicing PythonTask eventManager in MainThread Main
:task(spam): Done servicing PythonTask eventManager in MainThread Main

And for comparison, the same log with Panda3D 1.10.9 :

:task(spam): Adding PythonTask eventManager with sort 0 to chain default with current_sort -2147483647
CREATE
:task(debug): Adding PythonTask ex_test
:event(debug): Throwing event TaskManager-addTask(PythonTask)
:task(spam): Adding PythonTask ex_test with sort 0 to chain default with current_sort -2147483647
DONE
:task(spam): Servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Done servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Servicing PythonTask dataLoop in MainThread Main
:task(spam): Done servicing PythonTask dataLoop in MainThread Main
:task(spam): Servicing PythonTask eventManager in MainThread Main
:task(spam): Done servicing PythonTask eventManager in MainThread Main
:task(spam): Servicing PythonTask ex_test in MainThread Main
BEFORE
:task(debug): PythonTask ex_test received Exception from coroutine.
:task(spam): AsyncTaskManager TaskManager task chain default; 9 tasks: cleanup_task(PythonTask ex_test, 1, 1)
:event(debug): Throwing event TaskManager-removeTask(PythonTask)
:task(spam): Done servicing PythonTask ex_test in MainThread Main
:task(spam): Servicing PythonTask ivalLoop in MainThread Main
:task(spam): Done servicing PythonTask ivalLoop in MainThread Main
:task(spam): Servicing PythonTask collisionLoop in MainThread Main
:task(spam): Done servicing PythonTask collisionLoop in MainThread Main
:task(spam): Servicing PythonTask garbageCollectStates in MainThread Main
:task(spam): Done servicing PythonTask garbageCollectStates in MainThread Main
:task(spam): Servicing PythonTask igLoop in MainThread Main
:event(debug): Throwing event window-event(glxGraphicsWindow)
:event(spam): Throwing event NewFrame()
:task(spam): Done servicing PythonTask igLoop in MainThread Main
:task(spam): Servicing PythonTask audioLoop in MainThread Main
:task(spam): Done servicing PythonTask audioLoop in MainThread Main
:task(spam): AsyncTaskManager TaskManager task chain default; 8 tasks: next epoch
:task(spam): No more tasks on sleeping queue.
:task(spam): Servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Done servicing PythonTask resetPrevTransform in MainThread Main
:task(spam): Servicing PythonTask dataLoop in MainThread Main
:task(spam): Done servicing PythonTask dataLoop in MainThread Main
:task(spam): Servicing PythonTask eventManager in MainThread Main
:task(error): PythonTask ex_test exception was never retrieved:
Traceback (most recent call last):
  File "tests/test_async_ex.py", line 13, in test_async
    raise Exception()
Exception
:task(spam): Done servicing PythonTask eventManager in MainThread Main

rdb · May 28, 2021, 10:30am

Thanks.

I think the problem is that get_cancelled_error_type() is sometimes clearing the error indicator:

github.com

panda3d/panda3d/blob/571946739ecb3c9140afa1e5a64da26b3b849a65/panda/src/event/pythonTask.cxx#L633


    if (task_cat.is_debug()) {
      task_cat.debug()
        << *this << " received StopIteration from coroutine.\n";
    }
    // Store the result in _exc_value because that's not used anyway.
    Py_XDECREF(_exc_value);
    _exc_value = result;
    return DS_done;
  }

} else if (PyErr_ExceptionMatches(Extension<AsyncFuture>::get_cancelled_error_type())) {
  // Someone cancelled the coroutine, and it did not bother to handle it,
  // so we should consider it cancelled.
  if (task_cat.is_debug()) {
    task_cat.debug()
      << *this << " was cancelled and did not catch CancelledError.\n";
  }
  _state = S_servicing_removed;
  PyErr_Clear();
  return DS_done;

I will work on a fix.

I would be grateful to have a reproduction case for the other issue, although it may be related.

rdb · May 31, 2021, 3:56pm

eldee · May 31, 2021, 8:28pm

Thanks, it seems to fix the first issue in all the case.

Alas this one still occurs, but the condition to make it happens still eludes me, but I think I’m getting close to the actual scenario:

If I raise an exception at a given point in my code before I set some data that is needed by the parent task that spawned the task, in one dev-commit of my tree I get the SystemError: PyEval_EvalFrameEx returned NULL without setting an error, and if I switch to a later dev-commit (after some clean up of the task management), the SystemError does not appear, but also the manual exception does not appear either, only a follow-up exception is shown as the task did not complete its work and the data is not available.

On the other hand, if I raise an exception after setting the data that is needed by the parent task, I get as expected that exception in the log with the PythonTask ShapeObject.patch_task exception was never retrieved error.

So it seems the first exception is lost or hidden by the upper one. I’m trying to replicate this using a simple example, but I believe there is still one missing part that I need to reproduce the problem.