As far as I recall, this is a known issue, although I could not locate
early postings discussing this issue.  What happens is that proxy cache
makes use of the first item in the filter to discriminate between
responses.  In your filter template, the first item is the objectClass
equality, which means that any filter with that objectClass value,
regardless of the uid value, is treated as a duplicate of the first one. 
If you reverse the order of the equality filters you'll get the expected
behavior.  There should be another open ITS for this issue, but I can't
locate it right now.

p.

changed notes
moved from Incoming to Software Bugs

Please keep replies to the list, so the issue can be tracked.

> Thank you for your help. Reversal of the filters is easily done.
> However the searches I try to cache are taken from Samba. I have no
> control over the way searches are done in Samba. I understand from the
> documentation that the search template must be exact the same as the
> search filter to be cachable.  So this solution does not solve my
> problem, I guess.

Clear.  I understand this issue needs to be fixed somehow.  The reason for
just using the first simple filter in composite filters is probably
related to the fact it did not require extensive data manipulation, as
probably would the definition of a criterion that accounts for the whole
filter.  The ITS remains open as a software bug.

p.

masarati@aero.polimi.it wrote:
> As far as I recall, this is a known issue, although I could not locate
> early postings discussing this issue.  What happens is that proxy cache
> makes use of the first item in the filter to discriminate between
> responses.  In your filter template, the first item is the objectClass
> equality, which means that any filter with that objectClass value,
> regardless of the uid value, is treated as a duplicate of the first one.
> If you reverse the order of the equality filters you'll get the expected
> behavior.  There should be another open ITS for this issue, but I can't
> locate it right now.

The filter behavior you're describing was noted in ITS#5756, fixed in January.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

> masarati@aero.polimi.it wrote:
>> As far as I recall, this is a known issue, although I could not locate
>> early postings discussing this issue.  What happens is that proxy cache
>> makes use of the first item in the filter to discriminate between
>> responses.  In your filter template, the first item is the objectClass
>> equality, which means that any filter with that objectClass value,
>> regardless of the uid value, is treated as a duplicate of the first one.
>> If you reverse the order of the equality filters you'll get the expected
>> behavior.  There should be another open ITS for this issue, but I can't
>> locate it right now.
>
> The filter behavior you're describing was noted in ITS#5756, fixed in
> January.

That's exactly the ITS I was looking for.  Apparently I didn't use the
right keywords, or just overlooked it.

p.

changed notes
changed state Open to Suspended

hyc@symas.com wrote:
 > The filter behavior you're describing was noted in ITS#5756, fixed in 
January.

If it was fixed in January, why does openldap-2.4.16 (20090411) still 
exhibit the described behaviour?

regards,

Jim van Keulen

Jim van Keulen wrote:
> hyc@symas.com wrote:
>   >  The filter behavior you're describing was noted in ITS#5756, fixed in
> January.
>
> If it was fixed in January, why does openldap-2.4.16 (20090411) still
> exhibit the described behaviour?

I don't believe what you're seeing now is due to the situation Ando described.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

> Jim van Keulen wrote:
>> hyc@symas.com wrote:
>>   >  The filter behavior you're describing was noted in ITS#5756, fixed
>> in
>> January.
>>
>> If it was fixed in January, why does openldap-2.4.16 (20090411) still
>> exhibit the described behaviour?
>
> I don't believe what you're seeing now is due to the situation Ando
> described.

But he said that reversing the order of the filters (i.e. no
objectClass=someclass first) cures the problem.

p.

masarati@aero.polimi.it wrote:
>> Jim van Keulen wrote:
>>> hyc@symas.com wrote:
>>>    >   The filter behavior you're describing was noted in ITS#5756, fixed
>>> in
>>> January.
>>>
>>> If it was fixed in January, why does openldap-2.4.16 (20090411) still
>>> exhibit the described behaviour?
>>
>> I don't believe what you're seeing now is due to the situation Ando
>> described.
>
> But he said that reversing the order of the filters (i.e. no
> objectClass=someclass first) cures the problem.

Sorry, if he told you that it must have been in a private email. There is no 
such statement recorded in the ITS. He said it would be simple to reverse the 
filters, but that it would not accomplish anything since he wants to cache 
searches from Samba. He didn't say that he actually tried reversing the 
filters or that it worked. At any rate, the issue in 5756 was confirmed fixed 
so again, I do not believe it's responsible for the current situation.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

moved from Software Bugs to Incoming

>> But he said that reversing the order of the filters (i.e. no
>> objectClass=someclass first) cures the problem.
>
> Sorry, if he told you that it must have been in a private email. There is
> no
> such statement recorded in the ITS. He said it would be simple to reverse
> the
> filters, but that it would not accomplish anything since he wants to cache
> searches from Samba. He didn't say that he actually tried reversing the
> filters or that it worked. At any rate, the issue in 5756 was confirmed
> fixed
> so again, I do not believe it's responsible for the current situation.

No private message.  I probably misunderstood the message in followup 2. 
My understanding of that message is that he tried swapping the simple
filters, but I admit the sentence sound ambiguous to me.

p.

changed state Suspended to Open

> hyc@symas.com wrote:
>  > The filter behavior you're describing was noted in ITS#5756, fixed in
> January.
>
> If it was fixed in January, why does openldap-2.4.16 (20090411) still
> exhibit the described behaviour?

Did you actually try to swap the order of the filters, and did it work? 
Since Howard fixed ITS#5756, you might be experiencing something
different.

Also, can you check whether you're actually using 2.4.16?  According to
the changelog, the fix to ITS#5756 was released with 2.4.14.

p.

masarati@aero.polimi.it wrote:
>> hyc@symas.com wrote:
>>  > The filter behavior you're describing was noted in ITS#5756, fixed in
>> January.
>>
>> If it was fixed in January, why does openldap-2.4.16 (20090411) still
>> exhibit the described behaviour?
> 
> Did you actually try to swap the order of the filters, and did it work? 
> Since Howard fixed ITS#5756, you might be experiencing something
> different.
> 
> Also, can you check whether you're actually using 2.4.16?  According to
> the changelog, the fix to ITS#5756 was released with 2.4.14.
> 
> p.
> 

I am using 2.4.16. The problem is, that caching seems to work for some 
entries but not for others. It is not related to the order of the filter 
rules. Here is what happens:  (lines starting with *** are my comments)



**** slapd is started showing version, query templates and attributes

bash-2.05# ./slapd -d 4096
@(#) $OpenLDAP: slapd 2.4.16 (Jun 30 2009 16:56:26) $
 
jim@flits:/net/build.sparc/management/openldap/openldap-2.4.16/servers/slapd
/opt/openldap/openldap-2.4.16/etc/openldap/slapd.conf: line 78: rootdn 
is always granted unlimited privileges.
/opt/openldap/openldap-2.4.16/etc/openldap/slapd.conf: line 85: rootdn 
is always granted unlimited privileges.
Total # of attribute sets to be cached = 10.
Template:
   query template: (&(objectClass=)(uid=))
   attributes:
         uid
         cn
Template:
   query template: (&(uid=)(objectClass=))
   attributes:
         uid
         cn

slapd starting


*** Now I enter a search in another window

bash-2.05$ /usr/local/bin/ldapsearch -x -h localhost 
'(&(objectClass=sambaSamAccount)(uid=wvk))' uid cn
# extended LDIF
#
# LDAPv3
# base <> with scope subtree
# filter: (&(objectClass=sambaSamAccount)(uid=wvk))
# requesting: uid cn
#

# wvk, People, few.vu.nl
dn: uid=wvk,ou=People,dc=few,dc=vu,dc=nl
uid: wvk
cn: wvk

*** requested attributes are returned as expected

# search result
search: 2
result: 0 Success

# numResponses: 2
# numEntries: 1

*** Output of slapd for this search *****

query template of incoming query = (&(objectClass=)(uid=))
Entering QC, querystr = (&(objectClass=sambaSamAccount)(uid=wvk))
Lock QC index = 31e698
Not answerable: Unlock QC index=31e698
QUERY NOT ANSWERABLE
QUERY CACHEABLE
Added query expires at 1249416628 (POSITIVE)
Lock AQ index = 31e698
TEMPLATE 31e698 QUERIES++ 1
Unlock AQ index = 31e698
Base of added query = dc=few,dc=vu,dc=nl
UUID for query being added = 68ab725c-157a-102e-87a7-cd469e2cf913
ENTRY ADDED/MERGED, CACHED ENTRIES=0
STORED QUERIES = 1

*** same search is repeated

bash-2.05$ /usr/local/bin/ldapsearch -x -h localhost 
'(&(objectClass=sambaSamAccount)(uid=wvk))' uid cn
# extended LDIF
#
# LDAPv3
# base <> with scope subtree
# filter: (&(objectClass=sambaSamAccount)(uid=wvk))
# requesting: uid cn
#

*** Note that nothing is returned
# search result
search: 2
result: 0 Success

# numResponses: 1

*** Output of slapd for the second search ****

query template of incoming query = (&(objectClass=)(uid=))
Entering QC, querystr = (&(objectClass=sambaSamAccount)(uid=wvk))
Lock QC index = 31e698
QUERY ANSWERABLE


*** For another uid it works perfectly.

/usr/local/bin/ldapsearch -x -h localhost 
'(&(objectClass=sambaSamAccount)(uid=jim))' uid cn
# extended LDIF
#
# LDAPv3
# base <> with scope subtree
# filter: (&(objectClass=sambaSamAccount)(uid=jim))
# requesting: uid cn
#

# jim, People, few.vu.nl
dn: uid=jim,ou=People,dc=few,dc=vu,dc=nl
uid: jim
cn: W. van Keulen

# search result
search: 2
result: 0 Success

# numResponses: 2
# numEntries: 1
bash-2.05$ /usr/local/bin/ldapsearch -x -h localhost 
'(&(objectClass=sambaSamAccount)(uid=jim))' uid cn
# extended LDIF
#
# LDAPv3
# base <> with scope subtree
# filter: (&(objectClass=sambaSamAccount)(uid=jim))
# requesting: uid cn
#

# jim, People, few.vu.nl
dn: uid=jim,ou=People,dc=few,dc=vu,dc=nl
uid: jim
cn: W. van Keulen

# search result
search: 2
result: 0 Success

# numResponses: 2
# numEntries: 1
bash-2.05

*** Output of slapd for second case

$bash-2.05# ./slapd -d 4096
@(#) $OpenLDAP: slapd 2.4.16 (Jun 30 2009 16:56:26) $
 
jim@flits:/net/build.sparc/management/openldap/openldap-2.4.16/servers/slapd
/opt/openldap/openldap-2.4.16/etc/openldap/slapd.conf: line 78: rootdn 
is always granted unlimited privileges.
/opt/openldap/openldap-2.4.16/etc/openldap/slapd.conf: line 85: rootdn 
is always granted unlimited privileges.
Total # of attribute sets to be cached = 10.
Template:
   query template: (&(objectClass=)(uid=))
   attributes:
         uid
         cn
Template:
   query template: (&(uid=)(objectClass=))
   attributes:
         uid
         cn
slapd starting
query template of incoming query = (&(objectClass=)(uid=))
Entering QC, querystr = (&(objectClass=sambaSamAccount)(uid=jim))
Lock QC index = 31e698
Not answerable: Unlock QC index=31e698
QUERY NOT ANSWERABLE
QUERY CACHEABLE
Added query expires at 1249417816 (POSITIVE)
Lock AQ index = 31e698
TEMPLATE 31e698 QUERIES++ 1
Unlock AQ index = 31e698
Base of added query = dc=few,dc=vu,dc=nl
UUID for query being added = 2c8d245c-157d-102e-87c5-e7c795cd8bf5
ENTRY ADDED/MERGED, CACHED ENTRIES=0
STORED QUERIES = 1
query template of incoming query = (&(objectClass=)(uid=))
Entering QC, querystr = (&(objectClass=sambaSamAccount)(uid=jim))
Lock QC index = 31e698
QUERY ANSWERABLE






There is no difference if I reverse the filter. It works for
some uid's, but not for others.

Regards,

Jim

changed notes

> I am using 2.4.16. The problem is, that caching seems to work for some
> entries but not for others. It is not related to the order of the filter
> rules. Here is what happens:  (lines starting with *** are my comments)
>
>
>
> **** slapd is started showing version, query templates and attributes
>
> bash-2.05# ./slapd -d 4096
> @(#) $OpenLDAP: slapd 2.4.16 (Jun 30 2009 16:56:26) $
>
> jim@flits:/net/build.sparc/management/openldap/openldap-2.4.16/servers/slapd
> /opt/openldap/openldap-2.4.16/etc/openldap/slapd.conf: line 78: rootdn
> is always granted unlimited privileges.
> /opt/openldap/openldap-2.4.16/etc/openldap/slapd.conf: line 85: rootdn
> is always granted unlimited privileges.

This tells us you have some ACLs in place.  Could you show them? 
Actually, could you post your whole slapd.conf, if you're using any, or
the contents of your cn=config database?  Of course, after removing any
sensitive information, like passwords.

p.

masarati@aero.polimi.it wrote:
> 
> This tells us you have some ACLs in place.  Could you show them? 
> Actually, could you post your whole slapd.conf, if you're using any, or
> the contents of your cn=config database?  Of course, after removing any
> sensitive information, like passwords.
> 
> p.
> 

Here are slapd.conf and proxycache.conf as attachments.

regards,

Jim vK

> Here are slapd.conf and proxycache.conf as attachments.

I just wanted to feed back before I leave for a few days.  I don't see
anything critical in your files.  You explicitly give the rootdn write
permissions, which is useless, but apart from this everything looks fine.

I've tested a simple setup and it works as expected. I used HEAD and re24
code; the latter is nearly identical to 2.4.17.  I also tested with TLS.

At this point, I'm a bit clueless.  There must be something we're
overlooking.

p.

masarati@aero.polimi.it wrote:
>> Here are slapd.conf and proxycache.conf as attachments.
> 
> I just wanted to feed back before I leave for a few days.  I don't see
> anything critical in your files.  You explicitly give the rootdn write
> permissions, which is useless, but apart from this everything looks fine.
> 
> I've tested a simple setup and it works as expected. I used HEAD and re24
> code; the latter is nearly identical to 2.4.17.  I also tested with TLS.
> 
> At this point, I'm a bit clueless.  There must be something we're
> overlooking.
> 
> p.
> 

Here is some more info, that I just discovered.
If my filter rule is
'(&(objectClass=sambaSamAccount)(uid=wvk))'
the data is cached the first time, but not returned
the second and later time. However when my filter rule is
(&(objectClass=posixAccount)(uid=wvk))'
it works as expected.

Jim

w.van.keulen@few.vu.nl wrote:
> masarati@aero.polimi.it wrote:
>>> Here are slapd.conf and proxycache.conf as attachments.
>>
>> I just wanted to feed back before I leave for a few days.  I don't see
>> anything critical in your files.  You explicitly give the rootdn write
>> permissions, which is useless, but apart from this everything looks fine.
>>
>> I've tested a simple setup and it works as expected. I used HEAD and re24
>> code; the latter is nearly identical to 2.4.17.  I also tested with TLS.
>>
>> At this point, I'm a bit clueless.  There must be something we're
>> overlooking.

> Here is some more info, that I just discovered.
> If my filter rule is
> '(&(objectClass=sambaSamAccount)(uid=wvk))'
> the data is cached the first time, but not returned
> the second and later time. However when my filter rule is
> (&(objectClass=posixAccount)(uid=wvk))'
> it works as expected.

Sounds like you may have already had the entry in the cache DB but with an 
incompatible objectclass before, and the attempt to update it with the new 
objectclass failed. This seems to be related to ITS#6242 which was recently 
fixed in HEAD. Can you please retest with the latest overlays/pcache.c?

-- 
   -- 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 Open to Feedback

Howard Chu wrote:
> w.van.keulen@few.vu.nl wrote:
>> masarati@aero.polimi.it wrote:
>>>> Here are slapd.conf and proxycache.conf as attachments.
>>>
>>> I just wanted to feed back before I leave for a few days.  I don't see
>>> anything critical in your files.  You explicitly give the rootdn write
>>> permissions, which is useless, but apart from this everything looks 
>>> fine.
>>>
>>> I've tested a simple setup and it works as expected. I used HEAD and 
>>> re24
>>> code; the latter is nearly identical to 2.4.17.  I also tested with TLS.
>>>
>>> At this point, I'm a bit clueless.  There must be something we're
>>> overlooking.
> 
>> Here is some more info, that I just discovered.
>> If my filter rule is
>> '(&(objectClass=sambaSamAccount)(uid=wvk))'
>> the data is cached the first time, but not returned
>> the second and later time. However when my filter rule is
>> (&(objectClass=posixAccount)(uid=wvk))'
>> it works as expected.
> 
> Sounds like you may have already had the entry in the cache DB but with 
> an incompatible objectclass before, and the attempt to update it with 
> the new objectclass failed. This seems to be related to ITS#6242 which 
> was recently fixed in HEAD. Can you please retest with the latest 
> overlays/pcache.c?
> 

As you requested I retested with HEAD. However the cache is still not 
working correctly.

When my filter rule is:
'(&(objectClass=posixAccount)(uid=<who>))' the named attributes are 
cached and correctly returned from the cache for every uid from the 
existing user base
When my filter rule is:
'(&(objectClass=sambaSamAccount)(uid=<who>))' the named attributes are
cached and correctly returned from the cache for a subset of the 
existing user base only. For all uid's the query is cached (according to 
  the log), but for some no data is returned.

regards

Jim van K

-- 
// Set startup state to online
user_pref("offline.startup_state", 2);

Jim van Keulen wrote:
> Howard Chu wrote:
>> w.van.keulen@few.vu.nl wrote:
>>> masarati@aero.polimi.it wrote:
>>>>> Here are slapd.conf and proxycache.conf as attachments.
>>>>
>>>> I just wanted to feed back before I leave for a few days.  I don't see
>>>> anything critical in your files.  You explicitly give the rootdn write
>>>> permissions, which is useless, but apart from this everything looks
>>>> fine.
>>>>
>>>> I've tested a simple setup and it works as expected. I used HEAD and
>>>> re24
>>>> code; the latter is nearly identical to 2.4.17.  I also tested with TLS.
>>>>
>>>> At this point, I'm a bit clueless.  There must be something we're
>>>> overlooking.
>>
>>> Here is some more info, that I just discovered.
>>> If my filter rule is
>>> '(&(objectClass=sambaSamAccount)(uid=wvk))'
>>> the data is cached the first time, but not returned
>>> the second and later time. However when my filter rule is
>>> (&(objectClass=posixAccount)(uid=wvk))'
>>> it works as expected.
>>
>> Sounds like you may have already had the entry in the cache DB but with
>> an incompatible objectclass before, and the attempt to update it with
>> the new objectclass failed. This seems to be related to ITS#6242 which
>> was recently fixed in HEAD. Can you please retest with the latest
>> overlays/pcache.c?
>>
>
> As you requested I retested with HEAD. However the cache is still not
> working correctly.
>
> When my filter rule is:
> '(&(objectClass=posixAccount)(uid=<who>))' the named attributes are
> cached and correctly returned from the cache for every uid from the
> existing user base
> When my filter rule is:
> '(&(objectClass=sambaSamAccount)(uid=<who>))' the named attributes are
> cached and correctly returned from the cache for a subset of the
> existing user base only. For all uid's the query is cached (according to
>    the log), but for some no data is returned.

Sounds more like a schema config issue then. Most likely you don't have the 
matching schema in the proxy server, so it is unable to store the entries it 
has received.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

> Sounds more like a schema config issue then. Most likely you don't have
> the
> matching schema in the proxy server, so it is unable to store the entries
> it
> has received.

That was my first thought as well, but the proxy's slapd.conf he posted
earlier included some samba-related schema file (I'm blindly assuming that
file was defining sambaSamAccount).

p.

changed state Feedback to Closed

I am experiencing what appears to be the same issue, and opened a ticket -
http://www.openldap.org/its/index.cgi?findid=6831 - because this one did not pop up when I searched for existing ITS's
(perhaps my search terms did not match or I just overlooked it).  As I mentioned in the ticket I opened, this is not a
schema issue - all the schema match on every server, and if that were the problem, none of the users would be served
properly.  What I found is that the keys that proxycache was looking for did not exist in the bdb it was searching.  Why
exactly that is, I'm not sure.  Hopefully the information I provided in that ITS (or, perhaps some additional debugging
information - gdb output or copies of databases exhibiting the problem) will help shed some light.  If it is indeed the
same issue, I'm all for coalescing the two.  I have tested this all the way up through 2.4.23, and there are no commits
to pcache.c or back-ldap/search.c since 2.4.23 was released that addresses this problem.

ryans@aweber.com wrote:
> I am experiencing what appears to be the same issue, and opened a ticket -
> http://www.openldap.org/its/index.cgi?findid=6831 - because this one did not pop up when I searched for existing ITS's
> (perhaps my search terms did not match or I just overlooked it).  As I mentioned in the ticket I opened, this is not a
> schema issue - all the schema match on every server, and if that were the problem, none of the users would be served
> properly.  What I found is that the keys that proxycache was looking for did not exist in the bdb it was searching.  Why
> exactly that is, I'm not sure.  Hopefully the information I provided in that ITS (or, perhaps some additional debugging
> information - gdb output or copies of databases exhibiting the problem) will help shed some light.  If it is indeed the
> same issue, I'm all for coalescing the two.  I have tested this all the way up through 2.4.23, and there are no commits
> to pcache.c or back-ldap/search.c since 2.4.23 was released that addresses this problem.

Since you are not having the objectclass-related problem described in this 
ticket it is not the same issue.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

Also, this is not the same as ITS#6242, because the patch for that issue (adding the manageDSAit control) already exists
in the versions of OpenLDAP I've tested with (2.4.21, 2.4.23).

hyc@symas.com wrote:
>
> ryans@aweber.com wrote:
> > I am experiencing what appears to be the same issue, and opened a
> > ticket - http://www.openldap.org/its/index.cgi?findid=6831 -
> > because this one did not pop up when I searched for existing ITS's
> > (perhaps my search terms did not match or I just overlooked it).
> > As I mentioned in the ticket I opened, this is not a schema issue;
> > all the schema match on every server, and if that were the problem,
> > none of the users would be served properly.  What I found is that
> > the keys that proxycache was looking for did not exist in the bdb
> > it was searching.  Why exactly that is, I'm not sure.  Hopefully
> > the information I provided in that ITS (or, perhaps some additional
> > debugging information - gdb output or copies of databases exhibiting
> > the problem) will help shed some light.  If it is indeed the same
> > issue, I'm all for coalescing the two.  I have tested this all the
> > way up through 2.4.23, and there are no commits to pcache.c or
> > back-ldap/search.c since 2.4.23 was released that addresses this problem.
>
> Since you are not having the objectclass-related problem described in this
> ticket it is not the same issue.

Actually, having just tested that theory, I think my problem is actually objectclass-related, because it seems that it
only happens when the objectClass attribute is included in the filter, and I can get different results by swapping the
order of the filter components.  Consider these two users, who have the same objectclasses, same attributes, and differ
only in the attribute values (e.g., their name, phone number, and so on):

bash:~# ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomEmployee)(objectClass=examplecomUtilityUser))(uid=jdoe1))' uid
dn: uid=jdoe1,ou=Users,dc=example,dc=com
uid: jdoe1

bash:~# ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomEmployee)(objectClass=examplecomUtilityUser))(uid=jdoe2))' uid


So, one entry doesn't get returned when it should.  If I reverse the filter, I get the expected results:

bash:~# ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe1))' uid
dn: uid=jdoe1,ou=Users,dc=example,dc=com
uid: jdoe1

bash:~# ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe2))' uid
dn: uid=jdoe2,ou=Users,dc=example,dc=com
uid: jdoe2

Furthermore, if I now try the first query again, it too works:

bash:~# ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomEmployee)(objectClass=examplecomUtilityUser))(uid=jdoe1))' uid
dn: uid=jdoe1,ou=Users,dc=example,dc=com
uid: jdoe1

bash:~# ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomEmployee)(objectClass=examplecomUtilityUser))(uid=jdoe2))' uid
dn: uid=jdoe2,ou=Users,dc=example,dc=com
uid: jdoe2


And, like Jim, I already have the patch for ITS#5756 applied in 2.4.17, 2.4.21, and 2.4.23.  I can give you an example
database exhibiting this behavior, if you like?

I just uploaded two log file snippets for consideration (also posted to ITS#6831, since there has not been a formal
merge or acceptance of the two being one and the same).  One is a failed query to the proxycache database exhibiting
this problem, and the other is a successful query to the same proxycache database.  A gzipp'ed tarball can be found
here: ftp://ftp.openldap.org/incoming/ryan-steele-110221.proxycache-logs-for-comparison.tar.gz.

For reference, the queries issued and results for each were:

## Failed query
ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe1))' uid

## Successful query
ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe2))' uid
dn: uid=jdoe2,ou=Users,dc=example,dc=com
uid: jdoe2

The cache reported both to be "ANSWERABLE" before attempting to retrieve the data.


Up until the point where the unsuccessful query fails to read the key for the UID equality candidate, both the failed
query and the successful query lock the same exact QC index (0x7f50429860f0), attempt to fetch the exact same keys
([b49d1940], [807e234d], [8f951c4a]), and compare the exact same equality/filter/list candidates ("id=9, first=2699,
last=2731").  This is what I would expect, since the values for the two objectClasses in the search filter are the same.

However, once it gets to the point where it compares the bdb_equality_candidates for the UID, the values of the
bdb_filter_candidates, bdb_equality_candidates, and bdb_list_candidates in logs for the unsuccessful query are a little
confusing:

## UID portion of unsuccessful query

Feb 21 10:02:00 blog2 slapd[18797]: bdb_idl_fetch_key: [8f951c4a]
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_index_read 9 candidates
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_equality_candidates: id=9, first=2699, last=2731
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=9 first=2699 last=2731
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:02:00 blog2 slapd[18797]: => bdb_filter_candidates
Feb 21 10:02:00 blog2 slapd[18797]:     EQUALITY
Feb 21 10:02:00 blog2 slapd[18797]: => bdb_equality_candidates (uid)
Feb 21 10:02:00 blog2 slapd[18797]: => key_read
Feb 21 10:02:00 blog2 slapd[18797]: bdb_idl_fetch_key: [efb8b856]
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_equality_candidates: id=0, first=0, last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=0 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=0 first=2699 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=2699 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=0 first=0 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=0 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=0 first=2 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=2 last=0
Feb 21 10:02:00 blog2 slapd[18797]: bdb_search_candidates: id=0 first=2 last=0
Feb 21 10:02:00 blog2 slapd[18797]: hdb_search: no candidates


## UID portion of successful query

Feb 21 10:06:22 blog2 slapd[18797]: bdb_idl_fetch_key: [8f951c4a]
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_index_read 9 candidates
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_equality_candidates: id=9, first=2699, last=2731
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=9 first=2699 last=2731
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:06:22 blog2 slapd[18797]: => bdb_filter_candidates
Feb 21 10:06:22 blog2 slapd[18797]:     EQUALITY
Feb 21 10:06:22 blog2 slapd[18797]: => bdb_equality_candidates (uid)
Feb 21 10:06:22 blog2 slapd[18797]: => key_read
Feb 21 10:06:22 blog2 slapd[18797]: bdb_idl_fetch_key: [ea38ed84]
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_index_read 1 candidates
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_equality_candidates: id=1, first=2701, last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: bdb_search_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: => test_filter

I gather that a value of "0" for id/first/last is normal when it cannot find the index in question (as it does for the
UID value that it had deemed to be answerable), but the "first=2" and "first=2699" values seem a little strange,
especially since the "first=2699" value supposedly matches the bdb_equality_candidates "first" value found at one of the
indices searched for the objectClass attribute(s).  I have no idea where the value "2" comes from, but it too seems
incorrect if it couldn't find the index.  Perhaps those values make more sense in the context of it thinking it could
find the values, but then ultimately not being able to (though I admit that sounds like a pretty big stretch).


Unfortunately, I don't understand enough about what's going here, or where things might be going awry in the codebase,
to abstract something more meaningful from these logs, but hopefully this provides a little bit of framing/contextual
information to someone else that does.


Cheers

Additionally, today I found myself in a situation where reversing the order of *just* the objectClasses in the filter -
i.e., from (&(|(objectClass=foo)(objectClass=bar))(uid=jdoe1)) to (&(|(objectClass=bar)(objectClass=foo))(uid=jdoe1)) -
didn't fix things, but changing the search base (from ou=Users,dc=example,dc=com to dc=example,dc=com) did.

I was then able to issue the original search with searchbase ou=Users,dc=example,dc=com and filter
(&(|(objectClass=foo)(objectClass=bar))(uid=jdoe1)) and it worked fine.  Strange...

Some more information: once I changed the search base from ou=Users,dc=example,dc=com to dc=example,dc=com to "fix" the
problem for that particular user (after which the original query with the ou=Users,dc=example,dc=com search base began
working again), the following entries popped up in the log:
ftp://ftp.openldap.org/incoming/ryan-steele-110221.proxycache-log-fixing-broken-entries.log.1

It gets stranger, though.  If I start out by using the root entry as the search base (dc=example,dc=com) with a user who
is not yet in the cache, not only will it say it is ANSWERABLE (which it clearly isn't) and then return nothing without
even trying to reach out to the upstream host, but if I then change the search base to ou=Users,dc=example,dc=com, I get
the following error on the CLI (and this is with a successful bind as the directory admin):


ldapsearch -x -D cn=admin,dc=example,dc=com -y /etc/ldap.secret -H ldaps://localhost -LLL -b cn=admin,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe4))' uid
No such object (32)
Matched DN: dc=example,dc=com

Debugging logs generated by that query can be found here:
ftp://ftp.openldap.org/incoming/ryan-steele-110221.proxycache-log-attempt-to-fix-broken-entries-error.log.1

See ITS#6242