Bug 558099 - Enhancement request: Log more information about the search result being a paged one
Summary: Enhancement request: Log more information about the search result being a pag...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: 389
Classification: Retired
Component: Database - Indexes/Searches
Version: 1.2.1
Hardware: All
OS: Linux
low
low
Target Milestone: ---
Assignee: Noriko Hosoi
QA Contact: Viktor Ashirov
URL:
Whiteboard:
Depends On:
Blocks: 639035
TreeView+ depends on / blocked
 
Reported: 2010-01-23 17:48 UTC by Andrey Ivanov
Modified: 2015-12-07 17:15 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-12-07 17:15:45 UTC


Attachments (Terms of Use)
git patch file (master) (9.57 KB, patch)
2010-09-14 17:49 UTC, Noriko Hosoi
nhosoi: review?
nhosoi: review?
rmeggins: review+
Details | Diff

Description Andrey Ivanov 2010-01-23 17:48:19 UTC
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.9.2) Gecko/20100115 Firefox/3.6 (.NET CLR 3.5.30729)

The access log entries for the paged searches are not different from the "normal" sequential search operations. It is very confusing, especially the "nentries=..." part - it does not correspond to the whole number of entries returned from the backend but is presented in the same way as if it were a usual search.

Reproducible: Always

Steps to Reproduce:
1. Make a paged search with a page smaller than the total number of entries returned.
2. Take a look at the access log file from this connection

Actual Results:  
The example is for 8 total returned entries and the page size is 3

23/Jan/2010:18:35:03 +0100] conn=38 fd=128 slot=128 connection from 127.0.0.1 to 127.0.0.1
[23/Jan/2010:18:35:03 +0100] conn=38 op=0 BIND dn="" method=128 version=3
[23/Jan/2010:18:35:03 +0100] conn=38 op=0 RESULT err=0 tag=97 nentries=0 etime=0.006000 dn=""
[23/Jan/2010:18:35:03 +0100] conn=38 op=1 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=*alice*)" attrs=ALL
[23/Jan/2010:18:35:03 +0100] conn=38 op=1 RESULT err=0 tag=101 nentries=3 etime=0.008000
[23/Jan/2010:18:35:04 +0100] conn=38 op=2 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=*alice*)" attrs=ALL
[23/Jan/2010:18:35:04 +0100] conn=38 op=2 RESULT err=0 tag=101 nentries=3 etime=0.002000
[23/Jan/2010:18:35:05 +0100] conn=38 op=3 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=*alice*)" attrs=ALL
[23/Jan/2010:18:35:05 +0100] conn=38 op=3 RESULT err=0 tag=101 nentries=2 etime=0.001000
[23/Jan/2010:18:35:05 +0100] conn=38 op=4 UNBIND
[23/Jan/2010:18:35:05 +0100] conn=38 op=4 fd=128 closed - U1

Expected Results:  
The access log should provide some minimum information about using paged results. Something like "notes=P":

[23/Jan/2010:18:35:04 +0100] conn=38 op=2 RESULT err=0 tag=101 nentries=3 etime=0.002000 notes=P

This is not a bug, it's a feature request

Comment 2 Noriko Hosoi 2010-09-14 17:49:32 UTC
Created attachment 447285 [details]
git patch file (master)

Description: searched entry count is logged in the access log as
(nentries=<num>). When RFC 2696 page results control is passed,
the nentries logs the page size instead of the total searched
count.  andrey.ivanov@polytechnique.fr proposed to log the control
info as follows:
[..] conn=# op=#RESULT err=0 tag=101 nentries=# etime=0 notes=P
This patch implemented the spec.
Also, there was a bug regarding unindexed note "notes=U" when
the paged results control is received.  Only the first page logs
it, but not the rest.  The bug was fixed.

Comment 3 Noriko Hosoi 2010-09-15 17:27:58 UTC
Reviewed by Rich (Thanks !!!)

Pushed to master.

$ git merge work
Updating 20d1e7c..529b056
Fast-forward
 ldap/servers/slapd/back-ldbm/filterindex.c |    6 ++++++
 ldap/servers/slapd/back-ldbm/ldbm_search.c |    1 +
 ldap/servers/slapd/back-ldbm/vlv.c         |    5 +++--
 ldap/servers/slapd/opshared.c              |    5 +++++
 ldap/servers/slapd/pagedresults.c          |   25 +++++++++++++++++++++++++
 ldap/servers/slapd/proto-slap.h            |    2 ++
 ldap/servers/slapd/result.c                |    3 ++-
 ldap/servers/slapd/slap.h                  |    4 ++++
 ldap/servers/slapd/slapi-plugin.h          |    1 +
 9 files changed, 49 insertions(+), 3 deletions(-)

$ git push
Counting objects: 29, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (15/15), done.
Writing objects: 100% (15/15), 2.12 KiB, done.
Total 15 (delta 13), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   20d1e7c..529b056  master -> master

Comment 4 Amita Sharma 2011-07-20 11:26:39 UTC
Simple Ldapsearch access logs
===================================
[root@testvm ~]# tail -f /var/log/dirsrv/slapd-testvm1/access
[20/Jul/2011:16:27:59 +051800] conn=13 op=46 SRCH base="ou=Accounting,dc=example,dc=com" scope=1 filter="(|(&(numSubordinates=*)(numSubordinates>=1)(|(objectClass=*)(objectClass=ldapsubentry)))(objectClass=organization)(objectClass=organizationalUnit)(objectClass=netscapeServer)(objectClass=netscapeResource)(objectClass=domain))" attrs="distinguishedName"
[20/Jul/2011:16:27:59 +051800] conn=13 op=46 RESULT err=0 tag=101 nentries=0 etime=0 notes=U
[20/Jul/2011:16:27:59 +051800] conn=13 op=47 SRCH base="ou=Product Development,dc=example,dc=com" scope=1 filter="(|(&(numSubordinates=*)(numSubordinates>=1)(|(objectClass=*)(objectClass=ldapsubentry)))(objectClass=organization)(objectClass=organizationalUnit)(objectClass=netscapeServer)(objectClass=netscapeResource)(objectClass=domain))" attrs="distinguishedName"
[20/Jul/2011:16:27:59 +051800] conn=13 op=47 RESULT err=0 tag=101 nentries=0 etime=0 notes=U
[20/Jul/2011:16:27:59 +051800] conn=13 op=48 SRCH base="ou=Product Testing,dc=example,dc=com" scope=1 filter="(|(&(numSubordinates=*)(numSubordinates>=1)(|(objectClass=*)(objectClass=ldapsubentry)))(objectClass=organization)(objectClass=organizationalUnit)(objectClass=netscapeServer)(objectClass=netscapeResource)(objectClass=domain))" attrs="distinguishedName"
[20/Jul/2011:16:27:59 +051800] conn=13 op=48 RESULT err=0 tag=101 nentries=0 etime=0 notes=U
[20/Jul/2011:16:27:59 +051800] conn=13 op=49 SRCH base="ou=Human Resources,dc=example,dc=com" scope=1 filter="(|(&(numSubordinates=*)(numSubordinates>=1)(|(objectClass=*)(objectClass=ldapsubentry)))(objectClass=organization)(objectClass=organizationalUnit)(objectClass=netscapeServer)(objectClass=netscapeResource)(objectClass=domain))" attrs="distinguishedName"
[20/Jul/2011:16:27:59 +051800] conn=13 op=49 RESULT err=0 tag=101 nentries=0 etime=0 notes=U
[20/Jul/2011:16:27:59 +051800] conn=13 op=50 SRCH base="ou=Payroll,dc=example,dc=com" scope=1 filter="(|(&(numSubordinates=*)(numSubordinates>=1)(|(objectClass=*)(objectClass=ldapsubentry)))(objectClass=organization)(objectClass=organizationalUnit)(objectClass=netscapeServer)(objectClass=netscapeResource)(objectClass=domain))" attrs="distinguishedName"
[20/Jul/2011:16:27:59 +051800] conn=13 op=50 RESULT err=0 tag=101 nentries=0 etime=0 notes=U

Simple Paged Search - Access Logs
===================================
[root@testvm ~]# tail -f /var/log/dirsrv/slapd-testvm1/access
[20/Jul/2011:16:52:16 +051800] conn=16 op=26 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:16 +051800] conn=16 op=26 RESULT err=0 tag=101 nentries=33 etime=0 notes=U,P
[20/Jul/2011:16:52:16 +051800] conn=16 op=27 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:16 +051800] conn=16 op=27 RESULT err=0 tag=101 nentries=33 etime=0 notes=U,P
[20/Jul/2011:16:52:17 +051800] conn=16 op=28 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:17 +051800] conn=16 op=28 RESULT err=0 tag=101 nentries=33 etime=0 notes=U,P
[20/Jul/2011:16:52:17 +051800] conn=16 op=29 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:17 +051800] conn=16 op=29 RESULT err=0 tag=101 nentries=33 etime=0 notes=U,P
[20/Jul/2011:16:52:17 +051800] conn=16 op=30 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:17 +051800] conn=16 op=30 RESULT err=0 tag=101 nentries=33 etime=0 notes=U,P
[20/Jul/2011:16:52:58 +051800] conn=16 op=31 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:58 +051800] conn=16 op=31 RESULT err=0 tag=101 nentries=35 etime=0 notes=U,P
[20/Jul/2011:16:52:59 +051800] conn=16 op=32 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:52:59 +051800] conn=16 op=32 RESULT err=0 tag=101 nentries=54 etime=0 notes=U,P
[20/Jul/2011:16:53:00 +051800] conn=16 op=33 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:53:00 +051800] conn=16 op=33 RESULT err=0 tag=101 nentries=435 etime=0 notes=U,P
[20/Jul/2011:16:53:01 +051800] conn=16 op=34 SRCH base="dc=example,dc=com" scope=2 filter="(objectClass=*)" attrs="cn"
[20/Jul/2011:16:53:01 +051800] conn=16 op=34 RESULT err=0 tag=101 nentries=345 etime=0 notes=U,P

notes=U,P - In Simple Page Search. Hence VERIFIED.

Comment 5 Amita Sharma 2011-07-20 11:29:31 UTC
Sorry correction, First one is without simple page search access logs and second one is simple paged - In last comment#4


Note You need to log in before you can comment on or make changes to this bug.