Bug 1249784
Summary: | ipa-dnskeysyncd unhandled exception on named-pkcs11 start | ||||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|---|---|
Product: | Red Hat Enterprise Linux 7 | Reporter: | Scott Poore <spoore> | ||||||||||
Component: | 389-ds-base | Assignee: | Noriko Hosoi <nhosoi> | ||||||||||
Status: | CLOSED ERRATA | QA Contact: | Viktor Ashirov <vashirov> | ||||||||||
Severity: | medium | Docs Contact: | |||||||||||
Priority: | medium | ||||||||||||
Version: | 7.2 | CC: | kbanerje, mbasti, mkosek, nhosoi, nkinder, pspacek, rcritten, rmeggins, tbordaz | ||||||||||
Target Milestone: | rc | ||||||||||||
Target Release: | --- | ||||||||||||
Hardware: | Unspecified | ||||||||||||
OS: | Unspecified | ||||||||||||
Whiteboard: | |||||||||||||
Fixed In Version: | 389-ds-base-1.3.4.0-11.el7 | Doc Type: | Bug Fix | ||||||||||
Doc Text: | Story Points: | --- | |||||||||||
Clone Of: | Environment: | ||||||||||||
Last Closed: | 2015-11-19 11:43:55 UTC | Type: | Bug | ||||||||||
Regression: | --- | Mount Type: | --- | ||||||||||
Documentation: | --- | CRM: | |||||||||||
Verified Versions: | Category: | --- | |||||||||||
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||
Cloudforms Team: | --- | Target Upstream Version: | |||||||||||
Embargoed: | |||||||||||||
Attachments: |
|
Description
Scott Poore
2015-08-03 20:02:51 UTC
Created attachment 1058887 [details]
abrt dir for crash
Scott, I assume you tried to rename some DNS entry and it was rejected by the DNSSEC daemon. I will CC Martin to look at the bug when he returns from his leave. From the timing, it looks like the crash occurred during ipa-server-install. I figured out that IPA receives entries with *non unique* UUID. http://pastebin.test.redhat.com/304726 However, ldapsearch returns entries with unique uuid (nsuniqueid), so error is caused by syncrepl. I tested python-ldap syncrepl consumer, it worked as expected on F22 (389-ds-base-1.3.4.1-1.fc22.x86_64), but returns nonunique UUIDs from (389-ds-base-1.3.4.0-10.el7.x86_64) Thierry is investigating. Using Martin machine, I can reproduce using his script or ldapsearch. In fact the uuid in some cookie are looking identical: ldapsearch -L -D "cn=directory manager" -w hesloheslo -b "cn=sec,cn=dns,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" -E sync=ro nsuniqueid ... # keys, sec, dns, abc.idm.lab.eng.brq.redhat.com dn: cn=keys,cn=sec,cn=dns,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com # control: 1.3.6.1.4.1.4203.1.9.1.2 false MBUKAQEEEBx2AHR5fwAAFwAAAAAAAAA= nsuniqueid: 1c760040-402911e5-8adbaa93-ff7e4820 # 2dcfe996-4029-11e5-bbe7-001a4a231210, keys, sec, dns, abc.idm.lab.eng.brq.r edhat.com dn: ipk11UniqueID=2dcfe996-4029-11e5-bbe7-001a4a231210,cn=keys,cn=sec,cn=dns,d c=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com # control: 1.3.6.1.4.1.4203.1.9.1.2 false MBUKAQEEEBx2AHR5fwAAFwAAAAAAAAA= nsuniqueid: 1c760042-402911e5-8adbaa93-ff7e4820 UUID are built from 'nsuniqueid' It should return different values: [root@vm-127 slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM]# /root/nsuniqueid_2_uuid 1c760040-402911e5-8adbaa93-ff7e4820 uuid[ 0] = 0x1c uuid[ 1] = 0x76 ['v'] uuid[ 2] = 0x00 uuid[ 3] = 0x40 ['@'] uuid[ 4] = 0x40 ['@'] uuid[ 5] = 0x29 [')'] uuid[ 6] = 0x11 uuid[ 7] = 0xffffffe5 uuid[ 8] = 0xffffff8a uuid[ 9] = 0xffffffdb uuid[10] = 0xffffffaa uuid[11] = 0xffffff93 uuid[12] = 0xffffffff uuid[13] = 0x7e ['~'] uuid[14] = 0x48 ['H'] uuid[15] = 0x20 [' '] [root@vm-127 slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM]# [root@vm-127 slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM]# /root/nsuniqueid_2_uuid 1c760042-402911e5-8adbaa93-ff7e4820 uuid[ 0] = 0x1c uuid[ 1] = 0x76 ['v'] uuid[ 2] = 0x00 uuid[ 3] = 0x42 ['B'] uuid[ 4] = 0x40 ['@'] uuid[ 5] = 0x29 [')'] uuid[ 6] = 0x11 uuid[ 7] = 0xffffffe5 uuid[ 8] = 0xffffff8a uuid[ 9] = 0xffffffdb uuid[10] = 0xffffffaa uuid[11] = 0xffffff93 uuid[12] = 0xffffffff uuid[13] = 0x7e ['~'] uuid[14] = 0x48 ['H'] uuid[15] = 0x20 [' '] There is no specific logging at that place, I am debugging it. Created attachment 1062053 [details]
wireshark capture of a ldap lookup
SRCH under cn=sec,cn=dns,SUFFIX. 2 entries have the same uuid
Here is the current status - The RC is that DS uses slapi_ch_smprintf("%s") to manipulate the UUID If the computed UUID contains a NULL character, then smprintf does not copy all the computed UUID and the remaining part of the UUID is random (depends on what was on the heap at that time) Breakpoint 4, sync_nsuniqueid2uuid (nsuniqueid=0x7f796c046cf0 "1c760042-402911e5-8adbaa93-ff7e4820") at ldap/servers/plugins/sync/sync_util.c:110 110 uuid = slapi_ch_smprintf("%s",(char *)u); (gdb) n 106 u[15] = slapi_str_to_u8(nsuniqueid+33); (gdb) 110 uuid = slapi_ch_smprintf("%s",(char *)u); (gdb) 108 u[16] = '\0'; (gdb) 110 uuid = slapi_ch_smprintf("%s",(char *)u); (gdb) 113 } (gdb) x/16bx u 0x7f79917ead00: 0x1c 0x76 0x00 0x42 0x40 0x29 0x11 0xe5 0x7f79917ead08: 0x8a 0xdb 0xaa 0x93 0xff 0x7e 0x48 0x20 (gdb) x/16bx uuid 0x7f7978341eb0: 0x1c 0x76 0x00 0x78 0x79 0x7f 0x00 0x00 0x7f7978341eb8: 0x17 0x00 0x00 0x00 0x00 0x00 0x00 0x00 - The buffer is correctly copied if it does not contain NULL (gdb) x/16x u 0x7f7993fefd00: 0x1c 0x76 0x00 0x42 0x40 0x29 0x11 0xe5 0x7f7993fefd08: 0x8a 0xdb 0xaa 0x93 0xff 0x7e 0x48 0x00 $15 = (void *) 0x7f7993fefd00 (gdb) set {char}0x7f7993fefd02 = 18 (gdb) x/16x u 0x7f7993fefd00: 0x1c 0x76 0x12 0x42 0x40 0x29 0x11 0xe5 0x7f7993fefd08: 0x8a 0xdb 0xaa 0x93 0xff 0x7e 0x48 0x00 (gdb) n 106 u[15] = slapi_str_to_u8(nsuniqueid+33); (gdb) 110 uuid = slapi_ch_smprintf("%s",(char *)u); (gdb) 108 u[16] = '\0'; (gdb) 110 uuid = slapi_ch_smprintf("%s",(char *)u); (gdb) 113 } (gdb) x/16x u 0x7f7993fefd00: 0x1c 0x76 0x12 0x42 0x40 0x29 0x11 0xe5 0x7f7993fefd08: 0x8a 0xdb 0xaa 0x93 0xff 0x7e 0x48 0x20 (gdb) x/16x uuid 0x7f797c021670: 0x1c 0x76 0x12 0x42 0x40 0x29 0x11 0xe5 0x7f797c021678: 0x8a 0xdb 0xaa 0x93 0xff 0x7e 0x48 0x20 - The fact that two entries have same "wrong" UUID is really random but in fact it happens very frequently - This should also occured in 7.1 but was not noticed In conclusion: Since 7.1 UUID values may be corrupted. With collision of entries UUID or same entry having a different UUID some time later. Here are the next steps - This is a DS bug. Moving it to 389-ds - The fix is easy, allocate+memcopy the final UUID Upstream ticket: https://fedorahosted.org/389/ticket/48249 Thank you for your investigation, Thierry! Please use this ticket for the usual review process. https://fedorahosted.org/389/ticket/48249 Thanks! Created attachment 1063143 [details]
Reading the UUID from a repl_sync search
I borrow that script from mbasti.
It does a search on a subtree using repl_sync control and displays the returned entry DN with their UUID.
Created attachment 1064853 [details] userRoot.ldif for verification [1] Import ldif with user entries, that contain 0x00 in their nsuniqeid: # ldif2db -n userRoot -i /var/lib/dirsrv/slapd-rhel7ds/ldif/rhel7ds-userRoot-2015_08_19_151141.ldif # ldapsearch -D "cn=Directory Manager" -w Secret123 -b dc=example,dc=com -o ldif-wrap=no -LLL "(cn=usr*)" nsuniqueid dn: cn=usr1,ou=People,dc=example,dc=com nsuniqueid: 105b0001-465c11e5-aa2ab26e-9f0d9380 dn: cn=usr2,ou=People,dc=example,dc=com nsuniqueid: 105b0002-465c11e5-aa2ab26e-9f0d9380 [2] Enable retro changelog and content synchronization operation plugins. [3] With an older version of 389-ds-base script from comment 14 returned the same UUID for both entries, though every time random. [root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# python replsync_uuid.py entry 020ad983-4658-11e5-836e-d1c2fb4ae609 ou=People,dc=example,dc=com entry 105b0010-027f-0000-6c65-2c64633d636f cn=usr1,ou=People,dc=example,dc=com entry 105b0010-027f-0000-6c65-2c64633d636f cn=usr2,ou=People,dc=example,dc=com ^C[root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# python replsync_uuid.py entry 020ad983-4658-11e5-836e-d1c2fb4ae609 ou=People,dc=example,dc=com entry 105b00fc-017f-0000-6c65-2c64633d636f cn=usr1,ou=People,dc=example,dc=com entry 105b00fc-017f-0000-6c65-2c64633d636f cn=usr2,ou=People,dc=example,dc=com ^C[root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# python replsync_uuid.py entry 020ad983-4658-11e5-836e-d1c2fb4ae609 ou=People,dc=example,dc=com entry 105b0008-027f-0000-6c65-2c64633d636f cn=usr1,ou=People,dc=example,dc=com entry 105b0008-027f-0000-6c65-2c64633d636f cn=usr2,ou=People,dc=example,dc=com With 389-ds-base-1.3.4.0-12.el7.x86_64: [root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# python replsync_uuid.py entry 020ad983-4658-11e5-836e-d1c2fb4ae609 ou=People,dc=example,dc=com entry 105b0001-465c-11e5-aa2a-b26e9f0d9380 cn=usr1,ou=People,dc=example,dc=com entry 105b0002-465c-11e5-aa2a-b26e9f0d9380 cn=usr2,ou=People,dc=example,dc=com ^C[root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# python replsync_uuid.py entry 020ad983-4658-11e5-836e-d1c2fb4ae609 ou=People,dc=example,dc=com entry 105b0001-465c-11e5-aa2a-b26e9f0d9380 cn=usr1,ou=People,dc=example,dc=com entry 105b0002-465c-11e5-aa2a-b26e9f0d9380 cn=usr2,ou=People,dc=example,dc=com ^C[root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# python replsync_uuid.py entry 020ad983-4658-11e5-836e-d1c2fb4ae609 ou=People,dc=example,dc=com entry 105b0001-465c-11e5-aa2a-b26e9f0d9380 cn=usr1,ou=People,dc=example,dc=com entry 105b0002-465c-11e5-aa2a-b26e9f0d9380 cn=usr2,ou=People,dc=example,dc=com ^C[root@rhel7ds 1249784-ipa-dnskeysyncd-unhandled-exception-on-named-pkcs1]# UUIDs are different for each entry. Marking as VERIFIED. Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHBA-2015-2351.html |