https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #6 from Ondřej Kuzník ondra@mistotebe.net --- On Mon, Aug 18, 2025 at 10:05:50PM +0000, openldap-its@openldap.org wrote:
The requirement is for STATistics (STAT level) records representing the activity on an instance of slapd that is initiated/processed because of `syncrepl` traffic initiated by a consumer (Master or Replica) via a syncrepl query. At a minimum it should report the "operations" performed by the relevant Provider (Master, by definition) and made available by `syncprov` for retrieval by consumers.
Hi Marty, on the consumer, we only see what is received not what provider performed. Even more so in a refresh. This matters and it's why I keep asking what you *need*.
It is important that the "operations" performed during refresh also be consistently represented in the STAT log as these represent work being done on the relevant server in support of achieving consistency of data through the replication mechanism(s).
There is no consistency, refresh (all forms), persist and delta are wildly different in what provider meant and what we do with it. We can still log what we *receive*, not each individual work item involved in dealing with the message. Especially in the context of what you say further on.
The requirement includes MUST make these records in general format to the existing STAT-level records for BIND, ADD, SRCH, etc. These records MAY be represented merely as RESULT (style) records as there is little to report about the start/receipt of the "operation".
The justification for this requirement is that the STAT(istics) level logging is expected to represent the actual load and performance on a server ... its representation of "local" load which is often quite different than the actual "load" on other servers in the cluster (RT3402 for example). And the difference is quite often found to be the operation of the replication mechanism(s). Without meeting the requirement above the end-user or support engineer has to study the SYNC level log records to understand the true "load" on the server.
You can and should observe true "load" through cn=monitor already - the average number of active workers (threads). Nothing will come close to this metric in terms of accuracy.
Based on the above I believe you're actually interested in the contribution that syncrepl consumers make to this true "load" and will interpret the rest accordingly.
Furthermore, the monitoring tools would be required to understand the more complex SYNC logging formats and content. Most customers rely at best on AWS Cloudwatch (a Grafana based system) and/or batch log reduction programs like SPLUNK and DataDog which lack the more complex processing capabilities to understand SYNC logging. The best of our customers have no idea what the total "load" being presented to their OpenLDAP servers and are unable to diagnose performance issues without it.
Instead of flooding the STATS level with yet another firehose of data, wouldn't exposing a cn=monitor counter like "total time spent on processing messages from this provider" be better? That's the exact contribution you're looking for, no expensive log processing needed *and* fairly easy to provide.
If not, let's be concrete then, have a look at the below and see if it covers what you're after. "etime=" are seconds since we started processing the message, so to the extent you consider current etime= logging to represent "load", it should too. There is no "hidden" processing time except overheads that would have been hidden from current STATS messages as well. And certainly no double-counting which your previous suggestions would have been prone to.
RFC4533 which we're processing defines the following message types (I won't touch on other replication protocols we support e.g. dirsync):
Intermediate "newcookie" message: rid=001 SYNC NEW_COOKIE cookie=<cookie value> etime=0.123
For a refreshDelete/refreshPresent Intermediate message: rid=012 SYNC REFRESH_DELETE refreshDone=0 cookie=<cookie value if sent> etime=0.012 rid=012 SYNC REFRESH_PRESENT refreshDone=0 cookie=<cookie value if sent> etime=0.012
For a syncIdSet (present/delete phase contents) Intermediate message: rid=123 SYNC ID_SET delete=0|1 cookie=<cookie value if sent> etime=0.234 result=<"processed"/"failed">
For a search entry message regardless of how we ended up interpreting it: rid=201 SYNC ENTRY dn="<dn as received>" state=<"state" field from the control: 0|1|2|3> cookie=<cookie value if sent> etime=0.123 result=<"processed"/"skipped"/"failed">
For a search result message (end of refreshOnly): rid=321 SYNC RESULT err=<resultCode as received> delete=0|1 cookie=<value if sent> etime=0.... result=<"processed"/"failed">
I believe this is a little too much information to put into the logs but this is what might fit the description above. It might also not be feasible to provide "result=skipped" messages and they might show "processed" instead, can't tell right now.
Regards,