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
toby@inf.ed.ac.uk wrote: > 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. The issue is confirmed. I could reproduce it with a much simpler configuration: overlay pcache proxycache bdb 100 2 6 1m proxyattrset 0 uid proxyattrset 1 cn proxytemplate "(&(objectClass=)(uid=))" 0 1m 1m proxytemplate "(uid=)" 1 1m 1m Note that swapping the attrsets and templates does not affect it: the template with the simple filter works, while the other doesn't. I was unable to detect the root cause, but it seems to be related to query confinement, where something about the first filter does not allow to store the second query, since the first bit, (objectClass=x), is identical in both queries. Note that swapping the simple filters, making the "unique portion come first, cures the problem: overlay pcache proxycache bdb 100 2 6 1m proxyattrset 0 uid proxyattrset 1 cn proxytemplate "(&(uid=)(objectClass=))" 0 1m 1m proxytemplate "(uid=)" 1 1m 1m p. Ing. Pierangelo Masarati OpenLDAP Core Team SysNet s.r.l. via Dossi, 8 - 27100 Pavia - ITALIA http://www.sys-net.it ----------------------------------- Office: +39 02 23998309 Mobile: +39 333 4963172 Fax: +39 0382 476497 Email: ando@sys-net.it -----------------------------------
changed notes moved from Incoming to Software Bugs
Hi there, is there any further debugging I could usefully carry out for this issue, or does it need someone who understands the code a bit better? Cheers Toby -- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
toby@inf.ed.ac.uk wrote: > Hi there, is there any further debugging I could usefully carry out > for this issue, or does it need someone who understands the code a bit > better? It's not a debugging problem, but rather a design issue. The current design makes use of the first AVA of the filter to decide how two filters are compared. In your case, the first component is common to all filters, so only the first occurrence of a search with that template can be cached. This fact, to my knowledge, is undocumented, but there's little to do except redesign this weighing criterium. As I already pointed out, you need to make the most significant filter AVA appear first in your filter template. Unless anyone voluteers for a complete redesign [*] of this portion of slapo-pcache(5), I take your ITS as a request to document this aspect of template design. p. [*] a complete redesign could also get rid of strict ordering of filter AVAs, allow "static" portions of the filter (something like (&(objectClass=person)(uid=)) and so) and other relatively unfriendly aspects of slapo-pcache(5) configuration. Ing. Pierangelo Masarati OpenLDAP Core Team SysNet s.r.l. via Dossi, 8 - 27100 Pavia - ITALIA http://www.sys-net.it ----------------------------------- Office: +39 02 23998309 Mobile: +39 333 4963172 Fax: +39 0382 476497 Email: ando@sys-net.it -----------------------------------
On 4 Nov 2008, at 09:26, Pierangelo Masarati wrote: > toby@inf.ed.ac.uk wrote: >> Hi there, is there any further debugging I could usefully carry >> out for this issue, or does it need someone who understands the >> code a bit better? > > It's not a debugging problem, but rather a design issue. The > current design makes use of the first AVA of the filter to decide > how two filters are compared. In your case, the first component is > common to all filters, so only the first occurrence of a search with > that template can be cached. This fact, to my knowledge, is > undocumented, but there's little to do except redesign this weighing > criterium. As I already pointed out, you need to make the most > significant filter AVA appear first in your filter template. Unless > anyone voluteers for a complete redesign [*] of this portion of > slapo-pcache(5), I take your ITS as a request to document this > aspect of template design. > > p. > > [*] a complete redesign could also get rid of strict ordering of > filter AVAs, allow "static" portions of the filter (something like > (&(objectClass=person)(uid=)) and so) and other relatively > unfriendly aspects of slapo-pcache(5) configuration. The problem with changing the ordering in the template is that it then doesn't match the real lookups that occur and so the entries aren't cached - this is something over which I have no control - e.g. queries generated by 'ls -l', or by somebody logging into the machine, etc, etc. This is why we have the filters this way. e.g. sshing into one of our scientific linux 5.2 hosts generates the following lookups: [sybies]toby: grep 'query template' ~/tmp/pcache-login |cut -d' ' -f13| sort|uniq -c 1 (&(objectClass=)(cn=)) 2 (&(objectClass=)(|(memberUid=)(uniqueMember=))) 28 (&(objectClass=)(uid=)) 5 (&(objectClass=)(uidNumber=)) 26 (&(objectClass=)(uniqueMember=)) [sybies]toby: Cheers Toby -- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
changed notes changed state Open to Test
ando@sys-net.it wrote: > toby@inf.ed.ac.uk wrote: >> Hi there, is there any further debugging I could usefully carry out >> for this issue, or does it need someone who understands the code a bit >> better? > > It's not a debugging problem, but rather a design issue. The current > design makes use of the first AVA of the filter to decide how two > filters are compared. In your case, the first component is common to > all filters, so only the first occurrence of a search with that template > can be cached. This fact, to my knowledge, is undocumented, but there's > little to do except redesign this weighing criterium. As I already > pointed out, you need to make the most significant filter AVA appear > first in your filter template. Unless anyone voluteers for a complete > redesign [*] of this portion of slapo-pcache(5), I take your ITS as a > request to document this aspect of template design. The filter comparison function has been rewritten to compare all terms of the filter, instead of only the first. It now passes the simple cases from your previous followup. Please test... -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/
changed notes changed state Test to Release
Brilliant, many thanks for this. A simple test seems to confirm that it fixes the problem. I'll test in more detail and with more complex filters to confirm. Cheers Toby -- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
Hi there, I've put this patched version on a small lab of clients (about 23) and on one of them slapd has segfaulted and dumped core. Here's the backtrace: Program terminated with signal 11, Segmentation fault. #0 pcache_filter_cmp (f1=0x8af09f8, f2=0x39) at pcache.c:608 608 switch( f2->f_choice ) { (gdb) bt #0 pcache_filter_cmp (f1=0x8af09f8, f2=0x39) at pcache.c:608 #1 0x08155862 in tavl_insert (root=0x8afe590, data=0x8aefb88, fcmp=0x81399b0 <pcache_query_cmp>, fdup=0x8154700 <avl_dup_error>) at tavl.c:82 #2 0x0813a95d in add_query (op=0x8ae3658, qm=0x8a74cc0, query=0xb55af394, templ=0x8a90f88, why=PC_POSITIVE, wlock=1) at pcache.c:1252 #3 0x0813d7f1 in pcache_op_cleanup (op=0x8ae3658, rs=0xb5eb1148) at pcache.c:2041 #4 0x08076a04 in slap_cleanup_play (op=0x8ae3658, rs=0xb5eb1148) at result.c:341 #5 0x08079a56 in send_ldap_response (op=0x8ae3658, rs=0xb5eb1148) at result.c:522 #6 0x0807aa42 in slap_send_ldap_result (op=0x8ae3658, rs=0xb5eb1148) at result.c:650 #7 0x080f4fef in ldap_back_search (op=0x8ae3658, rs=0xb5eb1148) at search.c:549 #8 0x080cf431 in overlay_op_walk (op=0x8ae3658, rs=0xb5eb1148, which=op_search, oi=0x8a74ff0, on=0x8a750f0) at backover.c:670 #9 0x080cf9ed in over_op_func (op=0x8ae3658, rs=0xb5eb1148, which=op_search) at backover.c:722 #10 0x08069016 in fe_op_search (op=0x8ae3658, rs=0xb5eb1148) at search.c:366 #11 0x0806989b in do_search (op=0x8ae3658, rs=0xb5eb1148) at search.c: 217 #12 0x08066a66 in connection_operation (ctx=0xb5eb1218, arg_v=0x8ae3658) at connection.c:1090 #13 0x08067082 in connection_read_thread (ctx=0xb5eb1218, argv=0xf) at connection.c:1216 #14 0x08159704 in ldap_int_thread_pool_wrapper (xpool=0x8a52f90) at tpool.c:663 #15 0x0064f46b in start_thread () from /lib/libpthread.so.0 #16 0x005a6dbe in clone () from /lib/libc.so.6 This looks a little strange to me... (gdb) p f2->f_choice Cannot access memory at address 0x39 (gdb) up #1 0x08155862 in tavl_insert (root=0x8afe590, data=0x8aefb88, fcmp=0x81399b0 <pcache_query_cmp>, fdup=0x8154700 <avl_dup_error>) at tavl.c:82 82 cmp = fcmp( data, p->avl_data ); (gdb) p p->avl_data $1 = (void *) 0x8af62e0 (gdb) Cheers Toby -- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
toby@inf.ed.ac.uk wrote: > This looks a little strange to me... > > (gdb) p f2->f_choice > Cannot access memory at address 0x39 > (gdb) up > #1 0x08155862 in tavl_insert (root=0x8afe590, data=0x8aefb88, > fcmp=0x81399b0<pcache_query_cmp>, fdup=0x8154700<avl_dup_error>) > at tavl.c:82 > 82 cmp = fcmp( data, p->avl_data ); > (gdb) p p->avl_data > $1 = (void *) 0x8af62e0 > (gdb) It appears you've compiled with debug and optimization, can you please compile without optimization and try to reproduce this? -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/
changed notes changed state Release to Closed
On 13 Feb 2009, at 22:01, Howard Chu wrote: > toby@inf.ed.ac.uk wrote: > >> This looks a little strange to me... >> >> (gdb) p f2->f_choice >> Cannot access memory at address 0x39 >> (gdb) up >> #1 0x08155862 in tavl_insert (root=0x8afe590, data=0x8aefb88, >> fcmp=0x81399b0<pcache_query_cmp>, fdup=0x8154700<avl_dup_error>) >> at tavl.c:82 >> 82 cmp = fcmp( data, p->avl_data ); >> (gdb) p p->avl_data >> $1 = (void *) 0x8af62e0 >> (gdb) > > It appears you've compiled with debug and optimization, can you > please compile without optimization and try to reproduce this? Sure, will do. Cheers Toby -- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
fixed in HEAD fixed in RE24