https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #9 from mheyman@symas.com mheyman@symas.com --- (In reply to Ondřej Kuzník from comment #6)
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*.
And this gets to the heart of what "I NEED" (on behalf of the customer). For each update request handled by any producer the same update is performed on every consumer (replicated). I MAY have included irrelevant SRCH and CMP ops in my original work but the ADD, MOD, MODDN, and DEL changes are reflected and processed as received. I only suggest that those operations are invisible to all but those processing the SYNC level logs and deserve to be represented in the STATS level log as a courtesy to the users of simplified log reduction packages like SPLUNK and DATA DOG..
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.
This feels a lot like quibbling. I see what I'm trying to get promoted out of the SYNC log to the STATS log clearly in the SYNC log.
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.
In spite of the enormous value of the cn=monitor counters they are largely ignored by the tools used by customers. AWS has made no effort to add them to Cloudwatch and we, by offering our Telegraf/Prometheus work to them will at least take a step to showing them what SHOULD be done to support our OpenLDAP customers using their platform.
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.
For the reasons above about the lack of actual customer use of cn=monitor I would respond with NO. cn=monitor is only valuable processed into a time-series database and through analysis tools like Grafana and Prometheus. And it lacks information like the etime (already hidden in the SYNC log) and rid from which the update was replicated.
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
Right ... that was actually an addition we made at least partially to earlier suggestions/pressure from my requests. No?
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
At no time did I ask for that.
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">
Or that.
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">
I wonder what the producer would be searching for directly via the replication process. I was under the impression this was part of something like delta-sync and not in reference to recording the occurence of an update replicated down. I would be happy to better understand how this fits such that it could/should/would be part of what I think the customer wants/needs.
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">
See previous comment about search in the SYNC information log.
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.
I hope taking all but the actual updates as requested through the original producer off the table it is less of a firehose and more reasonable.
Regards,
Marty