search

389ds / 389-ds-base

The enterprise-class Open Source LDAP server for Linux
https://www.port389.org/
Other
210 stars 90 forks source link

RFE - improve unindexed search information in the access log #3192

Open 389-ds-bot opened 4 years ago

389-ds-bot commented 4 years ago

Cloned from Pagure issue: https://pagure.io/389-ds-base/issue/50133

Issue Description

When an unindexed search, or an unindexed search component, is used we log notes=A (for fully unindexed), or notes=U(unindexed filter component) in the access log.

Notes=U is the tricky one because it's not always "bad", but it should be investigated none the less.

One way to help troubleshoot/investigate notes=A/notes=U would be add more info to the message about what attributes in the filter were unindexed (and why? No index or id scan limit exceeded).

The format could be something like:

notes=U[<list of unindexed attributes>]
notes=U[objectclass(missing index), mail(exceeded id scan limit)]

Or even do a dictionary format for easier parsing by external tools:

notes=U{<dict of unindexed attributes>}
notes=U{objectclass: missing index, mail: exceeded id scan limit}

We could also add a new access logging level to trigger this extra info, but if there isn't much overhead to doing it then it should be logged by default (no special log level).

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2019-01-08 23:41:12

I think this looks great! This is exactly what I had in mind. My concern still is that in notes=U we still shouldn't list objectClass=* since that's intended to be unindexed, but this change would be a huge improvement for debugging performance issues :)

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2019-01-08 23:41:12

Metadata Update from @Firstyear:

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2019-01-10 17:55:42

Metadata Update from @mreynolds389:

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-02-26 16:52:42

Metadata Update from @mreynolds389:

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2020-07-21 17:44:52

Metadata Update from @mreynolds389:

mreynolds389 commented 1 year ago

@tbordaz - did your recent access log stats RFE satisfy this issue?

tbordaz commented 1 year ago

The RFE #3729 covers this need of index details but at a lower level.

3192 aims to report high level events like missing index or hitting a threshold.

3729 reports idlist information, then you need from those idlist to evaluate if a higher level event is hit. For example #3729 reports something like

[26/Jan/2023:16:45:11.496955496 +0100] conn=1 op=73 SRCH base="dc=example,dc=com" scope=2 filter="(cn=user_*)" attrs=ALL
[26/Jan/2023:16:45:11.498412335 +0100] conn=1 op=73 STAT read index: attribute=objectclass key(eq)=referral --> count 0
[26/Jan/2023:16:45:11.499350266 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=er_ --> count 24
[26/Jan/2023:16:45:11.500206733 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=ser --> count 25
[26/Jan/2023:16:45:11.500985035 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=use --> count 25
[26/Jan/2023:16:45:11.501672325 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=^us --> count 24
[26/Jan/2023:16:45:11.502622354 +0100] conn=1 op=73 STAT read index: duration 0.000011139 
[26/Jan/2023:16:45:11.503357196 +0100] conn=1 op=73 RESULT err=0 tag=101 nentries=24 wtime=0.000085400 optime=0.001456515 etime=0.001540305

I think #3729 is helpful when you have a good knownledge of internals (support), while #3129 is helpful for administrator/support.

In conclusion, I think this RFE differs from #3729 and makes sense