[Date Prev][Date Next] [Chronological] [Thread] [Top]

trouble with slapo-pcache

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