accesslog contextcsn isn't always updated - openldap-technical

25 Aug 2017


      hi, i am seeing a symptom where the accesslog contextcsn is not always 
updated when a new entry is added to the accesslog.  i have a test setup 
[config is below], with a content database using the accesslog and 
syncprov overlays, and an accesslog database using the syncprov overlay. 
  for the purposes of testing, i'm not using it as a provider for any 
consumers.  just running by itself, and watching its behavior.
when a modification is made to an entry in the content db, the 
contextcsn value for the content db is always updated, and a new entry 
is always added to the accesslog db.  but when the accesslog db gets a 
new entry, the accesslog contextcsn does not always update to match the 
new entry [see example below].  ldap_accesslog_noop is just a small 
shell script which updates the info attribute for an entry.
it's somewhat anecdotal, but there may be a timing factor involved.  if 
there is no activity for a little while [as little as a few minutes, 
sometimes], then a modification performed, that does not update the 
accesslog contextcsn.  but if subsequent modifications are done within a 
few moments, it then eventually updates the accesslog contextcsn 
correctly, typically as of the second modification, but sometimes the 
third.  if modifications then continue, with little delay between them, 
then the contextcsn seems to stay consistently up to date.  if activity 
then stops, and some time passes as before, the symptom reappears.
this is version 2.4.44 on freebsd 10.3-release, built from ports.
i'm hoping someone can offer some guidance on how to troubleshoot this 
further, or what i might be doing wrong.  i can provide more config 
details, logs, debugging ,etc., if needed.
apologies for the long collections of details following, and thanks!
###### first mod, after some time of inactivity: ######
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170825225855.866010Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503221460
entryCSN: 20170825225855.866010Z#000000#001#000000
...
./ldap_accesslog_noop
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503717700
entryCSN: 20170826032140.674259Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b dc=example,dc=com -s base contextcsn
dn: dc=example,dc=com
contextCSN: 20170826032140.674259Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 
(reqdn=uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com) 
entrycsn
dn: reqStart=20170825034142.000004Z,cn=accesslog2
entryCSN: 20170825034142.304465Z#000000#001#000000
dn: reqStart=20170825034147.000004Z,cn=accesslog2
entryCSN: 20170825034147.248214Z#000000#001#000000
dn: reqStart=20170825034238.000004Z,cn=accesslog2
entryCSN: 20170825034238.430123Z#000000#001#000000
dn: reqStart=20170825034239.000004Z,cn=accesslog2
entryCSN: 20170825034239.815833Z#000000#001#000000
dn: reqStart=20170825034320.000004Z,cn=accesslog2
entryCSN: 20170825034320.198025Z#000000#001#000000
dn: reqStart=20170825034321.000004Z,cn=accesslog2
entryCSN: 20170825034321.767124Z#000000#001#000000
dn: reqStart=20170825225347.000004Z,cn=accesslog2
entryCSN: 20170825225347.344528Z#000000#001#000000
dn: reqStart=20170825225849.000007Z,cn=accesslog2
entryCSN: 20170825225849.109615Z#000000#001#000000
dn: reqStart=20170825225855.000007Z,cn=accesslog2
entryCSN: 20170825225855.866010Z#000000#001#000000
dn: reqStart=20170826032140.000007Z,cn=accesslog2
entryCSN: 20170826032140.674259Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170825225855.866010Z#000000#001#000000
###### second mod, a few seconds later: ######
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w 
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170825225855.866010Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503717700
entryCSN: 20170826032140.674259Z#000000#001#000000
...
./ldap_accesslog_noop
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503717721
entryCSN: 20170826032201.236788Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b dc=example,dc=com -s base contextcsn
dn: dc=example,dc=com
contextCSN: 20170826032201.236788Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 
(reqdn=uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com) 
entrycsn
dn: reqStart=20170825034142.000004Z,cn=accesslog2
entryCSN: 20170825034142.304465Z#000000#001#000000
dn: reqStart=20170825034147.000004Z,cn=accesslog2
entryCSN: 20170825034147.248214Z#000000#001#000000
dn: reqStart=20170825034238.000004Z,cn=accesslog2
entryCSN: 20170825034238.430123Z#000000#001#000000
dn: reqStart=20170825034239.000004Z,cn=accesslog2
entryCSN: 20170825034239.815833Z#000000#001#000000
dn: reqStart=20170825034320.000004Z,cn=accesslog2
entryCSN: 20170825034320.198025Z#000000#001#000000
dn: reqStart=20170825034321.000004Z,cn=accesslog2
entryCSN: 20170825034321.767124Z#000000#001#000000
dn: reqStart=20170825225347.000004Z,cn=accesslog2
entryCSN: 20170825225347.344528Z#000000#001#000000
dn: reqStart=20170825225849.000007Z,cn=accesslog2
entryCSN: 20170825225849.109615Z#000000#001#000000
dn: reqStart=20170825225855.000007Z,cn=accesslog2
entryCSN: 20170825225855.866010Z#000000#001#000000
dn: reqStart=20170826032140.000007Z,cn=accesslog2
entryCSN: 20170826032140.674259Z#000000#001#000000
dn: reqStart=20170826032201.000007Z,cn=accesslog2
entryCSN: 20170826032201.236788Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170825225855.866010Z#000000#001#000000
###### third mod, a few seconds after second mod: ######
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w 
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170825225855.866010Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503717721
entryCSN: 20170826032201.236788Z#000000#001#000000
...
./ldap_accesslog_noop
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503717758
entryCSN: 20170826032238.330244Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b dc=example,dc=com -s base contextcsn
dn: dc=example,dc=com
contextCSN: 20170826032238.330244Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 
(reqdn=uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com) 
entrycsn
dn: reqStart=20170825034142.000004Z,cn=accesslog2
entryCSN: 20170825034142.304465Z#000000#001#000000
dn: reqStart=20170825034147.000004Z,cn=accesslog2
entryCSN: 20170825034147.248214Z#000000#001#000000
dn: reqStart=20170825034238.000004Z,cn=accesslog2
entryCSN: 20170825034238.430123Z#000000#001#000000
dn: reqStart=20170825034239.000004Z,cn=accesslog2
entryCSN: 20170825034239.815833Z#000000#001#000000
dn: reqStart=20170825034320.000004Z,cn=accesslog2
entryCSN: 20170825034320.198025Z#000000#001#000000
dn: reqStart=20170825034321.000004Z,cn=accesslog2
entryCSN: 20170825034321.767124Z#000000#001#000000
dn: reqStart=20170825225347.000004Z,cn=accesslog2
entryCSN: 20170825225347.344528Z#000000#001#000000
dn: reqStart=20170825225849.000007Z,cn=accesslog2
entryCSN: 20170825225849.109615Z#000000#001#000000
dn: reqStart=20170825225855.000007Z,cn=accesslog2
entryCSN: 20170825225855.866010Z#000000#001#000000
dn: reqStart=20170826032140.000007Z,cn=accesslog2
entryCSN: 20170826032140.674259Z#000000#001#000000
dn: reqStart=20170826032201.000007Z,cn=accesslog2
entryCSN: 20170826032201.236788Z#000000#001#000000
dn: reqStart=20170826032238.000007Z,cn=accesslog2
entryCSN: 20170826032238.330244Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170826032238.330244Z#000000#001#000000
###### fourth mod, after ~5 minutes have passed ######
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170826032238.330244Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503717758
entryCSN: 20170826032238.330244Z#000000#001#000000
...
./ldap_accesslog_noop
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com 
-s base info entrycsn
dn: 
uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com
info: 1503718313
entryCSN: 20170826033153.554034Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b dc=example,dc=com -s base contextcsn
dn: dc=example,dc=com
contextCSN: 20170826033153.554034Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 
(reqdn=uid=accesslog_noop,ou=replication,ou=system,ou=accounts,dc=example,dc=com) 
entrycsn
dn: reqStart=20170825034142.000004Z,cn=accesslog2
entryCSN: 20170825034142.304465Z#000000#001#000000
dn: reqStart=20170825034147.000004Z,cn=accesslog2
entryCSN: 20170825034147.248214Z#000000#001#000000
dn: reqStart=20170825034238.000004Z,cn=accesslog2
entryCSN: 20170825034238.430123Z#000000#001#000000
dn: reqStart=20170825034239.000004Z,cn=accesslog2
entryCSN: 20170825034239.815833Z#000000#001#000000
dn: reqStart=20170825034320.000004Z,cn=accesslog2
entryCSN: 20170825034320.198025Z#000000#001#000000
dn: reqStart=20170825034321.000004Z,cn=accesslog2
entryCSN: 20170825034321.767124Z#000000#001#000000
dn: reqStart=20170825225347.000004Z,cn=accesslog2
entryCSN: 20170825225347.344528Z#000000#001#000000
dn: reqStart=20170825225849.000007Z,cn=accesslog2
entryCSN: 20170825225849.109615Z#000000#001#000000
dn: reqStart=20170825225855.000007Z,cn=accesslog2
entryCSN: 20170825225855.866010Z#000000#001#000000
dn: reqStart=20170826032140.000007Z,cn=accesslog2
entryCSN: 20170826032140.674259Z#000000#001#000000
dn: reqStart=20170826032201.000007Z,cn=accesslog2
entryCSN: 20170826032201.236788Z#000000#001#000000
dn: reqStart=20170826032238.000007Z,cn=accesslog2
entryCSN: 20170826032238.330244Z#000000#001#000000
dn: reqStart=20170826033153.000007Z,cn=accesslog2
entryCSN: 20170826033153.554034Z#000000#001#000000
...
ldapsearch -xLLLH ldap://localhost/ -D uid=admin,dc=example,dc=com -w
xxxxxx -b cn=accesslog2 -s base contextcsn
dn: cn=accesslog2
contextCSN: 20170826032238.330244Z#000000#001#000000
###### configuration ######
dn: cn=config
objectClass: olcGlobal
cn: config
olcArgsFile: /var/run/openldap/slapd.args
olcLogLevel: stats sync
olcPasswordCryptSaltFormat: $6$rounds=8000$%.16s
olcPidFile: /var/run/openldap/slapd.pid
olcSaslSecProps: noanonymous
olcServerID: 1
olcTLSCACertificateFile: 
/usr/local/etc/pki/trusted_root_authorities/example_roo
  t_ca-cert.pem
olcTLSCertificateFile: /usr/local/etc/openldap/pki/dsa0.example.com-cert.pe
  m
olcTLSCertificateKeyFile: /usr/local/etc/openldap/pki/dsa0.example.com-key.
  pem
olcTLSVerifyClient: never
structuralObjectClass: olcGlobal
entryUUID: 5e961a2a-290d-1036-96af-778fc97ab8bc
creatorsName: cn=config
createTimestamp: 20161017233001Z
entryCSN: 20170520231408.133014Z#000000#001#000000
modifiersName: cn=config
modifyTimestamp: 20170520231408Z
dn: cn=module{0},cn=config
objectClass: olcModuleList
cn: module{0}
olcModulePath: /usr/local/libexec/openldap
olcModuleLoad: {0}back_monitor.la
olcModuleLoad: {1}back_mdb.la
olcModuleLoad: {2}nssov.la
olcModuleLoad: {3}ppolicy.la
olcModuleLoad: {4}refint.la
olcModuleLoad: {5}unique.la
olcModuleLoad: {6}constraint.la
olcModuleLoad: {7}memberof.la
olcModuleLoad: {8}dynlist.la
olcModuleLoad: {9}translucent.la
olcModuleLoad: {10}valsort.la
olcModuleLoad: {11}pw-sha2.la
olcModuleLoad: {12}syncprov.la
olcModuleLoad: {13}accesslog.la
structuralObjectClass: olcModuleList
entryUUID: 5e962542-290d-1036-96b0-778fc97ab8bc
creatorsName: cn=config
createTimestamp: 20161017233001Z
entryCSN: 20161017233001.558726Z#000000#001#000000
modifiersName: cn=config
modifyTimestamp: 20161017233001Z
[...]
dn: olcDatabase={4}mdb,cn=config
objectClass: olcDatabaseConfig
objectClass: olcMdbConfig
olcDatabase: {4}mdb
olcDbDirectory: /var/db/openldap-data/example.com
olcSuffix: dc=example,dc=com
olcAccess:: ezB9dG8gYXR0cnM9dXNlclBhc3N3b3JkCglieSBhbm9ueW1vdXMgYXV0aAoJYnkg
  c2VsZiA9eHcKCWJ5ICogbm9uZQ==
olcAccess:: ezF9dG8gKg0JYnkgc2VsZiB3cml0ZQ0JYnkgdXNlcnMgcmVhZA0JYnkgKiBub25l
olcRootDN: uid=admin,dc=example,dc=com
structuralObjectClass: olcMdbConfig
entryUUID: 4801edee-14ed-1037-9fb8-99e8705e53d3
creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
createTimestamp: 20170814033454Z
entryCSN: 20170814035744.555520Z#000000#001#000000
modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
modifyTimestamp: 20170814035744Z
dn: olcOverlay={0}syncprov,olcDatabase={4}mdb,cn=config
objectClass: olcSyncProvConfig
objectClass: olcOverlayConfig
objectClass: olcConfig
objectClass: top
olcOverlay: {0}syncprov
olcSpCheckpoint: 10 5
olcSpSessionlog: 500
olcSpReloadHint: TRUE
structuralObjectClass: olcSyncProvConfig
entryUUID: 198df6be-14ee-1037-9fbd-99e8705e53d3
creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
createTimestamp: 20170814034045Z
entryCSN: 20170814034045.759202Z#000000#001#000000
modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
modifyTimestamp: 20170814034045Z
dn: olcOverlay={1}accesslog,olcDatabase={4}mdb,cn=config
objectClass: olcAccessLogConfig
objectClass: olcOverlayConfig
objectClass: olcConfig
objectClass: top
olcOverlay: {1}accesslog
olcAccessLogDB: cn=accesslog2
olcAccessLogOps: writes
olcAccessLogPurge: 14+00:00 1+00:00
olcAccessLogSuccess: TRUE
structuralObjectClass: olcAccessLogConfig
entryUUID: 0a21a20c-14ee-1037-9fbc-99e8705e53d3
creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
createTimestamp: 20170814034019Z
entryCSN: 20170814034019.883417Z#000000#001#000000
modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
modifyTimestamp: 20170814034019Z
dn: olcDatabase={5}mdb,cn=config
objectClass: olcMdbConfig
objectClass: olcDatabaseConfig
objectClass: olcConfig
objectClass: top
olcDatabase: {5}mdb
olcDbDirectory: /var/db/openldap-data/accesslog2
olcSuffix: cn=accesslog2
olcRootDN: uid=admin,dc=example,dc=com
structuralObjectClass: olcMdbConfig
entryUUID: 16132114-14ec-1037-9fb7-99e8705e53d3
creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
createTimestamp: 20170814032620Z
entryCSN: 20170814034648.206981Z#000000#001#000000
modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
modifyTimestamp: 20170814034648Z
dn: olcOverlay={0}syncprov,olcDatabase={5}mdb,cn=config
objectClass: olcSyncProvConfig
objectClass: olcOverlayConfig
objectClass: olcConfig
objectClass: top
olcOverlay: {0}syncprov
olcSpNoPresent: TRUE
olcSpReloadHint: TRUE
structuralObjectClass: olcSyncProvConfig
entryUUID: e2927c2a-14ed-1037-9fbb-99e8705e53d3
creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
createTimestamp: 20170814033913Z
entryCSN: 20170814033913.514143Z#000000#001#000000
modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=com
modifyTimestamp: 20170814033913Z