Re: slapd: null_callback : error code 0x14

["Paul B. Henson" <henson@acm.org>]

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...