[Date Prev][Date Next] [Chronological] [Thread] [Top]
ldapsearch (all ssl based queries) hang (never terminate, unless timeout specified) (ITS#3307)

To: openldap-its@OpenLDAP.org
Subject: ldapsearch (all ssl based queries) hang (never terminate, unless timeout specified) (ITS#3307)
From: mwt@cems.umn.edu
Date: Fri, 27 Aug 2004 18:49:47 GMT
Full_Name: Mike Thomas
Version: 2.2.15 (2.0.27, 2.1.30)
OS: Linux, BSD
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (134.84.164.244)


I'm issuing the following ldapsearch command (the problem first appeared when i
was trying to get nss_ldap working and I was having the same 'hanging' problem,
and I have since gone "up the chain" to openldap itself to find the problem) and
the ldapsearch command never returns, it just hangs. I see this behavior on
Gentoo, Debian, and RHEL 3.1 (I tried it on 5 different machines, all have the
same result)

This is querying a Windows 2000 Active Directory domain, no slapd is running, in
fact, openldap was built with --enable-slapd=no. The SSL cert on the server side
was generated automatically using Certificate Services to enable LDAP + SSL on
Active Directory.

ldapsearch -LLL -x -W -D "cn=cemsadmin,ou=Users,ou=IT
Office,dc=cems,dc=umn,dc=edu" -H ldaps://phoenix.cems.umn.edu -b
dc=cems,dc=umn,dc=edu -s sub -d 1 "(cn=mwt)"

ldap.conf settings:

only tls_reqcert never


Here's the debug output:

ldap_create
ldap_url_parse_ext(ldaps://phoenix.cems.umn.edu)
Enter LDAP Password: <some pass put in here>
ldap_bind_s
ldap_simple_bind_s
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ber_sockbuf_ctrl
ldap_new_connection
ldap_int_open_connection
ldap_connect_to_host: TCP phoenix.cems.umn.edu:636
ldap_new_socket: 3
ldap_prepare_socket: 3
ldap_connect_to_host: Trying 134.84.165.42:636
ldap_connect_timeout: fd: 3 tm: -1 async: 0
ldap_ndelay_on: 3
ldap_is_sock_ready: 3
ldap_ndelay_off: 3
ber_sockbuf_ctrl
ber_sockbuf_ctrl
TLS trace: SSL_connect:before/connect initialization
TLS trace: SSL_connect:SSLv2/v3 write client hello A
TLS trace: SSL_connect:SSLv3 read server hello A
TLS certificate verification: depth: 0, err: 20, subject:
/CN=phoenix.cems.umn.edu, issuer:
/emailAddress=cems_sys@cems.umn.edu/C=US/ST=MN/L=Minneapolis/O=University of
Minnesota/OU=CEMS/CN=phoenix
TLS certificate verification: Error, unable to get local issuer certificate
TLS trace: SSL_connect:SSLv3 read server certificate A
TLS trace: SSL_connect:SSLv3 read server certificate request A
TLS trace: SSL_connect:SSLv3 read server done A
TLS trace: SSL_connect:SSLv3 write client certificate A
TLS trace: SSL_connect:SSLv3 write client key exchange A
TLS trace: SSL_connect:SSLv3 write change cipher spec A
TLS trace: SSL_connect:SSLv3 write finished A
TLS trace: SSL_connect:SSLv3 flush data
TLS trace: SSL_connect:SSLv3 read finished A
ber_sockbuf_ctrl
ber_sockbuf_ctrl
ldap_open_defconn: successful
ldap_send_server_request
ber_flush: 81 bytes to sd 3
ber_sockbuf_ctrl
ldap_result msgid 1
ldap_chkResponseList for msgid=1, all=1
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid 1
wait4msg continue, msgid 1, all 1
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 18:49:27 2004

** Outstanding Requests:
* msgid 1,  origid 1, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=1, all=1
ldap_chkResponseList returns NULL
ber_sockbuf_ctrl
ldap_int_select
ber_sockbuf_ctrl
read1msg: msgid 1, all 1
ber_get_next
ber_get_next: tag 0x30 len 16 contents:
ldap_read: message type bind msgid 1, original id 1
ber_scanf fmt ({iaa) ber:
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
ber_scanf fmt ({iaa) ber:
ber_scanf fmt (}) ber:
ldap_msgfree
ldap_search_ext
put_filter: "(cn=mwt)"
put_filter: simple
put_simple_filter: "cn=mwt"
ldap_send_initial_request
ber_sockbuf_ctrl
ldap_send_server_request
ber_flush: 58 bytes to sd 3
ber_sockbuf_ctrl
ldap_result msgid -1
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid -1
wait4msg continue, msgid -1, all 0
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 18:49:27 2004

** Outstanding Requests:
* msgid 2,  origid 2, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
ber_sockbuf_ctrl
ldap_int_select
ber_sockbuf_ctrl
read1msg: msgid -1, all 0
ber_get_next
ber_get_next: tag 0x30 len 1794 contents:
ldap_read: message type search-entry msgid 2, original id 2
ldap_get_dn_ber
ber_scanf fmt ({ml{) ber:
dn: CN=mwt,OU=Users,OU=IT Office,DC=cems,DC=umn,DC=edu
ber_scanf fmt ({xx) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
memberOf: CN=PAS Admins,OU=User Groups,OU=IT Office,DC=cems,DC=umn,DC=edu
memberOf: CN=Domain Users,OU=User Groups,OU=IT Office,DC=cems,DC=umn,DC=edu
memberOf: CN=Domain Admins,OU=User Groups,OU=IT Office,DC=cems,DC=umn,DC=edu
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
accountExpires: 0
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
adminCount: 1
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
badPasswordTime: 127379458892452791
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
badPwdCount: 1
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
codePage: 0
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
cn: mwt
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
countryCode: 0
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
description: CEMS Systems Office Staff
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
displayName: Mike Thomas
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
dSCorePropagationData: 20030122213926.0Z
dSCorePropagationData: 16010101000002.0Z
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
givenName: Mike
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
homeDirectory: \\MOZART\mwt
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
homeDrive: H:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
instanceType: 4
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
lastLogoff: 0
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
lastLogon: 127373437788546459
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
lockoutTime: 0
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
logonCount: 192
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
logonHours:: ////////////////////////////
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
distinguishedName: CN=mwt,OU=Users,OU=IT Office,DC=cems,DC=umn,DC=edu
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
objectCategory: CN=Person,CN=Schema,CN=Configuration,DC=cems,DC=umn,DC=edu
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: user
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
objectGUID:: B4YvW7YJIEKV9GpUvrQeMA==
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
objectSid:: AQUAAAAAAAUVAAAAOUhbB3Rdt23LdNwEVwoAAA==
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
primaryGroupID: 2394
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
profilePath: \\MOTHRA\staffprofiles$\mwt
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
pwdLastSet: 127280869749646795
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
name: mwt
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
sAMAccountName: mwt
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
sAMAccountType: 805306368
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
sn: Thomas
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
userAccountControl: 512
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
userPrincipalName: mwt@cems.umn.edu
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
uSNChanged: 4070476
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
uSNCreated: 1992100
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
whenChanged: 20040503200559.0Z
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
whenCreated: 20020909175124.0Z
ldap_get_attribute_ber
ldap_msgfree
ldap_result msgid -1
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid -1
wait4msg continue, msgid -1, all 0
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 18:49:27 2004

** Outstanding Requests:
* msgid 2,  origid 2, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
ber_sockbuf_ctrl
read1msg: msgid -1, all 0
ber_get_next
ber_get_next: tag 0x30 len 69 contents:
ldap_read: message type search-reference msgid 2, original id 2

ber_scanf fmt ({v) ber:
ber_scanf fmt (}) ber:
# refldap://cems.umn.edu/CN=Configuration,DC=cems,DC=umn,DC=edu
ldap_msgfree
ldap_result msgid -1
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid -1
wait4msg continue, msgid -1, all 0
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 18:49:27 2004

** Outstanding Requests:
* msgid 2,  origid 2, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
ber_sockbuf_ctrl
read1msg: msgid -1, all 0
ber_get_next
ber_get_next: tag 0x30 len 16 contents:
ldap_read: message type search-result msgid 2, original id 2
ber_scanf fmt ({iaa) ber:
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
ldap_int_select 

I hit cntrl-c here to kill the process. I have waited over 30 minutes for the
process to terminate, and it never does.


********************************************************************

Here's the software versions:

OpenSSL 0.9.7d
OpenLDAP 2.2.15 (in this instance, also recieved this behavior with OpenLDAP
2.0.27 and OpenLDAP 2.1.30)

However, I tried this on two *BSD machines, one machine FreeBSD 5.2.1, one
machine MacOSX 10.3 (Darwin 7.1) and the command succeeds successfully, no
hanging. Here's the debug output of the same command:

********************************************************************

ldap_create
ldap_url_parse_ext(ldaps://phoenix.cems.umn.edu)
ldap_bind_s
ldap_simple_bind_s
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_new_connection
ldap_int_open_connection
ldap_connect_to_host: TCP phoenix.cems.umn.edu:636
ldap_new_socket: 3
ldap_prepare_socket: 3
ldap_connect_to_host: Trying 134.84.165.42:636
ldap_connect_timeout: fd: 3 tm: -1 async: 0
ldap_ndelay_on: 3
ldap_is_sock_ready: 3
ldap_ndelay_off: 3
TLS trace: SSL_connect:before/connect initialization
TLS trace: SSL_connect:SSLv2/v3 write client hello A
TLS trace: SSL_connect:SSLv3 read server hello A
TLS certificate verification: depth: 1, err: 0, subject:
/emailAddress=cems_sys@cems.umn.edu/C=US/ST=MN/L=Minneapolis/O=University of
Minnesota/OU=CEMS/CN=phoenix, issuer: /emailAddress=cems_sy
s@cems.umn.edu/C=US/ST=MN/L=Minneapolis/O=University of
Minnesota/OU=CEMS/CN=phoenix
TLS certificate verification: depth: 0, err: 0, subject:
/CN=phoenix.cems.umn.edu, issuer:
/emailAddress=cems_sys@cems.umn.edu/C=US/ST=MN/L=Minneapolis/O=University of
Minnesota/OU=CEMS/CN=phoe
nix
TLS trace: SSL_connect:SSLv3 read server certificate A
TLS trace: SSL_connect:SSLv3 read server certificate request A
TLS trace: SSL_connect:SSLv3 read server done A
TLS trace: SSL_connect:SSLv3 write client certificate A
TLS trace: SSL_connect:SSLv3 write client key exchange A
TLS trace: SSL_connect:SSLv3 write change cipher spec A
TLS trace: SSL_connect:SSLv3 write finished A
TLS trace: SSL_connect:SSLv3 flush data
TLS trace: SSL_connect:SSLv3 read finished A
ldap_open_defconn: successful
ldap_send_server_request
ber_flush: 81 bytes to sd 3
ldap_result msgid 1
ldap_chkResponseList for msgid=1, all=1
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid 1
wait4msg continue, msgid 1, all 1
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 19:05:29 2004

** Outstanding Requests:
* msgid 1,  origid 1, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=1, all=1
ldap_chkResponseList returns NULL
ldap_int_select
read1msg: msgid 1, all 1
ber_get_next
ber_get_next: tag 0x30 len 16 contents:
ldap_read: message type bind msgid 1, original id 1
ber_scanf fmt ({iaa) ber:
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
ber_scanf fmt ({iaa) ber:
ber_scanf fmt (}) ber:
ldap_msgfree
ldap_search_ext
put_filter: "(cn=mwt)"
put_filter: simple
put_simple_filter: "cn=mwt"
ldap_send_initial_request
ldap_send_server_request
ber_flush: 58 bytes to sd 3
ldap_result msgid -1
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid -1
wait4msg continue, msgid -1, all 0
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 19:05:29 2004

** Outstanding Requests:
* msgid 2,  origid 2, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
ldap_int_select
read1msg: msgid -1, all 0
ber_get_next
ber_get_next: tag 0x30 len 1794 contents:
ldap_read: message type search-entry msgid 2, original id 2
ldap_get_dn
ber_scanf fmt ({a) ber:
ber_scanf fmt ({xx) ber:
ldap_first_attribute
ber_scanf fmt ({xl{) ber:
ber_scanf fmt ({ax}) ber:
ldap_get_values_len
ber_scanf fmt ({x{{a) ber:
ber_scanf fmt ([V]) ber:
ldap_next_attribute
ber_scanf fmt ({ax}) ber:
ldap_get_values_len
ber_scanf fmt ({x{{a) ber:
ber_scanf fmt (x}{a) ber:
ber_scanf fmt ([V]) ber:
ldap_next_attribute
*********
<snipped output as it just repeats that a lot>
*********
ber_scanf fmt ([V]) ber:
ldap_next_attribute
ldap_msgfree
ldap_result msgid -1
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid -1
wait4msg continue, msgid -1, all 0
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 19:05:29 2004

** Outstanding Requests:
* msgid 2,  origid 2, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
read1msg: msgid -1, all 0
ber_get_next
ber_get_next: tag 0x30 len 69 contents:
ldap_read: message type search-reference msgid 2, original id 2
ber_scanf fmt ({v) ber:
ber_scanf fmt (}) ber:
ldap_msgfree
ldap_result msgid -1
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
wait4msg (infinite timeout), msgid -1
wait4msg continue, msgid -1, all 0
** Connections:
* host: phoenix.cems.umn.edu  port: 636  (default)
 refcnt: 2  status: Connected
 last used: Wed Aug 25 19:05:29 2004

** Outstanding Requests:
* msgid 2,  origid 2, status InProgress
  outstanding referrals 0, parent count 0
** Response Queue:
  Empty
ldap_chkResponseList for msgid=-1, all=0
ldap_chkResponseList returns NULL
read1msg: msgid -1, all 0
ber_get_next
ber_get_next: tag 0x30 len 16 contents:
ldap_read: message type search-result msgid 2, original id 2
ber_scanf fmt ({iaa) ber:
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

ldap_parse_result
ber_scanf fmt ({iaa) ber:
ber_scanf fmt (}) ber:
ldap_unbind
ldap_free_connection
ldap_send_unbind
ber_flush: 7 bytes to sd 3
ldap_free_connection: actually freed
TLS trace: SSL3 alert write:warning:close notify

********************************************************************

And viola, it completes sucessfully, so it appears that its hanging on
ldap_int_select.

Thanks for your help guys.
Prev by Date: replicas store normalized entryUUIDs (ITS#3306)
Next by Date: Re: constraint overlay (ITS#3292)
Index(es):
- Chronological
- Thread