[Date Prev][Date Next] [Chronological] [Thread] [Top]
(ITS#4850) back-meta stops returning data

To: openldap-its@OpenLDAP.org
Subject: (ITS#4850) back-meta stops returning data
From: ulf.moeller@secardeo.com
Date: Fri, 23 Feb 2007 18:16:10 GMT
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 ()
Prev by Date: Re: (ITS#4844) Missing 2.4 man pages and things marked as "Experimental"
Next by Date: Re: (ITS#4850) back-meta stops returning data
Index(es):
- Chronological
- Thread