Intro
I'm writing a python application which uses a library written in C. When some event occurred at C level a Python callback is used to be called.
Here is a part of my python callback definition:
def callback(str1, str2, cdata, flag):
print("PYTHON HANDLER")
...
print(">>EXIT<<")
Before passing callback to C it is converted using this code:
FuncType = ctypes.CFUNCTYPE(None, ctypes.c_char_p, ctypes.c_char_p,
ctypes.c_void_p, ctypes.c_bool)
ctype_function_wrapper = FuncType(callback)
cfunction_pointer = ctypes.cast(ctype_function_wrapper, ctypes.c_void_p)
py_callback_ptr = cfunction_pointer.value
After that py_callback_ptr is passed to C library and saved there as a (void *) pointer.
When an event occurs C level py_callback_ptr is called. Here is a piece of code which does this at C level:
...
printf("Acquire GIL\r\n");
PyGILState_STATE gstate;
gstate = PyGILState_Ensure();
printf("Callback()\r\n");
((void (*)(char*, char*, DataStructure*, bool))py_callback_ptr)(
str1, str2, value, bool_flag);
printf("Callback return\r\n");
PyGILState_Release(gstate);
printf("Release GIL\r\n");
...
Most of the time it works as expected and callback is called. I get this output in stdout:
...
Acquire GIL
Callback()
PYTHON HANDLER
>>EXIT<<
Callback return
Release GIL
...
But some times I get this output mixed with stderr output. It shows me that C code around callback executed normally but callback itself didn't executed:
...
Acquire GIL
Callback()
SystemError: null argument to internal routine # from stderr
Callback return
Release GIL
...
Research
I have looked for SystemError in Python and found the explanation
Raised when the interpreter finds an internal error, but the situation does not look so serious to cause it to abandon all hope. The associated value is a string indicating what went wrong (in low-level terms).
So this is error caught in interpreter code which writes to stderr some string. I decided to catch that call and investigate it.
Debugging
I have tried to catch this error in gdb. I have set up a breakpoint which stops program execution on stderr output using this command:
(gdb) b write if 2==$rdi
Also a have caught backtrace of normal callback execution. Here they are.
Part of normal backtrace:
#0 write () at ../sysdeps/unix/syscall-template.S:81
#1 0x0000000000437735 in _Py_write_impl (gil_held=1, count=4, buf=<optimized out>, fd=2) at Python/fileutils.c:1331
#2 _Py_write (fd=2, buf=0x961100, count=<optimized out>) at Python/fileutils.c:1393
#3 0x00000000005b73ce in _io_FileIO_write_impl (b=0x7ffff3916b00, b=0x7ffff3916b00, self=0x7ffff7f0c3a8) at ./Modules/_io/fileio.c:857
#4 _io_FileIO_write (self=0x7ffff7f0c3a8, arg=<optimized out>) at ./Modules/_io/clinic/fileio.c.h:251
#5 0x00000000004aa139 in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff4f9d828, args=args@entry=0x7ffff3916c40, nargs=nargs@entry=1, kwargs=kwargs@entry=0x0) at Objects/methodobject.c:209
#6 0x0000000000451b68 in _PyObject_FastCallDict (func=0x7ffff4f9d828, args=0x7ffff3916c40, nargs=1, kwargs=0x0) at Objects/abstract.c:2313
#7 0x0000000000452b86 in PyObject_CallMethodObjArgs (callable=0x7ffff4f9d828, name=<optimized out>) at Objects/abstract.c:2759
#8 0x00000000005bb24a in _bufferedwriter_raw_write (self=self@entry=0x7ffff7fd0b48, start=<optimized out>, len=4) at ./Modules/_io/bufferedio.c:1853
#9 0x00000000005bbd0f in _bufferedwriter_flush_unlocked (self=self@entry=0x7ffff7fd0b48) at ./Modules/_io/bufferedio.c:1898
#10 buffered_flush_and_rewind_unlocked (self=self@entry=0x7ffff7fd0b48) at ./Modules/_io/bufferedio.c:827
#11 0x00000000005bbf27 in buffered_flush (self=0x7ffff7fd0b48, args=<optimized out>) at ./Modules/_io/bufferedio.c:854
#12 0x00000000004aa1ff in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff4f9d5a0, args=args@entry=0x7ffff3916f30, nargs=nargs@entry=0, kwargs=kwargs@entry=0x0) at Objects/methodobject.c:192
#13 0x0000000000451b68 in _PyObject_FastCallDict (func=0x7ffff4f9d5a0, args=0x7ffff3916f30, nargs=0, kwargs=0x0) at Objects/abstract.c:2313
#14 0x0000000000452b86 in PyObject_CallMethodObjArgs (callable=0x7ffff4f9d5a0, name=<optimized out>) at Objects/abstract.c:2759
#15 0x00000000005c1924 in _io_TextIOWrapper_write_impl (text=0x7ffff7f30a40, self=0x7ffff7f7d708) at ./Modules/_io/textio.c:1367
#16 _io_TextIOWrapper_write (self=0x7ffff7f7d708, arg=<optimized out>) at ./Modules/_io/clinic/textio.c.h:216
#17 0x00000000004aa139 in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff4f9d5e8, args=args@entry=0x7ffff3917148, nargs=nargs@entry=1, kwargs=kwargs@entry=0x0) at Objects/methodobject.c:209
#18 0x0000000000451b68 in _PyObject_FastCallDict (func=func@entry=0x7ffff4f9d5e8, args=args@entry=0x7ffff3917148, nargs=nargs@entry=1, kwargs=kwargs@entry=0x0) at Objects/abstract.c:2313
#19 0x000000000047a4cc in PyFile_WriteObject (flags=1, f=<optimized out>, v=0x7ffff7f30a40) at Objects/fileobject.c:150
#20 PyFile_WriteString (s=s@entry=0x5e4ac5 "\n", f=<optimized out>) at Objects/fileobject.c:174
#21 0x000000000053b103 in builtin_print (self=<optimized out>, args=0x7ffff65df748, kwds=<optimized out>) at Python/bltinmodule.c:1814
#22 0x00000000004aa3d9 in PyCFunction_Call (func=func@entry=0x7ffff7fcdf30, args=args@entry=0x7ffff65df748, kwds=kwds@entry=0x7ffff4f9d8b8) at Objects/methodobject.c:98
#23 0x0000000000548572 in do_call_core (kwdict=0x7ffff4f9d8b8, callargs=0x7ffff65df748, func=0x7ffff7fcdf30) at Python/ceval.c:5116
#24 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3404
#25 0x000000000053f401 in PyEval_EvalFrameEx (throwflag=0, f=0x7ffff4fa1048) at Python/ceval.c:754
#26 _PyEval_EvalCodeWithName (_co=0x7ffff7f089c0, globals=globals@entry=0x7ffff7f4c360, locals=locals@entry=0x0, args=<optimized out>, argcount=1, kwnames=0x0, kwargs=kwargs@entry=0x7ffff7ed4d60, kwcount=0, kwstep=kwstep@entry=1,
defs=0x0, defcount=defcount@entry=0, kwdefs=0x0, closure=0x0, name=name@entry=0x7ffff7f0f3b0, qualname=0x7ffff7f0f3b0) at Python/ceval.c:4166
#27 0x000000000053f6ff in fast_function (kwnames=0x0, nargs=<optimized out>, stack=<optimized out>, func=0x7ffff7f36e18) at Python/ceval.c:4992
#28 call_function (pp_stack=pp_stack@entry=0x7ffff3917550, oparg=<optimized out>, kwnames=kwnames@entry=0x0) at Python/ceval.c:4872
#29 0x000000000054138b in _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3335
#30 0x000000000053e791 in PyEval_EvalFrameEx (throwflag=0, f=0x7ffff7ed4bb8) at Python/ceval.c:754
#31 _PyFunction_FastCall (co=<optimized out>, args=<optimized out>, nargs=4, globals=globals@entry=0x7ffff7f4c360) at Python/ceval.c:4933
#32 0x000000000053f927 in fast_function (kwnames=0x0, nargs=<optimized out>, stack=<optimized out>, func=0x7ffff4f9ed08) at Python/ceval.c:4968
#33 call_function (pp_stack=pp_stack@entry=0x7ffff3917770, oparg=<optimized out>, kwnames=kwnames@entry=0x0) at Python/ceval.c:4872
#34 0x000000000054138b in _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3335
#35 0x000000000053f401 in PyEval_EvalFrameEx (throwflag=0, f=0x7ffff4fa0048) at Python/ceval.c:754
#36 _PyEval_EvalCodeWithName (_co=0x7ffff65d0810, globals=<optimized out>, locals=locals@entry=0x0, args=args@entry=0x7ffff6569330, argcount=4, kwnames=kwnames@entry=0x0, kwargs=kwargs@entry=0x0, kwcount=kwcount@entry=0,
kwstep=kwstep@entry=2, defs=defs@entry=0x0, defcount=defcount@entry=0, kwdefs=kwdefs@entry=0x0, closure=closure@entry=0x7ffff7e9e208, name=name@entry=0x0, qualname=qualname@entry=0x0) at Python/ceval.c:4166
#37 0x00000000005401dd in PyEval_EvalCodeEx (_co=<optimized out>, globals=<optimized out>, locals=locals@entry=0x0, args=args@entry=0x7ffff6569330, argcount=<optimized out>, kws=kws@entry=0x0, kwcount=kwcount@entry=0,
defs=defs@entry=0x0, defcount=defcount@entry=0, kwdefs=0x0, closure=0x7ffff7e9e208) at Python/ceval.c:4187
#38 0x000000000048101c in function_call (func=0x7ffff4f9eea0, arg=0x7ffff6569318, kw=0x0) at Objects/funcobject.c:604
#39 0x0000000000451820 in PyObject_Call (func=0x7ffff4f9eea0, args=args@entry=0x7ffff6569318, kwargs=<optimized out>) at Objects/abstract.c:2261
#40 0x0000000000540696 in PyEval_CallObjectWithKeywords (func=func@entry=0x7ffff4f9eea0, args=args@entry=0x7ffff6569318, kwargs=kwargs@entry=0x0) at Python/ceval.c:4771
#41 0x00000000004516e7 in PyObject_CallObject (o=o@entry=0x7ffff4f9eea0, a=a@entry=0x7ffff6569318) at Objects/abstract.c:2187
#42 0x00007ffff4d54d2c in _CallPythonObject (pArgs=<optimized out>, flags=257, converters=0x7ffff656a908, callable=0x7ffff4f9eea0, setfunc=0x0, restype=0x7ffff4f631d0 <ffi_type_void>, mem=0x7ffff3917c20)
at /home/ns-sergeev/.pythons/src/Python-3.6.8/Modules/_ctypes/callbacks.c:234
#43 closure_fcn (cif=<optimized out>, resp=0x7ffff3917c20, args=0x7ffff3917a80, userdata=<optimized out>) at /home/ns-sergeev/.pythons/src/Python-3.6.8/Modules/_ctypes/callbacks.c:296
#44 0x00007ffff4b42a6b in ffi_closure_unix64_inner (closure=0x7ffff7ff2010, rvalue=0x7ffff3917c20, reg_args=0x7ffff3917b70, argp=0x7ffff3917c40 "P\r") at ../src/x86/ffi64.c:667
#45 0x00007ffff4b42de4 in ffi_closure_unix64 () at ../src/x86/unix64.S:229
...
C-library frames are omitted
Backtrace with callback call error:
#0 write () at ../sysdeps/unix/syscall-template.S:81
#1 0x0000000000437735 in _Py_write_impl (gil_held=1, count=47, buf=<optimized out>, fd=2) at Python/fileutils.c:1331
#2 _Py_write (fd=2, buf=0x961100, count=<optimized out>) at Python/fileutils.c:1393
#3 0x00000000005b73ce in _io_FileIO_write_impl (b=0x7ffff3916e80, b=0x7ffff3916e80, self=0x7ffff7f0c3a8) at ./Modules/_io/fileio.c:857
#4 _io_FileIO_write (self=0x7ffff7f0c3a8, arg=<optimized out>) at ./Modules/_io/clinic/fileio.c.h:251
#5 0x00000000004aa139 in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff4f9e7e0, args=args@entry=0x7ffff3916fc0, nargs=nargs@entry=1,
kwargs=kwargs@entry=0x0) at Objects/methodobject.c:209
#6 0x0000000000451b68 in _PyObject_FastCallDict (func=0x7ffff4f9e7e0, args=0x7ffff3916fc0, nargs=1, kwargs=0x0) at Objects/abstract.c:2313
#7 0x0000000000452b86 in PyObject_CallMethodObjArgs (callable=0x7ffff4f9e7e0, name=<optimized out>) at Objects/abstract.c:2759
#8 0x00000000005bb24a in _bufferedwriter_raw_write (self=self@entry=0x7ffff7fd0b48, start=<optimized out>, len=47) at ./Modules/_io/bufferedio.c:1853
#9 0x00000000005bbd0f in _bufferedwriter_flush_unlocked (self=self@entry=0x7ffff7fd0b48) at ./Modules/_io/bufferedio.c:1898
#10 buffered_flush_and_rewind_unlocked (self=self@entry=0x7ffff7fd0b48) at ./Modules/_io/bufferedio.c:827
#11 0x00000000005bbf27 in buffered_flush (self=0x7ffff7fd0b48, args=<optimized out>) at ./Modules/_io/bufferedio.c:854
#12 0x00000000004aa1ff in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff4f9e558, args=args@entry=0x7ffff39172b0, nargs=nargs@entry=0,
kwargs=kwargs@entry=0x0) at Objects/methodobject.c:192
#13 0x0000000000451b68 in _PyObject_FastCallDict (func=0x7ffff4f9e558, args=0x7ffff39172b0, nargs=0, kwargs=0x0) at Objects/abstract.c:2313
#14 0x0000000000452b86 in PyObject_CallMethodObjArgs (callable=0x7ffff4f9e558, name=<optimized out>) at Objects/abstract.c:2759
#15 0x00000000005c1924 in _io_TextIOWrapper_write_impl (text=0x7ffff7f30a40, self=0x7ffff7f7d708) at ./Modules/_io/textio.c:1367
#16 _io_TextIOWrapper_write (self=0x7ffff7f7d708, arg=<optimized out>) at ./Modules/_io/clinic/textio.c.h:216
#17 0x00000000004aa139 in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff4f9e5a0, args=args@entry=0x7ffff39174c8, nargs=nargs@entry=1,
kwargs=kwargs@entry=0x0) at Objects/methodobject.c:209
#18 0x0000000000451b68 in _PyObject_FastCallDict (func=func@entry=0x7ffff4f9e5a0, args=args@entry=0x7ffff39174c8, nargs=nargs@entry=1,
kwargs=kwargs@entry=0x0) at Objects/abstract.c:2313
#19 0x000000000047a4cc in PyFile_WriteObject (flags=1, f=0x7ffff7f30a40, v=0x7ffff7f30a40) at Objects/fileobject.c:150
#20 PyFile_WriteString (s=s@entry=0x5e4ac5 "\n", f=f@entry=0x7ffff7f7d708) at Objects/fileobject.c:174
#21 0x0000000000425790 in print_exception (value=<optimized out>, f=0x7ffff7f7d708) at Python/pythonrun.c:819
#22 print_exception_recursive (f=f@entry=0x7ffff7f7d708, value=value@entry=0x7ffff4f9a1a8, seen=seen@entry=0x7ffff650ee48) at Python/pythonrun.c:891
---Type <return> to continue, or q <return> to quit---
#23 0x0000000000426683 in PyErr_Display (exception=<optimized out>, value=0x7ffff4f9a1a8, tb=<optimized out>) at Python/pythonrun.c:925
#24 0x000000000043199a in sys_excepthook (self=<optimized out>, args=<optimized out>) at ./Python/sysmodule.c:230
#25 0x00000000004aa1ac in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7ffff7f61f78, args=args@entry=0x7ffff39176c0, nargs=nargs@entry=3,
kwargs=kwargs@entry=0x0) at Objects/methodobject.c:234
#26 0x0000000000451b68 in _PyObject_FastCallDict (func=0x7ffff7f61f78, args=args@entry=0x7ffff39176c0, nargs=nargs@entry=3, kwargs=kwargs@entry=0x0)
at Objects/abstract.c:2313
#27 0x00000000004267f5 in PyErr_PrintEx (set_sys_last_vars=set_sys_last_vars@entry=1) at Python/pythonrun.c:669
#28 0x0000000000426a9a in PyErr_Print () at Python/pythonrun.c:532
#29 0x00007ffff4d54b78 in PrintError (msg=msg@entry=0x7ffff4d5bc7a "BUG: PySequence_Length")
at /home/ns-sergeev/.pythons/src/Python-3.6.8/Modules/_ctypes/callbacks.c:91
#30 0x00007ffff4d54e8e in _CallPythonObject (pArgs=0x7ffff3917a80, flags=4353, converters=0x0, callable=0x0, setfunc=0x0,
restype=0x7ffff4f631d0 <ffi_type_void>, mem=0x7ffff3917c20) at /home/ns-sergeev/.pythons/src/Python-3.6.8/Modules/_ctypes/callbacks.c:149
#31 closure_fcn (cif=<optimized out>, resp=0x7ffff3917c20, args=0x7ffff3917a80, userdata=<optimized out>)
at /home/ns-sergeev/.pythons/src/Python-3.6.8/Modules/_ctypes/callbacks.c:296
#32 0x00007ffff4b42a6b in ffi_closure_unix64_inner (closure=0x7ffff7ff0cc0, rvalue=0x7ffff3917c20, reg_args=0x7ffff3917b70,
argp=0x7ffff3917c40 "\240\021\243") at ../src/x86/ffi64.c:667
#33 0x00007ffff4b42de4 in ffi_closure_unix64 () at ../src/x86/unix64.S:229
...
C-library frames are omitted
Preliminary findings
It seems like arguments converters and callable of _CallPythonObject are not Ok (changed or corrupted by some reason).
frame 42 from normal backtrace. Normal values and callback called.
#42 0x00007ffff4d54d2c in _CallPythonObject (pArgs=<optimized out>, flags=257,
converters=0x7ffff656a908, callable=0x7ffff4f9eea0, setfunc=0x0,
restype=0x7ffff4f631d0 <ffi_type_void>, mem=0x7ffff3917c20)
frame 30 from error backtrace. Zero values and callback abandoned.
#30 0x00007ffff4d54e8e in _CallPythonObject (pArgs=0x7ffff3917a80, flags=4353,
converters=0x0, callable=0x0, setfunc=0x0,
restype=0x7ffff4f631d0 <ffi_type_void>, mem=0x7ffff3917c20)
Can someone help with solving this issue or suggest a way to further dig and debug it?