Full_Name: Ulf Moeller Version: 2.3.32 OS: SLES 9 URL: Submission from: (NULL) (62.245.244.226)
I am experiencing problems with back_meta. It does return search results for some time, but at some point starts returning empty search results, with SEARCH RESULT err=32 in the logfile. This often (but not always) happens after 5 - 30 minutes.
It doesn't return data from either of the ldap servers it is connected to. The problem also occurs in a minimal configuration with just one "uri" defined.
After slapd is restarted, it again works properly for some time.
When running in GDB, I get the following backtrace:
Program received signal SIGPIPE, Broken pipe. 0xffffe410 in __kernel_vsyscall () (gdb) bt #0 0xffffe410 in __kernel_vsyscall () #1 0x4003a55b in __write_nocancel () from /lib/tls/libpthread.so.0 #2 0x08127f34 in sb_stream_write (sbiod=0x81e69c0, buf=0x81deb60, len=64) at sockbuf.c:521 #3 0x081287b6 in sb_debug_write (sbiod=0x81e69d8, buf=0x81deb60, len=64) at sockbuf.c:820 #4 0x08127e50 in ber_int_sb_write (sb=0x81e6d38, buf=0x81deb60, len=64) at sockbuf.c:431 #5 0x08124dd6 in ber_flush (sb=0x81e6d38, ber=0x81e6e40, freeit=0) at io.c:232 #6 0x08111813 in ldap_int_flush_request (ld=0x81e6c00, lr=0x81dfb88) at request.c:151 #7 0x08111c1a in ldap_send_server_request (ld=0x81e6c00, ber=0x81e6e40, msgid=21, parentreq=0x0, srvlist=0x0, lc=0x81dfb40, bind=0x0) at request.c:301 #8 0x081117ca in ldap_send_initial_request (ld=0x81e6c00, msgtype=99, dn=0x40a1300c "", ber=0x81e6e40, msgid=21) at request.c:135 #9 0x08104661 in ldap_search_ext (ld=0x81e6c00, base=0x40a1300c "", scope=2, filter=0x81e6e18 "(mail=someone@domain.de)", attrs=0x0, attrsonly=0, sctrls=0x0, cctrls=0x0, timeout=0x40a10f18, sizelimit=500, msgidp=0x81e6b60) at search.c:109 #10 0x080c8194 in meta_back_search_start (op=0x40c007b0, rs=0x40a12210, dc=0x40a110f0, msc=0x81e6bb8, candidate=0, candidates=0x81e6b58) at search.c:208 #11 0x080c83f3 in meta_back_search (op=0x40c007b0, rs=0x40a12210) at search.c:285 #12 0x08063944 in fe_op_search (op=0x40c007b0, rs=0x40a12210) at search.c:355 #13 0x08063465 in do_search (op=0x40c007b0, rs=0x40a12210) at search.c:217 #14 0x08061180 in connection_operation (ctx=0x40a122a0, arg_v=0x40c007b0) at connection.c:1132 #15 0x0810052f in ldap_int_thread_pool_wrapper (xpool=0x81b8b18) at tpool.c:478 #16 0x40035cf7 in start_thread () from /lib/tls/libpthread.so.0 #17 0x400fa21e in clone () from /lib/tls/libc.so.6 #18 0x40a12bb0 in ?? ()
Here is an (anonymized) log:
Feb 22 15:16:17 server slapd[14494]: daemon: activity on 1 descriptor Feb 22 15:16:17 server slapd[14494]: daemon: activity on: Feb 22 15:16:17 server slapd[14494]: Feb 22 15:16:17 server slapd[14494]: >>> slap_listener(ldap://:3389) Feb 22 15:16:17 server slapd[14494]: daemon: listen=8, new connection on 11 Feb 22 15:16:17 server slapd[14494]: daemon: added 11r (active) listener=(nil) Feb 22 15:16:17 server slapd[14494]: conn=5 fd=11 ACCEPT from IP=127.0.0.1:34632 (IP=0.0.0.0 :3389) Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: activity on 1 descriptor Feb 22 15:16:17 server slapd[14494]: daemon: activity on: Feb 22 15:16:17 server slapd[14494]: 11r Feb 22 15:16:17 server slapd[14494]: Feb 22 15:16:17 server slapd[14494]: daemon: read active on 11 Feb 22 15:16:17 server slapd[14494]: connection_get(11) Feb 22 15:16:17 server slapd[14494]: connection_get(11): got connid=5 Feb 22 15:16:17 server slapd[14494]: connection_read(11): checking for input on id=5 Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: do_bind Feb 22 15:16:17 server slapd[14494]: >>> dnPrettyNormal: <> Feb 22 15:16:17 server slapd[14494]: <<< dnPrettyNormal: <>, <> Feb 22 15:16:17 server slapd[14494]: do_bind: version=3 dn="" method=128 Feb 22 15:16:17 server slapd[14494]: conn=5 op=0 BIND dn="" method=128 Feb 22 15:16:17 server slapd[14494]: conn=5 op=0 BIND dn="" method=128 Feb 22 15:16:17 server slapd[14494]: send_ldap_result: conn=5 op=0 p=3 Feb 22 15:16:17 server slapd[14494]: send_ldap_result: err=0 matched="" text="" Feb 22 15:16:17 server slapd[14494]: send_ldap_response: msgid=1 tag=97 err=0 Feb 22 15:16:17 server slapd[14494]: conn=5 op=0 RESULT tag=97 err=0 text= Feb 22 15:16:17 server slapd[14494]: do_bind: v3 anonymous bind Feb 22 15:16:17 server slapd[14494]: daemon: activity on 1 descriptor Feb 22 15:16:17 server slapd[14494]: daemon: activity on: Feb 22 15:16:17 server slapd[14494]: 11r Feb 22 15:16:17 server slapd[14494]: Feb 22 15:16:17 server slapd[14494]: daemon: read active on 11 Feb 22 15:16:17 server slapd[14494]: connection_get(11) Feb 22 15:16:17 server slapd[14494]: connection_get(11): got connid=5 Feb 22 15:16:17 server slapd[14494]: connection_read(11): checking for input on id=5 Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: do_search Feb 22 15:16:17 server slapd[14494]: >>> dnPrettyNormal: <> Feb 22 15:16:17 server slapd[14494]: <<< dnPrettyNormal: <>, <> Feb 22 15:16:17 server slapd[14494]: SRCH "" 2 0 Feb 22 15:16:17 server slapd[14494]: 0 0 0 Feb 22 15:16:17 server slapd[14494]: begin get_filter Feb 22 15:16:17 server slapd[14494]: EQUALITY Feb 22 15:16:17 server slapd[14494]: end get_filter 0 Feb 22 15:16:17 server slapd[14494]: filter: (mail=someone@domain.de) Feb 22 15:16:17 server slapd[14494]: attrs: Feb 22 15:16:17 server slapd[14494]: Feb 22 15:16:17 server slapd[14494]: conn=5 op=1 SRCH base="" scope=2 deref=0 filter="(mail=someone@domain.de)" Feb 22 15:16:17 server slapd[14494]: ==> limits_get: conn=5 op=1 dn="[anonymous]" Feb 22 15:16:17 server slapd[14494]: conn=5 op=1: meta_back_getconn[0] Feb 22 15:16:17 server slapd[14494]: conn=5 op=1 meta_back_getconn: candidates=1 conn=-1 fet ched Feb 22 15:16:17 server slapd[14494]: conn=5 op=1 meta_back_dobind: conn=-1 Feb 22 15:16:17 server slapd[14494]: conn=5 op=1 meta_back_dobind: conn=-1 bound=1 Feb 22 15:16:17 server slapd[14494]: [rw] searchBase: "" -> "" Feb 22 15:16:17 server slapd[14494]: send_ldap_result: conn=5 op=1 p=3 Feb 22 15:16:17 server slapd[14494]: send_ldap_result: err=32 matched="" text="" Feb 22 15:16:17 server slapd[14494]: send_ldap_response: msgid=2 tag=101 err=32 Feb 22 15:16:17 server slapd[14494]: conn=5 op=1 SEARCH RESULT tag=101 err=32 nentries=0 tex t= Feb 22 15:16:17 server slapd[14494]: daemon: activity on 1 descriptor Feb 22 15:16:17 server slapd[14494]: daemon: activity on: Feb 22 15:16:17 server slapd[14494]: 11r Feb 22 15:16:17 server slapd[14494]: Feb 22 15:16:17 server slapd[14494]: daemon: read active on 11 Feb 22 15:16:17 server slapd[14494]: connection_get(11) Feb 22 15:16:17 server slapd[14494]: connection_get(11): got connid=5 Feb 22 15:16:17 server slapd[14494]: connection_read(11): checking for input on id=5 Feb 22 15:16:17 server slapd[14494]: ber_get_next on fd 11 failed errno=0 (Success) Feb 22 15:16:17 server slapd[14494]: connection_read(11): input error=-2 id=5, closing. Feb 22 15:16:17 server slapd[14494]: connection_closing: readying conn=5 sd=11 for close Feb 22 15:16:17 server slapd[14494]: connection_close: deferring conn=5 sd=11 Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: activity on 1 descriptor Feb 22 15:16:17 server slapd[14494]: daemon: activity on: Feb 22 15:16:17 server slapd[14494]: Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 22 15:16:17 server slapd[14494]: do_unbind Feb 22 15:16:17 server slapd[14494]: conn=5 op=2 UNBIND Feb 22 15:16:17 server slapd[14494]: connection_resched: attempting closing conn=5 sd=11 Feb 22 15:16:17 server slapd[14494]: connection_close: conn=5 sd=11 Feb 22 15:16:17 server slapd[14494]: =>meta_back_conn_destroy: fetching conn=5 DN="" Feb 22 15:16:17 server slapd[14494]: daemon: removing 11 Feb 22 15:16:17 server slapd[14494]: conn=5 fd=11 closed ()