Univention Bugzilla – Bug 27895
Listener bleibt bei SIGTERM stecken
Last modified: 2020-07-04 13:24:38 CEST
Beim Shutdown des Listener blieb dieser hängen. Könnte ein Folge durch die Änderungen im Bezug auf Bug #25868 sein. Fehleranalyse nach <https://hutten.knut.univention.de/mediawiki/index.php/Philipp_memo/debug#Python> $ ucr set repository/online/unmaitained=yes repository/online/sources=yes $ univention-install gdb python2.6-dbg libc6-dbg univention-directory-listener-dbg build-essentials $ apt-get source univention-directory-listener $ cd univention-directory-listener-*/src $ gdb -p `pidof univention-directory-listener` (gdb) bt #0 __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97 #1 0x00007f242a2697a2 in _L_lock_11403 () from /lib/libc.so.6 #2 0x00007f242a268ae4 in *__GI___libc_realloc (oldmem=0x7f242a54ee40, bytes=60) at malloc.c:3814 #3 0x00007f242a2581b3 in _IO_vasprintf (result_ptr=0x7fff3e81d730, format=<value optimized out>, args=0x7fff3e81d640) at vasprintf.c:86 #4 0x00007f242a23db08 in ___asprintf (string_ptr=0x7f242a54ee40, format=0x80 <Address 0x80 out of bounds>) at asprintf.c:37 #5 0x000000000040632a in handler_free (handler=0x739a50) at handlers.c:539 #6 0x0000000000406645 in handlers_free_all () at handlers.c:578 #7 0x000000000040e5e4 in exit_handler (sig=15) at signals.c:119 #8 <signal handler called> #9 0x00007f242a291b06 in __libc_fork () at ../nptl/sysdeps/unix/sysv/linux/x86_64/../fork.c:130 #10 0x00007f242a97bd3b in posix_fork (self=<value optimized out>, noargs=<value optimized out>) at ../Modules/posixmodule.c:3694 #11 0x00007f242a90dcd5 in call_function (f= Frame 0xe94410, for file /usr/lib/python2.6/os.py, line 535, in _spawnvef (mode=1, file='/usr/sbin/rndc', args=['rndc', '-p', '953', 'reload', 'amd64.de'], env=None, func=<built-in function execv>), throwflag=<value optimized out>) at ../Python/ceval.c:3734 #12 PyEval_EvalFrameEx (f= Frame 0xe94410, for file /usr/lib/python2.6/os.py, line 535, in _spawnvef (mode=1, file='/usr/sbin/rndc', args=['rndc', '-p', '953', 'reload', 'amd64.de'], env=None, func=<built-in function execv>), throwflag=<value optimized out>) at ../Python/ceval.c:2412 #13 0x00007f242a90e878 in fast_function (f= Frame 0xd3d980, for file /usr/lib/python2.6/os.py, line 567, in spawnv (mode=1, file='/usr/sbin/rndc', args=['rndc', '-p', '953', 'reload', 'amd64.de']), throwflag=<value optimized out>) at ../Python/ceval.c:3836 #14 call_function (f=Frame 0xd3d980, for file /usr/lib/python2.6/os.py, line 567, in spawnv (mode=1, file='/usr/sbin/rndc', args=['rndc', '-p', '953', 'reload', 'amd64.de']), throwflag=<value optimized out>) at ../Python/ceval.c:3771 #15 PyEval_EvalFrameEx (f= Frame 0xd3d980, for file /usr/lib/python2.6/os.py, line 567, in spawnv (mode=1, file='/usr/sbin/rndc', args=['rndc', '-p', '953', 'reload', 'amd64.de']), throwflag=<value optimized out>) at ../Python/ceval.c:2412 #16 0x00007f242a90e878 in fast_function (f= Frame 0x6a08d0, for file /usr/lib/univention-directory-listener/system/bind.py, line 185, in _reload (zones=['amd64.de'], restart=False, pids={29856: ['rndc', '-p', '55555', 'reload', 'amd64.de']}, zone='amd64.de', cmd=['rndc', '-p', '953', 'reload', 'amd64.de'], pid=29856), throwflag=<value optimized out>) at ../Python/ceval.c:3836 #17 call_function (f= Frame 0x6a08d0, for file /usr/lib/univention-directory-listener/system/bind.py, line 185, in _reload (zones=['amd64.de'], restart=False, pids={29856: ['rndc', '-p', '55555', 'reload', 'amd64.de']}, zone='amd64.de', cmd=['rndc', '-p', '953', 'reload', 'amd64.de'], pid=29856), throwflag=<value optimized out>) at ../Python/ceval.c:3771 #18 PyEval_EvalFrameEx (f= Frame 0x6a08d0, for file /usr/lib/univention-directory-listener/system/bind.py, line 185, in _reload (zones=['amd64.de'], restart=False, pids={29856: ['rndc', '-p', '55555', 'reload', 'amd64.de']}, zone='amd64.de', cmd=['rndc', '-p', '953', 'reload', 'amd64.de'], pid=29856), throwflag=<value optimized out>) at ../Python/ceval.c:2412 #19 0x00007f242a90fcc0 in PyEval_EvalCodeEx (co=0xc30648, globals=<value optimized out>, locals=<value optimized out>, args=0x2, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0, defs=0x8728e8, defcount=1, closure=0x0) at ../Python/ceval.c:3000 #20 0x00007f242a90dffb in fast_function (f= Frame 0xe90830, for file /usr/lib/univention-directory-listener/system/bind.py, line 288, in postrun (named_conf=<file at remote 0xbf04b0>, proxy_conf=<file at remote 0xbf05d0>, f='amd64.de', restart=False, zones=['amd64.de'], filename='amd64.de.zone', zone='amd64.de'), throwflag=<value optimized out>) at ../Python/ceval.c:3846 #21 call_function (f= Frame 0xe90830, for file /usr/lib/univention-directory-listener/system/bind.py, line 288, in postrun (named_conf=<file at remote 0xbf04b0>, proxy_conf=<file at remote 0xbf05d0>, f='amd64.de', restart=False, zones=['amd64.de'], filename='amd64.de.zone', zone='amd64.de'), throwflag=<value optimized out>) at ../Python/ceval.c:3771 #22 PyEval_EvalFrameEx (f= Frame 0xe90830, for file /usr/lib/univention-directory-listener/system/bind.py, line 288, in postrun (named_conf=<file at remote 0xbf04b0>, proxy_conf=<file at remote 0xbf05d0>, f='amd64.de', restart=False, zones=['amd64.de'], filename='amd64.de.zone', zone='amd64.de'), throwflag=<value optimized out>) at ../Python/ceval.c:2412 #23 0x00007f242a90fcc0 in PyEval_EvalCodeEx (co=0xc307b0, globals=<value optimized out>, locals=<value optimized out>, args=0x7f242b4a3068, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0, defs=0x0, defcount=0, closure=0x0) at ../Python/ceval.c:3000 #24 0x00007f242a895980 in function_call (func=<function at remote 0xc30d70>, arg=(), kw=0x0) at ../Objects/funcobject.c:524 #25 0x00007f242a868103 in PyObject_Call (func=<function at remote 0xc30d70>, arg=0x0, kw=0x0) at ../Objects/abstract.c:2492 #26 0x00007f242a908103 in PyEval_CallObjectWithKeywords (func=<function at remote 0xc30d70>, arg=(), kw=0x0) at ../Python/ceval.c:3619 #27 0x0000000000405afc in handler_postrun (handler=0x9b0160) at handlers.c:310 #28 0x0000000000405b8d in handlers_postrun_all () at handlers.c:328 #29 0x00000000004047c9 in notifier_listen (lp=0x669110, kp=0x0, write_transaction_file=1, lp_local=0x669190) at notifier.c:150 #30 0x00000000004044ae in main (argc=17, argv=0x7fff3e81e728) at main.c:586 (gdb) print *handler $1 = {module = <module at remote 0x7f242b49e7c0>, name = 0xa814f0 "replication", description = 0xa5da20 "LDAP slave replication", filters = 0xa5da60, attributes = 0x8ae1d0, modrdn = 0x0, handler = <function at remote 0x7fcc80>, initialize = <function at remote 0x7fcd70>, clean = <function at remote 0x7fccf8>, postrun = 0x0, prerun = 0x0, setdata = <function at remote 0x7fcf50>, next = 0x9a4410, state = 3, prepared = -1} (gdb) up 5 #5 0x000000000040632a in handler_free (handler=0x739a50) at handlers.c:539 539 asprintf(&state_filename, "%s/handlers/%s", cache_dir, handler->name); $ ~phahn/src/proc_sig.py 28928 Pending Signals for Thread: 0000000000000000[] Pending Signals for Process: 0000000000004000[TERM] Blocked Signals: 0000000000005027[HUP INT QUIT ABRT PIPE TERM] Ignored Signals: 0000000001001000[PIPE XFSZ] Caught Signals: 0000000180004a25[HUP QUIT ABRT USR1 USR2 TERM 32-33] Mann sieht aus /proc/$pid/status, daß der Prozeß per SIGTERM beendet werden sollte (Pending Signals for Process: TERM). Scheinbar wurde dieses Signal nicht sofort abgearbeitet, sondern erst beim fork() für rndc. Beim schließen ist dann der "LDAP slave replication" Handler hängengeblieben. Bezüglich SIGNAL-Handler muß unbeding "man 7 signal" → "Async-signal-safe functions" beachtet werden; ist das ggf. ist hier das Problem?
Again: Slave: $ ssh -i ~/.ss/tech.pem -l root 10.210.94.112 tail /var/log/univention/join.log > Could not chdir to home directory /dev/null: Not a directory > bash: /dev/null/.bashrc: Not a directory > scp: /etc/univention/ssl/slave202.autotest201.local: No such file or directory Master: $ ssh -i ~/.ss/tech.pem -l root 10.210.39.205 > # ls -gG /etc/univention/ssl > insgesamt 20 > lrwxrwxrwx 1 47 Mär 6 06:04 master201 -> /etc/univention/ssl/master201.autotest201.local > drwxr-x--- 2 4096 Mär 6 06:04 master201.autotest201.local > -rw-rw---- 1 3405 Mär 6 06:04 openssl.cnf > -rw-rw---- 1 20 Mär 6 06:04 password > drwxrwxr-x 6 4096 Mär 6 06:04 ucsCA > lrwxrwxrwx 1 57 Mär 6 06:04 unassigned-hostname -> /etc/univention/ssl/unassigned-hostname.autotest201.local > # udm computers/domaincontroller_slave list > > DN: cn=slave202,cn=dc,cn=server,cn=computers,ou=School1,dc=autotest201,dc=local > ARG: None > domain: autotest201.local > ip: 10.210.94.112 > network: None > reinstalloption: None > unixhome: /dev/null > instprofile: None > shell: /bin/bash > description: None > objectFlag: None > mac: 02:06:53:ea:7a:69 > groups: cn=DC Slave Hosts,cn=groups,dc=autotest201,dc=local > groups: cn=DC-Edukativnetz,cn=ucsschool,cn=groups,dc=autotest201,dc=local > groups: cn=OUschool1-DC-Edukativnetz,cn=ucsschool,cn=groups,dc=autotest201,dc=local > primaryGroup: cn=DC Slave Hosts,cn=groups,dc=autotest201,dc=local > password: {crypt}$6$P.4J2X.iBbHYI/Ba$Puej8wj5BgWnTiH1KPRSloeqe24MzGrV4ov428cD099r6kRjTOOHrL7awdCjgTdRG.J.uEXWXIay31oHg4AwP0 > reinstall: None > serverRole: slave > name: slave202 > fqdn: slave202.autotest201.local > sambaRID: 5018 > > # /usr/share/univention-directory-listener/get_notifier_id.py > 1359 > # cat /var/lib/univention-directory-listener/notifier_id;echo > 943 > # ls -l /var/log/univention/listener.log*-rw-r----- 1 root adm 0 Mär 8 06:25 /var/log/univention/listener.log > -rw-r----- 1 root adm 1992 Mär 6 06:17 /var/log/univention/listener.log.1.gz > # lsof -a -p $(</etc/runit/univention-directory-listener/supervise/pid) -d 0-1023 > COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME > univentio 11186 listener 0u CHR 1,3 0t0 5592 /dev/null > univentio 11186 listener 1w REG 202,1 21243 10387 /var/log/univention/listener.log.1 (deleted) > univentio 11186 listener 2w REG 202,1 21243 10387 /var/log/univention/listener.log.1 (deleted) > univentio 11186 listener 3u sock 0,7 0t0 79250 can't identify protocol > cp /proc/11186/fd/2 /var/log/univention/listener.log.1 > # zcat /var/log/univention/listener.log.1.gz | wc -c > 21243 > # wc -c /var/log/univention/listener.log.1 > 21243 /var/log/univention/listener.log.1 Das ist exakt die momentane Dateiposition vom Listener in der Datei, also hat es da auch nicht weiteres geschrieben - oder anders ausgedrückt - da fehlt nichts. > # less /var/log/univention/listener.log.1 > 06.03.15 06:12:43.913 DEBUG_INIT > 06.03.15 06:12:43.930 LISTENER ( ERROR ) : failed to connect to any notifier > 06.03.15 06:12:43.930 LISTENER ( WARN ) : can not connect any server, retrying i > 06.03.15 06:12:49.999 LISTENER ( WARN ) : received signal 15 > 06.03.15 06:14:05.952 DEBUG_INIT ... > 06.03.15 06:17:32.816 LISTENER ( ERROR ) : change_update_dn: Can't contact LDAP s ... > 06.03.15 06:17:36.867 LISTENER ( WARN ) : received signal 15 > 06.03.15 06:17:43.112 DEBUG_INIT > 06.03.15 06:17:43.125 LISTENER ( WARN ) : received signal 15 > # strace -f -p 11186 > Process 11186 attached - interrupt to quit > futex(0x7f838fadae40, FUTEX_WAIT_PRIVATE, 2, NULL > # ucr set repository/online/unmaintained=yes > # univention-install python2.7-dbg libc6-dbg gdb libssl1.0.0-dbg univention-directory-listener-dbg > # gdb -p 11186 --batch -ex bt > [Thread debugging using libthread_db enabled] > Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". > __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97 > 97 ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: Datei oder Verzeichnis nicht gefunden. > #0 __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97 > #1 0x00007f838f7d0458 in _L_lock_9676 () from /lib/x86_64-linux-gnu/libc.so.6 > #2 0x00007f838f7ce7b1 in *__GI___libc_free (mem=0x7f838fadae40) at malloc.c:3736 > #3 0x000000000040fe4c in exit_handler (sig=15) at signals.c:124 > #4 <signal handler called> > #5 _int_malloc (av=0x7f838fadae40, bytes=8193) at malloc.c:4738 > #6 0x00007f838f7cf4b6 in _int_realloc (av=0x7f838fadae40, oldp=0x1c284b0, oldsize=4112, nb=8208) at malloc.c:5319 > #7 0x00007f838f7cfa00 in *__GI___libc_realloc (oldmem=0x1c284c0, bytes=8192) at malloc.c:3821 > #8 0x00007f838e9376d1 in CRYPTO_realloc (str=0x1c284c0, num=num@entry=8192, file=file@entry=0x7f838ea47749 "lhash.c", line=line@entry=347) at mem.c:346 > #9 0x00007f838e9bf8f1 in expand (lh=0x1c23830) at lhash.c:346 > #10 lh_insert (lh=lh@entry=0x1c23830, data=data@entry=0x7f838eca4810) at lhash.c:187 > #11 0x00007f838e9c1d4a in int_err_set_item (d=0x7f838eca4810) at err.c:407 > #12 0x00007f838e9c177b in err_load_strings (lib=lib@entry=0, str=0x7f838eca4810, str@entry=0x7f838eca47e0) at err.c:676 > #13 0x00007f838e9c2120 in ERR_load_strings (lib=lib@entry=0, str=str@entry=0x7f838eca47e0) at err.c:684 > #14 0x00007f838e93959e in ERR_load_CRYPTO_strings () at cpt_err.c:101 > #15 0x00007f838e9c2f7a in ERR_load_crypto_strings () at err_all.c:132 > #16 0x00007f838ecef8b9 in SSL_load_error_strings () at ssl_err2.c:66 > #17 0x00007f83902da8e9 in ?? () from /usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2 > #18 0x00007f83902d88c1 in ldap_int_tls_start () from /usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2 > #19 0x00007f83902d8cc2 in ldap_start_tls_s () from /usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2 > #20 0x00007f83904f4ddc in univention_ldap_open () from /usr/lib/x86_64-linux-gnu/libuniventionpolicy.so.0 > #21 0x0000000000403d6d in do_connection (lp=0x1c1a150) at main.c:315 > #22 0x00000000004044a5 in main (argc=16, argv=0x7fff019a14f8) at main.c:528 > # python proc_sig.py 11186 > Executable name: univention-dire > Process state: S (sleeping) > Thread Group Identifier: 11186 > Ngid 0 > Process Identifier: 11186 > Parent Process Identifier: 2305 > Process Identifier of tracing process: 0 > User Identifier: real=0[root] effective=100[listener] saved=0[root] fs=100[listener] > Group Identifier: real=0[root] effective=65534[nogroup] saved=0[root] fs=65534[nogroup] > Max File Descriptors: 64 > Supplementary groups: > Peak Virtual Memory size: 46712 kB > Current Virtual Memory size: 46708 kB > Locked Virtual Memory size: 0 kB > VmPin 0 kB > Peak Resident Set Virtual Memory size: 4312 kB (high water mark) > Current Resident Set Virtual Memory size: 4312 kB > Virtual Memory size for data segments: 344 kB > Virtual Memory size for stack segments: 136 kB > Virtual Memory size for text segments: 88 kB > Virtual Memory size for shared code: 8556 kB > Virtual Memory Page Table Entries size: 104 kB > VmSwap 0 kB > Number of Threads: 1 > Number of pending signals / user: 2/14893 > Pending Signals for Thread: 0000000000000000[] > Pending Signals for Process: 0000000000004000[TERM] > Blocked Signals: 0000000000005027[HUP INT QUIT ABRT PIPE TERM] > Ignored Signals: 0000000000000000[] > Caught Signals: 0000000180005a27[HUP INT QUIT ABRT USR1 USR2 PIPE TERM 32-33] > Inherited Capabilities: 0000000000000000 > Permitted Capabilities: 0000003fffffffff > Effective Capabilities: 0000000000000000 > Bounding set of Capabilities: 0000003fffffffff > Seccomp 0 > Allowed CPUs: 1 > Allowed CPUs: 0 > Allowed Memory Nodes: ['00000000', '00000001'] > Allowed Memory Nodes: 0 > Voluntary Context Switches: 27 > Involuntary Context Switches: 20
Happened again on a jenkins instance and blocked the jenkins test (univention-join is still waiting indefinitely for the listener to shut down). See attached gdb backtrace of univention-directory-listener. Looks like the exit handler called handlers_postrun_all() upon incoming TERM signal *again*, while it was still running.
Created attachment 6786 [details] GDB traceback of univention-directory-listener
# ~/proc_sig.py 2991 Executable name: univention-dire Process state: S (sleeping) Thread Group Identifier: 2991 Process Identifier: 2991 Parent Process Identifier: 1015 Process Identifier of tracing process: 0 User Identifier: real=0[root] effective=0[root] saved=0[root] fs=0[root] Group Identifier: real=0[root] effective=65534[nogroup] saved=0[root] fs=65534[nogroup] Max File Descriptors: 64 Supplementary groups: Peak Virtual Memory size: 463452 kB Current Virtual Memory size: 461616 kB Locked Virtual Memory size: 0 kB VmPin 0 kB Peak Resident Set Virtual Memory size: 29988 kB (high water mark) Current Resident Set Virtual Memory size: 29668 kB Virtual Memory size for data segments: 16956 kB Virtual Memory size for stack segments: 152 kB Virtual Memory size for text segments: 88 kB Virtual Memory size for shared code: 29444 kB Virtual Memory Page Table Entries size: 904 kB VmSwap 0 kB Number of Threads: 1 Number of pending signals / user: 5/29673 Pending Signals for Thread: 0000000000000000[] Pending Signals for Process: 0000000000004000[TERM] Blocked Signals: 0000000000005027[HUP INT QUIT ABRT PIPE TERM] Ignored Signals: 0000000001001000[PIPE XFSZ] Caught Signals: 0000000180004a27[HUP INT QUIT ABRT USR1 USR2 TERM 32-33] Inherited Capabilities: 0000000000000000 Permitted Capabilities: 0000001fffffffff Effective Capabilities: 0000001fffffffff Bounding set of Capabilities: 0000001fffffffff Seccomp 0 Allowed CPUs: 1 Allowed CPUs: 0 Allowed Memory Nodes: ['00000000', '00000001'] Allowed Memory Nodes: 0 Voluntary Context Switches: 3875 Involuntary Context Switches: 2582 # gdb --quiet -p 2991 --batch -ex bt #0 __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97 #1 0x00007f46dac85f02 in _L_lock_11500 () from /lib/libc.so.6 #2 0x00007f46dac85244 in *__GI___libc_realloc (oldmem=0x7f46daf6ee40, bytes=64) at malloc.c:3814 #3 0x00007f46db2bcb61 in PyList_Append () from /usr/lib/libpython2.6.so.1.0 #4 0x00007f46db2ad271 in ?? () from /usr/lib/libpython2.6.so.1.0 #5 0x00007f46db32e1c0 in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #6 0x00007f46db32eab8 in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #7 0x00007f46db32eab8 in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #8 0x00007f46db32ff00 in PyEval_EvalCodeEx () from /usr/lib/libpython2.6.so.1.0 #9 0x00007f46db2b5b80 in ?? () from /usr/lib/libpython2.6.so.1.0 #10 0x00007f46db2882d3 in PyObject_Call () from /usr/lib/libpython2.6.so.1.0 #11 0x00007f46db328343 in PyEval_CallObjectWithKeywords () from /usr/lib/libpython2.6.so.1.0 #12 0x0000000000405edc in handler_postrun (handler=0x8d80b0) at handlers.c:348 #13 0x0000000000405f6d in handlers_postrun_all () at handlers.c:368 #14 0x0000000000410062 in exit_handler (sig=15) at signals.c:127 #15 <signal handler called> #16 0x00007f46dacafd24 in __libc_fork () at ../nptl/sysdeps/unix/sysv/linux/x86_64/../fork.c:130 #17 0x00007f46db39c51b in ?? () from /usr/lib/libpython2.6.so.1.0 #18 0x00007f46db32df15 in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #19 0x00007f46db32eab8 in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #20 0x00007f46db32eab8 in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #21 0x00007f46db32ff00 in PyEval_EvalCodeEx () from /usr/lib/libpython2.6.so.1.0 #22 0x00007f46db32e23b in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0 #23 0x00007f46db32ff00 in PyEval_EvalCodeEx () from /usr/lib/libpython2.6.so.1.0 #24 0x00007f46db2b5b80 in ?? () from /usr/lib/libpython2.6.so.1.0 #25 0x00007f46db2882d3 in PyObject_Call () from /usr/lib/libpython2.6.so.1.0 #26 0x00007f46db328343 in PyEval_CallObjectWithKeywords () from /usr/lib/libpython2.6.so.1.0 #27 0x0000000000405edc in handler_postrun (handler=0x8d80b0) at handlers.c:348 #28 0x0000000000405f6d in handlers_postrun_all () at handlers.c:368 #29 0x0000000000404a50 in notifier_listen (lp=0x74c150, kp=0x0, write_transaction_file=0, lp_local=0x74c1d0) at notifier.c:140 #30 0x0000000000404763 in main (argc=16, argv=0x7ffc60ad1418) at main.c:612
This issue has been filed against UCS 3. UCS 3 is out of the normal maintenance and many UCS components have vastly changed in UCS 4. If this issue is still valid, please change the version to a newer UCS version otherwise this issue will be automatically closed in the next weeks.
Again failed like Bug #30005: <http://jenkins.knut.univention.de:8080/job/UCS-4.2/job/UCS-4.2-1/job/AutotestJoin/SambaVersion=s3,Systemrolle=slave/66/console> slave:/var/log/univention/join.log >ldap_dn="cn=slave094,cn=dc,cn=computers,dc=autotest094,dc=local" ... >Could not chdir to home directory /dev/null: Not a directory >scp: /etc/univention/ssl/slave094: No such file or directory >Could not chdir to home directory /dev/null: Not a directory >scp: /etc/univention/ssl/slave094.autotest094.local: No such file or directory Ad infinite master:/home/Administrator/.univention-server-join.log >univention-server-join called >Parameter: -bindpwfile /tmp/tmp.nZjm2rDH6c -binddn uid=Administrator,cn=users,dc=autotest094,dc=local -ip 10.210.14.44 -netmask 255.255.0.0 -mac 02:af:97:51:86:38 -role domaincontroller_slave -hostname slave094 -domainname autotest094.local > Calculated subnet = 10.210 > forwardZone zoneName=autotest094.local,cn=dns,dc=autotest094,dc=local > reverseZone zoneName=210.10.in-addr.arpa,cn=dns,dc=autotest094,dc=local > dhcpEntry >Join DC Slave > Create new DC Slave >16.08.17 00:53:22.256 DEBUG_INIT master:/var/log/univention/listener.log >16.08.17 00:09:38.104 LISTENER ( ERROR ) : connection to notifier was closed >16.08.17 00:09:38.104 LISTENER ( ERROR ) : failed to recv result >16.08.17 00:09:38.104 LISTENER ( ERROR ) : listener: 1 Setting ucs/server/saml-idp-server/master094.autotest094.local File: /etc/stunnel/univention_saml.conf File: /etc/simplesamlphp/config.php Create umc/saml/trusted/sp/master094.autotest094.local File: /etc/ldap/sasl2/slapd.conf >16.08.17 00:09:44.056 DEBUG_INIT >16.08.17 00:09:44.084 LISTENER ( WARN ) : received signal 15 # univention-ldapsearch -LLLb cn=slave094,cn=dc,cn=computers,dc=autotest094,dc=local createTimestamp modifyTimestamp dn: cn=slave094,cn=dc,cn=computers,dc=autotest094,dc=local createTimestamp: 20170815225322Z modifyTimestamp: 20170815225322Z # lsof -p 27043 -a -d 0-255 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME univentio 27043 listener 0u CHR 1,3 0t0 6530 /dev/null univentio 27043 listener 1w REG 202,1 46472 812458 /var/log/univention/listener.log univentio 27043 listener 2w REG 202,1 46472 812458 /var/log/univention/listener.log univentio 27043 listener 4u sock 0,8 0t0 134710 can't identify protocol Cost: - 2 EC2 running since 14h - 1 Developer (/me) debugging this again for ½h
seen again in ec2 tests $ tail -1 /var/log/univention/listener.log 09.07.19 01:04:21.278 LISTENER ( WARN ) : received signal 15 $ date Di 9. Jul 13:35:14 CEST 2019 $ ps aux| grep listener listener 16307 0.0 0.8 2684108 61308 ? S 01:03 0:02 /usr/sbin/univention-directory-listener -F -d 2 -b dc=autotest092,dc=local -m /usr/lib/univention-directory-listener/system -c /var/lib/univention-directory-listener -o -ZZ -x -D cn=admin,dc=autotest092,dc=local -y /etc/ldap.secret $ strace -p 16307 -f strace: Process 16307 attached futex(0x7f0892682b00, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 16307 detached <detached ...> $ gdb -p 16307 --batch -ex "bt" [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95 95 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: Datei oder Verzeichnis nicht gefunden. #0 __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95 #1 0x00007f0892360bd0 in _int_free (av=0x7f0892682b00 <main_arena>, p=0x56523b4d54b0, have_lock=0) at malloc.c:4000 #2 0x00007f08926977c7 in mdb_env_close () from /usr/lib/x86_64-linux-gnu/liblmdb.so.0 #3 0x0000565239f2fb24 in cache_close () at cache.c:833 #4 0x0000565239f2cd6f in exit_handler (sig=15) at signals.c:115 #5 <signal handler called> #6 0x00007f08923624f4 in _int_malloc (av=av@entry=0x7f0892682b00 <main_arena>, bytes=bytes@entry=49) at malloc.c:3765 #7 0x00007f0892363021 in _int_realloc (av=av@entry=0x7f0892682b00 <main_arena>, oldp=oldp@entry=0x56523bd76380, oldsize=oldsize@entry=48, nb=nb@entry=64) at malloc.c:4342 #8 0x00007f0892364719 in __GI___libc_realloc (oldmem=0x56523bd76390, bytes=48) at malloc.c:3083 #9 0x0000565239f325e9 in parse_entry (data=0x7f080a1cf4ec, size=1459, entry=entry@entry=0x7fff11504820) at cache_lowlevel.c:249 #10 0x0000565239f2f530 in cache_get_entry (dn=dn@entry=0x56523bd6b000 "cn=domain users,cn=groups,dc=autotest092,dc=local", entry=entry@entry=0x7fff11504820) at cache.c:696 #11 0x0000565239f2f682 in cache_get_entry_lower_upper (dn=0x56523bce6140 "cn=Domain Users,cn=groups,dc=autotest092,dc=local", entry=entry@entry=0x7fff11504820) at cache.c:716 #12 0x0000565239f2af69 in change_update_dn (trans=trans@entry=0x7fff115047f0) at change.c:659 #13 0x0000565239f279f0 in notifier_listen (lp=<optimized out>, write_transaction_file=true, lp_local=<optimized out>) at notifier.c:218 #14 0x0000565239f2728f in main (argc=<optimized out>, argv=<optimized out>) at main.c:610 $ gdb -p 16307 --batch -ex "bt full" [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95 95 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: Datei oder Verzeichnis nicht gefunden. #0 __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95 No locals. #1 0x00007f0892360bd0 in _int_free (av=0x7f0892682b00 <main_arena>, p=0x56523b4d54b0, have_lock=0) at malloc.c:4000 size = 4112 fb = <optimized out> nextchunk = <optimized out> nextsize = <optimized out> nextinuse = <optimized out> prevsize = <optimized out> bck = <optimized out> fwd = <optimized out> errstr = 0x0 locked = 0 __func__ = "_int_free" #2 0x00007f08926977c7 in mdb_env_close () from /usr/lib/x86_64-linux-gnu/liblmdb.so.0 No symbol table info available. #3 0x0000565239f2fb24 in cache_close () at cache.c:833 No locals. #4 0x0000565239f2cd6f in exit_handler (sig=15) at signals.c:115 c = <optimized out> exit_handler_running = true #5 <signal handler called> No locals. #6 0x00007f08923624f4 in _int_malloc (av=av@entry=0x7f0892682b00 <main_arena>, bytes=bytes@entry=49) at malloc.c:3765 p = 0x56523bd6d2d0 iters = <optimized out> nb = 64 idx = 5 bin = <optimized out> victim = 0x56523bd6d2d0 size = <optimized out> victim_index = <optimized out> remainder = <optimized out> remainder_size = 256 block = <optimized out> bit = <optimized out> map = <optimized out> fwd = <optimized out> bck = <optimized out> errstr = 0x0 __func__ = "_int_malloc" #7 0x00007f0892363021 in _int_realloc (av=av@entry=0x7f0892682b00 <main_arena>, oldp=oldp@entry=0x56523bd76380, oldsize=oldsize@entry=48, nb=nb@entry=64) at malloc.c:4342 newp = <optimized out> newsize = <optimized out> newmem = <optimized out> next = 0x56523bd763b0 remainder = <optimized out> remainder_size = <optimized out> bck = <optimized out> fwd = <optimized out> copysize = <optimized out> ncopies = <optimized out> s = <optimized out> d = <optimized out> errstr = 0x0 __func__ = "_int_realloc" nextsize = <optimized out> #8 0x00007f0892364719 in __GI___libc_realloc (oldmem=0x56523bd76390, bytes=48) at malloc.c:3083 ar_ptr = 0x7f0892682b00 <main_arena> nb = 64 newp = <optimized out> hook = <optimized out> oldp = 0x56523bd76380 oldsize = 48 __func__ = "__libc_realloc" #9 0x0000565239f325e9 in parse_entry (data=0x7f080a1cf4ec, size=1459, entry=entry@entry=0x7fff11504820) at cache_lowlevel.c:249 type = <optimized out> key_data = 0x7f080a1cfa73 data_data = <optimized out> key_size = 4 data_size = 0 pos = 1419 #10 0x0000565239f2f530 in cache_get_entry (dn=dn@entry=0x56523bd6b000 "cn=domain users,cn=groups,dc=autotest092,dc=local", entry=entry@entry=0x7fff11504820) at cache.c:696 rv = 0 dnid = 258 read_txn = 0x56523bd6a760 id2dn_read_cursor_p = 0x56523bd92a90 key = {mv_size = 8, mv_data = 0x7fff115045d8} data = {mv_size = 1459, mv_data = 0x7f080a1cf4ec} __func__ = "cache_get_entry" __PRETTY_FUNCTION__ = "cache_get_entry" #11 0x0000565239f2f682 in cache_get_entry_lower_upper (dn=0x56523bce6140 "cn=Domain Users,cn=groups,dc=autotest092,dc=local", entry=entry@entry=0x7fff11504820) at cache.c:716 lower_dn = 0x56523bd6b000 "cn=domain users,cn=groups,dc=autotest092,dc=local" mixedcase = true rv = <optimized out> #12 0x0000565239f2af69 in change_update_dn (trans=trans@entry=0x7fff115047f0) at change.c:659 res = 0x56523bd9f5c0 base = <optimized out> scope = <optimized out> filter = "\000\000\000\000\000\000\000\000\276\v\000\005\000\000\000\000reqSession=3007,cn=translog\000\377\177\000\000\260HP\021\377\177\000\000\276\v\000\000\000\000\000" attrs = {0x565239f346ea "*", 0x565239f3407f "+", 0x0} timeout = {tv_sec = 300, tv_usec = 0} rv = <optimized out> uuid = 0x0 delete = <optimized out> #13 0x0000565239f279f0 in notifier_listen (lp=<optimized out>, write_transaction_file=true, lp_local=<optimized out>) at notifier.c:218 msgid = <optimized out> timeout = <optimized out> rv = <optimized out> id = 3007 trans = {lp = 0x56523b4916c0, lp_local = 0x56523b491740, ldap = 0x0, cur = {notify = {id = 3007, dn = 0x56523bce6140 "cn=Domain Users,cn=groups,dc=autotest092,dc=local", command = 109 'm'}, cache = {attributes = 0x56523bd6cec0, attribute_count = 20, modules = 0x56523bd76390, module_count = 4}, ldap_dn = 0x0, uuid = 0x0}, prev = {notify = {id = 0, dn = 0x0, command = 0 '\000'}, cache = {attributes = 0x0, attribute_count = 0, modules = 0x0, module_count = 0}, ldap_dn = 0x0, uuid = 0x0}} #14 0x0000565239f2728f in main (argc=<optimized out>, argv=<optimized out>) at main.c:610 lp = 0x56523b4916c0 lp_local = 0x56523b491740 server_role = <optimized out> debugging = 2 from_scratch = false foreground = <optimized out> initialize_only = false write_transaction_file = true rv = 0 id = 2756 stbuf = {st_dev = 0, st_ino = 0, st_nlink = 0, st_mode = 0, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 0, st_blksize = 0, st_blocks = 0, st_atim = {tv_sec = 0, tv_nsec = 0}, st_mtim = {tv_sec = 0, tv_nsec = 0}, st_ctim = {tv_sec = 0, tv_nsec = 0}, __glibc_reserved = {0, 0, 0}} cache_mdb_dir = "/var/lib/univention-directory-listener/cache", '\000' <repeats 4051 times> $ lsof -p 16307 -a -d 0-255 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME univentio 16307 listener 0u CHR 1,3 0t0 1040 /dev/null univentio 16307 listener 1w REG 202,1 396064 1053761 /var/log/univention/listener.log univentio 16307 listener 2w REG 202,1 396064 1053761 /var/log/univention/listener.log univentio 16307 listener 3uW REG 202,1 0 1054199 /var/lib/univention-directory-listener/cache.lock univentio 16307 listener 4u sock 0,8 0t0 430370 protocol: TCP univentio 16307 listener 5u sock 0,8 0t0 429982 protocol: TCP univentio 16307 listener 6ur REG 202,1 8192 1054189 /var/lib/univention-directory-listener/cache/lock.mdb univentio 16307 listener 7u REG 202,1 2166784 1054190 /var/lib/univention-directory-listener/cache/data.mdb univentio 16307 listener 8u REG 202,1 2166784 1054190 /var/lib/univention-directory-listener/cache/data.mdb univentio 16307 listener 9u sock 0,8 0t0 430050 protocol: TCP univentio 16307 listener 10w REG 202,1 0 1054205 /var/log/univention/listener_modules/portal_groups.log univentio 16307 listener 11w REG 202,1 460 1054206 /var/log/univention/listener_modules/app_attributes.log univentio 16307 listener 12u sock 0,8 0t0 430056 protocol: TCPv6 univentio 16307 listener 13u sock 0,8 0t0 430443 protocol: TCP univentio 16307 listener 14r CHR 1,9 0t0 1045 /dev/urandom
This issue has been filed against UCS 4.2. UCS 4.2 is out of maintenance and many UCS components have changed in later releases. Thus, this issue is now being closed. If this issue still occurs in newer UCS versions, please use "Clone this bug" or reopen it and update the UCS version. In this case please provide detailed information on how this issue is affecting you.
This still happens and still is not fixed since 8 years.