hello everyone, I'm having issue with the pcachBind that it's not getting update from the upstream proxy ldap.
The use case is that after users have updated userPassword on the upstream LDAP, the new password is updated and it's authenticated correctly with the updated password when directly query the upstream LDAP. But with the proxyldap pcache setting that I have with 3 attributes set of pcache configuration as below: overlay pcache pcache hdb 100000 3 1000 60 pcacheAttrset 0 +
pcacheTemplate (uid=) 0 120 0 0 30 pcacheTemplate (&(uid=)(objectClass=)) 0 60 0 0 30 pcacheTemplate (&(objectClass=)(uidNumber=)) 0 60 0 0 30 pcacheTemplate (&(uid=)(memberOf=)) 0 60 0 0 30 pcacheBind (uid=) 0 30 sub "o=mycompany.com"
pcacheAttrset 1 memberOf pcacheTemplate (objectClass=*) 1 360 0 0 30 pcacheTemplate (uid=) 1 360 0 0 30 pcacheBind (uid=) 1 30 sub "o=mycompany.com"
pcacheAttrset 2 memberOf member pcacheTemplate (uid=) 2 360 0 0 30 pcacheBind (uid=) 2 30 sub "o=mycompany.com"
pcacheOffline TRUE pcacheValidate TRUE The cacheable template for uid= is set with TTL 120 and TTR at 30. The first time query to the proxy pcache server, it's cached uid= data
Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: slap_listener_activate(8): Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 busy Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: >>> slap_listener(ldap:///) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: listen=8, new connection on 13 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: added 13r (active) listener=(nil) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: conn=1000 fd=13 ACCEPT from IP=10.239.134.126:60966 (IP=0.0.0.0:389) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on 2 descriptors Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1000 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1000 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: op tag 0x60, time 1655184692 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: conn=1000 op=0 do_bind Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: >>> dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: conn=1000 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: do_bind: version=3 dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: ndn: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: oc: "(null)", at: "(null)" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => hdb_dn2id("o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= hdb_dn2id: got id=0x1 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => hdb_dn2id("ou=employees,o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= hdb_dn2id: got id=0x2 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => hdb_dn2id("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= hdb_dn2id: got id=0x3 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: entry_decode: "" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= entry_decode() Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: found entry: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: bdb_entry_get: rc=0 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: str2filter "(uid=userX)" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: begin get_filter Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: EQUALITY Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: end get_filter 0 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Lock QC index = 0x5638d82e9910 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Not answerable: Unlock QC index=0x5638d82e9910 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: QUERY NOT ANSWERABLE Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: QUERY CACHEABLE Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: =>ldap_back_getconn: conn=1000 op=0: lc=0x7f8710109d80 inserted refcnt=1 rc=0 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: => ldap_back_munge_filter "(uid=userX)" Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <= ldap_back_munge_filter "(uid=userX)" (0) Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnPrettyNormal: <uid=userX,OU=employees,O=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnPretty: <CN=cie_ldap_test,OU=Groups,O=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnPretty: <cn=cie_ldap_test,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnPretty: <CN=hps_opsinf_admin,OU=Groups,O=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnPretty: <cn=hps_opsinf_admin,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnNormalize: <cn=cie_ldap_test,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnNormalize: <cn=cie_ldap_test,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnNormalize: <cn=hps_opsinf_admin,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnNormalize: <cn=hps_opsinf_admin,ou=Groups,o=mycompany.com> But any sub-sequence queries after that it's always using the entry that found in the cached (CACHED BIND) instead of re-query with new connection to the upstream LDAP as it's expired (longer that TTL/TTR). Same situation when users change password from the upstream LDAP, the proxy ldap doesn't take the update password.
Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: slap_listener_activate(8): Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 busy Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: >>> slap_listener(ldap:///) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: listen=8, new connection on 13 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: added 13r (active) listener=(nil) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 fd=13 ACCEPT from IP=10.239.134.126:60993 (IP=0.0.0.0:389) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1001 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1001 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: op tag 0x60, time 1655184873 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 do_bind Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: >>> dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: do_bind: version=3 dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: ndn: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: oc: "(null)", at: "(null)" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: found entry: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_entry_get: rc=0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: str2filter "(uid=userX)" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: begin get_filter Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: EQUALITY Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: end get_filter 0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Lock QC index = 0x5638d82e9910 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: QUERY ANSWERABLE (answered 1 times) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => hdb_search Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access to "uid=userX,ou=employees,o=mycompany.com" "entry" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= root access granted Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access granted by manage(=mwrscxd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: base_candidates: base: "uid=userX,ou=employees,o=mycompany.com" (0x00000003) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => test_filter Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: EQUALITY Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access to "uid=userX,ou=employees,o=mycompany.com" "uid" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= root access granted Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access granted by manage(=mwrscxd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= test_filter 6 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: conn=1001 op=0 p=3 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: err=0 matched="" text="" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: pcache_op_bind: CACHED BIND for uid=userX,ou=employees,o=mycompany.com Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: ==> hdb_bind: dn: uid=userX,ou=employees,o=mycompany.com Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: result not in cache (userPassword) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: auth access to "uid=userX,ou=employees,o=mycompany.com" "userPassword" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => dn: [1] Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => dn: [2] cn=subschema Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => acl_get: [3] attr userPassword Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => acl_mask: access to entry "uid=userX,ou=employees,o=mycompany.com", attr "userPassword" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => acl_mask: to value by "", (=0) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= check a_dn_pat: self Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= check a_dn_pat: anonymous Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= acl_mask: [2] applying auth(=xd) (stop) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= acl_mask: [2] mask: auth(=xd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => slap_access_allowed: auth access granted by auth(=xd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: auth access granted by auth(=xd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" mech=SIMPLE ssf=0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: do_bind: v3 bind: "uid=userX,ou=employees,o=mycompany.com" to "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: conn=1001 op=0 p=3 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: err=0 matched="" text="" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_response: msgid=1 tag=97 err=0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 RESULT tag=97 err=0 text= Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: op tag 0x77, time 1655184874 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 do_extended Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 EXT oid=1.3.6.1.4.1.4203.1.11.3 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: do_extended: oid=1.3.6.1.4.1.4203.1.11.3 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 WHOAMI Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: send_ldap_extended: err=0 oid= len=43 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: send_ldap_response: msgid=2 tag=120 err=0 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 RESULT oid= err=0 text= Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: op tag 0x42, time 1655184874 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: ber_get_next on fd 13 failed errno=0 (Success) Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_read(13): input error=-2 id=1001, closing. Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_closing: readying conn=1001 sd=13 for close Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_close: deferring conn=1001 sd=13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=2 do_unbind Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=2 UNBIND Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_resched: attempting closing conn=1001 sd=13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_close: conn=1001 sd=13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: =>ldap_back_conn_destroy: fetching conn 1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: removing 13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 fd=13 closed Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
Wondering that if there is anything missing with configuration or if this is a bug that I can file for bug ticket. Thanks, -Tommy
Tri Tu wrote:
hello everyone,
I'm having issue with the pcachBind that it's not getting update from the upstream proxy ldap.
The use case is that after users have updated userPassword on the upstream LDAP, the new password is updated and it's authenticated correctly with the updated password when directly query the upstream LDAP.
But with the proxyldap pcache setting that I have with 3 attributes set of pcache configuration as below:
overlay pcache pcache hdb 100000 3 1000 60 pcacheAttrset 0 +
pcacheTemplate (uid=) 0 120 0 0 30 pcacheTemplate (&(uid=)(objectClass=)) 0 60 0 0 30 pcacheTemplate (&(objectClass=)(uidNumber=)) 0 60 0 0 30 pcacheTemplate (&(uid=)(memberOf=)) 0 60 0 0 30 pcacheBind (uid=) 0 30 sub "o=mycompany.com"
pcacheAttrset 1 memberOf pcacheTemplate (objectClass=*) 1 360 0 0 30 pcacheTemplate (uid=) 1 360 0 0 30 pcacheBind (uid=) 1 30 sub "o=mycompany.com"
pcacheAttrset 2 memberOf member pcacheTemplate (uid=) 2 360 0 0 30 pcacheBind (uid=) 2 30 sub "o=mycompany.com"
pcacheOffline TRUE
Read the slapo-pcache manpage more carefully. Setting pcacheOffline TRUE disables cache expiration.
pcacheValidate TRUE
The cacheable template for uid= is set with TTL 120 and TTR at 30. The first time query to the proxy pcache server, it's cached uid= data
Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: slap_listener_activate(8): Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 busy Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: >>> slap_listener(ldap:///) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: listen=8, new connection on 13 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: added 13r (active) listener=(nil) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: conn=1000 fd=13 ACCEPT from IP=10.239.134.126:60966 (IP=0.0.0.0:389) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on 2 descriptors Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1000 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1000 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: op tag 0x60, time 1655184692 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: conn=1000 op=0 do_bind Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: >>> dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: conn=1000 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: do_bind: version=3 dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: ndn: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: oc: "(null)", at: "(null)" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => hdb_dn2id("o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= hdb_dn2id: got id=0x1 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => hdb_dn2id("ou=employees,o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= hdb_dn2id: got id=0x2 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => hdb_dn2id("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= hdb_dn2id: got id=0x3 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: entry_decode: "" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: <= entry_decode() Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: found entry: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: bdb_entry_get: rc=0 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: str2filter "(uid=userX)" Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: begin get_filter Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: EQUALITY Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: end get_filter 0 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Lock QC index = 0x5638d82e9910 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Not answerable: Unlock QC index=0x5638d82e9910 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: QUERY NOT ANSWERABLE Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: QUERY CACHEABLE Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: =>ldap_back_getconn: conn=1000 op=0: lc=0x7f8710109d80 inserted refcnt=1 rc=0 Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:31:32 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: => ldap_back_munge_filter "(uid=userX)" Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <= ldap_back_munge_filter "(uid=userX)" (0) Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnPrettyNormal: <uid=userX,OU=employees,O=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnPretty: <CN=cie_ldap_test,OU=Groups,O=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnPretty: <cn=cie_ldap_test,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnPretty: <CN=hps_opsinf_admin,OU=Groups,O=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnPretty: <cn=hps_opsinf_admin,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnNormalize: <cn=cie_ldap_test,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnNormalize: <cn=cie_ldap_test,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: >>> dnNormalize: <cn=hps_opsinf_admin,ou=Groups,o=mycompany.com> Jun 14 05:31:33 prd-ldap1-euc1 slapd[7178]: <<< dnNormalize: <cn=hps_opsinf_admin,ou=Groups,o=mycompany.com>
But any sub-sequence queries after that it's always using the entry that found in the cached (CACHED BIND) instead of re-query with new connection to the upstream LDAP as it's expired (longer that TTL/TTR). Same situation when users change password from the upstream LDAP, the proxy ldap doesn't take the update password.
Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: slap_listener_activate(8): Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 busy Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: >>> slap_listener(ldap:///) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: listen=8, new connection on 13 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: added 13r (active) listener=(nil) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 fd=13 ACCEPT from IP=10.239.134.126:60993 (IP=0.0.0.0:389) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1001 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1001 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: op tag 0x60, time 1655184873 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 do_bind Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: >>> dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: do_bind: version=3 dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: ndn: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: oc: "(null)", at: "(null)" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => bdb_entry_get: found entry: "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_entry_get: rc=0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: str2filter "(uid=userX)" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: begin get_filter Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: EQUALITY Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: end get_filter 0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Lock QC index = 0x5638d82e9910 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: QUERY ANSWERABLE (answered 1 times) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => hdb_search Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access to "uid=userX,ou=employees,o=mycompany.com" "entry" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= root access granted Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access granted by manage(=mwrscxd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: base_candidates: base: "uid=userX,ou=employees,o=mycompany.com" (0x00000003) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => test_filter Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: EQUALITY Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access to "uid=userX,ou=employees,o=mycompany.com" "uid" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= root access granted Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: search access granted by manage(=mwrscxd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= test_filter 6 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: conn=1001 op=0 p=3 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: err=0 matched="" text="" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: pcache_op_bind: CACHED BIND for uid=userX,ou=employees,o=mycompany.com Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: ==> hdb_bind: dn: uid=userX,ou=employees,o=mycompany.com Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: result not in cache (userPassword) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: auth access to "uid=userX,ou=employees,o=mycompany.com" "userPassword" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => dn: [1] Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => dn: [2] cn=subschema Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => acl_get: [3] attr userPassword Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => acl_mask: access to entry "uid=userX,ou=employees,o=mycompany.com", attr "userPassword" requested Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => acl_mask: to value by "", (=0) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= check a_dn_pat: self Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= check a_dn_pat: anonymous Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= acl_mask: [2] applying auth(=xd) (stop) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: <= acl_mask: [2] mask: auth(=xd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => slap_access_allowed: auth access granted by auth(=xd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: => access_allowed: auth access granted by auth(=xd) Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" mech=SIMPLE ssf=0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: do_bind: v3 bind: "uid=userX,ou=employees,o=mycompany.com" to "uid=userX,ou=employees,o=mycompany.com" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: conn=1001 op=0 p=3 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_result: err=0 matched="" text="" Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: send_ldap_response: msgid=1 tag=97 err=0 Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: conn=1001 op=0 RESULT tag=97 err=0 text= Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:33 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: op tag 0x77, time 1655184874 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 do_extended Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 EXT oid=1.3.6.1.4.1.4203.1.11.3 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: do_extended: oid=1.3.6.1.4.1.4203.1.11.3 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 WHOAMI Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: send_ldap_extended: err=0 oid= len=43 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: send_ldap_response: msgid=2 tag=120 err=0 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=1 RESULT oid= err=0 text= Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: 13r Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: read active on 13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13) Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_get(13): got connid=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_read(13): checking for input on id=1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: op tag 0x42, time 1655184874 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: ber_get_next on fd 13 failed errno=0 (Success) Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_read(13): input error=-2 id=1001, closing. Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_closing: readying conn=1001 sd=13 for close Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_close: deferring conn=1001 sd=13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=2 do_unbind Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 op=2 UNBIND Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_resched: attempting closing conn=1001 sd=13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: connection_close: conn=1001 sd=13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: =>ldap_back_conn_destroy: fetching conn 1001 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: removing 13 Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: conn=1001 fd=13 closed Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on 1 descriptor Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: activity on: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 05:34:34 prd-ldap1-euc1 slapd[7178]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
Wondering that if there is anything missing with configuration or if this is a bug that I can file for bug ticket.
Thanks,
-Tommy
Hi Howard,
Thanks for your replying.
I thought that pcacheOffline is only active when the connection is disconnected with the remote DSA.
pcacheOffline { TRUE | FALSE } Set the cache to offline mode. While offline, the consistency checker will be stopped and no expirations will occur. This allows the cache contents to be used indefinitely while the proxy is cut off from network access to the remote DSA. The default is FALSE, i.e. consistency checks and expirations will be performed.
If we set the pcacheOffline FALSE (default) then we can't use the proxycache/slapd-pcache offline in the event that remote DSA is disconnected/unreachable from the LDAP proxy. We would get 'Proxy operation retry failed' when 'Server is unavailable'.
How do we set the proxycache so that we can still be able to use the proxy while remote DSA is offline/unavailable?
Thanks
Hi Howard, Thanks for your replying. If we set the pcacheOffline FALSE (default) then when the cache is expired, query would failed with "Proxy operation retry failed" because the DSA is offline/unreachable.
pcacheOffline { TRUE | FALSE } Set the cache to offline mode. While offline, the consistency checker will be stopped and no expirations will occur. This allows the cache contents to be used indefinitely while the proxy is cut off from network access to the remote DSA. The default is FALSE, i.e. consistency checks and expirations will be performed. If we manually update configuration to pcacheOffline TRUE and restarted slapd, the existing cached data is still existing on database (hdb/dbd) but it can't query proxycache (QUERY NOT ANSWERABLE) and tries to update the cache (QUERY CACHEABLE) and would fail with "Proxy can't contact remote server" as below.
Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: conn=1001 op=0 do_bindJun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: >>> dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com> Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: conn=1001 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: do_bind: version=3 dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: => bdb_entry_get: ndn: "uid=userX,ou=employees,o=mycompany.com" Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: => bdb_entry_get: oc: "(null)", at: "(null)" Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: => bdb_entry_get: found entry: "uid=userX,ou=employees,o=mycompany.com" Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: bdb_entry_get: rc=0 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: str2filter "(uid=userX)" Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: begin get_filter Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: EQUALITY Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: end get_filter 0 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: Lock QC index = 0x56286a9179d0 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: Not answerable: Unlock QC index=0x56286a9179d0 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: QUERY NOT ANSWERABLE Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: QUERY CACHEABLE Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: =>ldap_back_getconn: conn=1001 op=0: lc=0x7f22f010c620 inserted refcnt=1 rc=0 Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: activity on 1 descriptor Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: activity on: Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Jun 14 18:47:49 prd-ldap1-euc1 slapd[4304]: daemon: epoll: listen=11 active_threads=0 tvp=NULL Jun 14 18:47:59 prd-ldap1-euc1 slapd[4304]: send_ldap_result: conn=1001 op=0 p=3 Jun 14 18:47:59 prd-ldap1-euc1 slapd[4304]: send_ldap_result: err=52 matched="" text="Proxy can't contact remote server" Jun 14 18:47:59 prd-ldap1-euc1 slapd[4304]: =>ldap_back_getconn: conn=1001 op=0: lc=0x7f22f018f610 inserted refcnt=1 rc=0 Jun 14 18:48:09 prd-ldap1-euc1 slapd[4304]: conn=1001 op=0 ldap_back_retry: retrying URI="ldaps://dsa.mycompany.com" DN="" Jun 14 18:48:19 prd-ldap1-euc1 slapd[4304]: send_ldap_result: conn=1001 op=0 p=3 Jun 14 18:48:19 prd-ldap1-euc1 slapd[4304]: send_ldap_result: err=52 matched="" text="Proxy operation retry failed" Jun 14 18:48:19 prd-ldap1-euc1 slapd[4304]: send_ldap_response: msgid=1 tag=97 err=52 Jun 14 18:48:19 prd-ldap1-euc1 slapd[4304]: conn=1001 op=0 RESULT tag=97 err=52 text=Proxy operation retry failed How do we continue to use the ldap proxy when the remote DSA is cut off from network / server is unavailable.
Thanks, On Tuesday, June 14, 2022, 08:07:25 AM PDT, Howard Chu hyc@symas.com wrote:
Read the slapo-pcache manpage more carefully. Setting pcacheOffline TRUE disables cache expiration.
Tri Tu wrote:
Hi Howard,
Thanks for your replying.
If we set the pcacheOffline FALSE (default) then when the cache is expired, query would failed with "Proxy operation retry failed" because the DSA is offline/unreachable.
pcacheOffline { TRUE | FALSE } Set the cache to offline mode. While offline, the consistency checker will be stopped and no expirations will occur. This allows the cache contents to be used indefinitely while the proxy is cut off from network access to the remote DSA. The default is FALSE, i.e. consistency checks and expirations will be performed.
If we manually update configuration to pcacheOffline TRUE and restarted slapd,
Don't restart slapd. The pcacheOffline setting is meant to be used by changing it dynamically as your network status changes.
the existing cached data is still existing on database (hdb/dbd) but it can't query proxycache (QUERY NOT ANSWERABLE) and tries to update the cache (QUERY CACHEABLE) and would fail with "Proxy can't contact remote server" as below.
How do we continue to use the ldap proxy when the remote DSA is cut off from network / server is unavailable.
Thanks,
On Tuesday, June 14, 2022, 08:07:25 AM PDT, Howard Chu hyc@symas.com wrote:
Read the slapo-pcache manpage more carefully. Setting pcacheOffline TRUE disables cache expiration.
Hi Howard, Thanks again for your replying. So with the pcacheOffline FALSE (default), pcache would use the local cached data and continues to response its cached data when the DSA is cut off/unreachable.
But once remote DSA is offline and the cached is expired, the client would get the respond with error "Proxy operation retry failed" because "cache is stale". Is it something that I missed on the configuration side? Can we continue to use the existing expired cached data (the cache contents to be used indefinitely) until remote DSA is back online?
Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: conn=1115 op=0 do_bind Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: >>> dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com> Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: <<< dnPrettyNormal: <uid=userX,ou=employees,o=mycompany.com>, <uid=userX,ou=employees,o=mycompany.com> Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: conn=1115 op=0 BIND dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: do_bind: version=3 dn="uid=userX,ou=employees,o=mycompany.com" method=128 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => bdb_entry_get: ndn: "uid=userX,ou=employees,o=mycompany.com" Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => bdb_entry_get: oc: "(null)", at: "(null)" Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => bdb_entry_get: found entry: "uid=userX,ou=employees,o=mycompany.com" Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: bdb_entry_get: rc=0 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: str2filter "(uid=userX)" Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: begin get_filter Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: EQUALITY Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: end get_filter 0 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: Lock QC index = 0x562be57eb700 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: QUERY ANSWERABLE (answered 115 times) Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => hdb_search Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: bdb_dn2entry("uid=userX,ou=employees,o=mycompany.com") Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => access_allowed: search access to "uid=userX,ou=employees,o=mycompany.com" "entry" requested Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: <= root access granted Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => access_allowed: search access granted by manage(=mwrscxd) Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: base_candidates: base: "uid=userX,ou=employees,o=mycompany.com" (0x00000003) Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => test_filter Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: EQUALITY Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => access_allowed: search access to "uid=userX,ou=employees,o=mycompany.com" "uid" requested Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: <= root access granted Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: => access_allowed: search access granted by manage(=mwrscxd) Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: <= test_filter 6 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: pc_bind_search: cache is stale, reftime: 1655318380, current time: 1655318385 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: send_ldap_result: conn=1115 op=0 p=3 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: send_ldap_result: err=0 matched="" text="" Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: =>ldap_back_getconn: conn=1115 op=0: lc=0x7f2644105d10 inserted refcnt=1 rc=0 Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: activity on 1 descriptor Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: activity on: Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: epoll: listen=7 active_threads=0 tvp=zero Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: epoll: listen=8 active_threads=0 tvp=zero Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: epoll: listen=9 active_threads=0 tvp=zero Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: epoll: listen=10 active_threads=0 tvp=zero Jun 15 18:39:45 prd-ldap1-euc1 slapd[12041]: daemon: epoll: listen=11 active_threads=0 tvp=zero Jun 15 18:39:55 prd-ldap1-euc1 slapd[12041]: conn=1115 op=0 ldap_back_retry: retrying URI="ldaps://dsa.mycompany.com" DN="" Jun 15 18:40:05 prd-ldap1-euc1 slapd[12041]: send_ldap_result: conn=1115 op=0 p=3 Jun 15 18:40:05 prd-ldap1-euc1 slapd[12041]: send_ldap_result: err=52 matched="" text="Proxy operation retry failed" Jun 15 18:40:05 prd-ldap1-euc1 slapd[12041]: send_ldap_response: msgid=1 tag=97 err=52 Jun 15 18:40:05 prd-ldap1-euc1 slapd[12041]: conn=1115 op=0 RESULT tag=97 err=52 text=Proxy operation retry failed Jun 15 18:40:06 prd-ldap1-euc1 slapd[12041]: daemon: activity on 1 descriptor Jun 15 18:40:06 prd-ldap1-euc1 slapd[12041]: daemon: activity on:
Thanks
On Tuesday, June 14, 2022, 02:45:46 PM PDT, Howard Chu hyc@symas.com wrote:
Tri Tu wrote:
Hi Howard,
Thanks for your replying.
If we set the pcacheOffline FALSE (default) then when the cache is expired, query would failed with "Proxy operation retry failed" because the DSA is offline/unreachable.
pcacheOffline { TRUE | FALSE } Set the cache to offline mode. While offline, the consistency checker will be stopped and no expirations will occur. This allows the cache contents to be used indefinitely while the proxy is cut off from network access to the remote DSA. The default is FALSE, i.e. consistency checks and expirations will be performed.
If we manually update configuration to pcacheOffline TRUE and restarted slapd,
Don't restart slapd. The pcacheOffline setting is meant to be used by changing it dynamically as your network status changes.
openldap-technical@openldap.org
-
Howard Chu -
mtritu＠gmail.com -
Tri Tu