[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
accesslog contextcsn isn't always updated
- To: openldap-technical@openldap.org
- Subject: accesslog contextcsn isn't always updated
- From: btb <btb@bitrate.net>
- Date: Fri, 25 Aug 2017 23:36:56 -0400
- Content-language: en-US
- Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=bitrate.net; s=default; t=1503718619; bh=KcIRKaaVg6q5ZX3SdIR3PBGgODb34M0r8R9El7pgOgc=; h=To:From:Subject:Date:From; b=WAe4ppG3h/m79sq3x/1S5G+3DlFgqnyByAM9/JEaZ8ZgXBaPt8hUDNbxuAJc9KudF D1WMmEl3H3uCHFep2mN5r2avXvMGEgwFZC0bpuuibWYE9NlYkouoI1ZgKlduuygNI0 qvmylTf/6nuHDhLJxYwGQz0cUqcDXL6401TZ0Apw=
- User-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:54.0) Gecko/20100101 Thunderbird/54.0
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