-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
hi,
please advise
I need to replicate not all but some branches from one master to one slave
not sure how much correct I have done that, but here what I have:
slave starts successfully, records appear on slave as expected, services successfully use data as expected ... but the replication fails (fragments of log files are bellow)
on master I see: consumer state is newer than provider on slave: LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform
so ... what is wrong here?
branches to replicate: ou=People,dc=example ou=clusterX,ou=Sendmail,dc=example
to be used by 3 services on the slave
1. email (smtp auth and imap4/pop3 auth) object dn sample: uid=ja@foo.bar,authorizedService=mail@foo.bar,uid=johnd,ou=People,dc=example
2. jabber object dn sample: uid=aj@foo.bar,authorizedService=xmpp@foo.bar,uid=johnd,ou=People,dc=example
3. sendmail configuration
(here is the detailed diagram https://github.com/z-eos/umi/wiki/DB-topology)
====================================================================== here is the configuration layout:
- ---[ master configuration quotation start ]--------------------------- ... access to dn.children="dc=example" by dn.exact="uid=replABC,ou=repl,dc=example" read by * break
# syncprov specific indexing index entryCSN eq index entryUUID eq
overlay syncprov syncprov-checkpoint 50 10 syncprov-sessionlog 100
overlay accesslog logdb cn=example-accesslog logops writes logold (objectclass=*) index default eq
### Accesslog DB database mdb maxsize 1073741824 suffix cn=example-accesslog rootdn "cn=root,cn=example-accesslog" rootpw *** directory "/var/db/openldap-data/example-accesslog"
index default eq index entryCSN,objectClass,reqEnd,reqResult,reqStart
overlay syncprov syncprov-nopresent TRUE syncprov-reloadhint TRUE ... - ---[ master configuration quotation end ]---------------------------
- ---[ slave configuration quotation start ]---------------------------- syncrepl rid=123 provider=ldap://master.example:389 starttls=critical searchbase="dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" filter="(|(&(objectClass=authorizedServiceObject)(objectClass=mailutilsAccount)(authorizedService=mail@foo.bar)))" attrs="cn,entry,entryCSN,entryUUID,o,uid,uidNumber,gidNumber,gecos,homeDirectory,loginShell,userPassword,creatorsName,createTimestamp,modifiersName,modifyTimestamp,mail,rfc822MailMember,sn,authorizedService,mu-mailBox" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog
syncrepl rid=123 provider=ldap://master.example:389 starttls=critical searchbase="dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" filter="(&(objectClass=authorizedServiceObject)(authorizedService=xmpp@foo.bar))" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog
syncrepl rid=123 provider=ldap://master.example:389 starttls=critical searchbase="ou=ABC,ou=Sendmail,dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog - ---[ slave configuration quotation end ]----------------------------
====================================================================== here are logs
- ---[ master slapd.log quotation start ]------------------------------- Jun 26 22:54:25 master slapd[75509]: conn=55585 fd=19 ACCEPT from IP=192.168.0.1:54127 (IP=192.168.0.254:389) Jun 26 22:54:25 master slapd[75509]: conn=55585 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Jun 26 22:54:25 master slapd[75509]: conn=55585 op=0 STARTTLS Jun 26 22:54:25 master slapd[75509]: conn=55586 fd=20 ACCEPT from IP=192.168.0.1:57184 (IP=192.168.0.254:389) Jun 26 22:54:25 master slapd[75509]: conn=55585 op=0 RESULT oid= err=0 text= Jun 26 22:54:25 master slapd[75509]: conn=55586 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Jun 26 22:54:25 master slapd[75509]: conn=55586 op=0 STARTTLS Jun 26 22:54:25 master slapd[75509]: conn=55586 op=0 RESULT oid= err=0 text= Jun 26 22:54:25 master slapd[75509]: conn=55586 fd=20 TLS established tls_ssf=256 ssf=256 Jun 26 22:54:25 master slapd[75509]: conn=55585 fd=19 TLS established tls_ssf=256 ssf=256 Jun 26 22:54:25 master slapd[75509]: conn=55586 op=1 BIND dn="uid=replABC,ou=repl,dc=example" method=128 Jun 26 22:54:25 master slapd[75509]: conn=55586 op=1 BIND dn="uid=replABC,ou=repl,dc=example" mech=SIMPLE ssf=0 Jun 26 22:54:25 master slapd[75509]: conn=55586 op=1 RESULT tag=97 err=0 text= Jun 26 22:54:25 master slapd[75509]: conn=55585 op=1 BIND dn="uid=replABC,ou=repl,dc=example" method=128 Jun 26 22:54:25 master slapd[75509]: conn=55585 op=1 BIND dn="uid=replABC,ou=repl,dc=example" mech=SIMPLE ssf=0 Jun 26 22:54:25 master slapd[75509]: conn=55585 op=1 RESULT tag=97 err=0 text= Jun 26 22:54:25 master slapd[75509]: conn=55586 op=2 SRCH base="cn=example-accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Jun 26 22:54:25 master slapd[75509]: conn=55586 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN Jun 26 22:54:25 master slapd[75509]: conn=55585 op=2 SRCH base="cn=example-accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Jun 26 22:54:25 master slapd[75509]: conn=55585 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN Jun 26 22:54:25 master slapd[75509]: conn=55586 op=2 SEARCH RESULT tag=101 err=53 nentries=0 text=consumer state is newer than provider! Jun 26 22:54:25 master slapd[75509]: conn=55585 op=2 SEARCH RESULT tag=101 err=53 nentries=0 text=consumer state is newer than provider! Jun 26 22:54:25 master slapd[75509]: conn=55586 op=3 UNBIND Jun 26 22:54:25 master slapd[75509]: conn=55586 fd=20 closed Jun 26 22:54:25 master slapd[75509]: conn=55585 op=3 UNBIND Jun 26 22:54:25 master slapd[75509]: conn=55585 fd=19 closed Jun 26 22:54:31 master slapd[75509]: conn=55587 fd=19 ACCEPT from IP=192.168.0.1:58488 (IP=192.168.0.254:389) Jun 26 22:54:31 master slapd[75509]: conn=55587 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Jun 26 22:54:31 master slapd[75509]: conn=55587 op=0 STARTTLS Jun 26 22:54:31 master slapd[75509]: conn=55587 op=0 RESULT oid= err=0 text= Jun 26 22:54:31 master slapd[75509]: conn=55587 fd=19 TLS established tls_ssf=256 ssf=256 Jun 26 22:54:31 master slapd[75509]: conn=55587 op=1 BIND dn="uid=replABC,ou=repl,dc=example" method=128 Jun 26 22:54:31 master slapd[75509]: conn=55587 op=1 BIND dn="uid=replABC,ou=repl,dc=example" mech=SIMPLE ssf=0 Jun 26 22:54:31 master slapd[75509]: conn=55587 op=1 RESULT tag=97 err=0 text= Jun 26 22:54:31 master slapd[75509]: conn=55587 op=2 SRCH base="cn=example-accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Jun 26 22:54:31 master slapd[75509]: conn=55587 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN Jun 26 22:54:31 master slapd[75509]: conn=55587 op=2 SEARCH RESULT tag=101 err=53 nentries=0 text=consumer state is newer than provider! Jun 26 22:54:31 master slapd[75509]: conn=55587 op=3 UNBIND Jun 26 22:54:31 master slapd[75509]: conn=55587 fd=19 closed - ---[ master slapd.log quotation end ]-------------------------------
- ---[ slave slapd.log quotation start ]-------------------------------- Jun 26 21:41:44 ABC slapd[67186]: @(#) $OpenLDAP: slapd 2.4.44 (Feb 7 2017 01:19:39) $ root@foo.bar:/usr/ports/net/openldap24-server/work/openldap-2.4.44/servers/slapd Jun 26 21:41:44 ABC slapd[67187]: slapd starting Jun 26 21:41:44 ABC slapd[67187]: conn=1000 fd=14 ACCEPT from IP=127.0.0.1:32266 (IP=127.0.0.1:389) Jun 26 21:41:44 ABC slapd[67187]: conn=1001 op=0 BIND dn="" method=128 Jun 26 21:41:44 ABC slapd[67187]: conn=1002 fd=17 ACCEPT from IP=127.0.0.1:35827 (IP=127.0.0.1:389) Jun 26 21:41:44 ABC slapd[67187]: conn=1000 op=0 BIND dn="" method=128 Jun 26 21:41:44 ABC slapd[67187]: conn=1001 op=0 RESULT tag=97 err=0 text= Jun 26 21:41:44 ABC slapd[67187]: conn=1001 fd=16 ACCEPT from IP=127.0.0.1:37048 (IP=127.0.0.1:389) Jun 26 21:41:44 ABC slapd[67187]: conn=1002 op=0 BIND dn="" method=128 Jun 26 21:41:44 ABC slapd[67187]: conn=1000 op=0 RESULT tag=97 err=0 text= Jun 26 21:41:44 ABC slapd[67187]: conn=1002 op=0 RESULT tag=97 err=0 text= Jun 26 21:41:45 ABC slapd[67187]: do_syncrep2: rid=123 LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform Jun 26 21:41:45 ABC slapd[67187]: do_syncrep2: rid=123 (53) Server is unwilling to perform Jun 26 21:41:45 ABC slapd[67187]: do_syncrepl: rid=123 rc -2 retrying Jun 26 21:41:45 ABC slapd[67187]: do_syncrep2: rid=123 LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform Jun 26 21:41:45 ABC slapd[67187]: do_syncrep2: rid=123 (53) Server is unwilling to perform Jun 26 21:41:45 ABC slapd[67187]: do_syncrepl: rid=123 rc -2 retrying Jun 26 21:41:45 ABC slapd[67187]: do_syncrep2: rid=123 LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform Jun 26 21:41:45 ABC slapd[67187]: do_syncrep2: rid=123 (53) Server is unwilling to perform Jun 26 21:41:45 ABC slapd[67187]: do_syncrepl: rid=123 rc -2 retrying Jun 26 21:42:43 ABC slapd[67187]: conn=1003 fd=9 ACCEPT from IP=127.0.0.1:37489 (IP=127.0.0.1:389) Jun 26 21:42:43 ABC slapd[67187]: conn=1003 op=0 BIND dn="" method=128 - ---[ slave slapd.log quotation end ]--------------------------------
- -- Zeus V. Panchenko jid:zeus@im.ibs.dn.ua IT Dpt., I.B.S. LLC GMT+2 (EET)
On Tue, Jun 27, 2017 at 01:04:38AM -2100, Zeus Panchenko wrote:
Subject: [Q] can I replicate several branches to the same slave from one master?
on master I see: consumer state is newer than provider on slave: LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform
so ... what is wrong here?
I suspect part of the trouble is that you have two syncrepl clauses using the same search base on the same master. The timestamps are likely to be stored in the same place, causing a clash.
One definite error is that all three clauses are labelled 'rid=123'. They should all have different numbers.
Try fixing the RIDs - use small numbers, all different. The exact values are not important. Also try commenting out the second syncrepl clause until you have the others working properly. You should be able to merge the first and second clauses as they share a search-base.
You may also need to put ACLs on the accesslog database.
Andrew
- ---[ master configuration quotation start ]---------------------------
... access to dn.children="dc=example" by dn.exact="uid=replABC,ou=repl,dc=example" read by * break
# syncprov specific indexing index entryCSN eq index entryUUID eq
overlay syncprov syncprov-checkpoint 50 10 syncprov-sessionlog 100
overlay accesslog logdb cn=example-accesslog logops writes logold (objectclass=*) index default eq
### Accesslog DB database mdb maxsize 1073741824 suffix cn=example-accesslog rootdn "cn=root,cn=example-accesslog" rootpw *** directory "/var/db/openldap-data/example-accesslog"
index default eq index entryCSN,objectClass,reqEnd,reqResult,reqStart
overlay syncprov syncprov-nopresent TRUE syncprov-reloadhint TRUE ...
---[ master configuration quotation end ]---------------------------
---[ slave configuration quotation start ]----------------------------
syncrepl rid=123 provider=ldap://master.example:389 starttls=critical searchbase="dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" filter="(|(&(objectClass=authorizedServiceObject)(objectClass=mailutilsAccount)(authorizedService=mail@foo.bar)))" attrs="cn,entry,entryCSN,entryUUID,o,uid,uidNumber,gidNumber,gecos,homeDirectory,loginShell,userPassword,creatorsName,createTimestamp,modifiersName,modifyTimestamp,mail,rfc822MailMember,sn,authorizedService,mu-mailBox" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog
syncrepl rid=123 provider=ldap://master.example:389 starttls=critical searchbase="dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" filter="(&(objectClass=authorizedServiceObject)(authorizedService=xmpp@foo.bar))" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog
syncrepl rid=123 provider=ldap://master.example:389 starttls=critical searchbase="ou=ABC,ou=Sendmail,dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog
On Thu, Jun 29, 2017 at 03:47:07PM +0100, Andrew Findlay wrote:
I suspect part of the trouble is that you have two syncrepl clauses using the same search base on the same master. The timestamps are likely to be stored in the same place, causing a clash.
One definite error is that all three clauses are labelled 'rid=123'. They should all have different numbers.
As it happens, Quanah has just replied to a question with a very similar issue. See message below, and also the ITS: http://www.openldap.org/its/index.cgi/Software%20Bugs?id=8100;selectid=8100
... so you should also make at least one change to data on the master node so that the syncrepl process has something to do.
Andrew
On Tue, Jun 27, 2017 at 01:55:34PM -0700, Quanah Gibson-Mount wrote:
Date: Tue, 27 Jun 2017 13:55:34 -0700 From: Quanah Gibson-Mount quanah@symas.com To: btb btb@bitrate.net, openldap-technical@openldap.org Subject: Re: mmr pair stops replicating: "consumer state is newer than provider" Sender: openldap-technical openldap-technical-bounces@openldap.org
--On Tuesday, June 27, 2017 5:35 PM -0400 btb btb@bitrate.net wrote:
On 6/27/17 10:27 AM, Quanah Gibson-Mount wrote:
--On Tuesday, June 27, 2017 10:37 AM -0400 btb btb@bitrate.net wrote:
i'm using 2.4.44 on freebsd, built from ports. i can provide any config details etc - i just didn't want to inundate the post with guesses on detail that might not be relevant.
What is your accesslog purge setting? Do you have long periods of time with no write activity?
there are some extended periods of time with no write activity, yes.
That's one form of a known issue then with using accesslog (ITS#8100). I've made a suggestion on how it could be fixed, and Howard agreed that would be the correct solution. Just need the fix. :)
In the meantime, you can set up a cronjob that does a modify once a day on some object that doesn't really do anything, like if you had:
dn: cn=someobject,dc... objectClass: ... cn: someobject description: blah
you could have a job that does: dn: cn=someobject,dc... changetype: modify replace: description description: blah
So it in effect does nothing, but it keeps an active change in the accesslog alive.
Basically what happens with the accesslog empty is that it'll end up generating its own new contextCSN that differs for that server than the one stored in the rootDB, and will be /newer/ than it as well, which is why you get that message. You can also fix the problem simply by doing a modify on each master, and it'll reset the contextCSNs and things will flow (i.e., no need to do a dump/reload, etc).
--Quanah
--
Quanah Gibson-Mount Product Architect Symas Corporation Packaged, certified, and supported LDAP solutions powered by OpenLDAP: http://www.symas.com
Andrew Findlay andrew.findlay@skills-1st.co.uk wrote:
Try fixing the RIDs - use small numbers, all different. The exact values are not important. Also try commenting out the second syncrepl clause until you have the others working properly. You should be able to merge the first and second clauses as they share a search-base.
I did both of them, now slave configuration looks this way:
---[ slave configuration quotation start ]---------------------------- syncrepl rid=0 provider=ldap://master.example:389 starttls=critical searchbase="ou=ABC,ou=Sendmail,dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog
syncrepl rid=1 provider=ldap://master.example:389 starttls=critical searchbase="ou=People,dc=example" bindmethod=simple binddn="uid=replABC,ou=repl,dc=example" credentials="***" filter="(&(objectClass=authorizedServiceObject)(|(authorizedService=mail@foo.bar)(authorizedService=xmpp@foo.bar)))" attrs="cn,entry,entryCSN,entryUUID,o,uid,uidNumber,gidNumber,gecos,homeDirectory,loginShell,userPassword,creatorsName,createTimestamp,modifiersName,modifyTimestamp,mail,rfc822MailMember,sn,authorizedService,mu-mailBox" tls_cacert=/usr/local/etc/openldap/ssl/ca.crt tls_cert=/usr/local/etc/openldap/ssl/ABC.crt tls_key=/usr/local/etc/openldap/ssl/ABC.key tls_reqcert=try type=refreshAndPersist retry="60 +" logbase="cn=example-accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" syncdata=accesslog ---[ slave configuration quotation end ]----------------------------
I separated rid-s and even searchbases, but I still can see complains in slapd.log file, though now it is only rid=0 which is complained on, not both of them ...
---[ slave slapd.log quotation start ]-------------------------------- Jun 29 22:45:30 ABC slapd[12593]: do_syncrep2: rid=000 LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform Jun 29 22:45:30 ABC slapd[12593]: do_syncrep2: rid=000 (53) Server is unwilling to perform Jun 29 22:45:30 ABC slapd[12593]: do_syncrepl: rid=000 rc -2 retrying ---[ slave slapd.log quotation end ]--------------------------------
You may also need to put ACLs on the accesslog database.
is it something like this?
access to dn.children="cn=example-accesslog" by dn.children="ou=repl,dc=example" read by * break
but is not the fact that one replica working confirms, that replication is allowed and I can see the changes for the objects of rid=1
openldap-technical@openldap.org
-
Andrew Findlay -
Zeus Panchenko