Re: (ITS#6922) connection_read(20): no connection!

[hyc@symas.com]

michael@stroeder.com wrote:
> Full_Name: Michael Ströder
> Version: 2.4.25
> OS: openSUSE Linux 11.4
> URL:
> Submission from: (NULL) (84.128.243.158)
>
>
> Currently I observe something like below in my syslog.

The syslog output you included doesn't show anything unusual. Did you have an 
actual bug to report?

> This is a simple
> python-ldap (linked against OpenLDAP libs 2.4.25) script doing LDAPI connect and
> unbind. I occasionally experience hangs when doing unbind also to other LDAP
> servers.

Your syslog output doesn't show any problem. Your debug output also doesn't 
show any problem.

The debug output shows that a read attempt was queued up for a socket that was 
closed. This is a normal occurrence when an LDAP client closes its connection 
immediately after sending its last request (Unbind here) and slapd doesn't 
have enough CPU resources to process the read attempt immediately. By the time 
slapd gets to this event in its queue, the connection is gone.

If you're reporting a hang with OpenLDAP, you should have said that 
explicitly. If not, then I see no bug here and this ITS will be closed.

> ---------------------- debug log ----------------------
> [..private search results snipped..]
> <= send_search_entry: conn 1000 exit.
> send_ldap_result: conn=1000 op=0 p=3
> send_ldap_result: err=0 matched="" text=""
> send_ldap_response: msgid=1 tag=101 err=0
> ber_flush2: 14 bytes to sd 18
>    0000:  30 0c 02 01 01 65 07 0a  01 00 04 00 04 00         0....e........
> ldap_write: want=14, written=14
>    0000:  30 0c 02 01 01 65 07 0a  01 00 04 00 04 00         0....e........
> conn=1000 op=0 SEARCH RESULT tag=101 err=0 nentries=72 text=
> daemon: activity on 1 descriptor
> daemon: activity on: 18r
> daemon: read active on 18
> daemon: epoll: listen=7 active_threads=0 tvp=zero
> daemon: epoll: listen=8 active_threads=0 tvp=zero
> daemon: epoll: listen=9 active_threads=0 tvp=zero
> daemon: activity on 1 descriptor
> daemon: activity on:
> daemon: read active on 18
> daemon: epoll: listen=7 active_threads=0 tvp=zero
> daemon: epoll: listen=8 active_threads=0 tvp=zero
> daemon: epoll: listen=9 active_threads=0 tvp=zero
> daemon: activity on 1 descriptor
> daemon: activity on:
> daemon: read active on 18
> daemon: epoll: listen=7 active_threads=0 tvp=zero
> daemon: epoll: listen=8 active_threads=0 tvp=zero
> daemon: epoll: listen=9 active_threads=0 tvp=zero
> connection_get(18)
> connection_get(18): got connid=1000
> connection_read(18): checking for input on id=1000
> ber_get_next
> ldap_read: want=8, got=7
>    0000:  30 05 02 01 02 42 00                               0....B.
> ber_get_next: tag 0x30 len 5 contents:
> ber_dump: buf=0xe9d5a0 ptr=0xe9d5a0 end=0xe9d5a5 len=5
>    0000:  02 01 02 42 00                                     ...B.
> op tag 0x42, time 1304096292
> ber_get_next
> ldap_read: want=8, got=0
>
> ber_get_next on fd 18 failed errno=0 (Success)
> connection_read(18): input error=-2 id=1000, closing.
> connection_closing: readying conn=1000 sd=18 for close
> connection_close: deferring conn=1000 sd=18
> conn=1000 op=1 do_unbind
> conn=1000 op=1 UNBIND
> connection_resched: attempting closing conn=1000 sd=18
> connection_close: conn=1000 sd=18
> =>ldap_back_conn_destroy: fetching conn 1000
> daemon: removing 18
> conn=1000 fd=18 closed
> connection_get(18)
> connection_get(18): connection not used
> connection_read(18): no connection!
> connection_read(18) error
> connection_get(18)
> connection_get(18): connection not used
> connection_read(18): no connection!
> connection_read(18) error
> daemon: activity on 1 descriptor
> daemon: activity on:
> daemon: epoll: listen=7 active_threads=0 tvp=zero
> daemon: epoll: listen=8 active_threads=0 tvp=zero
> daemon: epoll: listen=9 active_threads=0 tvp=zero
>
>


-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/