Univention Bugzilla – Bug 53071
Listener does not print python tracebacks to listener.log
Last modified: 2021-06-22 16:18:22 CEST
It looks like tracebacks caused by the python listener modules is no longer printed to listener.log. The only hint for an error is: 13.04.21 17:45:16.968 LISTENER ( WARN ) : handler: fetchmailrc (failed)
This seems to be a problem related to systemd stderr/stdout redirection :( If the listener is started directly on a tty, tracebacks are still printed.
When invoked from systemd STDOUT:=STDERR:=/var/log/univention/listener.log, which is a file. Python 3 defaults to buffering then. As the Traceback is less than 8k bytes, it fits into the buffer, which is NOT flushed. When directly invoked from an interactive shell, STDOUT is a tty, which uses NO buffering. Then the Traceback is printed immediately. `raise ValueError("x" * 8192)` gets printed. Setting the environment variable PYTHONUNBUFFERED=1 solves the problem for me. ucr set repository/online/sources=yes apt-get -qq update apt-get install gdb lib6-dbg python3.7-dbg univention-directory-listener-dbgsym apt-get source univention-directory-listener python2.7 cat >.gdbinit <<__GDB__ file /usr/sbin/univention-directory-listener dir /root/python3.7-3.7.3/Python dir /root/univention-directory-listener-14.0.5/src set args -F -d 2 -b dc=phahn,dc=dev -m /usr/lib/univention-directory-listener/system -c /var/lib/univention-directory-listener -ZZ -x -D cn=admin,dc=phahn,dc=dev -y /etc/ldap.secret 1>/tmp/log.1 2>/tmp/log.2 set environment PYTHONUNBUFFERED 1 break PyErr_Print run # break print_exception_recursive break print_exception continue __GDB__ gdb #0 _io_TextIOWrapper_write_impl (text='Traceback (most recent call last):\n', self=0x7ffef3e7a708) at ../Modules/_io/textio.c:1599 #1 _io_TextIOWrapper_write (self=0x7ffef3e7a708, arg=<optimized out>) at ../Modules/_io/clinic/textio.c.h:256 #2 0x00007ffff7aee079 in _PyMethodDef_RawFastCallDict (method=0x7ffff7cf9660 <textiowrapper_methods+64>, self=<_io.TextIOWrapper at remote 0x7ffef3e7a708>, args=0x7fffffff6830, nargs=1, kwargs=<optimized out>) at ../Objects/call.c:497 #3 0x00007ffff7aeea45 in _PyCFunction_FastCallDict (func=<built-in method write of _io.TextIOWrapper object at remote 0x7ffef3e7a708>, args=<optimized out>, nargs=<optimized out>, kwargs=<optimized out>) at ../Objects/call.c:582 #4 0x00007ffff7aef2e5 in _PyObject_FastCallDict (callable=callable@entry=<built-in method write of _io.TextIOWrapper object at remote 0x7ffef3e7a708>, args=args@entry=0x7fffffff6830, nargs=nargs@entry=1, kwargs=kwargs@entry=0x0) at ../Objects/call.c:101 #5 0x00007ffff7aefd60 in object_vacall (callable=<built-in method write of _io.TextIOWrapper object at remote 0x7ffef3e7a708>, vargs=vargs@entry=0x7fffffff6890) at ../Objects/call.c:1198 #6 0x00007ffff7aefe89 in PyObject_CallFunctionObjArgs (callable=<optimized out>) at ../Objects/call.c:1263 #7 0x00007ffff7adcf21 in PyFile_WriteObject (v=v@entry='Traceback (most recent call last):\n', f=f@entry=<_io.TextIOWrapper at remote 0x7ffef3e7a708>, flags=flags@entry=1) at ../Objects/fileobject.c:137 #8 0x00007ffff7adcfeb in PyFile_WriteString (s=<optimized out>, f=<optimized out>, s=<optimized out>, f=<optimized out>) at ../Objects/fileobject.c:161 #9 0x00007ffff79db9a4 in PyTraceBack_Print (v=<optimized out>, f=<optimized out>, v=<optimized out>, f=<optimized out>) at ../Python/traceback.c:609 #10 0x00007ffff79e6100 in print_exception (value=ZeroDivisionError('division by zero',), f=<_io.TextIOWrapper at remote 0x7ffef3e7a708>) at ../Python/pythonrun.c:738 #11 print_exception_recursive (f=<_io.TextIOWrapper at remote 0x7ffef3e7a708>, value=ZeroDivisionError('division by zero',), seen=<optimized out>) at ../Python/pythonrun.c:901 #12 0x00007ffff79e6acc in PyErr_Display (exception=<optimized out>, value=ZeroDivisionError('division by zero',), tb=<optimized out>) at ../Python/pythonrun.c:935 #13 0x00007ffff79e6bdb in sys_excepthook (self=<optimized out>, args=<optimized out>) at ../Python/sysmodule.c:332 #14 0x00007ffff7aee068 in _PyMethodDef_RawFastCallDict (method=0x7ffff7d43f20 <sys_methods+192>, self=<module at remote 0x7ffef3ec0f98>, args=0x7fffffff6b70, nargs=3, kwargs=<optimized out>) at ../Objects/call.c:518 #15 0x00007ffff7aeea45 in _PyCFunction_FastCallDict (func=<built-in method excepthook of module object at remote 0x7ffef3ec0f98>, args=<optimized out>, nargs=<optimized out>, kwargs=<optimized out>) at ../Objects/call.c:582 #16 0x00007ffff79e6cdd in PyErr_PrintEx (set_sys_last_vars=set_sys_last_vars@entry=1) at ../Python/pythonrun.c:679 #17 0x00007ffff79e6f9a in PyErr_Print () at ../Python/pythonrun.c:542 #18 0x000055555555b0d4 in handler_exec (handler=handler@entry=0x555555a2a900, dn=dn@entry=0x555555bad3f0 "cn=o,dc=phahn,dc=dev", new=new@entry=0x7fffffff6cd0, old=old@entry=0x7fffffff6cf0, command=command@entry=97 'a') at handlers.c:405 #19 0x000055555555b326 in handler__update (handler=handler@entry=0x555555a2a900, dn=dn@entry=0x555555bad3f0 "cn=o,dc=phahn,dc=dev", new=new@entry=0x7fffffff6cd0, old=old@entry=0x7fffffff6cf0, command=command@entry=97 'a', changes=changes@entry=0x555555d77d00) at handlers.c:766 #20 0x000055555555c479 in handlers_update (dn=0x555555bad3f0 "cn=o,dc=phahn,dc=dev", new=new@entry=0x7fffffff6cd0, old=old@entry=0x7fffffff6cf0, command=command@entry=97 'a') at handlers.c:795 #21 0x000055555555cc45 in change_update_entry (lp=<optimized out>, id=16021, ldap_entry=<optimized out>, command=<optimized out>) at change.c:261 #22 0x000055555555e45a in change_update_cache (trans=0x7fffffff6ec0) at change.c:614 #23 change_update_dn (trans=trans@entry=0x7fffffff6ec0) at change.c:717 #24 0x000055555555a622 in notifier_listen (lp=lp@entry=0x555555584910, write_transaction_file=write_transaction_file@entry=false, lp_local=lp_local@entry=0x555555584990) at notifier.c:218 #25 0x0000555555559f2c in main (argc=<optimized out>, argv=<optimized out>) at main.c:616
[5.0-0] b5bcc3f6e5 fix[listener]: Make StdIO unbuffered doc/errata/staging/univention-directory-listener.yaml | 13 +++++++++++++ management/univention-directory-listener/debian/changelog | 6 ++++++ management/univention-directory-listener/src/handlers.c | 1 + 3 files changed, 20 insertions(+) Package: univention-directory-listener Version: 14.0.5-3A~5.0.0.202106081249 Branch: ucs_5.0-0 Scope: errata5.0-0 [5.0-0] 22f4fa7293 test[listener]: Make StdIO unbuffered test/ucs-test/debian/changelog | 6 ++++++ test/ucs-test/tests/10_ldap/54listener-stdio | 43 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 49 insertions(+) Package: ucs-test Version: 10.0.5-24A~5.0.0.202106081334 Branch: ucs_5.0-0 Scope: errata5.0-0 [5.0-0] 50419ab581 Bug #53071: univention-directory-listener 14.0.5-3A~5.0.0.202106081249 doc/errata/staging/univention-directory-listener.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
What I tested: Changes -> OK Tracebacks are shown (at once) again -> OK jenkins -> OK (Though this made some other bugs visible) yaml -> OK (small change) [5.0-0 f5dbd6f25d] Bug #53071: yaml -> Verified
<https://errata.software-univention.de/#/?erratum=5.0x13>