[Date Prev][Date Next] [Chronological] [Thread] [Top]
(ITS#3637) ldap_search_s hangs in ldap_int_select over stunnel

To: openldap-its@OpenLDAP.org
Subject: (ITS#3637) ldap_search_s hangs in ldap_int_select over stunnel
From: n.j.frost@soton.ac.uk
Date: Thu, 7 Apr 2005 14:13:57 GMT
Full_Name: Nigel Frost
Version: 2.2.24 stable-20050318
OS: Solaris client / Win2003 Active Directory
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (152.78.132.24)


Our openldap clients connect to Active Directory over stunnel.
We recently upgraded some of our Active Directory domain controllers to 2003.
This has resulted in calls to ldap_select_s hanging in ldap_int_select. 

I upgraded openldap, created a simple test programme on the Solaris client,
which connects and binds, then performs an ldap_search_s using the cn of a user
to return the full dn. 

The programme completes successfully when:
1. Connecting directly to the 2003 domain controller, without stunnel.
2. Connecting to one of the 2000 domain controllers, over stunnel.
3. Connecting to a 2003 domain controller, with debug output to the console,
over stunnel.

The programme hangs indefinitely when:
1. Exactly as 3. above, but with no debug output.
2. Exactly as 3. above, but with debug output redirected to a file.

>From this I assume that it is a timing error, and similar to several previous
issues (e.g. 3304) for which I can see the fix in version 2.2.24 result.c.

Here is the debug output for the failed run, followed by the diffs from the
successful run. (see *** diffs start here ***).

ldap_simple_bind_s
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_new_connection
ldap_int_open_connection
ldap_open_defconn: successful
ldap_send_server_request
** Connections:
* host: 127.0.0.1  port: 8389  (default)
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:20 2005

** Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
** Response Queue:
   Empty
ldap_int_select
read1msg: msgid 1, all 1
ldap_read: message type bind msgid 1, original id 1
new result:  res_errno: 0, res_error: <>, res_matched: <>
read1msg:  0 new referrals
read1msg:  mark request completed, id = 1
request 1 done
res_errno: 0, res_error: <>, res_matched: <>
ldap_free_request (origid 1, msgid 1)
ldap_free_connection
ldap_free_connection: refcnt 1
ldap_parse_result
ldap_msgfree
ldap_search
put_filter: "(cn=dcd)"
put_filter: simple
put_simple_filter: "cn=dcd"
ldap_send_initial_request
ldap_send_server_request
** Connections:
* host: 127.0.0.1  port: 8389  (default)
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:20 2005

** Outstanding Requests:
 * msgid 2,  origid 2, status InProgress
   outstanding referrals 0, parent count 0
** Response Queue:
   Empty
ldap_int_select
read1msg: msgid 2, all 1
ldap_read: message type search-entry msgid 2, original id 2
** Connections:
* host: 127.0.0.1  port: 8389  (default)
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:20 2005

** Outstanding Requests:
 * msgid 2,  origid 2, status InProgress
   outstanding referrals 0, parent count 0
** Response Queue:
 * msgid 2,  type 100
ldap_int_select
read1msg: msgid 2, all 1
ldap_read: message type search-reference msgid 2, original id 2
ldap_chase_v3referrals
ldap_url_parse_ext(ldaps://...,DC=soton,DC=ac,DC=uk)
re_encode_request: new msgid 3, new dn
<CN=Configuration,...DC=soton,DC=ac,DC=uk>
ldap_chase_v3referral: msgid 2, url "ldaps://...DC=soton,DC=ac,DC=uk"
ldap_send_server_request
ldap_new_connection
ldap_int_open_connection
anonymous rebind via ldap_bind_s
ldap_bind_s
ldap_simple_bind_s
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_send_server_request
** Connections:
* host: ....soton.ac.uk  port: 0
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:20 2005
  rebind in progress
    queue is empty

* host: 127.0.0.1  port: 8389  (default)
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:20 2005

** Outstanding Requests:
 * msgid 4,  origid 4, status InProgress
   outstanding referrals 0, parent count 0
 * msgid 2,  origid 2, status InProgress
   outstanding referrals 1, parent count 0
** Response Queue:
 * msgid 2,  type 100
ldap_int_select
read1msg: msgid 4, all 1

*** diffs start here ***

ldap_read: message type search-result msgid 2, original id 2
new result:  res_errno: 0, res_error: <>, res_matched: <>
read1msg:  0 new referrals
read1msg:  mark request completed, id = 2
ldap_free_connection
ldap_free_connection: refcnt 1
** Connections:
* host: ....soton.ac.uk  port: 0
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:20 2005
  rebind in progress
    queue is empty

* host: 127.0.0.1  port: 8389  (default)
  refcnt: 1  status: Connected
  last used: Thu Apr  7 13:50:20 2005

** Outstanding Requests:
 * msgid 4,  origid 4, status InProgress
   outstanding referrals 0, parent count 0
 * msgid 2,  origid 2, status Request Completed
   outstanding referrals 1, parent count 0
** Response Queue:
 * msgid 2,  type 100
ldap_int_select
read1msg: msgid 4, all 1
ber_get_next failed.
ldap_free_connection
ldap_free_connection: actually freed
ldap_err2string
Unable to chase referral "ldaps://...DC=soton,DC=ac,DC=uk" (Can't contact LDAP
server)
adding response id 2 type 115:
** Connections:
* host: 127.0.0.1  port: 8389  (default)
  refcnt: 1  status: Connected
  last used: Thu Apr  7 13:50:20 2005

** Outstanding Requests:
 * msgid 4,  origid 4, status InProgress
   outstanding referrals 0, parent count 0
 * msgid 2,  origid 2, status Request Completed
   outstanding referrals 0, parent count 0
** Response Queue:
 * msgid 2,  type 100
   chained responses:
  * msgid 2,  type 115
ldap_int_select


Successful completion
---------------------

*** diffs start here ***

ber_get_next failed.
ldap_free_connection
ldap_free_connection: actually freed
ldap_err2string
Unable to chase referral "ldaps://...DC=soton,DC=ac,DC=uk" (Can't contact LDAP
server)
adding response id 2 type 115:
** Connections:
* host: 127.0.0.1  port: 8389  (default)
  refcnt: 2  status: Connected
  last used: Thu Apr  7 13:50:19 2005

** Outstanding Requests:
 * msgid 4,  origid 4, status InProgress
   outstanding referrals 0, parent count 0
 * msgid 2,  origid 2, status InProgress
   outstanding referrals 0, parent count 0
** Response Queue:
 * msgid 2,  type 100
   chained responses:
  * msgid 2,  type 115
ldap_int_select
read1msg: msgid 2, all 1
ldap_read: message type search-result msgid 2, original id 2
new result:  res_errno: 0, res_error: <>, res_matched: <>
read1msg:  0 new referrals
read1msg:  mark request completed, id = 2
request 2 done
res_errno: 0, res_error: <>, res_matched: <>
ldap_free_request (origid 2, msgid 2)
ldap_free_connection
ldap_free_connection: refcnt 1
adding response id 2 type 101:
ldap_parse_result
ldap_get_dn
ldap_msgfree
Prev by Date: Re: (ITS#3636) more flexible file: URLs in LDIFs
Next by Date: (ITS#3635)
Index(es):
- Chronological
- Thread