(ITS#5756) 2.4 slapo-pcache only caches first lookup for certain templates - openldap-bugs

20 Oct 2008


      Full_Name: Toby Blake
Version: 2.4.11
OS: Scientific Linux 5.1
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (87.115.7.181)
Hello,
Caching of (more complex) lookups doesn't seem to work correctly using
openldap 2.4 and slapo-pcache.
Identical set-ups, one using openldap 2.3.43 and one using openldap
2.4.11 (+patch for ITS #5665).  Trivial testing of 2.4.12 suggests
that the problem remains.
Here's the pcache part of slapd.conf:
overlay                 pcache
proxycache              bdb 5000 2 500 300
proxycachequeries       10000
proxyattrset            0 primaryRoles secondaryRoles cn
proxyattrset            1 uid userPassword uidNumber gidNumber cn
afsHomeDirecto
ry loginShell gecos description objectClass
proxytemplate           (uid=) 0 600 600
proxytemplate           (&(objectClass=)(uid=)) 1 600 600
All works as expected with 2.3.43.
With 2.4:
The "(uid=)" template works fine all lookups.
What happens, for the "(&(objectClass=)(uid=))" template, is that only
the first lookup will be correctly cached, whether the results are
positive or negative.  Subsequent different lookups which match that
template will log 'QUERY NOT ANSWERABLE; QUERY CACHEABLE' but the
entry won't be successfully cached (in that the next identical lookup
will also log 'QUERY NOT ANSWERABLE; QUERY CACHEABLE' and fetch the
entry from the remote server).
I've attached a portion of the slapd log below this message which
shows the results of the following:
<slapd starting>...
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=toby))" uid
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=toby))" uid
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=bill))" uid
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=bill))" uid
...<cache expiry>...
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=bill))" uid
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=bill))" uid
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=toby))" uid
ldapsearch -x -h localhost "(&(objectClass=posixAccount)(uid=toby))" uid
In the first case the lookup for "...uid=toby" is successfully cached,
while the one for "...uid=bill" isn't.  After cache expiry, the
reverse is true.
If there is any more information that would be useful, or debugging I
could do, please let me know.
Many thanks
Toby Blake
School of Informatics
University of Edinburgh
Oct 20 14:20:16 sybies slapd[8187]: @(#) $OpenLDAP: slapd 2.4.11 (Aug 25 2008
11:25:11) $ 	toby@syd.inf.ed.ac.uk:/afs/inf.ed.ac.uk/user/t/toby/linux/BUILD/openldap-2.4.11/openldap-2.4.11/servers/slapd
Oct 20 14:20:16 sybies slapd[8187]: Total # of attribute sets to be cached = 2.
Oct 20 14:20:16 sybies slapd[8187]: Template: 
Oct 20 14:20:16 sybies slapd[8187]:   query template: (uid=) 
Oct 20 14:20:16 sybies slapd[8187]:   attributes:  
Oct 20 14:20:16 sybies slapd[8187]: 	primaryRoles 
Oct 20 14:20:16 sybies slapd[8187]: 	secondaryRoles 
Oct 20 14:20:16 sybies slapd[8187]: 	cn 
Oct 20 14:20:16 sybies slapd[8187]: Template: 
Oct 20 14:20:16 sybies slapd[8187]:   query template: (&(objectClass=)(uid=)) 
Oct 20 14:20:16 sybies slapd[8187]:   attributes:  
Oct 20 14:20:16 sybies slapd[8187]: 	uid 
Oct 20 14:20:16 sybies slapd[8187]: 	userPassword 
Oct 20 14:20:16 sybies slapd[8187]: 	uidNumber 
Oct 20 14:20:16 sybies slapd[8187]: 	gidNumber 
Oct 20 14:20:16 sybies slapd[8187]: 	cn 
Oct 20 14:20:16 sybies slapd[8187]: 	afsHomeDirectory 
Oct 20 14:20:16 sybies slapd[8187]: 	loginShell 
Oct 20 14:20:16 sybies slapd[8187]: 	gecos 
Oct 20 14:20:16 sybies slapd[8187]: 	description 
Oct 20 14:20:16 sybies slapd[8187]: 	objectClass 
Oct 20 14:20:16 sybies slapd[8189]: slapd starting 
Oct 20 14:20:30 sybies slapd[8189]: conn=0 fd=16 ACCEPT from IP=127.0.0.1:60516
(IP=0.0.0.0:389) 
Oct 20 14:20:30 sybies slapd[8189]: conn=0 op=0 BIND dn="" method=128 
Oct 20 14:20:30 sybies slapd[8189]: conn=0 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=toby))" 
Oct 20 14:20:30 sybies slapd[8189]: conn=0 op=1 SRCH attr=uid 
Oct 20 14:20:30 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:20:30 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=toby)) 
Oct 20 14:20:30 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:20:30 sybies slapd[8189]: Not answerable: Unlock QC index=0x8cc25c8 
Oct 20 14:20:30 sybies slapd[8189]: QUERY NOT ANSWERABLE 
Oct 20 14:20:30 sybies slapd[8189]: QUERY CACHEABLE 
Oct 20 14:20:30 sybies slapd[8189]: conn=0 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:20:30 sybies slapd[8189]: Added query expires at 1224509430 (POSITIVE)
Oct 20 14:20:30 sybies slapd[8189]: Lock AQ index = 0x8cc25c8 
Oct 20 14:20:30 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES++ 1 
Oct 20 14:20:30 sybies slapd[8189]: Unlock AQ index = 0x8cc25c8  
Oct 20 14:20:30 sybies slapd[8189]: Base of added query =
dc=inf,dc=ed,dc=ac,dc=uk 
Oct 20 14:20:30 sybies slapd[8189]: UUID for query being added =
9cfdd1c0-32f5-102d-88aa-9ff265a4b255 
Oct 20 14:20:30 sybies slapd[8189]: conn=0 op=2 UNBIND 
Oct 20 14:20:31 sybies slapd[8189]: ENTRY ADDED/MERGED, CACHED ENTRIES=1 
Oct 20 14:20:31 sybies slapd[8189]: STORED QUERIES = 1 
Oct 20 14:20:31 sybies slapd[8189]: conn=0 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:20:31 sybies slapd[8189]: conn=0 fd=16 closed 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 fd=16 ACCEPT from IP=127.0.0.1:60518
(IP=0.0.0.0:389) 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 op=0 BIND dn="" method=128 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=toby))" 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 op=1 SRCH attr=uid 
Oct 20 14:20:33 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:20:33 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=toby)) 
Oct 20 14:20:33 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:20:33 sybies slapd[8189]: QUERY ANSWERABLE 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 op=2 UNBIND 
Oct 20 14:20:33 sybies slapd[8189]: conn=1 fd=16 closed 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 fd=16 ACCEPT from IP=127.0.0.1:60519
(IP=0.0.0.0:389) 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 op=0 BIND dn="" method=128 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=bill))" 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 op=1 SRCH attr=uid 
Oct 20 14:20:40 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:20:40 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=bill)) 
Oct 20 14:20:40 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:20:40 sybies slapd[8189]: Not answerable: Unlock QC index=0x8cc25c8 
Oct 20 14:20:40 sybies slapd[8189]: QUERY NOT ANSWERABLE 
Oct 20 14:20:40 sybies slapd[8189]: QUERY CACHEABLE 
Oct 20 14:20:40 sybies slapd[8189]: Added query expires at 1224509440 (POSITIVE)
Oct 20 14:20:40 sybies slapd[8189]: Lock AQ index = 0x8cc25c8 
Oct 20 14:20:40 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES++ 1 
Oct 20 14:20:40 sybies slapd[8189]: Unlock AQ index = 0x8cc25c8  
Oct 20 14:20:40 sybies slapd[8189]: conn=2 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 op=2 UNBIND 
Oct 20 14:20:40 sybies slapd[8189]: conn=2 fd=16 closed 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 fd=16 ACCEPT from IP=127.0.0.1:60520
(IP=0.0.0.0:389) 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 op=0 BIND dn="" method=128 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=bill))" 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 op=1 SRCH attr=uid 
Oct 20 14:20:42 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:20:42 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=bill)) 
Oct 20 14:20:42 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:20:42 sybies slapd[8189]: Not answerable: Unlock QC index=0x8cc25c8 
Oct 20 14:20:42 sybies slapd[8189]: QUERY NOT ANSWERABLE 
Oct 20 14:20:42 sybies slapd[8189]: QUERY CACHEABLE 
Oct 20 14:20:42 sybies slapd[8189]: Added query expires at 1224509442 (POSITIVE)
Oct 20 14:20:42 sybies slapd[8189]: Lock AQ index = 0x8cc25c8 
Oct 20 14:20:42 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES++ 1 
Oct 20 14:20:42 sybies slapd[8189]: Unlock AQ index = 0x8cc25c8  
Oct 20 14:20:42 sybies slapd[8189]: conn=3 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 op=2 UNBIND 
Oct 20 14:20:42 sybies slapd[8189]: conn=3 fd=16 closed 
Oct 20 14:30:31 sybies slapd[8189]: Lock CR index = 0x8cc25c8 
Oct 20 14:30:31 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES-- 0 
Oct 20 14:30:31 sybies slapd[8189]: Unlock CR index = 0x8cc25c8 
Oct 20 14:30:31 sybies slapd[8189]: DELETING ENTRY
TEMPLATE=9cfdd1c0-32f5-102d-88aa-9ff265a4b255 
Oct 20 14:30:31 sybies slapd[8189]: STALE QUERY REMOVED, SIZE=1 
Oct 20 14:30:31 sybies slapd[8189]: STORED QUERIES = 0 
Oct 20 14:30:31 sybies slapd[8189]: STALE QUERY REMOVED, CACHE =0 entries 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 fd=16 ACCEPT from IP=127.0.0.1:52101
(IP=0.0.0.0:389) 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 op=0 BIND dn="" method=128 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=bill))" 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 op=1 SRCH attr=uid 
Oct 20 14:31:50 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:31:50 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=bill)) 
Oct 20 14:31:50 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:31:50 sybies slapd[8189]: Not answerable: Unlock QC index=0x8cc25c8 
Oct 20 14:31:50 sybies slapd[8189]: QUERY NOT ANSWERABLE 
Oct 20 14:31:50 sybies slapd[8189]: QUERY CACHEABLE 
Oct 20 14:31:50 sybies slapd[8189]: Added query expires at 1224510110 (POSITIVE)
Oct 20 14:31:50 sybies slapd[8189]: Lock AQ index = 0x8cc25c8 
Oct 20 14:31:50 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES++ 1 
Oct 20 14:31:50 sybies slapd[8189]: Unlock AQ index = 0x8cc25c8  
Oct 20 14:31:50 sybies slapd[8189]: Base of added query =
dc=inf,dc=ed,dc=ac,dc=uk 
Oct 20 14:31:50 sybies slapd[8189]: UUID for query being added =
321f6e16-32f7-102d-88ab-9ff265a4b255 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 op=2 UNBIND 
Oct 20 14:31:50 sybies slapd[8189]: ENTRY ADDED/MERGED, CACHED ENTRIES=1 
Oct 20 14:31:50 sybies slapd[8189]: STORED QUERIES = 1 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:31:50 sybies slapd[8189]: conn=4 fd=16 closed 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 fd=16 ACCEPT from IP=127.0.0.1:52103
(IP=0.0.0.0:389) 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 op=0 BIND dn="" method=128 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=bill))" 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 op=1 SRCH attr=uid 
Oct 20 14:31:53 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:31:53 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=bill)) 
Oct 20 14:31:53 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:31:53 sybies slapd[8189]: QUERY ANSWERABLE 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 op=2 UNBIND 
Oct 20 14:31:53 sybies slapd[8189]: conn=5 fd=16 closed 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 fd=16 ACCEPT from IP=127.0.0.1:52104
(IP=0.0.0.0:389) 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 op=0 BIND dn="" method=128 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=toby))" 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 op=1 SRCH attr=uid 
Oct 20 14:32:00 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:32:00 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=toby)) 
Oct 20 14:32:00 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:32:00 sybies slapd[8189]: Not answerable: Unlock QC index=0x8cc25c8 
Oct 20 14:32:00 sybies slapd[8189]: QUERY NOT ANSWERABLE 
Oct 20 14:32:00 sybies slapd[8189]: QUERY CACHEABLE 
Oct 20 14:32:00 sybies slapd[8189]: Added query expires at 1224510120 (POSITIVE)
Oct 20 14:32:00 sybies slapd[8189]: Lock AQ index = 0x8cc25c8 
Oct 20 14:32:00 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES++ 1 
Oct 20 14:32:00 sybies slapd[8189]: Unlock AQ index = 0x8cc25c8  
Oct 20 14:32:00 sybies slapd[8189]: conn=6 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 op=2 UNBIND 
Oct 20 14:32:00 sybies slapd[8189]: conn=6 fd=16 closed 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 fd=16 ACCEPT from IP=127.0.0.1:52105
(IP=0.0.0.0:389) 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 op=0 BIND dn="" method=128 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 op=0 RESULT tag=97 err=0 text= 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 op=1 SRCH
base="dc=inf,dc=ed,dc=ac,dc=uk" scope=2 deref=0
filter="(&(objectClass=posixAccount)(uid=toby))" 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 op=1 SRCH attr=uid 
Oct 20 14:32:05 sybies slapd[8189]: query template of incoming query =
(&(objectClass=)(uid=)) 
Oct 20 14:32:05 sybies slapd[8189]: Entering QC, querystr =
(&(objectClass=posixAccount)(uid=toby)) 
Oct 20 14:32:05 sybies slapd[8189]: Lock QC index = 0x8cc25c8 
Oct 20 14:32:05 sybies slapd[8189]: Not answerable: Unlock QC index=0x8cc25c8 
Oct 20 14:32:05 sybies slapd[8189]: QUERY NOT ANSWERABLE 
Oct 20 14:32:05 sybies slapd[8189]: QUERY CACHEABLE 
Oct 20 14:32:05 sybies slapd[8189]: Added query expires at 1224510125 (POSITIVE)
Oct 20 14:32:05 sybies slapd[8189]: Lock AQ index = 0x8cc25c8 
Oct 20 14:32:05 sybies slapd[8189]: TEMPLATE 0x8cc25c8 QUERIES++ 1 
Oct 20 14:32:05 sybies slapd[8189]: Unlock AQ index = 0x8cc25c8  
Oct 20 14:32:05 sybies slapd[8189]: conn=7 op=1 SEARCH RESULT tag=101 err=0
nentries=1 text= 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 op=2 UNBIND 
Oct 20 14:32:05 sybies slapd[8189]: conn=7 fd=16 closed