hi-
i'm having a few different issues with slapo-pcache. i did a bit of searching in the its and did not find any items which seemed to match my symptoms. i'm using 2.4.31, on ubuntu 12.10.
the first is that i so to not be able to add, via ldapadd, additional olcPcacheTemplate attributes to the config entry. i was able to add the first one using ldapadd, but subsequent modify operations to add another complain "no equality matching rule":
ldapsearch -LLLZZxWH 'ldap://localhost/' -D 'cn=config' -b 'olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config' -s base
Enter LDAP Password: dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+" olcPcacheTemplate: "(uid=)" 0 3600
cat template.ldif
dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config changetype: modify add: olcPcacheTemplate olcPcacheTemplate: "(cn=)" 0 3600
ldapadd -ZZxWH 'ldap://localhost/' -D 'cn=config' -f template.ldif
Enter LDAP Password: modifying entry "olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config" ldap_modify: Inappropriate matching (18) additional info: modify/add: olcPcacheTemplate: no equality matching rule
Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 op=0 STARTTLS Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 op=0 RESULT oid= err=0 text= Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 fd=12 ACCEPT from IP=127.0.0.1:32916 (IP=0.0.0.0:389) Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 fd=12 TLS established tls_ssf=128 ssf=128 Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=1 BIND dn="cn=config" method=128 Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=1 BIND dn="cn=config" mech=SIMPLE ssf=0 Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=1 RESULT tag=97 err=0 text= Oct 29 20:01:32 dsa1 slapd[8250]: connection_input: conn=1003 deferring operation: binding Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=2 MOD dn="olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config" Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=2 MOD attr=olcPcacheTemplate Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=2 RESULT tag=103 err=18 text=modify/add: olcPcacheTemplate: no equality matching rule Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=3 UNBIND Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 fd=12 closed
adding the attribute "manually" [e.g. slapcat, modify ldif, slapadd] seems to be fine:
ldapsearch -LLLZZxWH 'ldap://localhost/' -D 'cn=config' -b 'olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config' -s base
Enter LDAP Password: dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+" olcPcacheTemplate: "(objectclass=)" 0 3600 olcPcacheTemplate: "(uid=)" 0 3600
my second problem is with caching when slapo-nssov is involved. it appears to not cache [QUERY NOT ANSWERABLE/QUERY NOT CACHEABLE] when a query occurs via nss:
getent passwd flash
flash:x:2013:2013:flash gordon:/home/flash:/bin/bash
Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on: Oct 31 08:42:15 deepfield slapd[12862]: 11r Oct 31 08:42:15 deepfield slapd[12862]: Oct 31 08:42:15 deepfield slapd[12862]: daemon: read active on 11 Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: connection_get(11) Oct 31 08:42:15 deepfield slapd[12862]: connection_get(11): got connid=0 Oct 31 08:42:15 deepfield slapd[12862]: nssov: connection from uid=0 gid=0 Oct 31 08:42:15 deepfield slapd[12862]: nssov_passwd_byname(flash) Oct 31 08:42:15 deepfield slapd[12862]: str2filter "(&(objectClass=posixAccount)(uid=flash))" Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter Oct 31 08:42:15 deepfield slapd[12862]: AND Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter_list Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter Oct 31 08:42:15 deepfield slapd[12862]: EQUALITY Oct 31 08:42:15 deepfield slapd[12862]: end get_filter 0 Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:42:15 deepfield slapd[12862]: EQUALITY Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on: Oct 31 08:42:15 deepfield slapd[12862]: end get_filter 0 Oct 31 08:42:15 deepfield slapd[12862]: Oct 31 08:42:15 deepfield slapd[12862]: end get_filter_list Oct 31 08:42:15 deepfield slapd[12862]: end get_filter 0 Oct 31 08:42:15 deepfield slapd[12862]: query template of incoming query = (&(objectClass=)(uid=)) Oct 31 08:42:15 deepfield slapd[12862]: QUERY NOT ANSWERABLE Oct 31 08:42:15 deepfield slapd[12862]: QUERY NOT CACHEABLE Oct 31 08:42:15 deepfield slapd[12862]: =>ldap_back_getconn: conn 0xb51f8ee8 fetched refcnt=1. Oct 31 08:42:15 deepfield slapd[12862]: => ldap_back_munge_filter "(&(objectClass=posixAccount)(uid=flash))" Oct 31 08:42:15 deepfield slapd[12862]: <= ldap_back_munge_filter "(&(objectClass=posixAccount)(uid=flash))" (0) Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: >>> dnPrettyNormal: <uid=flash,ou=people,ou=accounts,dc=example,dc=net> Oct 31 08:42:15 deepfield slapd[12862]: <<< dnPrettyNormal: <uid=flash,ou=people,ou=accounts,dc=example,dc=net>, <uid=flash,ou=people,ou=accounts,dc=example,dc=net> Oct 31 08:42:15 deepfield slapd[12862]: send_ldap_result: conn=-1 op=0 p=0 Oct 31 08:42:15 deepfield slapd[12862]: send_ldap_result: err=0 matched="" text=""
although i believe i have a matching query template defined in the config:
dn: olcDatabase={2}ldap,cn=config objectClass: olcLDAPConfig objectClass: olcDatabaseConfig objectClass: olcConfig objectClass: top olcDatabase: {2}ldap olcSuffix: dc=example,dc=net olcLastMod: TRUE olcReadOnly: TRUE olcRootDN: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net olcMonitoring: TRUE olcDbURI: ldap://dsa1.example.net/ olcDbStartTLS: start tls_cacert="/etc/pki/trusted_roots/example_networks_roo t_ca-cert.pem" tls_reqcert="demand" olcDbACLBind: bindmethod=simple binddn="cn=slapd,ou=deepfield,ou=services,ou=a ccounts,dc=example,dc=net" credentials="xxxxxxxxxxxxxxx" s tarttls="critical" tls_cacert="/etc/pki/trusted_roots/example_networks_root _ca-cert.pem" tls_reqcert="demand" olcDbIDAssertBind: bindmethod=simple binddn="cn=slapd,ou=deepfield,ou=services ,ou=accounts,dc=example,dc=net" credentials="xxxxxxxxxxxxxxx" structuralObjectClass: olcLDAPConfig entryUUID: f24e435a-b35a-1031-8f37-336141b7bc90 creatorsName: cn=config createTimestamp: 20121026014812Z entryCSN: 20121031023501.089672Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121031023501Z
dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+" olcPcacheTemplate: "(objectClass=)" 0 3600 olcPcacheTemplate: "(uid=)" 0 3600 olcPcacheTemplate: "(&(objectClass=)(uid=))" 0 3600 olcPcacheBind: "(uid=)" 0 60 "sub" "dc=example,dc=net" structuralObjectClass: olcPcacheConfig entryUUID: ddb05d7e-b4fa-1031-811e-353e11fff366 creatorsName: cn=config createTimestamp: 20121028032528Z entryCSN: 20121030002115.179177Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121030002115Z
dn: olcDatabase={0}mdb,olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheDatabase objectClass: olcMdbConfig objectClass: olcDatabaseConfig objectClass: olcConfig objectClass: top olcDatabase: {0}mdb olcDbDirectory: /var/lib/ldap/example.net/ olcLastMod: TRUE olcMaxDerefDepth: 15 olcDbNoSync: FALSE olcDbIndex: certfingerprint eq olcDbIndex: cn eq olcDbIndex: default eq olcDbIndex: description eq olcDbIndex: entrycsn eq olcDbIndex: entryuuid eq olcDbIndex: gidnumber pres,eq olcDbIndex: host eq olcDbIndex: iphostnumber eq olcDbIndex: ipserviceport eq olcDbIndex: ipserviceprotocol eq olcDbIndex: mail eq olcDbIndex: maillocaladdress eq olcDbIndex: member eq olcDbIndex: memberof eq olcDbIndex: memberuid eq olcDbIndex: objectclass eq olcDbIndex: rfc822mailmember eq olcDbIndex: sudoUser eq olcDbIndex: uid pres,eq,sub olcDbIndex: uidnumber pres,eq olcDbMode: 0600 olcDbSearchStack: 16 structuralObjectClass: olcMdbConfig entryUUID: 88b37716-b590-1031-8c75-439de7087923 creatorsName: cn=config createTimestamp: 20121028211650Z entryCSN: 20121029021315.039143Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121029021315Z
dn: olcOverlay={1}nssov,olcDatabase={2}ldap,cn=config objectClass: olcNssOvConfig objectClass: olcOverlayConfig objectClass: olcConfig olcOverlay: {1}nssov olcNssMap: group uniquemember member olcNssPam: authz2dn hostservice olcNssPamSession: sshd olcNssPamSession: login structuralObjectClass: olcNssOvConfig entryUUID: 47ecaef0-b73e-1031-8761-9f0bff5d3212 creatorsName: cn=config createTimestamp: 20121031003305Z entryCSN: 20121031003305.637051Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121031003305Z
and if i perform the same query using ldapsearch:
ldapsearch -LLLZZxH 'ldap://localhost/' -D 'uid=flash,ou=people,ou=accounts,dc=example,dc=net' -w 'test' '(&(objectClass=posixAccount)(uid=flash))'
dn: uid=flash,ou=people,ou=accounts,dc=example,dc=net initials: fg givenName: flash loginShell: /bin/bash uidNumber: 2013 gidNumber: 2013 uid: flash objectClass: posixAccount objectClass: top objectClass: shadowAccount objectClass: inetOrgPerson objectClass: organizationalPerson objectClass: person objectClass: extensibleObject c: us homeDirectory: /home/flash sn: gordon cn: flash gordon displayName: flash_gordon mail: user@example.com
it does seem to cache it:
Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: slap_listener_activate(8): Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 busy Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: >>> slap_listener(ldap:///) Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: listen=8, new connection on 18 Oct 31 08:55:37 deepfield slapd[12862]: daemon: added 18r (active) listener=(nil) Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 fd=18 ACCEPT from IP=127.0.0.1:37220 (IP=0.0.0.0:389) Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: 18r Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: read active on 18 Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18) Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18): got connid=1003 Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: connection_read(18): checking for input on id=1003 Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: op tag 0x77, time 1351688137 Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=0 do_extended Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Oct 31 08:55:37 deepfield slapd[12862]: do_extended: oid=1.3.6.1.4.1.1466.20037 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=0 STARTTLS Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_extended: err=0 oid= len=0 Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_response: msgid=1 tag=120 err=0 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=0 RESULT oid= err=0 text= Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: 18r Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: read active on 18 Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18) Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18): got connid=1003 Oct 31 08:55:37 deepfield slapd[12862]: connection_read(18): checking for input on id=1003 Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: 18r Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: read active on 18 Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18) Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18): got connid=1003 Oct 31 08:55:37 deepfield slapd[12862]: connection_read(18): checking for input on id=1003 Oct 31 08:55:37 deepfield slapd[12862]: connection_read(18): unable to get TLS client DN, error=49 id=1003 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 fd=18 TLS established tls_ssf=128 ssf=128 Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: 18r Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: read active on 18 Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18) Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18): got connid=1003 Oct 31 08:55:37 deepfield slapd[12862]: connection_read(18): checking for input on id=1003 Oct 31 08:55:37 deepfield slapd[12862]: op tag 0x60, time 1351688137 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=1 do_bind Oct 31 08:55:37 deepfield slapd[12862]: >>> dnPrettyNormal: <uid=flash,ou=people,ou=accounts,dc=example,dc=net> Oct 31 08:55:37 deepfield slapd[12862]: <<< dnPrettyNormal: <uid=flash,ou=people,ou=accounts,dc=example,dc=net>, <uid=flash,ou=people,ou=accounts,dc=example,dc=net> Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=1 BIND dn="uid=flash,ou=people,ou=accounts,dc=example,dc=net" method=128 Oct 31 08:55:37 deepfield slapd[12862]: do_bind: version=3 dn="uid=flash,ou=people,ou=accounts,dc=example,dc=net" method=128 Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_get: ndn: "uid=flash,ou=people,ou=accounts,dc=example,dc=net" Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_get: oc: "(null)", at: "(null)" Oct 31 08:55:37 deepfield slapd[12862]: mdb_dn2entry("uid=flash,ou=people,ou=accounts,dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: => mdb_dn2id("uid=flash,ou=people,ou=accounts,dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_dn2id: got id=0x4 Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_decode: Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_entry_decode Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_get: found entry: "uid=flash,ou=people,ou=accounts,dc=example,dc=net" Oct 31 08:55:37 deepfield slapd[12862]: mdb_entry_get: rc=0 Oct 31 08:55:37 deepfield slapd[12862]: str2filter "(uid=flash)" Oct 31 08:55:37 deepfield slapd[12862]: begin get_filter Oct 31 08:55:37 deepfield slapd[12862]: EQUALITY Oct 31 08:55:37 deepfield slapd[12862]: end get_filter 0 Oct 31 08:55:37 deepfield slapd[12862]: Lock QC index = 0xb867e250 Oct 31 08:55:37 deepfield slapd[12862]: Base of added query = dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: QUERY ANSWERABLE (answered 5 times) Oct 31 08:55:37 deepfield slapd[12862]: => mdb_search Oct 31 08:55:37 deepfield slapd[12862]: mdb_dn2entry("uid=flash,ou=people,ou=accounts,dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: => mdb_dn2id("uid=flash,ou=people,ou=accounts,dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_dn2id: got id=0x4 Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_decode: Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_entry_decode Oct 31 08:55:37 deepfield slapd[12862]: => access_allowed: search access to "uid=flash,ou=people,ou=accounts,dc=example,dc=net" "entry" requested Oct 31 08:55:37 deepfield slapd[12862]: <= root access granted Oct 31 08:55:37 deepfield slapd[12862]: => access_allowed: search access granted by manage(=mwrscxd) Oct 31 08:55:37 deepfield slapd[12862]: base_candidates: base: "uid=flash,ou=people,ou=accounts,dc=example,dc=net" (0x00000004) Oct 31 08:55:37 deepfield slapd[12862]: => test_filter Oct 31 08:55:37 deepfield slapd[12862]: EQUALITY Oct 31 08:55:37 deepfield slapd[12862]: => access_allowed: search access to "uid=flash,ou=people,ou=accounts,dc=example,dc=net" "uid" requested Oct 31 08:55:37 deepfield slapd[12862]: <= root access granted Oct 31 08:55:37 deepfield slapd[12862]: => access_allowed: search access granted by manage(=mwrscxd) Oct 31 08:55:37 deepfield slapd[12862]: <= test_filter 6 Oct 31 08:55:37 deepfield slapd[12862]: pc_bind_search: cache is stale, reftime: 1351688135, current time: 1351688137 Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_result: conn=1003 op=1 p=3 Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_result: err=0 matched="" text="" Oct 31 08:55:37 deepfield slapd[12862]: =>ldap_back_getconn: conn=1003 op=1: lc=0xb38f9788 inserted refcnt=1 rc=0 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=1 BIND dn="uid=flash,ou=people,ou=accounts,dc=example,dc=net" mech=SIMPLE ssf=0 Oct 31 08:55:37 deepfield slapd[12862]: do_bind: v3 bind: "uid=flash,ou=people,ou=accounts,dc=example,dc=net" to "uid=flash,ou=people,ou=accounts,dc=example,dc=net" Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_result: conn=1003 op=1 p=3 Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_result: err=0 matched="" text="" Oct 31 08:55:37 deepfield slapd[12862]: pc_setpw: CACHING BIND for uid=flash,ou=people,ou=accounts,dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: mdb_modify: uid=flash,ou=people,ou=accounts,dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: mdb_dn2entry("uid=flash,ou=people,ou=accounts,dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: => mdb_dn2id("uid=flash,ou=people,ou=accounts,dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_dn2id: got id=0x4 Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_decode: Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_entry_decode Oct 31 08:55:37 deepfield slapd[12862]: mdb_modify_internal: 0x00000004: uid=flash,ou=people,ou=accounts,dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: <= acl_access_allowed: granted to database root Oct 31 08:55:37 deepfield slapd[12862]: mdb_modify_internal: replace userPassword Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_encode(0x00000004): uid=flash,ou=people,ou=accounts,dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_entry_encode(0x00000004): uid=flash,ou=people,ou=accounts,dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: mdb_modify: updated id=00000004 dn="uid=flash,ou=people,ou=accounts,dc=example,dc=net" Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_result: conn=1003 op=1 p=3 Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_result: err=0 matched="" text="" Oct 31 08:55:37 deepfield slapd[12862]: send_ldap_response: msgid=2 tag=97 err=0 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=1 RESULT tag=97 err=0 text= Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: 18r Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: read active on 18 Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18) Oct 31 08:55:37 deepfield slapd[12862]: connection_get(18): got connid=1003 Oct 31 08:55:37 deepfield slapd[12862]: connection_read(18): checking for input on id=1003 Oct 31 08:55:37 deepfield slapd[12862]: op tag 0x63, time 1351688137 Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=2 do_search Oct 31 08:55:37 deepfield slapd[12862]: >>> dnPrettyNormal: <dc=example,dc=net> Oct 31 08:55:37 deepfield slapd[12862]: <<< dnPrettyNormal: <dc=example,dc=net>, <dc=example,dc=net> Oct 31 08:55:37 deepfield slapd[12862]: SRCH "dc=example,dc=net" 2 0 Oct 31 08:55:37 deepfield slapd[12862]: 0 60 0 Oct 31 08:55:37 deepfield slapd[12862]: begin get_filter Oct 31 08:55:37 deepfield slapd[12862]: AND Oct 31 08:55:37 deepfield slapd[12862]: begin get_filter_list Oct 31 08:55:37 deepfield slapd[12862]: begin get_filter Oct 31 08:55:37 deepfield slapd[12862]: EQUALITY Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:55:37 deepfield slapd[12862]: daemon: activity on: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:55:37 deepfield slapd[12862]: end get_filter 0 Oct 31 08:55:37 deepfield slapd[12862]: begin get_filter Oct 31 08:55:37 deepfield slapd[12862]: EQUALITY Oct 31 08:55:37 deepfield slapd[12862]: end get_filter 0 Oct 31 08:55:37 deepfield slapd[12862]: end get_filter_list Oct 31 08:55:37 deepfield slapd[12862]: end get_filter 0 Oct 31 08:55:37 deepfield slapd[12862]: filter: (&(objectClass=posixAccount)(uid=flash)) Oct 31 08:55:37 deepfield slapd[12862]: attrs: Oct 31 08:55:37 deepfield slapd[12862]: Oct 31 08:55:37 deepfield slapd[12862]: conn=1003 op=2 SRCH base="dc=example,dc=net" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=flash))" Oct 31 08:55:37 deepfield slapd[12862]: ==> limits_get: conn=1003 op=2 self="uid=flash,ou=people,ou=accounts,dc=example,dc=net" this="dc=example,dc=net" Oct 31 08:55:37 deepfield slapd[12862]: query template of incoming query = (&(objectClass=)(uid=)) Oct 31 08:55:37 deepfield slapd[12862]: Entering QC, querystr = (&(objectClass=posixAccount)(uid=flash)) Oct 31 08:55:37 deepfield slapd[12862]: Lock QC index = 0xb867e350 Oct 31 08:55:37 deepfield slapd[12862]: Base of added query = dc=example,dc=net Oct 31 08:55:37 deepfield slapd[12862]: QUERY ANSWERABLE (answered 1 times) Oct 31 08:55:37 deepfield slapd[12862]: => mdb_search Oct 31 08:55:37 deepfield slapd[12862]: mdb_dn2entry("dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: => mdb_dn2id("dc=example,dc=net") Oct 31 08:55:37 deepfield slapd[12862]: <= mdb_dn2id: got id=0x1 Oct 31 08:55:37 deepfield slapd[12862]: => mdb_entry_decode:
what am i doing wrong?
-ben
btb@bitrate.net wrote:
hi-
i'm having a few different issues with slapo-pcache. i did a bit of searching in the its and did not find any items which seemed to match my symptoms. i'm using 2.4.31, on ubuntu 12.10.
the first is that i so to not be able to add, via ldapadd, additional olcPcacheTemplate attributes to the config entry. i was able to add the first one using ldapadd, but subsequent modify operations to add another complain "no equality matching rule":
ldapsearch -LLLZZxWH 'ldap://localhost/' -D 'cn=config' -b 'olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config' -s base
Enter LDAP Password: dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+" olcPcacheTemplate: "(uid=)" 0 3600
cat template.ldif
dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config changetype: modify add: olcPcacheTemplate olcPcacheTemplate: "(cn=)" 0 3600
ldapadd -ZZxWH 'ldap://localhost/' -D 'cn=config' -f template.ldif
Enter LDAP Password: modifying entry "olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config" ldap_modify: Inappropriate matching (18) additional info: modify/add: olcPcacheTemplate: no equality matching rule
Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 op=0 STARTTLS Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 op=0 RESULT oid= err=0 text= Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 fd=12 ACCEPT from IP=127.0.0.1:32916 (IP=0.0.0.0:389) Oct 29 20:01:30 dsa1 slapd[8250]: conn=1003 fd=12 TLS established tls_ssf=128 ssf=128 Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=1 BIND dn="cn=config" method=128 Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=1 BIND dn="cn=config" mech=SIMPLE ssf=0 Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=1 RESULT tag=97 err=0 text= Oct 29 20:01:32 dsa1 slapd[8250]: connection_input: conn=1003 deferring operation: binding Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=2 MOD dn="olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config" Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=2 MOD attr=olcPcacheTemplate Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=2 RESULT tag=103 err=18 text=modify/add: olcPcacheTemplate: no equality matching rule Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 op=3 UNBIND Oct 29 20:01:32 dsa1 slapd[8250]: conn=1003 fd=12 closed
adding the attribute "manually" [e.g. slapcat, modify ldif, slapadd] seems to be fine:
ldapsearch -LLLZZxWH 'ldap://localhost/' -D 'cn=config' -b 'olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config' -s base
Enter LDAP Password: dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+" olcPcacheTemplate: "(objectclass=)" 0 3600 olcPcacheTemplate: "(uid=)" 0 3600
my second problem is with caching when slapo-nssov is involved. it appears to not cache [QUERY NOT ANSWERABLE/QUERY NOT CACHEABLE] when a query occurs via nss:
getent passwd flash
flash:x:2013:2013:flash gordon:/home/flash:/bin/bash
Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on: Oct 31 08:42:15 deepfield slapd[12862]: 11r Oct 31 08:42:15 deepfield slapd[12862]: Oct 31 08:42:15 deepfield slapd[12862]: daemon: read active on 11 Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: connection_get(11) Oct 31 08:42:15 deepfield slapd[12862]: connection_get(11): got connid=0 Oct 31 08:42:15 deepfield slapd[12862]: nssov: connection from uid=0 gid=0 Oct 31 08:42:15 deepfield slapd[12862]: nssov_passwd_byname(flash) Oct 31 08:42:15 deepfield slapd[12862]: str2filter "(&(objectClass=posixAccount)(uid=flash))" Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter Oct 31 08:42:15 deepfield slapd[12862]: AND Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter_list Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter Oct 31 08:42:15 deepfield slapd[12862]: EQUALITY Oct 31 08:42:15 deepfield slapd[12862]: end get_filter 0 Oct 31 08:42:15 deepfield slapd[12862]: begin get_filter Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on 1 descriptor Oct 31 08:42:15 deepfield slapd[12862]: EQUALITY Oct 31 08:42:15 deepfield slapd[12862]: daemon: activity on: Oct 31 08:42:15 deepfield slapd[12862]: end get_filter 0 Oct 31 08:42:15 deepfield slapd[12862]: Oct 31 08:42:15 deepfield slapd[12862]: end get_filter_list Oct 31 08:42:15 deepfield slapd[12862]: end get_filter 0 Oct 31 08:42:15 deepfield slapd[12862]: query template of incoming query = (&(objectClass=)(uid=)) Oct 31 08:42:15 deepfield slapd[12862]: QUERY NOT ANSWERABLE Oct 31 08:42:15 deepfield slapd[12862]: QUERY NOT CACHEABLE Oct 31 08:42:15 deepfield slapd[12862]: =>ldap_back_getconn: conn 0xb51f8ee8 fetched refcnt=1. Oct 31 08:42:15 deepfield slapd[12862]: => ldap_back_munge_filter "(&(objectClass=posixAccount)(uid=flash))" Oct 31 08:42:15 deepfield slapd[12862]: <= ldap_back_munge_filter "(&(objectClass=posixAccount)(uid=flash))" (0) Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Oct 31 08:42:15 deepfield slapd[12862]: >>> dnPrettyNormal: <uid=flash,ou=people,ou=accounts,dc=example,dc=net> Oct 31 08:42:15 deepfield slapd[12862]: <<< dnPrettyNormal: <uid=flash,ou=people,ou=accounts,dc=example,dc=net>, <uid=flash,ou=people,ou=accounts,dc=example,dc=net> Oct 31 08:42:15 deepfield slapd[12862]: send_ldap_result: conn=-1 op=0 p=0 Oct 31 08:42:15 deepfield slapd[12862]: send_ldap_result: err=0 matched="" text=""
although i believe i have a matching query template defined in the config:
dn: olcDatabase={2}ldap,cn=config objectClass: olcLDAPConfig objectClass: olcDatabaseConfig objectClass: olcConfig objectClass: top olcDatabase: {2}ldap olcSuffix: dc=example,dc=net olcLastMod: TRUE olcReadOnly: TRUE olcRootDN: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net olcMonitoring: TRUE olcDbURI: ldap://dsa1.example.net/ olcDbStartTLS: start tls_cacert="/etc/pki/trusted_roots/example_networks_roo t_ca-cert.pem" tls_reqcert="demand" olcDbACLBind: bindmethod=simple binddn="cn=slapd,ou=deepfield,ou=services,ou=a ccounts,dc=example,dc=net" credentials="xxxxxxxxxxxxxxx" s tarttls="critical" tls_cacert="/etc/pki/trusted_roots/example_networks_root _ca-cert.pem" tls_reqcert="demand" olcDbIDAssertBind: bindmethod=simple binddn="cn=slapd,ou=deepfield,ou=services ,ou=accounts,dc=example,dc=net" credentials="xxxxxxxxxxxxxxx" structuralObjectClass: olcLDAPConfig entryUUID: f24e435a-b35a-1031-8f37-336141b7bc90 creatorsName: cn=config createTimestamp: 20121026014812Z entryCSN: 20121031023501.089672Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121031023501Z
dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+"
You should submit an ITS for this. This PcacheAttrset directive is not behaving as it should. Specifically, there is no support for "+" at all in the attrset matching code, and the support for "*" is incomplete, so it's also failing to match your search request.
olcPcacheTemplate: "(objectClass=)" 0 3600 olcPcacheTemplate: "(uid=)" 0 3600 olcPcacheTemplate: "(&(objectClass=)(uid=))" 0 3600 olcPcacheBind: "(uid=)" 0 60 "sub" "dc=example,dc=net" structuralObjectClass: olcPcacheConfig entryUUID: ddb05d7e-b4fa-1031-811e-353e11fff366 creatorsName: cn=config createTimestamp: 20121028032528Z entryCSN: 20121030002115.179177Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121030002115Z
dn: olcDatabase={0}mdb,olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheDatabase objectClass: olcMdbConfig objectClass: olcDatabaseConfig objectClass: olcConfig objectClass: top olcDatabase: {0}mdb olcDbDirectory: /var/lib/ldap/example.net/ olcLastMod: TRUE olcMaxDerefDepth: 15 olcDbNoSync: FALSE olcDbIndex: certfingerprint eq olcDbIndex: cn eq olcDbIndex: default eq olcDbIndex: description eq olcDbIndex: entrycsn eq olcDbIndex: entryuuid eq olcDbIndex: gidnumber pres,eq olcDbIndex: host eq olcDbIndex: iphostnumber eq olcDbIndex: ipserviceport eq olcDbIndex: ipserviceprotocol eq olcDbIndex: mail eq olcDbIndex: maillocaladdress eq olcDbIndex: member eq olcDbIndex: memberof eq olcDbIndex: memberuid eq olcDbIndex: objectclass eq olcDbIndex: rfc822mailmember eq olcDbIndex: sudoUser eq olcDbIndex: uid pres,eq,sub olcDbIndex: uidnumber pres,eq olcDbMode: 0600 olcDbSearchStack: 16 structuralObjectClass: olcMdbConfig entryUUID: 88b37716-b590-1031-8c75-439de7087923 creatorsName: cn=config createTimestamp: 20121028211650Z entryCSN: 20121029021315.039143Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121029021315Z
dn: olcOverlay={1}nssov,olcDatabase={2}ldap,cn=config objectClass: olcNssOvConfig objectClass: olcOverlayConfig objectClass: olcConfig olcOverlay: {1}nssov olcNssMap: group uniquemember member olcNssPam: authz2dn hostservice olcNssPamSession: sshd olcNssPamSession: login structuralObjectClass: olcNssOvConfig entryUUID: 47ecaef0-b73e-1031-8761-9f0bff5d3212 creatorsName: cn=config createTimestamp: 20121031003305Z entryCSN: 20121031003305.637051Z#000000#000#000000 modifiersName: cn=config modifyTimestamp: 20121031003305Z
and if i perform the same query using ldapsearch:
ldapsearch -LLLZZxH 'ldap://localhost/' -D 'uid=flash,ou=people,ou=accounts,dc=example,dc=net' -w 'test' '(&(objectClass=posixAccount)(uid=flash))'
dn: uid=flash,ou=people,ou=accounts,dc=example,dc=net initials: fg givenName: flash loginShell: /bin/bash uidNumber: 2013 gidNumber: 2013 uid: flash objectClass: posixAccount objectClass: top objectClass: shadowAccount objectClass: inetOrgPerson objectClass: organizationalPerson objectClass: person objectClass: extensibleObject c: us homeDirectory: /home/flash sn: gordon cn: flash gordon displayName: flash_gordon mail: user@example.com
it does seem to cache it:
what am i doing wrong?
-ben
On Mar 18, 2013, at 15.14, Howard Chu hyc@symas.com wrote:
dn: olcOverlay={0}pcache,olcDatabase={2}ldap,cn=config objectClass: olcPcacheConfig objectClass: olcOverlayConfig objectClass: olcConfig objectClass: top olcOverlay: {0}pcache olcPcache: mdb 1000 100 1000 60 olcPcacheAttrset: 0 "*" "+"
You should submit an ITS for this. This PcacheAttrset directive is not behaving as it should. Specifically, there is no support for "+" at all in the attrset matching code, and the support for "*" is incomplete, so it's also failing to match your search request.
its #7552
http://www.openldap.org/its/index.cgi/Incoming?selectid=7552
-ben
openldap-technical@openldap.org
-
btb＠bitrate.net -
Howard Chu