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