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
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 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.
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
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.
Sorry correction, First one is without simple page search access logs and second one is simple paged - In last comment#4