translucent ldap, local search timeouts - openldap-technical

15 Sep 2009


      Hi to all,
I'm a newbie with openldap, but I've spent some time reading the  
online docs/mailing list archives and testing various configurations  
with no success.
I'm trying to configure a translucent ldap server (v2.4.12) in a  
Fedora core 10 vhost with the following configuration:
(local-server, URI:local.xxx.yyy.zzz)
--------------
moduleload translucent.la
overlay translucent
translucent_local uid   #also tried _remote
uri     ldap://remote.xxx.yyy.zzz:389
lastmod off
acl-bind bindmethod=simple
#idassert-bind bindmethod=simple mode=none #(also tried this)
loglevel 4095
access to dn.base="" by * read
access to * by * read
database        bdb
suffix          "dc=xxx,dc=yyy,dc=zzz"
checkpoint      1024 15
rootdn          "uid=me,ou=people,dc=xxx,dc=yyy,dc=zzz"
rootpw          secret
directory       /var/lib/ldap-proxy
index objectClass                       eq,pres
index ou,cn,mail,surname,givenname      eq,pres,sub
index uidNumber,gidNumber,loginShell    eq,pres
index uid,memberUid                     eq,pres,sub
index nisMapName,nisMapEntry            eq,pres,sub
*I have full permissions in my local server but only read permission  
in the remote ldap (hence the anonymous bind)*. I only want to  
override the already existing remote entries (but not add new ones).
Both servers have very similar structure, and the SAME suffix, as  
suggested in the manuals. I've created a test user  
(uid=test,ou=people,dc=xxx,dc=yyy,dc=zzz) in the local server that  
exists also in the remote one.
What happens is: when translucent is disabled i get proper results in  
both servers with the same ldapsearch command.
When translucent is enabled, when i search the local server, the  
SEARCH HANGS (timeouts)! (remote still works, of course)
The LOCAL logs are: (I've included only the suspicious entries)
[...]
Sep 15 00:43:46 ldap slapd[5029]: slapd startup: initiated.
Sep 15 00:43:46 ldap slapd[5029]: ==> translucent_db_open
Sep 15 00:43:46 ldap slapd[5029]: backend_startup_one: starting "cn=config"
Sep 15 00:43:46 ldap slapd[5029]: config_back_db_open
Sep 15 00:43:46 ldap slapd[5029]: config_back_db_open: line 0:  
warning: cannot assess the validity of the ACL scope within backend  
naming context
[...]
Sep 15 00:43:46 ldap slapd[5029]: backend_startup_one: starting  
"dc=xxx,dc=yyy,dc=zzz"
Sep 15 00:43:46 ldap slapd[5029]: bdb_db_open: "dc=xxx,dc=yyy,dc=zzz"
Sep 15 00:43:46 ldap slapd[5029]: bdb_db_open: warning - no DB_CONFIG  
file found in directory /var/lib/ldap-proxy: (2).#012Expect poor  
performance for suffix "dc=xxx,dc=yyy,dc=zzz".
Sep 15 00:43:46 ldap slapd[5029]: bdb_db_open: database  
"dc=xxx,dc=yyy,dc=zzz": dbenv_open(/var/lib/ldap-proxy).
[...]
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on 1 descriptor
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on:
Sep 15 00:43:54 ldap slapd[5029]:
Sep 15 00:43:54 ldap slapd[5029]: slap_listener_activate(7):
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=7 busy
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: >>> slap_listener(ldap:///)
Sep 15 00:43:54 ldap slapd[5029]: daemon: listen=7, new connection on 14
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on 1 descriptor
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on:
Sep 15 00:43:54 ldap slapd[5029]:
Sep 15 00:43:54 ldap slapd[5029]: daemon: added 14r (active) listener=(nil)
Sep 15 00:43:54 ldap slapd[5029]: conn=0 fd=14 ACCEPT from  
IP=127.0.0.1:48453 (IP=0.0.0.0:389)
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=7  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on 2 descriptors
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on:
Sep 15 00:43:54 ldap slapd[5029]:  14r
Sep 15 00:43:54 ldap slapd[5029]:
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=7  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on 1 descriptor
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on:
Sep 15 00:43:54 ldap slapd[5029]:  14r
Sep 15 00:43:54 ldap slapd[5029]:
Sep 15 00:43:54 ldap slapd[5029]: daemon: read active on 14
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=7  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: connection_get(14)
Sep 15 00:43:54 ldap slapd[5029]: connection_get(14): got connid=0
Sep 15 00:43:54 ldap slapd[5029]: connection_read(14): checking for  
input on id=0
Sep 15 00:43:54 ldap slapd[5029]: conn=0 op=0 do_bind
Sep 15 00:43:54 ldap slapd[5029]: >>> dnPrettyNormal: <>
Sep 15 00:43:54 ldap slapd[5029]: <<< dnPrettyNormal: <>, <>
Sep 15 00:43:54 ldap slapd[5029]: conn=0 op=0 BIND dn="" method=128
Sep 15 00:43:54 ldap slapd[5029]: do_bind: version=3 dn="" method=128
Sep 15 00:43:54 ldap slapd[5029]: translucent_bind: <> method 128
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on 1 descriptor
Sep 15 00:43:54 ldap slapd[5029]: daemon: activity on:
Sep 15 00:43:54 ldap slapd[5029]:
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=7  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:43:54 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
[...here i pressed control-c on the ldapsearch...]
Sep 15 00:44:00 ldap slapd[5029]: daemon: activity on 1 descriptor
Sep 15 00:44:00 ldap slapd[5029]: daemon: activity on:
Sep 15 00:44:00 ldap slapd[5029]:  14r
Sep 15 00:44:00 ldap slapd[5029]:
Sep 15 00:44:00 ldap slapd[5029]: daemon: read active on 14
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=7  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: connection_get(14)
Sep 15 00:44:00 ldap slapd[5029]: connection_get(14): got connid=0
Sep 15 00:44:00 ldap slapd[5029]: connection_read(14): checking for  
input on id=0
Sep 15 00:44:00 ldap slapd[5029]: ber_get_next on fd 14 failed errno=0  
(Success)
Sep 15 00:44:00 ldap slapd[5029]: connection_read(14): input error=-2  
id=0, closing.
Sep 15 00:44:00 ldap slapd[5029]: connection_closing: readying conn=0  
sd=14 for close
Sep 15 00:44:00 ldap slapd[5029]: connection_close: conn=0 sd=14
Sep 15 00:44:00 ldap slapd[5029]: daemon: removing 14
Sep 15 00:44:00 ldap slapd[5029]: conn=0 fd=14 closed (connection lost)
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: daemon: activity on 1 descriptor
Sep 15 00:44:00 ldap slapd[5029]: daemon: activity on:
Sep 15 00:44:00 ldap slapd[5029]:
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=7  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=8  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=9  
active_threads=0 tvp=zero
Sep 15 00:44:00 ldap slapd[5029]: daemon: epoll: listen=10  
active_threads=0 tvp=zero
The REMOTE logs (from a yesterday's search though...) are the following:
Sep 14 12:18:32 srv004 slapd[2080]: conn=46075 fd=59 ACCEPT from  
IP=local.xxx.yyy.zzz:45311 (IP=0.0.0.0:389)
Sep 14 12:18:32 srv004 slapd[2080]: conn=46075 op=0 BIND dn="" method=128
Sep 14 12:18:32 srv004 slapd[2080]: conn=46075 op=0 RESULT tag=97 err=0 text=
Sep 14 12:18:32 srv004 slapd[2080]: conn=46075 op=1 UNBIND
Sep 14 12:18:32 srv004 slapd[2080]: conn=46075 fd=59 closed
[why there is NO SRCH command?? this is why it timeouts...]
Please help! I've spent several hours on this problem, and no matter  
what options I've tried, it is always the same behavior...
Best regards,
Theodoros