[Date Prev][Date Next] [Chronological] [Thread] [Top]
null_callbacks after initial sync

To: openldap-software@openldap.org
Subject: null_callbacks after initial sync
From: Nick Geron <ngeron@corenap.com>
Date: Tue, 04 Mar 2008 11:20:17 -0600
User-agent: Thunderbird 2.0.0.9 (X11/20071210)
I'm working with a test mirror mode setup on 2.4.7 with db 4.5.20 and
seeing issues with SyncRepl.  Specifically, do_syncrepl fails with an
initial error 0x10 and subsequent 0x14, though at least one modification
is propagated.  To put another way:

*Systems using same ldif to populate and running nearly identical
slapd.conf files (serverID is the only variance).

1) start server 1
2) start server 2
3) add host attribute to posixAccount entry on s-1
4) attribute seen on s-2 but results in the following log
5) no other updates successful until server process restarted.

Mar  4 10:46:14 slapd[22999]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE
- REFRESH_DELETE
Mar  4 10:46:14 slapd[22999]: do_syncrep2:
cookie=rid=001,sid=002,csn=20080304164630.523962Z#000000#001#000000
Mar  4 10:46:19 slapd[22999]: conn=0 fd=25 ACCEPT from
IP=172.30.24.5:53140 (IP=0.0.0.0:389)
Mar  4 10:46:19 slapd[22999]: conn=0 op=0 BIND
dn="uid=syncrepl,ou=ldap,dc=example,dc=com" method=128
Mar  4 10:46:19 slapd[22999]: conn=0 op=0 BIND
dn="uid=syncrepl,ou=ldap,dc=example,dc=com" mech=SIMPLE ssf=0
Mar  4 10:46:19 slapd[22999]: conn=0 op=0 RESULT tag=97 err=0 text=
Mar  4 10:46:19 slapd[22999]: conn=0 op=1 SRCH base="cn=accesslog"
scope=2 deref=0 filter="(reqResult=0)"
Mar  4 10:46:19 slapd[22999]: conn=0 op=1 SRCH attr=reqDN reqType reqMod
reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN
Mar  4 10:46:45 slapd[22999]: conn=1 fd=26 ACCEPT from
IP=172.16.71.134:65251 (IP=0.0.0.0:389)
Mar  4 10:46:45 slapd[22999]: conn=1 op=0 BIND
dn="cn=manager,dc=example,dc=com" method=128
Mar  4 10:46:45 slapd[22999]: conn=1 op=0 BIND
dn="cn=manager,dc=example,dc=com" mech=SIMPLE ssf=0
Mar  4 10:46:45 slapd[22999]: conn=1 op=0 RESULT tag=97 err=0 text=
Mar  4 10:46:45 slapd[22999]: conn=1 op=1 SRCH base="cn=accesslog"
scope=2 deref=0 filter="(objectClass=*)"
Mar  4 10:46:45 slapd[22999]: conn=1 op=1 SEARCH RESULT tag=101 err=0
nentries=2 text=
Mar  4 10:46:45 slapd[22999]: conn=1 op=2 UNBIND
Mar  4 10:46:45 slapd[22999]: conn=1 fd=26 closed
Mar  4 10:46:45 slapd[22999]: conn=2 fd=26 ACCEPT from
IP=192.168.15.32:45137 (IP=0.0.0.0:389)
Mar  4 10:46:45 slapd[22999]: conn=2 fd=26 closed (connection lost)
Mar  4 10:47:07 slapd[22999]: do_syncrep2:
cookie=rid=001,sid=002,csn=20080304164728.385080Z#000000#001#000000
Mar  4 10:47:07 slapd[22999]: syncrepl_message_to_op: rid=001 be_modify
uid=tguy,ou=employees,ou=people,dc=example,dc=com (0)
Mar  4 10:47:07 slapd[22999]: null_callback : error code 0x10
Mar  4 10:47:07 slapd[22999]: syncrepl_updateCookie: rid=001 be_modify
failed (16)
Mar  4 10:47:07 slapd[22999]: do_syncrepl: rid=001 retrying
Mar  4 10:47:17 slapd[22999]: null_callback : error code 0x14
Mar  4 10:47:17 slapd[22999]: syncrepl_message_to_op: rid=001 be_modify
uid=tguy,ou=employees,ou=people,dc=example,dc=com (20)
**** LAST 3 LINES REPEATED THEREAFTER ****

A little more verbose output on the consumer side shows some problem
modifying the underlying DB, but I can't see an obvious where to go from
here. 

Mar  4 10:57:10 slapd[23057]: =>do_syncrepl rid=001
Mar  4 10:57:10 slapd[23057]: =>do_syncrep2 rid=001
Mar  4 10:57:10 slapd[23057]: >>> dnPrettyNormal:
<uid=tguy,ou=employees,ou=people,dc=example,dc=com>
Mar  4 10:57:10 slapd[23057]: <<< dnPrettyNormal:
<uid=tguy,ou=employees,ou=people,dc=example,dc=com>,
<uid=tguy,ou=employees,ou=people,dc=example,dc=com>
Mar  4 10:57:10 slapd[23057]: >>> dnPretty: <cn=Manager,dc=example,dc=com>
Mar  4 10:57:10 slapd[23057]: <<< dnPretty: <cn=Manager,dc=example,dc=com>
Mar  4 10:57:10 slapd[23057]: >>> dnNormalize:
<cn=Manager,dc=example,dc=com>
Mar  4 10:57:10 slapd[23057]: <<< dnNormalize:
<cn=manager,dc=example,dc=com>
Mar  4 10:57:10 slapd[23057]: => bdb_entry_get: ndn:
"uid=tguy,ou=employees,ou=people,dc=example,dc=com"
Mar  4 10:57:10 slapd[23057]: => bdb_entry_get: oc: "(null)", at: "(null)"
Mar  4 10:57:10 slapd[23057]:
bdb_dn2entry("uid=tguy,ou=employees,ou=people,dc=example,dc=com")
Mar  4 10:57:10 slapd[23057]: => bdb_entry_get: found entry:
"uid=tguy,ou=employees,ou=people,dc=example,dc=com"
Mar  4 10:57:10 slapd[23057]: bdb_entry_get: rc=0
Mar  4 10:57:10 slapd[23057]: hdb_modify:
uid=tguy,ou=employees,ou=people,dc=example,dc=com
Mar  4 10:57:10 slapd[23057]:
bdb_dn2entry("uid=tguy,ou=employees,ou=people,dc=example,dc=com")
Mar  4 10:57:10 slapd[23057]: bdb_modify_internal: 0x00000a2b:
uid=tguy,ou=employees,ou=people,dc=example,dc=com
Mar  4 10:57:10 slapd[23057]: <= acl_access_allowed: granted to database
root
Mar  4 10:57:10 slapd[23057]: bdb_modify_internal: delete host
Mar  4 10:57:10 slapd[23057]: bdb_modify_internal: 16 modify/delete:
host: no such value
Mar  4 10:57:10 slapd[23057]: hdb_modify: modify failed (16)
Mar  4 10:57:10 slapd[23057]: send_ldap_result: conn=-1 op=0 p=0
Mar  4 10:57:10 slapd[23057]: send_ldap_result: err=16 matched=""
text="modify/delete: host: no such value"
Mar  4 10:57:10 slapd[23057]: null_callback : error code 0x10
Mar  4 10:57:10 slapd[23057]: syncrepl_message_to_op: rid=001 be_modify
uid=tguy,ou=employees,ou=people,dc=example,dc=com (16)


Again, if multiple, successful writes are made to the 'primary' server
in the mirror, only the first makes it to the 'secondary.'  If the
second server is restarted, it retrieves all new edits as expected. 

Can someone elaborate on what bdb_modify_internal is trying to tell me? 

Please let me know if more information is required.

Thanks.


Slapd.conf

# Global Settings
#################

include         /etc/openldap/schema/core.schema
include         /etc/openldap/schema/cosine.schema
include         /etc/openldap/schema/nis.schema
include         /etc/openldap/schema/inetorgperson.schema
include         /etc/openldap/schema/sendmail.schema
include         /etc/openldap/schema/solaris.schema
include         /etc/openldap/schema/example.schema

pidfile         /var/run/openldap/slapd.pid
argsfile        /var/run/openldap/slapd.args
sizelimit       unlimited

# Loglevel
##########

loglevel        any

moduleload      /usr/local/libexec/openldap/back_hdb.la
moduleload      /usr/local/libexec/openldap/accesslog.la

# TLS/SSL
#########

TLSCipherSuite          HIGH:MEDIUM:+SSLv2
TLSCertificateFile      /etc/openldap/certs/ldap.example.com.crt
TLSCertificateKeyFile   /etc/openldap/certs/ldap.example.com.key
TLSCACertificateFile    /etc/openldap/certs/ca.crt
TLSVerifyClient         never

# Access log
############

database        bdb
suffix          cn=accesslog
directory       /var/lib/openldap-data/accesslog
rootdn          cn=Manager,cn=accesslog
rootpw         secret
index           default eq
index           reqStart,objectClass,entryCSN,reqResult eq
cachesize   3000
idlcachesize   9000

overlay syncprov
syncprov-nopresent TRUE
syncprov-reloadhint TRUE

# Primary DB Configuration 
##########################

database        hdb
suffix          "dc=example,dc=com"
rootdn          "cn=Manager,dc=example,dc=com"
rootpw          secret
directory       /var/lib/openldap-data/example.com
cachesize       3000
idlcachesize    9000

# Primary DB Indexes
####################

index           objectClass,entryUUID,entryCSN          eq
index           cn,sn,uid                               eq,sub,pres,approx
index           sendmailMTAMapName                      eq,pres
index           sendmailMTAMapValue                     eq
index           sendmailMTAKey                          eq,sub,pres
index           sendmailMTAAliasValue                   eq,pres
index           sendmailMTAClassName                    eq
index           sendmailMTAClassValue                   eq
index           exampleUserModifiable                   eq

# Primary DB SyncRepl
#####################

syncrepl  rid=1
        provider=ldap://ldap.example.com
        type=refreshAndPersist
        searchbase="dc=example,dc=com"
        bindmethod=simple
        binddn="uid=syncrepl,ou=ldap,dc=example,dc=com"
        credentials="syncpw"
        retry="10 +"
        schemachecking=off
        logbase="cn=accesslog"
        syncdata=accesslog
        logfilter="(reqResult=0)"

mirrormode on
serverID 2

# Primary DB Sync Provider
##########################

overlay syncprov
syncprov-checkpoint 10 1
syncprov-sessionlog 100

# Primary DB accesslog
######################

overlay accesslog
logdb cn=accesslog
logops writes
logsuccess TRUE
logpurge 07+00:00 01+00:00



# ACLs for Primary DB 
#####################

access to attrs=userPassword
  by anonymous auth
  by self write
  by dn="uid=syncrepl,ou=ldap,dc=example,dc=com" read
  by dn="uid=pam,ou=ldap,dc=example,dc=com" read
  by * none

access to dn.subtree="ou=employees,ou=people,dc=example,dc=com"
  by anonymous auth
  by self write
  by dn.regex="uid=[^,]+,ou=employees,ou=people,dc=example,dc=com" read
  by dn="uid=syncrepl,ou=ldap,dc=example,dc=com" read
  by dn="uid=pam,ou=ldap,dc=example,dc=com" read
  by * none

access to dn.subtree="ou=group,dc=example,dc=com"
  by dn.regex="uid=[^,]+,ou=employees,ou=people,dc=example,dc=com" read
  by dn="uid=syncrepl,ou=ldap,dc=example,dc=com" read
  by dn="uid=pam,ou=ldap,dc=example,dc=com" read

access to dn.subtree="ou=ldap,dc=example,dc=com"
  by anonymous auth
  by dn="uid=syncrepl,ou=ldap,dc=example,dc=com" read
  by dn="uid=pam,ou=ldap,dc=example,dc=com" read

access to dn="ou=sendmail,dc=example,dc=com"
  by ssf=112 dn.base="uid=sendmail,ou=ldap,dc=example,dc=com"   read
  by dn.regex="uid=[^,]+,ou=employees,ou=people,dc=example,dc=com" read
  by dn="uid=syncrepl,ou=ldap,dc=example,dc=com" read

access to dn.subtree="dc=example,dc=com"
  by dn="uid=syncrepl,ou=ldap,dc=example,dc=com" read
  by dn="uid=pam,ou=ldap,dc=example,dc=com" read
  by dn.regex="uid=[^,]+,ou=employees,ou=people,dc=example,dc=com" read

access to dn.base=""
  by * read
Follow-Ups:
- Re: null_callbacks after initial sync
  - From: "Chris G. Sellers" <chris.sellers@nitle.org>
Prev by Date: RE: Testing the state of replicates
Next by Date: RE: Testing the state of replicates
Index(es):
- Chronological
- Thread