Bug 27895 - Listener bleibt bei SIGTERM stecken
Listener bleibt bei SIGTERM stecken
Status: REOPENED
Product: UCS
Classification: Unclassified
Component: Listener (univention-directory-listener)
UCS 5.0
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: 2020-07-04 13:24 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:
Flags outvoted (downgraded) after PO Review:
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
Comment 8 Ingo Steuwer univentionstaff 2020-07-03 20:53:45 CEST
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.
Comment 9 Philipp Hahn univentionstaff 2020-07-04 13:24:38 CEST
This still happens and still is not fixed since 8 years.