(ITS#5680) pcache not returning cached entries

[quanah@zimbra.com]

Full_Name: Quanah Gibson-Mount
Version: 2.4.10
OS: Linux 2.6
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (75.111.29.239)


As reported on the Debian bug tracker as bug#497697.

The pcache overlay caches the entries but fails to return them in later
searches.

Search with empty cache:
| # extended LDIF
| #
| # LDAPv3
| # base <cn=blank,o=Example> with scope subtree
| # filter: (objectclass=person)
| # requesting: cn 
| #
| 
| # blank, Example
| dn: cn=blank,o=Example
| 
| # search result
| search: 2
| result: 0 Success
| 
| # numResponses: 2
| # numEntries: 1

Search with hot cache:
| # extended LDIF
| #
| # LDAPv3
| # base <cn=blank,o=Example> with scope subtree
| # filter: (objectclass=person)
| # requesting: cn 
| #
| 
| # search result
| search: 2
| result: 0 Success
| 
| # numResponses: 1

Config:
| allow bind_anon_cred update_anon
| include         /etc/ldap/schema/core.schema
| pidfile         /var/run/slapd/slapd.pid
| argsfile        /var/run/slapd/slapd.args
| loglevel        none
| modulepath      /usr/lib/ldap
| moduleload      back_bdb
| moduleload      back_ldap
| moduleload      pcache
| sizelimit 500
| tool-threads 1
| 
| database        ldap
| suffix          "o=Example"
| rootdn          "cn=admin,o=Example"
| uri             "ldap://ldap.example.com/";
| protocol-version 3
| 
| overlay pcache
| proxycache bdb 10000 1 500 1000
| proxyattrset 0 cn
| proxytemplate "(objectClass=)" 0 3600
| directory       "/var/lib/ldap/cache"
| 
| access to * by * write

Log of first search:
| conn=0 op=1 SRCH base="cn=blank,o=Example" scope=2 deref=0
filter="(objectClass=person)"
| conn=0 op=1 SRCH attr=cn
| ==> limits_get: conn=0 op=1 dn="[anonymous]"
| query template of incoming query = (objectClass=)
| Entering QC, querystr = (objectClass=person)
| Lock QC index = 0x7d7040
| Not answerable: Unlock QC index=0x7d7040
| QUERY NOT ANSWERABLE
| QUERY CACHEABLE
| [...]
| send_ldap_result: conn=-1 op=0 p=3
| send_ldap_result: err=0 matched="" text=""
| ENTRY ADDED/MERGED, CACHED ENTRIES=1
| STORED QUERIES = 1

Log of second search:
| conn=1 op=1 SRCH base="cn=blank,o=Example" scope=2 deref=0
filter="(objectClass=person)"
| conn=1 op=1 SRCH attr=cn
| ==> limits_get: conn=1 op=1 dn="[anonymous]"
| query template of incoming query = (objectClass=)
| Entering QC, querystr = (objectClass=person)
| Lock QC index = 0x7d7040
| QUERY ANSWERABLE
| => bdb_search
Search in the cache db for (!(objectClass=glue)) or so.

| bdb_dn2entry("cn=blank,ou=cz,o=jura")
| => access_allowed: search access to "cn=blank,o=Example" "entry" requested
| => acl_get: [1] attr entry
| => acl_mask: access to entry "cn=blank,o=Example", attr "entry" requested
| => acl_mask: to all values by "", (=0)
| <= check a_dn_pat: *
| <= acl_mask: [1] applying write(=wrscxd) (stop)
| <= acl_mask: [1] mask: write(=wrscxd)
| => slap_access_allowed: search access granted by write(=wrscxd)
| => access_allowed: search access granted by write(=wrscxd)
| search_candidates: base="cn=blank,ou=cz,o=jura" (0x00000003) scope=2
| => bdb_dn2idl("cn=blank,ou=cz,o=jura")
| bdb_idl_fetch_key: @cn=blank,ou=cz,o=jura
| <= bdb_dn2idl: id=1 first=3 last=3
| => bdb_filter_candidates
|         AND
| => bdb_list_candidates 0xa0
| => bdb_filter_candidates
|         OR
| => bdb_list_candidates 0xa1
| => bdb_filter_candidates
|         EQUALITY
| => bdb_equality_candidates (objectClass)
| <= bdb_equality_candidates: (objectClass) not indexed
| <= bdb_filter_candidates: id=-1 first=1 last=3
| => bdb_filter_candidates
|         EQUALITY
| => bdb_equality_candidates (objectClass)
| <= bdb_equality_candidates: (objectClass) not indexed
| <= bdb_filter_candidates: id=-1 first=1 last=3
| <= bdb_list_candidates: id=-1 first=1 last=3
| <= bdb_filter_candidates: id=-1 first=1 last=3
| <= bdb_list_candidates: id=1 first=3 last=3
| <= bdb_filter_candidates: id=1 first=3 last=3
| bdb_search_candidates: id=1 first=3 last=3
| => test_filter
|     EQUALITY
| => access_allowed: search access to "cn=blank,ou=CZ,o=Jura" "objectClass"
requested
| => acl_get: [1] attr objectClass
| => acl_mask: access to entry "cn=blank,ou=CZ,o=Jura", attr "objectClass"
requested
| => acl_mask: to value by "", (=0)
| <= check a_dn_pat: *
| <= acl_mask: [1] applying write(=wrscxd) (stop)
| <= acl_mask: [1] mask: write(=wrscxd)
| => slap_access_allowed: search access granted by write(=wrscxd)
| => access_allowed: search access granted by write(=wrscxd)
| <= test_filter 21
test_filter returned LDAP_INVALID_SYNTAX.

| bdb_search: 3 does not match filter

Content of the cache db:
| dn: o=Example
| structuralObjectClass: glue
| objectClass: top
| objectClass: glue
| 
| dn: cn=blank,o=Example
| queryId: c975e84a-0e16-102d-8355-4be7c415200f
| queryId: 9b7f1afa-0e17-102d-8bae-452c11e3ff2d
| objectClass: inetOrgPerson
| objectClass: organizationalPerson
| objectClass: person
| objectClass: ndsLoginProperties
| objectClass: top

The backend server is a Novell eDirectory and the proxy don't have
information about the complete schema.

Bastian