--On Tuesday, September 19, 2017 7:40 PM -0700 "Paul B. Henson" henson@acm.org wrote:
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)
Well, my first question is, do you see these changes to this group entry in the log from your other rid as well? I.e., if it is being applied twice, you should see each modification logged twice. Usually with sync logging, you have lines noting what the CSN is that's being processed as well. There's not enough log information here to act on. :)
--Quanah
--
Quanah Gibson-Mount Product Architect Symas Corporation Packaged, certified, and supported LDAP solutions powered by OpenLDAP: http://www.symas.com
On Tue, Sep 19, 2017 at 07:22:19PM -0700, Quanah Gibson-Mount wrote:
Well, my first question is, do you see these changes to this group entry in the log from your other rid as well? I.e., if it is being applied twice, you should see each modification logged twice. Usually with sync logging, you have lines noting what the CSN is that's being processed as well. There's not enough log information here to act on. :)
Ah, I don't have sync logging on, just stats right now; I'll turn on sync logging and see what shows up tomorrow. I'm sorry for the bad bug reporting :(, but OTOH the fact that I'm in such bad practice at reporting bugs is a tribute to how infrequently I have to do so :).
Thanks...
On Tue, Sep 19, 2017 at 07:22:19PM -0700, Quanah Gibson-Mount wrote:
the log from your other rid as well? I.e., if it is being applied twice, you should see each modification logged twice. Usually with sync logging, you have lines noting what the CSN is that's being processed as well. There's not enough log information here to act on. :)
Ok, let's see if this is any better.
Here's a failure from this morning:
Sep 21 03:55:39 coeus slapd[103811]: null_callback : error code 0x14 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 be_modify uid=cs26401,ou=group,dc=cpp,dc=edu (20) Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 be_modify failed (20)
Here's what it looks like from a bit earlier than that:
Sep 21 03:55:39 coeus slapd[103811]: syncrepl_message_to_op: rid=002 be_modify uid=cs264,ou=group,dc =cpp,dc=edu (0) Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41acaa0 20170921105538.952721Z# 000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41170a0 20170921105538.952721Z# 000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41170a0 2017092110553 8.952721Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41acaa0 2017092110553 8.952721Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=003 CSN pending, ignoring 20170921105538.95272 1Z#000000#004#000000 (reqStart=20170921105539.000073Z,cn=accesslog) Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=002 cookie=rid=002,sid=002,csn=20170921105538. 996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b4102bf0 20170921105538.996047Z# 000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=003 cookie=rid=003,sid=003,csn=20170921105538. 998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=001 CSN pending, ignoring 20170921105538.95272 1Z#000000#004#000000 (reqStart=20170921105538.000091Z,cn=accesslog) Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=001 cookie=rid=001,sid=004,csn=20170921105538. 996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41a2f70 20170921105538.996047Z# 000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncprov_matchops: skipping original sid 004 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41a2f70 20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b4102bf0 20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_message_to_op: rid=002 be_modify uid=cs26401,ou=group,dc=cpp,dc=edu (0) Sep 21 03:55:39 coeus slapd[103811]: syncprov_sendresp: to=002, cookie=rid=002,sid=001,csn=20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b4112730 20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41acaa0 20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41acaa0 20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b4112730 20170921105538.996047Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=002 cookie=rid=002,sid=002,csn=20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95d8130560 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: null_callback : error code 0x14 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95d8130560 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_message_to_op: rid=003 be_modify uid=cs26401,ou=group,dc=cpp,dc=edu (20) Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20170921105539.000075Z,cn=accesslog), switching to REFRESH Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41acaa0 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_message_to_entry: rid=003 DN: uid=cs26401,ou=group,dc=cpp,dc=edu, UUID: af8393a4-8d2b-1027-9af4-e374887d0b81 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD) Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 be_search (0) Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 uid=cs26401,ou=group,dc=cpp,dc=edu Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41c8a10 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncprov_matchops: skipping original sid 004 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41c8a10 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41acaa0 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_message_to_op: rid=002 be_modify uid=cs26401,ou=group,dc=cpp,dc=edu (0) Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41a06f0 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: null_callback : error code 0x14 Sep 21 03:55:39 coeus slapd[103811]: syncprov_sendresp: to=002, cookie=rid=002,sid=001,csn=20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 be_modify uid=cs26401,ou=group,dc=cpp,dc=edu (20) Sep 21 03:55:39 coeus slapd[103811]: syncrepl_entry: rid=003 be_modify failed (20) Sep 21 03:55:39 coeus slapd[103811]: do_syncrepl: rid=003 rc 20 retrying (9 retries left) Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b410fc60 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b410fc60 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41a06f0 20170921105538.998639Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: do_syncrep2: rid=002 cookie=rid=002,sid=002,csn=20170921105539.466864Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41a2f70 20170921105539.466864Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_queue_csn: queueing 0x7f95b41a15d0 20170921105539.466864Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncprov_matchops: skipping original sid 004 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41a15d0 20170921105539.466864Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: slap_graduate_commit_csn: removing 0x7f95b41a2f70 20170921105539.466864Z#000000#004#000000 Sep 21 03:55:39 coeus slapd[103811]: syncrepl_message_to_op: rid=002 be_modify uid=cs400,ou=group,dc=cpp,dc=edu (0)
It seems there are updates for that group coming from rid 002 (egeria.ldap.cpp.edu) and 003 (minerva.ldap.cpp.edu), but none from rid 001 (themis.ldap.cpp.edu) which is serverid 4, where the change was actually made?
Then it complains about losing sync and switching to refresh?
I dunno. Are these logs at all helpful in explaining what's going on or am I still batting zero :(?
Thanks...
openldap-technical@openldap.org
-
Paul B. Henson -
Quanah Gibson-Mount