389-ds-base

Clone
Source Code
GIT

#47354 Indexed search are logged with 'notes=U' in the access logs
Closed: wontfix None Opened 10 years ago by tbordaz.

Closed: wontfix
Reopen Issue

A filter containing unindexed component will trigger a log with 'notes=U' although the full filter is indexed.

Step to reproduce:
- create an instance
- import /usr/share/dirsrv/data/Example-views.ldif (the bug is not related to views/roles/cos but this ldif file is convenient to reproduce)
- do a searche with '&' with only indexed component. The log will NOT contain 'notes=U'. Then add at least a component not indexed (being not indexed or allid), then the search will be logged 'notes=U' although it was indexed with the others components.

[30/Apr/2013:17:46:46 +0200] conn=10 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(l=Santa Clara)" attrs="distinguishedName"
[30/Apr/2013:17:46:46 +0200] conn=10 op=1 RESULT err=0 tag=101 nentries=76 etime=0

[30/Apr/2013:17:47:36 +0200] conn=11 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(&(l=Santa Clara)(roomNumber=*))" attrs=ALL
[30/Apr/2013:17:47:36 +0200] conn=11 op=1 RESULT err=0 tag=101 nentries=76 etime=0 notes=U

[30/Apr/2013:17:48:15 +0200] conn=12 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(&(roomNumber=*)(l=Santa Clara))" attrs=ALL
[30/Apr/2013:17:48:15 +0200] conn=12 op=1 RESULT err=0 tag=101 nentries=76 etime=0 notes=U

[30/Apr/2013:17:48:47 +0200] conn=13 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(&(roomNumber=3445)(l=Santa Clara))" attrs=ALL
[30/Apr/2013:17:48:47 +0200] conn=13 op=1 RESULT err=0 tag=101 nentries=1 etime=0 notes=U

[30/Apr/2013:17:49:14 +0200] conn=14 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(&(roomNumber=34*)(l=Santa Clara))" attrs=ALL
[30/Apr/2013:17:49:14 +0200] conn=14 op=1 RESULT err=0 tag=101 nentries=2 etime=0 notes=U

If this is a bug depends on the exact meaning of "unindexed", are all the filter components indexed, is at least one indexed in an AND filter, is the final resulting idlist indexed by applying the ancestorid or parentid index ?
Maybe we could log different "notes" for these different scenarios.

Hi Ludwig,

Yes the search is indexed taking benefit of candidate lists of the other indexed components, but the log record is notes=U as soon as it exists an unindexed attribute.
I have not tested what happens if a value of an indexed attribute becomes allids, if it is triggering the notes=U for the all filter.

The problem appears to be if one of the filter components is unindexed. In fact in the following example, objectclass is indexed but allid for a given value, if the second component (uid=xxx) returns a candidate list, the search is NOT logged with 'notes=U

{{{
[02/May/2013:19:19:56 +0200] conn=4567 fd=64 slot=64 connection from ::1 to ::1
[02/May/2013:19:19:56 +0200] conn=4567 op=0 BIND dn="cn=directory manager" method=128 version=3
[02/May/2013:19:19:56 +0200] conn=4567 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[02/May/2013:19:19:56 +0200] conn=4567 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=inetOrgPerson)" attrs="distinguishedName"
[02/May/2013:19:19:56 +0200] conn=4567 op=1 RESULT err=0 tag=101 nentries=4150 etime=0 notes=U
[02/May/2013:19:19:56 +0200] conn=4567 op=-1 fd=64 closed error 104 (Connection reset by peer) - TCP connection reset by peer.

[02/May/2013:19:20:29 +0200] conn=4568 fd=64 slot=64 connection from ::1 to ::1
[02/May/2013:19:20:29 +0200] conn=4568 op=0 BIND dn="cn=directory manager" method=128 version=3
[02/May/2013:19:20:29 +0200] conn=4568 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[02/May/2013:19:20:29 +0200] conn=4568 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(&(objectClass=inetOrgPerson)(uid=btalbot))" attrs=ALL
[02/May/2013:19:20:29 +0200] conn=4568 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[02/May/2013:19:20:29 +0200] conn=4568 op=2 UNBIND

}}}

'''Here is the current status'''

{{{
commit 458a42a
Author: Noriko Hosoi nhosoi@redhat.com
Date: Fri Dec 5 21:03:52 2008 +0000
}}}
In this fix, the opnote is set to SLAPI_OP_NOTE_UNINDEXED as soon as a filter component is unindexed.

'''Here are the next steps'''

As you said, the current behaviour was introduced with 474729 in 2008. Has there been a customer complaint about this ?
I agree that currently too often notes=U is logged, but logging only if the final idlist is unindexed, could hide problems for some time, eg as long as the ancestorid index is not allids.

So I am thinking to an other possibility. Keep the current behavior, i.e. as soon as a component is not indexed log "notes=U". Then in ldbm_back_search, if the full filter is unindexed (ALLID), change the log from "notes=U" to something like "notes=A" ('A' for All why not ;) )

Replying to [comment:8 tbordaz]:

So I am thinking to an other possibility. Keep the current behavior, i.e. as soon as a component is not indexed log "notes=U". Then in ldbm_back_search, if the full filter is unindexed (ALLID), change the log from "notes=U" to something like "notes=A" ('A' for All why not ;) )

That sounds like a good idea - notes=U means something was unindexed - notes=A means everything was unindexed. If we introduce another notes=A then we will have to update the docs and the logconv.pl tool as well.

'''Here is the current status'''

  • We agreed to keep the current behavior (i.e. notes=U as soon as a filter component is unindexed)
    And to introduce a new notes=A when the filter is unindexed (ALLID)

  • The second patch is attached

  • The output is shown below. With a DB with more than 4000 entries. 'l' is indexed in equality (not in substring). 'conn=3 op=1' is indexed because the ancestorid gives the candidate list, but the component 'l' is unindexed.

{{{
[17/May/2013:17:10:43 +0200] conn=1 fd=64 slot=64 connection from ::1 to ::1
[17/May/2013:17:10:43 +0200] conn=1 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[17/May/2013:17:10:43 +0200] conn=1 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[17/May/2013:17:10:43 +0200] conn=1 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(l=sunnyvale)" attrs="l"
[17/May/2013:17:10:43 +0200] conn=1 op=1 RESULT err=0 tag=101 nentries=40 etime=0
[17/May/2013:17:10:43 +0200] conn=1 op=2 UNBIND
[17/May/2013:17:10:43 +0200] conn=1 op=2 fd=64 closed - U1
[17/May/2013:17:11:06 +0200] conn=2 fd=64 slot=64 connection from ::1 to ::1
[17/May/2013:17:11:06 +0200] conn=2 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[17/May/2013:17:11:06 +0200] conn=2 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[17/May/2013:17:11:06 +0200] conn=2 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(l=sunny)" attrs="l"
[17/May/2013:17:11:06 +0200] conn=2 op=1 RESULT err=0 tag=101 nentries=40 etime=0 notes=A
[17/May/2013:17:11:06 +0200] conn=2 op=2 UNBIND
[17/May/2013:17:11:06 +0200] conn=2 op=2 fd=64 closed - U1
[17/May/2013:17:11:24 +0200] conn=3 fd=64 slot=64 connection from ::1 to ::1
[17/May/2013:17:11:24 +0200] conn=3 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[17/May/2013:17:11:24 +0200] conn=3 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[17/May/2013:17:11:24 +0200] conn=3 op=1 SRCH base="uid=ttully,ou=People,dc=example,dc=com" scope=2 filter="(l=sunny)" attrs="l"
[17/May/2013:17:11:24 +0200] conn=3 op=1 RESULT err=0 tag=101 nentries=1 etime=0 notes=U
[17/May/2013:17:11:24 +0200] conn=3 op=2 UNBIND
[17/May/2013:17:11:24 +0200] conn=3 op=2 fd=64 closed - U1
[17/May/2013:17:12:04 +0200] conn=4 fd=64 slot=64 connection from ::1 to ::1
[17/May/2013:17:12:04 +0200] conn=4 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[17/May/2013:17:12:04 +0200] conn=4 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[17/May/2013:17:12:04 +0200] conn=4 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(l=santa clara)" attrs="l"
[17/May/2013:17:12:05 +0200] conn=4 op=1 RESULT err=0 tag=101 nentries=4176 etime=1 notes=A
[17/May/2013:17:12:05 +0200] conn=4 op=2 UNBIND
[17/May/2013:17:12:05 +0200] conn=4 op=2 fd=64 closed - U1
[17/May/2013:17:12:17 +0200] conn=5 fd=64 slot=64 connection from ::1 to ::1
[17/May/2013:17:12:17 +0200] conn=5 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[17/May/2013:17:12:17 +0200] conn=5 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[17/May/2013:17:12:17 +0200] conn=5 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(&(roomNumber=3924)(l=sunnyvale))" attrs="l"
[17/May/2013:17:12:17 +0200] conn=5 op=1 RESULT err=0 tag=101 nentries=1 etime=0 notes=U
[17/May/2013:17:12:17 +0200] conn=5 op=2 UNBIND
[17/May/2013:17:12:17 +0200] conn=5 op=2 fd=64 closed - U1
}}}

  • The ouput of logconv.pl changes to display: Unindexed searches (notes=A) and Unindexed components (notes=U)

{{{
logconv.pl /var/log/dirsrv/slapd-ticket47354/access
...
Searches: 5 (0.05/sec) (3.19/min)
Modifications: 0 (0.00/sec) (0.00/min)
Adds: 0 (0.00/sec) (0.00/min)
Deletes: 0 (0.00/sec) (0.00/min)
Mod RDNs: 0 (0.00/sec) (0.00/min)
...
Unindexed Searches: 2
Unindexed Components: 2
...
}}}

With unindexed searches stats

{{{
logconv.pl -u /var/log/dirsrv/slapd-ticket47354/access
...
Searches: 5 (0.05/sec) (3.19/min)
Modifications: 0 (0.00/sec) (0.00/min)
Adds: 0 (0.00/sec) (0.00/min)
Deletes: 0 (0.00/sec) (0.00/min)
Mod RDNs: 0 (0.00/sec) (0.00/min)
...
Unindexed Searches: 2
Unindexed Components: 2

Unindexed Search #1
- Date/Time: 17/May/2013:17:11:06
- Connection Number: 2
- Operation Number: 1
- Etime: 0
- Nentries: 40
- IP Address: ?

Unindexed Search #2
- Date/Time: 17/May/2013:17:12:05
- Connection Number: 4
- Operation Number: 1
- Etime: 1
- Nentries: 4176
- IP Address: ?

Unindexed Components #1
- Date/Time: 17/May/2013:17:11:24
- Connection Number: 3
- Operation Number: 1
- Etime: 0
- Nentries: 1
- IP Address: ?

Unindexed Components #2
- Date/Time: 17/May/2013:17:12:17
- Connection Number: 5
- Operation Number: 1
- Etime: 0
- Nentries: 1
- IP Address: ?

}}}

'''Here are the next steps'''

  • waiting for the review

The server changes look ok. Should get Mark to review the logconv changes.

In logconv.pl, minor alignment issue:

651 print "VLV Unindexed Searches: $vlvNotesACount\n";
652 print "VLV Unindexed Components: $vlvNotesUCount\n"; <----- Extra space
653 print "SORT Operations: $vlvSortCount\n";

The rest looks good.

Thanks,
Mark

'''Push to master'''

git merge ticket47354
Updating 16c41ad..f2b5a97
Fast-forward
ldap/admin/src/logconv.pl | 221 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----------------
ldap/servers/slapd/back-ldbm/ldbm_search.c | 6 ++-
ldap/servers/slapd/result.c | 3 +-
ldap/servers/slapd/slapi-plugin.h | 1 +
4 files changed, 187 insertions(+), 44 deletions(-)

git push origin master
Counting objects: 23, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (11/11), done.
Writing objects: 100% (12/12), 2.33 KiB, done.
Total 12 (delta 9), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
16c41ad..f2b5a97 master -> master

commit f2b5a97
Author: Thierry bordaz (tbordaz) tbordaz@redhat.com
Date: Fri May 17 11:48:08 2013 +0200

Ticket has been cloned to Bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=1013160

To ssh://git.fedorahosted.org/git/389/ds.git
fbece32..313dd8e 389-ds-base-1.2.11 -> 389-ds-base-1.2.11
commit 4ef6e16
Author: Thierry bordaz (tbordaz) tbordaz@redhat.com
Date: Fri May 17 11:48:08 2013 +0200

To ssh://git.fedorahosted.org/git/389/ds.git
c96eaa0..9103b3e 389-ds-base-1.3.0 -> 389-ds-base-1.3.0
commit fb1c15d
Author: Thierry bordaz (tbordaz) tbordaz@redhat.com
Date: Fri May 17 11:48:08 2013 +0200

To ssh://git.fedorahosted.org/git/389/ds.git
ff9a292..e38685b 389-ds-base-1.3.1 -> 389-ds-base-1.3.1
commit 15c77ad
Author: Thierry bordaz (tbordaz) tbordaz@redhat.com
Date: Fri May 17 11:48:08 2013 +0200

Metadata Update from @tbordaz:
- Issue assigned to tbordaz
- Issue set to the milestone: 1.3.2 - 08/13 (August)
7 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/691

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Fixed)
3 years ago

Login to comment on this ticket.

Metadata
None
None
None
major
ack
Community
Powered by Pagure 5.13.3
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.