RE: timeout on ldap_simple_bind_s()

"Xu, Qiang (FXSGSC)" <[email protected]> Fri, 11 Sep 2009 19:35:47 +0800
Newsgroups gmane.comp.mozilla.devel.directory
Message-ID <D8C9BC7FFCF8154FB7141EB8DB609C172F0C105A0C@SGPAPHQ-EXSCC01.dc01.fujixerox.net>
> -----Original Message-----
> From: [email protected] [mailto:[email protected]] 
> Sent: Friday, September 11, 2009 6:34 PM
> To: Xu, Qiang (FXSGSC)
> Cc: [email protected]
> Subject: Re: timeout on ldap_simple_bind_s()
> 
> 
> just type gdb then type attach process_id then type bt. 
> obviously you gonna have to provide process_id of your 
> running client app.

Unstripped version of the executable (distributionService) has been loaded onto the printer, but the stack trace seems to be the same as the previous one: 
=================================================
XCTEST61:/var/log/nc <144> ps aux |grep distributionService
root      4952  0.3  1.6  38596  6856 ?        Ss   19:03   0:02 distributionService
root     23037  0.0  0.1   1904   452 ttyp1    R+   19:15   0:00 grep distributionService
XCTEST61:/var/log/nc <145> gdb
...
(gdb) attach 4952
Attaching to process 4952
Reading symbols from /opt/nc/dlms/s2distribution/apps/distributionService...done.
...
0x306b3680 in poll () from /lib/libc.so.6
(gdb) bt
#0  0x306b3680 in poll () from /lib/libc.so.6
#1  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#2  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#3  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#4  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#5  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#6  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#7  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#8  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#9  0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#10 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#11 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#12 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#13 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#14 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#15 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#16 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#17 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#18 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#19 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#20 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#21 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#22 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#23 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#24 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#25 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#26 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
#27 0x300fe2cc in PT_FPrintStats () from /usr/smart/lib/libnspr4.so
Previous frame inner to this frame (corrupt stack?)
(gdb)
=================================================
The stack trace is captured when ldap_simple_bind is still blocking. I am wondering why I can't see the function call of ldap_simple_bind(). 

When the blocking is finally finished, the log shows a whopping 7 mins: 
=================================================
<distribution> (Fri Sep 11 2009 19:14:38.567) <p4952,t813147760,aba_ldap_interface.c,1394>
     INFO>> Secure Login
<distribution> (Fri Sep 11 2009 19:14:38.567) <p4952,t813147760,aba_ldap_interface.c,5884>
     INFO>> debug ldap_simple_bind_ext_s timeout = 10
<distribution> (Fri Sep 11 2009 19:14:38.567) <p4952,t813147760,aba_ldap_interface.c,5888>
     INFO>> debug ldap_simple_bind_ext_s --1
<distribution> (Fri Sep 11 2009 19:21:22.495) <p4952,t813147760,aba_ldap_interface.c,1405>
     INFO>> ldap_simple_bind_ext_s return 91
<distribution> (Fri Sep 11 2009 19:21:22.885) <p4952,t813147760,aba_ldap_interface.c,1410>
     INFO>> LDAP BIND: Value of ldapStatus 91
<distribution> (Fri Sep 11 2009 19:21:22.885) <p4952,t813147760,aba_ldap_interface.c,1479>
    ERROR>> LDAP BIND: Value of ldap failure status and text 91 Can't connect to the LDAP server
=================================================
7 mins is too long, really absurd. 

For your reference, the related code is pasted here again: 
=================================================
static int ldap_simple_bind_ext_s( LDAP *ld, const char *dn, const char *passwd, struct timeval *timeout ) 
{
	int		msgid;
	LDAPMessage	*result;

            LOGINFO("debug ldap_simple_bind_ext_s timeout = %d ", timeout->tv_sec );

	if ( ld == NULL ) {
		return( LDAP_PARAM_ERROR );
	}

            LOGINFO("debug ldap_simple_bind_ext_s --1" );

	if ( (msgid = ldap_simple_bind( ld, dn, passwd )) == -1 )
		return( ldap_get_lderrno( ld, NULL, NULL ) );

            LOGINFO("debug ldap_simple_bind_ext_s --2 ");

	if ( ldap_result( ld, msgid, 1, timeout, &result ) == -1 )
		return( ldap_get_lderrno( ld, NULL, NULL ) );

            LOGINFO("debug ldap_simple_bind_ext_s --3" );

	return( ldap_result2error( ld, result, 1 ) );
} 
=================================================
Just can't explain why ldap_simple_bind() can block such a long time. ldap_result() is never entered at all. I am thinking that in what condition, the combination of ldap_simple_bind() and ldap_result(), with a non-NULL timeout pointer, takes effect.

In my case (the LDAP server is pointed to a windows XP workstation, which is not an AD), is there any way to unblock the call of ldap_simple_bind()?

Totally lost here,
Xu Qiang