Bug 27895 - Listener bleibt bei SIGTERM stecken
Listener bleibt bei SIGTERM stecken
Status: NEW
Product: UCS
Classification: Unclassified
Component: Listener (univention-directory-listener)
UCS 4.2
Other Linux
: P5 normal with 2 votes (vote)
: ---
Assigned To: UCS maintainers
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-07-12 14:51 CEST by Philipp Hahn
Modified: 2019-07-09 13:40 CEST (History)
4 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 6: Setup Problem: Issue for the setup process
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 3: A User would likely not purchase the product
User Pain: 0.206
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Ticket number:
Bug group (optional): Troubleshooting
Max CVSS v3 score:


Attachments
GDB traceback of univention-directory-listener (11.48 KB, text/plain)
2015-03-27 10:18 CET, Sönke Schwardt-Krummrich
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Philipp Hahn univentionstaff 2012-07-12 14:51:52 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?
Comment 1 Philipp Hahn univentionstaff 2015-03-08 12:34:43 CET
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
Comment 2 Sönke Schwardt-Krummrich univentionstaff 2015-03-27 10:09:12 CET
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.
Comment 3 Sönke Schwardt-Krummrich univentionstaff 2015-03-27 10:18:13 CET
Created attachment 6786 [details]
GDB traceback of univention-directory-listener
Comment 4 Philipp Hahn univentionstaff 2015-07-14 15:37:46 CEST
# ~/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
Comment 5 Stefan Gohmann univentionstaff 2017-06-16 20:39:51 CEST
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.
Comment 6 Philipp Hahn univentionstaff 2017-08-16 14:16:20 CEST
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
Comment 7 Felix Botner univentionstaff 2019-07-09 13:40:19 CEST
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