#50350 389 DS error and access logging should be changed
Opened 4 months ago by firstyear. Modified 2 months ago

Issue Description

We have always maintained a very simple access log format, however that format is very limited in the information it displays - it's effectively an audit log, and provides insufficent data to allow effective issue analysis. Additionally, it can be hard to see the sequence and relationship of events, and worse, due to threading, many operations log messages are interleaved causing noise and confusion.

I propose that our logging structure for access be rewritten such that:

  • There is a "log" field on the operation structure.
  • Calls to slapi_log_access append to this operation structure log.
  • If the operation is internal with a parent operation, the log is "nested" into the parent.
  • If the operation is external or a top level operation, on completion of the operation the log structure is sent as a whole unit to the log system.
  • That the operation log structure is written in a single, structured block, to keep all needed debugging information local to the operation.

Not only does this already have performance benefits (no locking during operations to the log, no need to check log levels etc), it has many human benefits - all data for an operation are in a single coherent package, we can provide detailed and relevant information always, and it will make many aspects of debugging an diagnosis much easier to understand.

From this would would not only be able to have information at a highlevel about events like the current SRCH, BIND, RESULT messages, but we could include records of plugin timing, filter application, query optimisation and more, at very little cost to the logging overhead due to the packaged and coherent nature. It would help QE and support a lot, as well as our debugging.

https://pagure.io/389-ds-base/pull-request/50252#comment-85208


Metadata Update from @mreynolds:
- Custom field origin adjusted to None
- Custom field reviewstatus adjusted to None
- Issue set to the milestone: 1.4.2

4 months ago

Metadata Update from @firstyear:
- Issue assigned to firstyear

4 months ago

It would also be nice if the new logging could also report all requested controls (deref, pwpolicy, etc)

@mreynolds I agree. deref could create perforamce issue, having this info will accelerate diag

Login to comment on this ticket.

Metadata