https://bugs.openldap.org/show_bug.cgi?id=10293
Issue ID: 10293 Summary: Log operations generated by syncrepl at STATS level Product: OpenLDAP Version: unspecified Hardware: All OS: All Status: UNCONFIRMED Keywords: needs_review Severity: normal Priority: --- Component: slapd Assignee: bugs@openldap.org Reporter: nivanova@symas.com Target Milestone: ---
Similarly to how incoming operations are logged, operations created by syncrepl should be logged as well.
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #1 from Quanah Gibson-Mount quanah@openldap.org --- Why? we already have "sync" log level for this.
https://bugs.openldap.org/show_bug.cgi?id=10293
Quanah Gibson-Mount quanah@openldap.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |DUPLICATE Status|UNCONFIRMED |RESOLVED Keywords|needs_review |
--- Comment #2 from Quanah Gibson-Mount quanah@openldap.org ---
*** This issue has been marked as a duplicate of issue 9886 ***
https://bugs.openldap.org/show_bug.cgi?id=10293
Quanah Gibson-Mount quanah@openldap.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |VERIFIED
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #3 from mheyman@symas.com mheyman@symas.com --- The current implementation of syncrepl operation logging should be updated to make the logging outut formatted the same as normal operations. Customers using data reduction tools like Splunk and DataDog expect regular and easily processed formats and this implementation is neither. Furthermore the splitting of the name of the verb being sent and the etime makes processing complex in geneeral.
To this end I asked @nivanova to to an implementation. It was completed and demonstrates the attributes I asked for. It would dramatically simplify the postprocessing of logs to better understand the overall load on consumer instances.
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #4 from Ondřej Kuzník ondra@mistotebe.net --- On Wed, Apr 09, 2025 at 08:26:06PM +0000, openldap-its@openldap.org wrote:
The current implementation of syncrepl operation logging should be updated to make the logging outut formatted the same as normal operations. Customers using data reduction tools like Splunk and DataDog expect regular and easily processed formats and this implementation is neither. Furthermore the splitting of the name of the verb being sent and the etime makes processing complex in general.
Hi Marty, before I go into specifics, what are you trying to measure/track and what sorts of insights are you trying to gain? Or if you think that's easier, maybe you want to provide an actual situation when it would have been useful? But that's the sort of things we'll need to sort first to get any changes going.
I would prefer we restart with the above and you can stop reading here.
If you do want to keep reading the below, remember that I have to take what you request at face value (and assume that you're talking about consumer logging only). If what you said and what you meant were different, you will certainly disagree with the rest of my response.
Most of syncrepl handling is considered internal for a reason, its internal searches are definitely nothing like a "Search", even modifications/adds/renames rarely correspond to a "Modify"/"Add"/... not least because the target and a large amount of context are different enough from the occasion they are initiated by a client and certainly not in line what one would expect to see at "stats" loglevel. This is the crux of why Nadya's MR!738[0] was not acceptable.
Also when you mention etime and it being "split" from the "verb", it rings similar alarm bells. The etime logged as a result of ITS#9886 is a different beast than a client initiated operation, it is the time to "make progress", that is: completely process a single message we received from the provider. Quite often this corresponds to multiple backend operations, it is not even rare that it corresponds to many "modifications" in the usual sense.
To make things more complicated, each replica only has a local view of the situation so many things are only ever observable by correlating events from across the cluster. Which is why I'm suggesting we pick a model incident and see what we can do to make it more tractable.
[0]. https://git.openldap.org/openldap/openldap/-/merge_requests/738
Regards,
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #5 from mheyman@symas.com mheyman@symas.com --- 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. 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). 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. 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.
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,
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #7 from mheyman@symas.com mheyman@symas.com ---
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*.
To remind others: in the sylog project and the ollrpt project on our gitlab instance I looked for lines whose bodies began with:
syncrepl_message_to_op: rid=002 be_modify
and created a pseudo-request. In `ollrpt` I added artificial "tag" values. I created a record in my temporary file(s) were used and included these pseudo-request counts in the summary report. `ollrpt` is the better of the two for this. I asked @nivanova to produce, in the STATS log a record with RID, tag, etime, etc. which she did and I reviewed the output. It would simplify log reduction and feed a reporting tool we use extensively to judge system activity. Similar reports have been done with mtail as I remember, gathering these pseudo-requests and their etimes and merging them internally (as COULD be done in `ollrpt`. The original ask was to merge @nivanova's work at least in a test build to evaluate and consider shipping as an improvement in STATS level reporting.
I am well aware that syncrepl is complex and much of what has been mentioned implies I was asking for much more which I was not.
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #8 from Ondřej Kuzník ondra@mistotebe.net --- On Tue, Aug 19, 2025 at 05:46:07PM +0000, openldap-its@openldap.org wrote:
To remind others: in the sylog project and the ollrpt project on our gitlab instance I looked for lines whose bodies began with:
syncrepl_message_to_op: rid=002 be_modifyand created a pseudo-request. In `ollrpt` I added artificial "tag" values. I created a record in my temporary file(s) were used and included these pseudo-request counts in the summary report.
Except this type of log message was never intended to be meaningful for performance/result tracking etc. Even if it was, there is a fair amount of processing that has no equivalent to these that you would lose out on.
`ollrpt` is the better of the two for this. I asked @nivanova to produce, in the STATS log a record with RID, tag, etime, etc. which she did and I reviewed the output.
And they pretended that anything that reached out to the overlay stack was a request, most egregiously the *internal* searches/questions which was beyond unacceptable. Quanah closed the MR before I managed to on these grounds, so I outlined that in a previous comment here.
These are not requests, they are internal work items whose timings have no relation to what is actually happening. Again, if we did *this* you'd either miss a large proportion of actual time or be double-counting making the "stats" completely bogus.
Take a configuration with a unique overlay, autogroup and ppolicy for an analogy. By the logic you proposed their own (interleaving!) "sub-requests" should also be reported and counted? How would this work if you still have the final result and its etime on top of it?
It would simplify log reduction and feed a reporting tool we use extensively to judge system activity. Similar reports have been done with mtail as I remember, gathering these pseudo-requests and their etimes and merging them internally (as COULD be done in `ollrpt`. The original ask was to merge @nivanova's work at least in a test build to evaluate and consider shipping as an improvement in STATS level reporting.
I am well aware that syncrepl is complex and much of what has been mentioned implies I was asking for much more which I was not.
Please engage with the suggestions (two) I outlined in my comment from yesterday which deals with all of the above *and* would actually simplify your "log reduction". To repeat, there are no actual MODIFY/DELETE/RENAME requests received from the provider, we get a message that we interpret based on the contents of our own DB, resulting in 0 or more probes and actions and the proposals account for this giving you the "real" cost as well.
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
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #10 from Ondřej Kuzník ondra@mistotebe.net --- On Wed, Nov 19, 2025 at 05:05:03PM +0000, openldap-its@openldap.org wrote:
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..
Hi Marty, I'm trying to say that in syncrepl, those operations *do not exist*. syncrepl is a search, you only get entries and a few other types of messages, all outlined in what you responded to below. There are no ADD/MOD/DEL/MODDN changes as such or they're already noted as such in what I mentioned. (There is a better explanation nearer the end of this message.)
What processing happens on the consumer to adapt their own database based on the information just isn't traceable the way you ask for. However I do believe that the proposal delivers pretty much what you need even if it doesn't look like what you expected.
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.
Sure, you don't want cn=monitor, noted.
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.
Please reread the proposal as it was written: as the syncrepl search unfolds, there are certain types of messages the consumer receives from the provider. The proposal lists all of them, outlines their purpose (or you can watch my last LDAPCon talk explaining the protocol if you want to see how it all fits together) and suggests corresponding message to show up in the log.
That way all replication related work gets counted for its processing cost which is what I understand you're asking for without risks of double-counting (making the exercise moot) or leaking irrelevant details. One message = one line in the log. And before you seize on this again, 90% of the time one message = one update on the consumer, but it could be anything between 0 (relatively common) and an unbounded number of tasks some of which are entry updates in ways that seemingly have no relation to the message that was received.
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.
The provider receives a search operation. Always, that's what the replication protocol is modeled on. So yes, the provider searches for what the consumer asked for, taking into account that if an entry could not have changed based on what the consumer said, it doesn't need to be sent again and vice versa. If you look at it this way, you'll see why all the above and below exist and would make sense logging since any of them could trigger vast changes to the replica.
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.
And again, there are no updates sent to the consumer, it's all just a "special search request" on the protocol level. It's a consumer's job to make sense of it however it wants.
Regards,
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #11 from mheyman@symas.com mheyman@symas.com --- Noted. Will find representative logs to extract examples of the entries seen in SYNC logs from consumers that you feel mislead me into my conclusions that underly my continuing pursuit of technical clarity on this issue. At the moment I have higher priorities than even this.
-- Marty
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #12 from mheyman@symas.com mheyman@symas.com --- (In reply to mheyman@symas.com from comment #11)
Noted. Will find representative logs to extract examples of the entries seen in SYNC logs from consumers that you feel mislead me into my conclusions that underly my continuing pursuit of technical clarity on this issue. At the moment I have higher priorities than even this.
-- Marty
In this context, I extracted the following line from a log from Slave-1A at Vitality as an example. Please help me understand what I am supposed to take away from this line that doesn't indicate that the syncrepl process is handling modification of something. --- 2025-01-13T12:28:44.007990+00:00 ip-10-105-13-212 slapd[54734]: syncrepl_message_to_op: rid=001 be_modify uid=refer_mgr,ou=specialusers,dc=vitality,dc=co,dc=uk (0) --- Thanks.
-- Marty
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #13 from Ondřej Kuzník ondra@mistotebe.net --- Created attachment 1097 --> https://bugs.openldap.org/attachment.cgi?id=1097&action=edit Proposed change to the STATS logs
https://bugs.openldap.org/show_bug.cgi?id=10293
--- Comment #14 from Ondřej Kuzník ondra@mistotebe.net --- On Thu, Nov 20, 2025 at 07:58:35PM +0000, openldap-its@openldap.org wrote:
In this context, I extracted the following line from a log from Slave-1A at Vitality as an example. Please help me understand what I am supposed to take away from this line that doesn't indicate that the syncrepl process is handling modification of something.
2025-01-13T12:28:44.007990+00:00 ip-10-105-13-212 slapd[54734]: syncrepl_message_to_op: rid=001 be_modify uid=refer_mgr,ou=specialusers,dc=vitality,dc=co,dc=uk (0)
I have put the patch up as a merge request here: https://git.openldap.org/openldap/openldap/-/merge_requests/821
As an example, the log message above might look like this instead:
2025-01-13T12:28:44.007990+00:00 ip-10-105-13-212 slapd[54734]: rid=001 SYNC ENTRY dn="uid=refer_mgr,ou=specialusers,dc=vitality,dc=co,dc=uk" state=1 cookie=20250113122000.654321Z#000000#001#000000 etime=0.123456 result=processed
As proposed, etime is the time it took from decoding the message (entry in this case) to the point it was processed and any changes effected.
Regards,
-
openldap-its＠openldap.org