[Date Prev][Date Next] [Chronological] [Thread] [Top]

ldapsearch (all ldap queries) hang, using SSL on Active Directory

To: openldap-software@OpenLDAP.org
Subject: ldapsearch (all ldap queries) hang, using SSL on Active Directory
From: Mike Thomas <mwt@cems.umn.edu>
Date: Wed, 25 Aug 2004 19:08:44 -0500
User-agent: Mozilla Thunderbird 0.7 (Macintosh/20040616)

Hello,

I'm issuing the following ldapsearch command (the problem first appeared when i was trying to get nss_ldap working, 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)

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)"

Here's the debug output:

ldap_create ldap_url_parse_ext(ldaps://phoenix.cems.umn.edu) Enter LDAP Password: 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


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

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, 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,

--Mike

Prev by Date: Re: JDBCLDAP Bridge Error
Next by Date: syncrepl multimaster
Index(es):
- Chronological
- Thread