--On Friday, September 15, 2017 8:48 PM -0700 "Paul B. Henson" henson@acm.org wrote:
So I've been putting off posting about this, but I recently upgraded to 2.4.45, stopped using the memberof overlay, no longer have a node with serverID 0, and overall think my ldap servers should be in good shape :), and it's still happening, so I thought it was time...
I'm getting weird errors in my logs about group replication changes:
Sep 15 03:55:16 minerva slapd[71654]: null_callback : error code 0x14 Sep 15 03:55:16 minerva slapd[71654]: syncrepl_message_to_op: rid=003 be_modify uid=arc464,ou=group,dc=cpp,dc=edu (20)
These aren't "wierd errors". 0x14=20. I.e., you're simply getting the same error logged twice.
As far as I can tell, all the updates succeed and the objects are exactly the same on all the replicas, so these failures just seem to be log noise?
Well, error code 20 is "type or value already exists". If the replica and the masters are starting from the same point, this would tend to imply that the replica is receiving the change multiple times, and it's failing on the subsequent modify operations. There's not enough information here to really deduce much beyond that. I've seen this occur in MMR situations where two masters were updating the same entries within a short window of each other.
--Quanah
--
Quanah Gibson-Mount Product Architect Symas Corporation Packaged, certified, and supported LDAP solutions powered by OpenLDAP: http://www.symas.com
On Mon, Sep 18, 2017 at 08:31:34AM -0700, Quanah Gibson-Mount wrote:
These aren't "wierd errors". 0x14=20. I.e., you're simply getting the same error logged twice.
Well, "unexpected" errors perhaps :).
I knew the lines were related but I didn't notice the hex decimal equivilency.
Well, error code 20 is "type or value already exists". If the replica and the masters are starting from the same point, this would tend to imply that the replica is receiving the change multiple times, and it's failing on the subsequent modify operations.
Hmm. I only have one active master, and it's the only server receiving updates. Let me try including some more detail on an error from this morning.
So here's the error on the replica:
Sep 19 03:56:19 coeus slapd[43551]: null_callback : error code 0x14 Sep 19 03:56:19 coeus slapd[43551]: syncrepl_message_to_op: rid=003 be_modify uid=egr44503,ou=group,dc=cpp,dc=edu (20)
rid 3 is the backup master:
syncrepl rid=3 provider=ldaps://minerva.ldap.cpp.edu/
Let's see what's in the accesslog:
dn: reqStart=20170919105619.000057Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000057Z reqEnd: 20170919105619.000058Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=michaelm3,ou=user,dc=cpp,dc=edu reqMod: entryCSN:= 20170919105619.291799Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 390ff571-794c-4fc1-86ac-d72aeac1dbbf creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.291799Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000060Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000060Z reqEnd: 20170919105619.000061Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: memberUid:- michaelm3 reqMod: entryCSN:= 20170919105619.295478Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 6d3a042b-d6ab-4b3e-bc14-6b37eaef91f7 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.295478Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000063Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000063Z reqEnd: 20170919105619.000069Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:+ uid=qxho,ou=user,dc=cpp,dc=edu reqMod: entryCSN:= 20170919105619.305311Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 2ce0cd50-70eb-4bbc-80a5-85fd8322290a creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.305311Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000071Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000071Z reqEnd: 20170919105619.000072Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: memberUid:+ qxho reqMod: entryCSN:= 20170919105619.308548Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 5f896be6-74b9-4c16-a96a-d7fc6f6a85eb creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.308548Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
That's all that's in the accesslog. Ok, now in the slapd log on minerva; there's no mention of egr44503 anywhere in the slapd log. In the accesslog:
dn: reqStart=20170919105619.000055Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000055Z reqEnd: 20170919105619.000057Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=michaelm3,ou=user,dc=cpp,dc=edu reqMod: entryCSN:= 20170919105619.291799Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: be73d55d-bccc-4409-b3e1-1620440a5b99 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.291799Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000059Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000059Z reqEnd: 20170919105619.000062Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: memberUid:- michaelm3 reqMod: entryCSN:= 20170919105619.295478Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: cff1d0f8-0fb2-4762-bd35-7039fbcd57f9 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.295478Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000065Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000065Z reqEnd: 20170919105619.000066Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:+ uid=qxho,ou=user,dc=cpp,dc=edu reqMod: entryCSN:= 20170919105619.305311Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 4acc741b-8d68-4826-8096-f3a0bf68c629 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.305311Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000067Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000067Z reqEnd: 20170919105619.000068Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: memberUid:+ qxho reqMod: entryCSN:= 20170919105619.308548Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 17bc3749-ba09-4125-aa2f-543bf04188d4 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.308548Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
That's it; now on the actual active master themis in the slapd log:
Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184525 MOD dn="uid=egr44503,ou=group,dc=cpp,dc=edu" Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184525 MOD attr=member Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184525 RESULT tag=103 err=0 text= Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184526 MOD dn="uid=egr44503,ou=group,dc=cpp,dc=edu" Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184526 MOD attr=memberUid Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184526 RESULT tag=103 err=0 text= Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184527 MOD dn="uid=egr44503,ou=group,dc=cpp,dc=edu" Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184527 MOD attr=member Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184527 RESULT tag=103 err=0 text= Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184528 MOD dn="uid=egr44503,ou=group,dc=cpp,dc=edu" Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184528 MOD attr=memberUid Sep 19 03:56:19 themis slapd[28201]: conn=251001 op=184528 RESULT tag=103 err=0 text=
And in the access log:
dn: reqStart=20170919105619.000028Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000028Z reqEnd: 20170919105619.000029Z reqType: modify reqSession: 251001 reqAuthzID: cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=michaelm3,ou=user,dc=cpp,dc=edu reqMod: entryCSN:= 20170919105619.291799Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 21e4f5be-08b0-4827-92a2-133046704847 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.291799Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000030Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000030Z reqEnd: 20170919105619.000031Z reqType: modify reqSession: 251001 reqAuthzID: cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: memberUid:- michaelm3 reqMod: entryCSN:= 20170919105619.295478Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 7a3ea0d1-f7ed-44d0-9227-d3769024d1c0 creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.295478Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000032Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000032Z reqEnd: 20170919105619.000033Z reqType: modify reqSession: 251001 reqAuthzID: cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:+ uid=qxho,ou=user,dc=cpp,dc=edu reqMod: entryCSN:= 20170919105619.305311Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryCSN: 20170919105619.305311Z#000000#004#000000 entryUUID: ee031e57-6634-41e7-bd82-096b198245e5 creatorsName: cn=accesslog createTimestamp: 20170919105619Z modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
dn: reqStart=20170919105619.000034Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20170919105619.000034Z reqEnd: 20170919105619.000035Z reqType: modify reqSession: 251001 reqAuthzID: cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqDN: uid=egr44503,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: memberUid:+ qxho reqMod: entryCSN:= 20170919105619.308548Z#000000#004#000000 reqMod: modifiersName:= cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqMod: modifyTimestamp:= 20170919105619Z reqEntryUUID: f0b9ac97-5eec-4ac7-86e6-ac691689a3c8 entryUUID: 57a7c864-bbd2-46af-89d8-a75d740aac6d creatorsName: cn=accesslog createTimestamp: 20170919105619Z entryCSN: 20170919105619.308548Z#000000#004#000000 modifiersName: cn=accesslog modifyTimestamp: 20170919105619Z
As far as I can tell, the only place this entry was changed was on the active master, serverid 4, and all the accesslog entry CSNs have that serverid. Yet it seems the error resulted from the replica getting an extra copy of the change from the backup non-active master, which seems to have forwarded a copy of the change too?
Any thoughts?
Thanks...
openldap-technical@openldap.org
-
Paul B. Henson -
Quanah Gibson-Mount