Univention Bugzilla – Bug 49780
slapd: Bus error
Last modified: 2020-04-06 13:02:52 CEST
Sometimes the restart of slapd after a schema registration fails with: Jul 02 23:47:37 master091 systemd[1]: Starting LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol)... Jul 02 23:47:37 master091 root[17646]: /etc/init.d/slapd start (pid: 17634, ppid: 1 systemd) Jul 02 23:47:37 master091 slapd[17647]: @(#) $OpenLDAP: slapd (Aug 6 2018 15:28:57) $ Debian OpenLDAP Maintainers <pkg-openldap-devel@lists.alioth.debian.org> Jul 02 23:47:37 master091 slapd[17648]: WARNING: No dynamic config support for overlay translog. Jul 02 23:47:37 master091 slapd[17648]: WARNING: No dynamic config support for overlay shadowbind. Jul 02 23:47:37 master091 slapd[17634]: Starting ldap server(s): slapd ...failed. Jul 02 23:47:37 master091 slapd[17634]: Bus error Jul 02 23:47:37 master091 slapd[17634]: . Jul 02 23:47:37 master091 systemd[1]: slapd.service: Control process exited, code=exited status=1 Jul 02 23:47:37 master091 systemd[1]: Failed to start LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol). Jul 02 23:47:37 master091 systemd[1]: slapd.service: Unit entered failed state. Jul 02 23:47:37 master091 systemd[1]: slapd.service: Failed with result 'exit-code'. We have seen this several time in our jenkins tests, always during the univention-appcenter schema/acl/udm registration setup: [master091] 2019-07-02T23:47:17.190364 __MSG__:Configure 30univention-appcenter [master091] 2019-07-02T23:47:17.190364 __STEP__:16 [master091] 2019-07-02T23:47:17.190364 Configure 30univention-appcenter.inst Tue Jul 2 23:47:15 CEST 2019 [master091] 2019-07-02T23:47:17.193208 2019-07-02 23:47:15.056485242+02:00 (in joinscript_init) [master091] 2019-07-02T23:47:17.837700 Object created: cn=apps,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:18.583790 Object exists: cn=ldapschema,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:18.876269 Object exists: cn=ldapacl,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:19.256089 Object created: cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:19.631919 Object created: cn=udm_module,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:20.622189 Object created: cn=univention-app,cn=ldapschema,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:20.622189 Object created: cn=66univention-appcenter_app,cn=ldapacl,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:20.622189 Object created: cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:47:20.622189 Object created: cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local [master091] 2019-07-02T23:50:31.606349 Waiting for activation of the extension object univention-app: ..................ERROR: Master did not mark the extension object active within 180 seconds. [master091] 2019-07-02T23:50:31.606695 ERROR [master091] 2019-07-02T23:50:31.606695 ucs_registerLDAPExtension: registraton of /usr/share/univention-appcenter/univention-app.schema failed. [master091] 2019-07-02T23:50:31.636065 __MSG__:Configure 30univention-nagios-client [master091] 2019-07-02T23:50:31.636065 __STEP__:17 listener: 02.07.19 23:47:15.697 LISTENER ( PROCESS ) : updating 'cn=apps,cn=univention,dc=AutoTest091,dc=local' command a 02.07.19 23:47:16.608 LISTENER ( PROCESS ) : updating 'cn=univention-app,cn=ldapschema,cn=univention,dc=AutoTest091,dc=local' command a 02.07.19 23:47:19.497 LISTENER ( PROCESS ) : updating 'cn=66univention-appcenter_app,cn=ldapacl,cn=univention,dc=AutoTest091,dc=local' command a 02.07.19 23:47:19.498 LISTENER ( PROCESS ) : ldap_extension: cn=66univention-appcenter_app,cn=ldapacl,cn=univention,dc=AutoTest091,dc=local active? ['FALSE'] 02.07.19 23:47:21.890 LISTENER ( PROCESS ) : updating 'cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local' command a 02.07.19 23:47:21.897 LISTENER ( PROCESS ) : updating 'cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local' command a UNIVENTION_DEBUG_BEGIN : uldap.__open host=master091.AutoTest091.local port=7389 base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master091.AutoTest091.local port=7389 base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : admin.handlers.simpleLdap._update_policies UNIVENTION_DEBUG_END : admin.handlers.simpleLdap._update_policies UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name 02.07.19 23:47:22.092 LISTENER ( PROCESS ) : updating 'cn=udm_module,cn=univention,dc=AutoTest091,dc=local' command a 02.07.19 23:47:22.096 LISTENER ( PROCESS ) : updating 'cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local' command a UNIVENTION_DEBUG_BEGIN : uldap.__open host=master091.AutoTest091.local port=7389 base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.__open host=master091.AutoTest091.local port=7389 base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = data UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = filename UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : uldap.parentDn dn=cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_END : uldap.parentDn dn=cn=udm_module,cn=univention,dc=AutoTest091,dc=local base=dc=AutoTest091,dc=local UNIVENTION_DEBUG_BEGIN : admin.handlers.simpleLdap._update_policies UNIVENTION_DEBUG_END : admin.handlers.simpleLdap._update_policies UNIVENTION_DEBUG_BEGIN : admin.handlers.base.__getitem__ key = name UNIVENTION_DEBUG_END : admin.handlers.base.__getitem__ key = name 02.07.19 23:47:22.271 LISTENER ( PROCESS ) : updating 'cn=app_syntax,cn=udm_syntax,cn=univention,dc=AutoTest091,dc=local' command m 02.07.19 23:47:22.276 LISTENER ( PROCESS ) : updating 'cn=appcenter/app,cn=udm_module,cn=univention,dc=AutoTest091,dc=local' command m Restarting nagios-nrpe-server (via systemctl): nagios-nrpe-server.service. 16069 02.07.19 23:47:37.548 LISTENER ( PROCESS ) : ldap_extension: Reloading LDAP server. Restarting slapd (via systemctl): slapd.serviceJob for slapd.service failed because the control process exited with error code. See "systemctl status slapd.service" and "journalctl -xe" for details. failed! UNIVENTION_DEBUG_BEGIN : uldap.__open host=master091.AutoTest091.local port=7389 base=dc=AutoTest091,dc=local Multifile: /etc/ldap/slapd.conf Multifile: /etc/ldap/slapd.conf Traceback (most recent call last): File "/usr/lib/univention-directory-listener/system/ldap_extension.py", line 97, in postrun handler_object.mark_active() File "/usr/lib/python2.7/dist-packages/univention/lib/ldap_extension.py", line 379, in mark_active lo, ldap_position = udm_uldap.getAdminConnection() File "/usr/lib/pymodules/python2.7/univention/admin/uldap.py", line 164, in getAdminConnection lo = univention.uldap.getAdminConnection(start_tls, decode_ignorelist=decode_ignorelist) File "/usr/lib/python2.7/dist-packages/univention/uldap.py", line 118, in getAdminConnection return access(host=ucr['ldap/master'], port=port, base=ucr['ldap/base'], binddn='cn=admin,' + ucr['ldap/base'], bindpw=bindpw, start_tls=start_tls, decode_ignorelist=decode_ignorelist, reconnect=reconnect) File "/usr/lib/python2.7/dist-packages/univention/uldap.py", line 250, in __init__ self.__open(ca_certfile) File "/usr/lib/python2.7/dist-packages/univention/uldap.py", line 316, in __open self.lo.start_tls_s() File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 954, in start_tls_s res = self._apply_method_s(SimpleLDAPObject.start_tls_s,*args,**kwargs) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 935, in _apply_method_s self.reconnect(self._uri,retry_max=self._retry_max,retry_delay=self._retry_delay) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 911, in reconnect raise e ldap.SERVER_DOWN: {'desc': "Can't contact LDAP server"} 03.07.19 05:43:24.984 LISTENER ( WARN ) : received signal 15 03.07.19 05:43:30.323 DEBUG_INIT 03.07.19 05:43:30.331 LISTENER ( WARN ) : Notifier/LDAP server is master091.AutoTest091.local:7389 03.07.19 05:43:30.331 LDAP ( PROCESS ) : connecting to ldap://master091.AutoTest091.local:7389 03.07.19 05:43:30.331 LDAP ( ERROR ) : start_tls: Can't contact LDAP server 03.07.19 05:43:30.331 LISTENER ( WARN ) : can not connect to LDAP server master091.AutoTest091.local:7389
(In reply to Felix Botner from comment #0) > Jul 02 23:47:37 master091 slapd[17634]: Starting ldap server(s): slapd > ...failed. > Jul 02 23:47:37 master091 slapd[17634]: Bus error > Jul 02 23:47:37 master091 slapd[17634]: . SIGBUS is caused by unaligned memory access, most often caused by memory corruption. This might be a hardware defect, but more probably some corrupt data structure containing pointers. Without a core dump or access to an affected sytem there is nothing we can do.
Again: UCS-4.4-1 AutotestJoin s4,master 29 @ 2019-08-06
Again in last nights tests: http://jenkins.knut.univention.de:8080/job/UCS-4.4/job/UCS-4.4-2/job/AutotestJoin/SambaVersion=no-samba,Systemrolle=member/ws/test/master/syslog
(In reply to Erik Damrose from comment #3) > Again in last nights tests: > http://jenkins.knut.univention.de:8080/job/UCS-4.4/job/UCS-4.4-2/job/ > AutotestJoin/SambaVersion=no-samba,Systemrolle=member/ws/test/master/syslog Here is a forever stored version: https://bepasty.knut.univention.de/HxxUxCUw/+inline
and again http://jenkins.knut.univention.de:8080/view/Seed%20Jobs/job/UCS-4.4/job/UCS-4.4-2/job/ADConnectorMultiEnv/Version=w2k12-german/ws/test/journalctl.log/*view*/ As we no longer remove the kvm instances if the setup fails, we may be able to investigate the situation on the live system (only KVM). Is there anything we should do in our test setups (activate core dumps? install dbg-symbols)?
(In reply to Felix Botner from comment #6) > Is there anything we should do in our test setups (activate core dumps? > install dbg-symbols)? Yes, activate core dumps and save one.
Created attachment 10230 [details] data.mdb And again. And with the attached database file (data.mdb) the problem can be reproduced, just by starting slapcat. with dbg: $ gdb slapcat bt #0 0x00005555555d0dc4 in strchrlen (len=<synthetic pointer>, ch=59 ';', end=0x7fff6bd62000 <error: Cannot access memory at address 0x7fff6bd62000>, beg=0x7fff6bd61ff5 "entry-de-de"<error: Cannot access memory at address 0x7fff6bd62000>) at ../../../../servers/slapd/ad.c:148 #1 slap_bv2ad (bv=bv@entry=0x7fffffffdbe0, ad=ad@entry=0x7fffffffdbb8, text=text@entry=0x7fffffffdbb0) at ../../../../servers/slapd/ad.c:224 #2 0x00007fffee70e043 in mdb_ad_read (mdb=mdb@entry=0x555555a58240, txn=<optimized out>) at ../../../../../servers/slapd/back-mdb/attr.c:573 #3 0x00007fffee6fe4ad in mdb_db_open (be=0x7fffffffdd90, cr=0x7fffffffdf80) at ../../../../../servers/slapd/back-mdb/init.c:263 #4 0x00005555555fa601 in over_db_open (be=<optimized out>, cr=0x7fffffffdf80) at ../../../../servers/slapd/backover.c:149 #5 0x000055555559a317 in backend_startup_one (be=be@entry=0x555555a580a0, cr=cr@entry=0x7fffffffdf80) at ../../../../servers/slapd/backend.c:224 #6 0x000055555559a4cb in backend_startup (be=be@entry=0x555555a580a0) at ../../../../servers/slapd/backend.c:278 #7 0x00005555555bc0e1 in slap_startup (be=0x555555a580a0) at ../../../../servers/slapd/init.c:219 #8 0x00005555555ffc84 in slap_tool_init (progname=progname@entry=0x55555561d2c1 "slapcat", tool=tool@entry=2, argc=<optimized out>, argv=<optimized out>) at ../../../../servers/slapd/slapcommon.c:908 #9 0x00005555555fec90 in slapcat (argc=<optimized out>, argv=<optimized out>) at ../../../../servers/slapd/slapcat.c:53 #10 0x0000555555570867 in main (argc=1, argv=0x7fffffffe568) at ../../../../servers/slapd/main.c:410
Created attachment 10231 [details] bt full log
Created attachment 10232 [details] strchrlen.patch Arvid already analyzed the problem and proposed a patch. openldap-2.4.45+dfsg/servers/slapd/ad.c static char *strchrlen( const char *beg, const char *end, const char ch, int *len ) { const char *p; for( p=beg; *p && p < end; p++ ) { (gdb) print p $1 = 0x7fff6bd62000 <error: Cannot access memory at address 0x7fff6bd62000> (gdb) print *p Cannot access memory at address 0x7fff6bd62000 (gdb) print end $2 = 0x7fff6bd62000 <error: Cannot access memory at address 0x7fff6bd62000> This "*p" is a bit optimistic, should be p < end and then *p. - for( p=beg; *p && p < end; p++ ) { + for( p=beg; p < end && *p; p++ ) { On my test machine, slapd/slapcat works fine with proposed patch.
The last line in the binary file is DMPropertyValueNotEditableO�univentionUDMPropertyCLIName �univentionUDMPropertyObjectClass�univentionUDMPropertyMultivalueuniventionUDMPropertyVersion$~univentionUDMPropertyLongDescription}univentionUDMPropertySyntax;|univentionUDMPropertyTranslationLongDescription;entry-de-de{univentionUDMPropertyModule%zuniventionUDMPropertyShortDescription<yuniventionUDMPropertyTranslationShortDescription;entry-de-de so this attribute univentionUDMPropertyTranslationShortDescription;entry-de-de name is the last thing in the database. Given that the mdb file is mapped into the memory, there is nothing after univentionUDMPropertyTranslationShortDescription;entry-de-de and strchrlen() fails.
r18742 | 2.4.45+dfsg-1~bpo9+1-errata4.4-2/90_bug49780_slapd_bus_error.quilt 3cd5b4f0ed | Advisory
OK - patch OK - slapd works with attached database file OK - yaml
<http://errata.software-univention.de/ucs/4.4/375.html>
Sent upstream http://www.openldap.org/its/index.cgi/Incoming?selectid=9128;usearchives=1
The OpenLDAP project switched from ITS to bugzilla, fortunately the IDs seem to have been preserved: https://bugs.openldap.org/show_bug.cgi?id=9128