wlav / cppyy

Other
405 stars 42 forks source link

Fatal Python error: notimplemented_dealloc: deallocating NotImplemented #189

Closed N-Coder closed 10 months ago

N-Coder commented 1 year ago

I found some weird crashes when implementing a C++ observer interface in Python. The interface is implemented as follows:

test.cpp (click me) ```cpp #include #include #include #include struct Observable; struct Observer { Observable *observed = nullptr; std::list::iterator it; virtual ~Observer() { observe(nullptr); } void observe(Observable *observable); virtual void onThingDone(const std::string &msg) = 0; virtual void onRegistered(Observable *previous) {}; }; struct Observable { std::list observers; ~Observable() { while (!observers.empty()) observers.front()->observe(nullptr); } void doThing(const std::string &msg) { for (auto o: observers) o->onThingDone(msg); } void registerObserver(Observer *obs) { assert(obs != nullptr); assert(obs->observed == nullptr); observers.push_back(obs); obs->it = observers.end(); --obs->it; obs->observed = this; obs->onRegistered(nullptr); } void unregisterObserver(Observer *obs) { assert(obs != nullptr); assert(obs->observed == this); observers.erase(obs->it); obs->it = std::list::iterator{}; obs->observed = nullptr; obs->onRegistered(this); } }; void Observer::observe(Observable *observable) { if (observed) observed->unregisterObserver(this); if (observable) observable->registerObserver(this); } struct MyObserver : Observer { MyObserver() { std::cout << this << " construct" << std::endl; } ~MyObserver() { std::cout << this << " destruct" << std::endl; } void onThingDone(const std::string &msg) override { std::cout << this << " onThingDone " << msg << std::endl; } void onRegistered(Observable *previous) override { std::cout << this << " onRegistered(was " << previous << " is " << observed << ")" << std::endl; } }; MyObserver long_lived_obs; int main() { Observable obj; long_lived_obs.observe(&obj); MyObserver obs; obs.observe(&obj); obj.doThing("1"); { MyObserver obs2; obs2.observe(&obj); obj.doThing("2"); } { MyObserver obs3; obs3.observe(&obj); obj.doThing("3"); } obj.doThing("4"); return 0; } ```

When directly running the tests in a compiled version of main, everything works and even valgrind is happy. When doing a similar thing via cppyy 2.4.2, I get an interpreter crash:

from cppyy import *
import cppyy.gbl as c

include("test.cpp")

class MyObserver(c.Observer):
    def onThingDone(self, msg):
        print(id(self), "onThingDone", msg)
    def onRegistered(self, prev):
        print(id(self), "onRegistered", "was", prev, "is", self.observed)

obj = c.Observable()
obs = MyObserver()
obs.observe(obj)
obj.doThing("test")

Re-running the last three lines (excluding the creation of obj) or running del obs results in the following interpreter crash either immediately or upon exiting the python interpreter:

Fatal Python error: notimplemented_dealloc: deallocating NotImplemented
Python runtime state: finalizing (tstate=0x00007f8899d0ed38)

Current thread 0x00007f8899d84740 (most recent call first):
  <no Python frame>
 *** Break *** abort
#0  0x00007f88996fcc37 in __GI___wait4 (pid=168978, stat_loc=stat_loc
entry=0x7ffcba6df5f8, options=options
entry=0, usage=usage
entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
#1  0x00007f88996fcbfb in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc
entry=0x7ffcba6df5f8, options=options
entry=0) at waitpid.c:38
#2  0x00007f88996711fb in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:171
#3  0x00007f888b9a0725 in CppyyLegacy::TUnixSystem::StackTrace() () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so
#4  0x00007f888b775a23 in (anonymous namespace)::do_trace (sig=5) at src/clingwrapper.cxx:239
#5  (anonymous namespace)::TExceptionHandlerImp::HandleException (this=<optimized out>, sig=5) at src/clingwrapper.cxx:252
#6  0x00007f888b99f231 in CppyyLegacy::TUnixSystem::DispatchSignals(CppyyLegacy::ESignals) () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so
#7  <signal handler called>
#8  __pthread_kill_implementation (threadid=<optimized out>, signo=signo
entry=6, no_tid=no_tid
entry=0) at pthread_kill.c:44
#9  0x00007f88996b08b3 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#10 0x00007f889965fabe in __GI_raise (sig=sig
entry=6) at ../sysdeps/posix/raise.c:26
#11 0x00007f889964887f in __GI_abort () at abort.c:79
#12 0x00007f889996e8fa in fatal_error_exit (status=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2626
#13 fatal_error (fd=<optimized out>, header=header
entry=1, prefix=prefix
entry=0x7f8899b429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=msg
entry=0x7f8899acc53a "deallocating NotImplemented", status=status
entry=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2737
#14 0x00007f889996eca9 in _Py_FatalErrorFunc (func=0x7f8899b429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=0x7f8899acc53a "deallocating NotImplemented") at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2823
#15 0x00007f889996ef19 in notimplemented_dealloc (ignore=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:1768
#16 0x00007f88999affdf in _Py_Dealloc (op=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:2390
#17 Py_DECREF (op=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/object.h:538
#18 Py_XDECREF (op=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/object.h:602
#19 free_keys_object (keys=0x555673f05700) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/dictobject.c:664
#20 0x00007f8899a69136 in finalize_restore_builtins (tstate=0x7f8899d0ed38 <_PyRuntime+166328>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:1470
#21 finalize_modules (tstate=tstate
entry=0x7f8899d0ed38 <_PyRuntime+166328>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:1557
#22 0x00007f8899a56289 in Py_FinalizeEx () at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:1833
#23 0x00007f8899a631ea in Py_RunMain () at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:682
#24 0x00007f8899a2a9fb in Py_BytesMain (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:734
#25 0x00007f8899649b4a in __libc_start_call_main (main=main
entry=0x555672061160 <main>, argc=argc
entry=1, argv=argv
entry=0x7ffcba6e2618) at ../sysdeps/nptl/libc_start_call_main.h:58
#26 0x00007f8899649c0b in __libc_start_main_impl (main=0x555672061160 <main>, argc=1, argv=0x7ffcba6e2618, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcba6e2608) at ../csu/libc-start.c:360
#27 0x0000555672061095 in _start ()
 *** Break *** abort
#0  0x00007f88996fcc37 in __GI___wait4 (pid=169145, stat_loc=stat_loc
entry=0x7ffcba6df5f8, options=options
entry=0, usage=usage
entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
#1  0x00007f88996fcbfb in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc
entry=0x7ffcba6df5f8, options=options
entry=0) at waitpid.c:38
#2  0x00007f88996711fb in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:171
#3  0x00007f888b9a0725 in CppyyLegacy::TUnixSystem::StackTrace() () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so
#4  0x00007f888b7758a7 in (anonymous namespace)::do_trace (sig=5) at src/clingwrapper.cxx:239
#5  (anonymous namespace)::TExceptionHandlerImp::HandleException (this=<optimized out>, sig=5) at src/clingwrapper.cxx:258
#6  0x00007f888b99f231 in CppyyLegacy::TUnixSystem::DispatchSignals(CppyyLegacy::ESignals) () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so
#7  <signal handler called>
#8  __pthread_kill_implementation (threadid=<optimized out>, signo=signo
entry=6, no_tid=no_tid
entry=0) at pthread_kill.c:44
#9  0x00007f88996b08b3 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#10 0x00007f889965fabe in __GI_raise (sig=sig
entry=6) at ../sysdeps/posix/raise.c:26
#11 0x00007f889964887f in __GI_abort () at abort.c:79
#12 0x00007f889996e8fa in fatal_error_exit (status=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2626
#13 fatal_error (fd=<optimized out>, header=header
entry=1, prefix=prefix
entry=0x7f8899b429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=msg
entry=0x7f8899acc53a "deallocating NotImplemented", status=status
entry=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2737
#14 0x00007f889996eca9 in _Py_FatalErrorFunc (func=0x7f8899b429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=0x7f8899acc53a "deallocating NotImplemented") at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2823
#15 0x00007f889996ef19 in notimplemented_dealloc (ignore=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:1768
#16 0x00007f88999affdf in _Py_Dealloc (op=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:2390
#17 Py_DECREF (op=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/object.h:538
#18 Py_XDECREF (op=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/object.h:602
#19 free_keys_object (keys=0x555673f05700) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/dictobject.c:664
#20 0x00007f8899a69136 in finalize_restore_builtins (tstate=0x7f8899d0ed38 <_PyRuntime+166328>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:1470
#21 finalize_modules (tstate=tstate
entry=0x7f8899d0ed38 <_PyRuntime+166328>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:1557
#22 0x00007f8899a56289 in Py_FinalizeEx () at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:1833
#23 0x00007f8899a631ea in Py_RunMain () at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:682
#24 0x00007f8899a2a9fb in Py_BytesMain (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:734
#25 0x00007f8899649b4a in __libc_start_call_main (main=main
entry=0x555672061160 <main>, argc=argc
entry=1, argv=argv
entry=0x7ffcba6e2618) at ../sysdeps/nptl/libc_start_call_main.h:58
#26 0x00007f8899649c0b in __libc_start_main_impl (main=0x555672061160 <main>, argc=1, argv=0x7ffcba6e2618, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcba6e2608) at ../csu/libc-start.c:360
#27 0x0000555672061095 in _start ()
0x7f88995fa010 destruct

I also got this pretty arbitrary backtrace when trying to do dome more logging and exception handling in a __del__ method.

Fatal Python error: notimplemented_dealloc: deallocating NotImplemented
Python runtime state: initialized

Current thread 0x00007ffff7f95740 (most recent call first):
  File "/usr/lib64/python3.11/traceback.py", line 622 in indent
  File "/usr/lib64/python3.11/traceback.py", line 627 in emit
  File "/usr/lib64/python3.11/traceback.py", line 917 in format
  File "/usr/lib64/python3.11/traceback.py", line 981 in print
  File "/usr/lib64/python3.11/traceback.py", line 125 in print_exception
  File "/usr/lib64/python3.11/traceback.py", line 183 in print_exc
  File "<stdin>", line 16 in __del__
  File "<stdin>", line 20 in onRegistered
  File "<stdin>", line 1 in <module>

Extension modules: libcppyy, systemd._journal, systemd._reader, systemd.id128 (total: 4)

Program received signal SIGABRT, Aborted.

Doing the same thing with cppyy 3.0 yields the following:

>>> from cppyy import *
>>> import cppyy.gbl as c
>>> 
>>> include("test.cpp")
[runStaticInitializersOnce]: Failed to materialize symbols: { (main, { __clang_call_terminate, _ZTI10MyObserver, _ZNSt7__cxx114listIP8ObserverSaIS2_EED1Ev, __cxx_global_var_initcling_module_140_, _ZTI8Observer, _ZN10MyObserver12onRegisteredEP10Observable, _ZTS10MyObserver, _ZN10MyObserverC2Ev, _GLOBAL__sub_I_cling_module_140, _ZN8ObserverD2Ev, $.cling-module-140.__inits.0, main, __orc_init_func.cling-module-140, _ZTS8Observer, _ZTV8Observer, _ZN8Observer7observeEP10Observable, _ZN10MyObserverD0Ev, _ZN8Observer12onRegisteredEP10Observable, _ZTV10MyObserver, _ZN8ObserverD0Ev, _ZN10MyObserver11onThingDoneERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE, _ZNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEE12_M_constructIPKcEEvT_S8_St20forward_iterator_tag, long_lived_obs, _ZN10MyObserverD1Ev, _ZN8ObserverD1Ev, _ZN10MyObserverD2Ev }) }
True
>>> c.main()
[runStaticInitializersOnce]: Failed to materialize symbols: { (main, { __orc_init_func.cling-module-140 }) }
cling JIT session error: Failed to materialize symbols: { (main, { main }) }
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
cppyy.gbl.std.runtime_error: int ::main() =>
    runtime_error: failed to resolve function
>>> 
>>> class MyObserver(c.Observer):
...     def onThingDone(self, msg):
...         print(id(self), "onThingDone", msg)
...     def onRegistered(self, prev):
...         print(id(self), "onRegistered", "was", prev, "is", self.observed)
... 
>>> obj = c.Observable()
>>> obs = MyObserver()
cling JIT session error: Failed to materialize symbols: { (main, { _ZN8Observer7observeEP10Observable }) }
cling JIT session error: Failed to materialize symbols: { (main, { _ZTVN16__cppyy_internal11Dispatcher1E }) }
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: none of the 2 overloaded methods succeeded. Full details:
  none of the 3 overloaded methods succeeded. Full details:
  Dispatcher1::Dispatcher1(const __cppyy_internal::Dispatcher1& other) =>
    TypeError: takes at least 1 arguments (0 given)
  Dispatcher1::Dispatcher1(const Observer& a0) =>
    TypeError: takes at least 1 arguments (0 given)
  __cppyy_internal::Dispatcher1 constructor failed
  none of the 3 overloaded methods succeeded. Full details:
  Dispatcher1::Dispatcher1(const __cppyy_internal::Dispatcher1& other) =>
    TypeError: takes at least 1 arguments (0 given)
  Dispatcher1::Dispatcher1(const Observer& a0) =>
    TypeError: takes at least 1 arguments (0 given)
  __cppyy_internal::Dispatcher1 constructor failed

Note that I get those Failed to materialize symbols errors all the time, which is why I tend to prefer 2.4 over 3.0.

wlav commented 1 year ago

The "failed to materialize" is also reported here: https://github.com/wlav/cppyy/issues/175 and is one that I've yet to be able to reproduce. I'm pestering upstream about it.

The first is reproducible and appears to be a double delete (I get a different, clearer, error message on Mac).

wlav commented 1 year ago

It's an ordering thing on application shutdown: the Python object goes dodo-bird before the C++ one, with result that an attempt is made to call a virtual method on that Python object (coming down from ~Observer()) that is now gone, which leads to a CPyCppyy::PyException that is unhandled, which causes an std::terminate() and Python then attempts final cleanup from a broken state.

N-Coder commented 1 year ago

Ah, I got something remotely similar in C++ when declaring Observer:: onRegistered(...) = 0, that is as pure virtual, as the slicing during the final destructor call of ~Observer removes any implementations (and then leads to a crash due to a call to a purely virtual method). Please note that this is probably not related to the interpreter shutdown, as the same behaviour can be reproduced by smashing GC on the variable by repeated deletion or overwriting.

Regarding the symbols failing to materialise, I will see whether I can build a MRE in a Linux container.

wlav commented 1 year ago

It's the destruction order, not so much the shutdown itself (although that complicates matters in this case b/c the state of the interpreter is muddled), followed by the exception. B/c the Python object is already deleted and set to Py_None, the call fails, eventually raising a CPyCppyy::PyException once exiting the dispatcher. This C++ exception is the way to get a Python exception through the C++ call stack back into Python. But here, that means coming out of the C++ destructor, which C++ disagrees with.

There's a trivial fix to the example above, which is to add del obs or del obj. Basically, these objects and, most importantly, the Python-side dispatcher object, are all destroyed during the second phase of Python shutdown. There, cleanup is run for objects that failed to go away during the normal reference counting shutdown and their order of destruction thus does not follow refcounting rules. It so happens that the dispatcher goes before obj and obs, leaving obs in a broken state.

The reason is either a circular reference count somewhere, preventing normal destruction of obs and del; or a Py_INCREF too many somewhere in the cppyy code.

wlav commented 1 year ago

So far, I don't see any obvious refcounting errors. Beyond that, although it's easy enough to detect that the dispatcher is gone, it's not possible to be either silent about it (ie. not report it) or not send that exception (if this call didn't originate from a destructor, it wouldn't be an issue).

Best I can do is assume something is going down when the dispatcher is gone and only leave the Python error. That means the error can only propagate through 1 level of indirection.

N-Coder commented 1 year ago

There's a trivial fix to the example above, which is to add del obs or del obj. Basically, these objects and, most importantly, the Python-side dispatcher object, are all destroyed during the second phase of Python shutdown. [...] It so happens that the dispatcher goes before obj and obs, leaving obs in a broken state.

As far as I understood, this means that the crash only happens when 1) not deleting obs and 2) then during interpreter shutdown. The following reproduces the crash without either of the points holding:

from cppyy import *
import cppyy.gbl as c

include("test.cpp")

class MyObserver(c.Observer):
    def onThingDone(self, msg):
        print(id(self), "onThingDone", msg)
    def onRegistered(self, prev):
        print(id(self), "onRegistered", "was", prev, "is", self.observed)

obj = c.Observable()
obs = MyObserver()
obs.observe(obj)
obj.doThing("test")

del obs
obs = MyObserver()
obs.observe(obj)
obj.doThing("test")

import gc
[str(o) for o in gc.get_objects()]
crash log (click me) ``` >>> [str(o) for o in gc.get_objects()] Fatal Python error: notimplemented_dealloc: deallocating NotImplemented Python runtime state: initialized Current thread 0x00007fa6d93cd740 (most recent call first): File "", line 1 in File "", line 1 in Extension modules: libcppyy (total: 1) *** Break *** abort #0 0x00007fa6d8cfcc37 in __GI___wait4 (pid=297130, stat_loc=stat_loc entry=0x7ffe32f00038, options=options entry=0, usage=usage entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30 #1 0x00007fa6d8cfcbfb in __GI___waitpid (pid=, stat_loc=stat_loc entry=0x7ffe32f00038, options=options entry=0) at waitpid.c:38 #2 0x00007fa6d8c711fb in do_system (line=) at ../sysdeps/posix/system.c:171 #3 0x00007fa6cafa0725 in CppyyLegacy::TUnixSystem::StackTrace() () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so #4 0x00007fa6cb0aca23 in (anonymous namespace)::do_trace (sig=5) at src/clingwrapper.cxx:239 #5 (anonymous namespace)::TExceptionHandlerImp::HandleException (this=, sig=5) at src/clingwrapper.cxx:252 #6 0x00007fa6caf9f231 in CppyyLegacy::TUnixSystem::DispatchSignals(CppyyLegacy::ESignals) () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so #7 #8 __pthread_kill_implementation (threadid=, signo=signo entry=6, no_tid=no_tid entry=0) at pthread_kill.c:44 #9 0x00007fa6d8cb08b3 in __pthread_kill_internal (signo=6, threadid=) at pthread_kill.c:78 #10 0x00007fa6d8c5fabe in __GI_raise (sig=sig entry=6) at ../sysdeps/posix/raise.c:26 #11 0x00007fa6d8c4887f in __GI_abort () at abort.c:79 #12 0x00007fa6d8f6e8fa in fatal_error_exit (status=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2626 #13 fatal_error (fd=, header=header entry=1, prefix=prefix entry=0x7fa6d91429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=msg entry=0x7fa6d90cc53a "deallocating NotImplemented", status=status entry=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2737 #14 0x00007fa6d8f6eca9 in _Py_FatalErrorFunc (func=0x7fa6d91429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=0x7fa6d90cc53a "deallocating NotImplemented") at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2823 #15 0x00007fa6d8f6ef19 in notimplemented_dealloc (ignore=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:1768 #16 0x00007fa6d90113f3 in _Py_Dealloc (op=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:2390 #17 Py_DECREF (op=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/object.h:538 #18 dict_repr (mp=0x7fa6cb590e80) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/dictobject.c:2463 #19 0x00007fa6d8fe66fd in object_str (self={'__name__': 'builtins', '__doc__': "Built-in functions, types, exceptions, and other objects.\n\nThis module provides direct access to all 'built-in'\nidentifiers of Python; for example, builtins.len is\nthe full name for the built-in function len().\n\nThis module is not normally accessed explicitly by most\napplications, but can be useful in modules that provide\nobjects with the same name as a built-in value, but in\nwhich the built-in of that name is also needed.", '__package__': '', '__loader__': , '__spec__': , origin='built-in', loader_state=None, submodule_search_locations=None, _uninitialized_submodules=[], _set_fileattr=False, _cached=None) at remote 0x7fa6cb593690>, '__build_class__': , '__import__': , 'abs': , '__spec__': , origin='built-in', loader_state=None, submodule_search_locations=None, _uninitialized_submodules=[], _set_fileattr=False, _cached=None) at remote 0x7fa6cb593690>, '__build_class__': , '__import__': , 'abs': , frame=, throwflag=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/ceval.c:4945 #22 0x00007fa6d8fb57da in _PyEval_EvalFrame (throwflag=0, frame=0x7fa6d9388020, tstate=0x7fa6d930ed38 <_PyRuntime+166328>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/internal/pycore_ceval.h:73 #23 _PyEval_Vector (tstate=tstate entry=0x7fa6d930ed38 <_PyRuntime+166328>, func=func entry=0x7fa6cb5984a0, locals=locals entry={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), args=args entry=0x0, argcount=argcount entry=0, kwnames=kwnames entry=0x0) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/ceval.c:6439 #24 0x00007fa6d903a6ec in PyEval_EvalCode (co=, globals=, locals={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated)) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/ceval.c:1154 #25 0x00007fa6d9057c33 in run_eval_code_obj (tstate=tstate entry=0x7fa6d930ed38 <_PyRuntime+166328>, co=co entry=0x7fa6cb363930, globals=globals entry={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), locals=locals entry={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated)) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:1712 #26 0x00007fa6d90542fa in run_mod (mod=mod entry=0x56112f057910, filename=filename entry='', globals={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), locals={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), flags=flags entry=0x7ffe32f031d8, arena=arena entry=0x7fa6cb51b830) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:1733 #27 0x00007fa6d8f98562 in PyRun_InteractiveOneObjectEx (fp=fp entry=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename=filename entry='', flags=flags entry=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:261 #28 0x00007fa6d8f98702 in _PyRun_InteractiveLoopObject (fp=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename='', flags=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:138 #29 0x00007fa6d8f25655 in _PyRun_AnyFileObject (fp=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename='', closeit=0, flags=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:73 #30 0x00007fa6d8f9887f in PyRun_AnyFileExFlags (fp=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename=, closeit=0, flags=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:105 #31 0x00007fa6d8f215f3 in pymain_run_stdin (config=0x7fa6d92f4d80 <_PyRuntime+59904>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:509 #32 pymain_run_python (exitcode=0x7ffe32f031d0) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:604 #33 Py_RunMain () at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:680 #34 0x00007fa6d902a9fb in Py_BytesMain (argc=, argv=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:734 #35 0x00007fa6d8c49b4a in __libc_start_call_main (main=main entry=0x56112e9ec160
, argc=argc entry=1, argv=argv entry=0x7ffe32f03438) at ../sysdeps/nptl/libc_start_call_main.h:58 #36 0x00007fa6d8c49c0b in __libc_start_main_impl (main=0x56112e9ec160
, argc=1, argv=0x7ffe32f03438, init=, fini=, rtld_fini=, stack_end=0x7ffe32f03428) at ../csu/libc-start.c:360 #37 0x000056112e9ec095 in _start () *** Break *** abort #0 0x00007fa6d8cfcc37 in __GI___wait4 (pid=297586, stat_loc=stat_loc entry=0x7ffe32f00038, options=options entry=0, usage=usage entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30 #1 0x00007fa6d8cfcbfb in __GI___waitpid (pid=, stat_loc=stat_loc entry=0x7ffe32f00038, options=options entry=0) at waitpid.c:38 #2 0x00007fa6d8c711fb in do_system (line=) at ../sysdeps/posix/system.c:171 #3 0x00007fa6cafa0725 in CppyyLegacy::TUnixSystem::StackTrace() () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so #4 0x00007fa6cb0ac8a7 in (anonymous namespace)::do_trace (sig=5) at src/clingwrapper.cxx:239 #5 (anonymous namespace)::TExceptionHandlerImp::HandleException (this=, sig=5) at src/clingwrapper.cxx:258 #6 0x00007fa6caf9f231 in CppyyLegacy::TUnixSystem::DispatchSignals(CppyyLegacy::ESignals) () from /home/finksim/.local/lib/python3.11/site-packages/cppyy_backend/lib/libCoreLegacy.so #7 #8 __pthread_kill_implementation (threadid=, signo=signo entry=6, no_tid=no_tid entry=0) at pthread_kill.c:44 #9 0x00007fa6d8cb08b3 in __pthread_kill_internal (signo=6, threadid=) at pthread_kill.c:78 #10 0x00007fa6d8c5fabe in __GI_raise (sig=sig entry=6) at ../sysdeps/posix/raise.c:26 #11 0x00007fa6d8c4887f in __GI_abort () at abort.c:79 #12 0x00007fa6d8f6e8fa in fatal_error_exit (status=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2626 #13 fatal_error (fd=, header=header entry=1, prefix=prefix entry=0x7fa6d91429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=msg entry=0x7fa6d90cc53a "deallocating NotImplemented", status=status entry=-1) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2737 #14 0x00007fa6d8f6eca9 in _Py_FatalErrorFunc (func=0x7fa6d91429b0 <__func__.2.lto_priv.0> "notimplemented_dealloc", msg=0x7fa6d90cc53a "deallocating NotImplemented") at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pylifecycle.c:2823 #15 0x00007fa6d8f6ef19 in notimplemented_dealloc (ignore=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:1768 #16 0x00007fa6d90113f3 in _Py_Dealloc (op=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/object.c:2390 #17 Py_DECREF (op=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/object.h:538 #18 dict_repr (mp=0x7fa6cb590e80) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Objects/dictobject.c:2463 #19 0x00007fa6d8fe66fd in object_str (self={'__name__': 'builtins', '__doc__': "Built-in functions, types, exceptions, and other objects.\n\nThis module provides direct access to all 'built-in'\nidentifiers of Python; for example, builtins.len is\nthe full name for the built-in function len().\n\nThis module is not normally accessed explicitly by most\napplications, but can be useful in modules that provide\nobjects with the same name as a built-in value, but in\nwhich the built-in of that name is also needed.", '__package__': '', '__loader__': , '__spec__': , origin='built-in', loader_state=None, submodule_search_locations=None, _uninitialized_submodules=[], _set_fileattr=False, _cached=None) at remote 0x7fa6cb593690>, '__build_class__': , '__import__': , 'abs': , '__spec__': , origin='built-in', loader_state=None, submodule_search_locations=None, _uninitialized_submodules=[], _set_fileattr=False, _cached=None) at remote 0x7fa6cb593690>, '__build_class__': , '__import__': , 'abs': , frame=, throwflag=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/ceval.c:4945 #22 0x00007fa6d8fb57da in _PyEval_EvalFrame (throwflag=0, frame=0x7fa6d9388020, tstate=0x7fa6d930ed38 <_PyRuntime+166328>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Include/internal/pycore_ceval.h:73 #23 _PyEval_Vector (tstate=tstate entry=0x7fa6d930ed38 <_PyRuntime+166328>, func=func entry=0x7fa6cb5984a0, locals=locals entry={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), args=args entry=0x0, argcount=argcount entry=0, kwnames=kwnames entry=0x0) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/ceval.c:6439 #24 0x00007fa6d903a6ec in PyEval_EvalCode (co=, globals=, locals={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated)) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/ceval.c:1154 #25 0x00007fa6d9057c33 in run_eval_code_obj (tstate=tstate entry=0x7fa6d930ed38 <_PyRuntime+166328>, co=co entry=0x7fa6cb363930, globals=globals entry={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), locals=locals entry={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated)) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:1712 #26 0x00007fa6d90542fa in run_mod (mod=mod entry=0x56112f057910, filename=filename entry='', globals={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), locals={'__name__': '__main__', '__doc__': None, '__package__': None, '__loader__': , '__spec__': None, '__annotations__': {}, '__builtins__': , 'cppdef': , 'cppexec': , 'include': , 'c_include': , 'load_library': , 'nullptr': , 'sizeof': , 'typeid': , 'multi': , 'add_include_path': , 'add_library_path': , 'add_autoload_map': , 'set_debug': , 'c': <_meta(__module__='cppyy._cpython_cppyy', __dict__=, __weakref__=, __doc_...(truncated), flags=flags entry=0x7ffe32f031d8, arena=arena entry=0x7fa6cb51b830) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:1733 #27 0x00007fa6d8f98562 in PyRun_InteractiveOneObjectEx (fp=fp entry=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename=filename entry='', flags=flags entry=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:261 #28 0x00007fa6d8f98702 in _PyRun_InteractiveLoopObject (fp=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename='', flags=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:138 #29 0x00007fa6d8f25655 in _PyRun_AnyFileObject (fp=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename='', closeit=0, flags=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:73 #30 0x00007fa6d8f9887f in PyRun_AnyFileExFlags (fp=0x7fa6d8df6aa0 <_IO_2_1_stdin_>, filename=, closeit=0, flags=0x7ffe32f031d8) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Python/pythonrun.c:105 #31 0x00007fa6d8f215f3 in pymain_run_stdin (config=0x7fa6d92f4d80 <_PyRuntime+59904>) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:509 #32 pymain_run_python (exitcode=0x7ffe32f031d0) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:604 #33 Py_RunMain () at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:680 #34 0x00007fa6d902a9fb in Py_BytesMain (argc=, argv=) at /usr/src/debug/python3.11-3.11.5-1.fc38.x86_64/Modules/main.c:734 #35 0x00007fa6d8c49b4a in __libc_start_call_main (main=main entry=0x56112e9ec160
, argc=argc entry=1, argv=argv entry=0x7ffe32f03438) at ../sysdeps/nptl/libc_start_call_main.h:58 #36 0x00007fa6d8c49c0b in __libc_start_main_impl (main=0x56112e9ec160
, argc=1, argv=0x7ffe32f03438, init=, fini=, rtld_fini=, stack_end=0x7ffe32f03428) at ../csu/libc-start.c:360 #37 0x000056112e9ec095 in _start () 0x7fa6d8bfa010 destruct ```

So everything should be "clean" here in the sense that the dispatcher is still alive and the previous object was properly disposed of. Note that there are two *** Break *** abort in there and that the very last line still does seem to log a C++ ~MyObserver call -- but of a C++ class that wasn't even instantiated. Messing with the gc interface was the only way I found for reliably reproducing this, although I got various other non-deterministic crashes at various points during runtime (that is while not intentionally shuting down the interpreter).

wlav commented 1 year ago

I think it's still the same/similar conclusion: the Python object is accessed in the C++ destructor after it has gone awol. Memory is then corrupted and the final call to str is an innocent bystander (the actual crash is eventually on an object that looks fine in every way and it's Python's builtin repr that is crashing).

The basic problem here appears to be that if the object is created on the Python side, it's the Python proxy that goes away first. Its reference count goes to zero, its __del__ is called, and only then are the C++ destructors run. Thus, calling Python methods of the final derived object in the destructor of the base class is simply not going to work.

Not sure whether anything can be done about that: one or the other side has to go first and the side that goes second can no longer call into the side that has gone first. I.e., if C++ were forced to go first, then __del__ can't access the C++ object, just as here C++ can't access the Python object in its destructor. I do think I can silence the error (prevent the memory corruption and crash), but that doesn't give you the functionality that you want.

A general solution could be to allow the cleanup in the destructor to be called in the __del__ of the Python derived object (i.e. at the point where both the C++ and Python side are still in a complete state). Similar to how a close() method can be either run directly or from the destructor. Now, in this particular example, it happens to be that the destructor is safe to call and does the right cleanup, so adding this:

    def __del__(self):
        c.Observer.__destruct__(self)

to MyObserver solves the issue.

I still need to some error suppression, e.g. the above has to be done with implementing __del__ on the Python side, not __destruct__ (which would be your choice if the destruction starts on the C++ side). I'll also add some extra checks to turn the escaping exception into a diagnostic printout instead of an abort.

N-Coder commented 1 year ago

Adding the def __del__(self): c.Observer.__destruct__(self) will cause ~Observer to be called twice, which is usually not good C++ style as I recall, but no problem here as the method is idempotent, right? I just tried it and it actually does solve the problem, thanks! I will check whether it also resolves the issues in the more involved actual code.

So this means that deletion from the Python side is very different to deletion from the C++ side. To understand the life cycle a little bit better, I tried to use logging in the following example, but it actually got me more confused.

>>> import cppyy
>>> 
>>> cppyy.cppdef("""\
... class Base {
... public:
...     virtual ~Base() {
...         std::cout << "~Base" << std::endl;
...     }
... };
... 
... void delete_it(Base *p) { delete p; }
... """)
True
>>> 
>>> def noop(*args, **kws):
...     return None
... 
>>> class Derived(cppyy.gbl.Base):
...     def __destruct__(self):
...         print("Derived.__destruct__")
...     def __del__(self):
...         print("Derived.__del__ start")
...         getattr(super(), "__del__", noop)() # https://stackoverflow.com/a/59870543/805569
...         print("Derived.__del__ end")
... 
>>> d = Derived()
>>> d = Derived()
Derived.__del__ start
Derived.__del__ end
AttributeError: 'NoneType' object has no attribute '__destruct__'
~Base
>>> d.__python_owns__ = False
>>> cppyy.gbl.delete_it(d)
Derived.__destruct__
~Base
>>> del(d)
Derived.__del__ start
Derived.__del__ end
>>> 
Fatal Python error: notimplemented_dealloc: deallocating NotImplemented
Python runtime state: finalizing (tstate=0x00007fa661f0ed38)

Is the AttributeError: 'NoneType' object has no attribute '__destruct__' a bug or did I do something wrong, i.e. do I have to call the actual destructor manually when overriding __destruct__? Probably this also crosses the new crash on shutdown. If you can help me understanding this I'd gladly elaborate the docs on this and maybe even include the example or a flowchart showing the different code paths to make this also clearer to others.

wlav commented 11 months ago

Back to this one ...

Yes, not good C++ side, but it works here. Cleaner is to have a separate cleanup() function that becomes a no-op if called from the dtor.

Code in repo turns the crash in a RuntimeWarning and ignores the AttributeError if the Python object is already deleted (this is debatable, but there's no implementation guarantee that Python's __del__ will run at shutdown, so being silent about it seems fair).

wlav commented 10 months ago

Should all be good now with release 3.1.0. Feel free to reopen if you find otherwise.