Setting bonsai.set_connect_async(True) causes LDAPS connection to hang until the timeout is reached

mhdonnelly commented 5 years ago

Testing on Fedora30 with module built against openldap-devel-2.4.47-1.fc30.x86_64

Code to reproduce:

import asyncio
import bonsai

bonsai.set_connect_async(True)
bonsai.set_debug(True)

LDAP_URL = "ldaps://ldaps.capable.lan"
CACERT_FILE = "ca.crt"

async def main():
    print("running")
    cli = bonsai.LDAPClient(LDAP_URL)
    cli.set_ca_cert(CACERT_FILE)
    async with cli.connect(is_async=True, timeout=5):
        pass

asyncio.run(main())

If I change bonsai.set_connect_async(True) to False the connection succeeds but the code blocks. Which causes problems in the app I am building when an ldap server becomes unreachable.

Changing the URL to ldap:// with bonsai.set_connect_async(True) works as expected.

The truncated debug output from running the example code is included below

Thanks!

DBG: ldapconnection_new [self:0x7f485f110648]
DBG: ldapconnection_init (self:0x7f485f110648)
DBG: ldapconnection_open (self:0x7f485f110648)
DBG: connecting (self:0x7f485f110648)
DBG: create_conn_info (mech:SIMPLE, sock:6, creds:0x7f486ce6e9f0)
DBG: ldapconnectiter_new [self:0x7f485ed4ed68]
DBG: create_init_thread_data (client:0x7f485ed449e8, sock:6)
DBG: create_init_thread (ld:0x559352f0bf40, info:0x5593530b5b00, thread:0)
DBG: ldap_init_thread_func (params:0x559352f0bf40)
DBG: set connecting async: 1
DBG: ldap_init_thread_func [retval:0]
DBG: ldapconnection_result (self:0x7f485f110648, args:0x7f485f8eafd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f485f110648, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f485ed4ed68, timeout:-1) [tls:0, state:0]
DBG: _ldap_finish_init_thread (async:1, thread:139948802778880, timeout:-1, misc:0x559352f0bf40)
DBG: _pthread_mutex_timedlock
DBG: set_certificates (self:0x7f485ed4ed68)
DBG: binding [state:3]
DBG: _ldap_bind (ld:0x7f4858000b20, info:0x5593530b5b00, ppolicy:0, result:(nil), msgid:0)
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_result (self:0x7f485f110648, args:0x7f485f8eafd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f485f110648, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f485ed4ed68, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_result (self:0x7f485f110648, args:0x7f485f8eafd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f485f110648, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f485ed4ed68, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_fileno (self:0x7f485f110648)[desc:8]
DBG: ldapconnection_result (self:0x7f485f110648, args:0x7f485f8eafd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f485f110648, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f485ed4ed68, timeout:-1) [tls:0, state:4]

... The binding to LDAPConnectIter_Next block repeats until the timeout is reached

Traceback (most recent call last):
  File "./bonsai_ldaps_hang.py", line 21, in <module>
    asyncio.run(main())
  File "/usr/lib64/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib64/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "./bonsai_ldaps_hang.py", line 18, in main
    async with cli.connect(is_async=True, timeout=5):
  File "bonsai/lib/python3.7/site-packages/bonsai/asyncio/aioconnection.py", line 30, in __aenter__
    return await self.__open_coro
  File "bonsai/lib/python3.7/site-packages/bonsai/asyncio/aioconnection.py", line 63, in _poll
    raise exc
  File "bonsai/lib/python3.7/site-packages/bonsai/asyncio/aioconnection.py", line 59, in _poll
    return await asyncio.wait_for(fut, timeout)
  File "/usr/lib64/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

noirello commented 5 years ago

Thank you for reporting it.

I tried to reproduce it using a Fedora 30 base Docker image and I did get an error, but a little bit different than yours. I got a bonsai.TimeoutError almost immediately after start. I think both errors have the same root cause, but could you rerun your code with:

Setting the optional second parameter to -1 for set_debug method: bonsai.set_debug(True, -1). That'll show the openldap trace as well.
Checking the connection with STARTTLS (using ldap:// in the URL and set tls=True in the LDAPClient):

LDAP_URL = "ldap://ldaps.capable.lan
...
bonsai.LDAPClient(LDAP_URL, tls=True)

mhdonnelly commented 5 years ago

No worries.

I have rerun the code snippet with bonsai.set_debug(True, -1). The output is below.

I also get a timeout error immediately if I use STARTTLS. Full debug output is at https://paste.firnsy.com/paste/syeLkutFqVv

bonsai.errors.TimeoutError: Timed out. Start TLS request accepted.Server willing to negotiate SSL. (0xFFFB [-5])

I have omitted the timeout tracedebug

ldap_url_parse_ext(ldap://localhost/)
ldap_init: trying /etc/openldap/ldap.conf
ldap_init: using /etc/openldap/ldap.conf
ldap_init: HOME env is /home/mhd
ldap_init: trying /home/mhd/ldaprc
ldap_init: trying /home/mhd/.ldaprc
ldap_init: trying ldaprc
ldap_init: LDAPCONF env is NULL
ldap_init: LDAPRC env is NULL
ldap_create
ldap_url_parse_ext(ldaps://ldaps.capable.lan:636)
ldap_sasl_bind
ldap_send_initial_request
ldap_new_connection 1 1 0
ldap_int_open_connection
ldap_connect_to_host: TCP ldaps.capable.lan:636
ldap_new_socket: 8
ldap_prepare_socket: 8
ldap_connect_to_host: Trying 10.10.10.10:636
ldap_pvt_connect: fd: 8 tm: 0 async: -1
ldap_ndelay_on: 8
attempting to connect: 
connect errno: 115
ldap_open_defconn: successful
ldap_send_server_request
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status Writing
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
DBG: ldapconnection_new [self:0x7f6ce9d82708]
DBG: ldapconnection_init (self:0x7f6ce9d82708)
DBG: ldapconnection_open (self:0x7f6ce9d82708)
DBG: connecting (self:0x7f6ce9d82708)
DBG: create_conn_info (mech:SIMPLE, sock:6, creds:0x7f6cf7ae09f0)
DBG: ldapconnectiter_new [self:0x7f6ce99c0c90]
DBG: create_init_thread_data (client:0x7f6ce99b76a0, sock:6)
DBG: create_init_thread (ld:0x556590184420, info:0x5565902b3270, thread:0)
DBG: ldap_init_thread_func (params:0x556590184420)
DBG: set connecting async: 1
DBG: ldap_init_thread_func [retval:0]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:0]
DBG: _ldap_finish_init_thread (async:1, thread:140105749907200, timeout:-1, misc:0x556590184420)
DBG: _pthread_mutex_timedlock
DBG: set_certificates (self:0x7f6ce99c0c90)
DBG: binding [state:3]
DBG: _ldap_bind (ld:0x7f6ce4000b20, info:0x5565902b3270, ppolicy:0, result:(nil), msgid:0)
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]
DBG: binding [state:4]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (seldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
ldap_result ld 0x7f6ce4000b20 msgid 1
wait4msg ld 0x7f6ce4000b20 msgid 1 (timeout 10 usec)
wait4msg continue ld 0x7f6ce4000b20 msgid 1 all 1
** ld 0x7f6ce4000b20 Connections:
* host: ldaps.capable.lan  port: 636  (default)
  refcnt: 2  status: Connected
  last used: Fri Jun 21 09:27:59 2019

** ld 0x7f6ce4000b20 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x7f6ce4000b20 request count 1 (abandoned 0)
** ld 0x7f6ce4000b20 Response Queue:
   Empty
  ld 0x7f6ce4000b20 response count 0
ldap_chkResponseList ld 0x7f6ce4000b20 msgid 1 all 1
ldap_chkResponseList returns ld 0x7f6ce4000b20 NULL
ldap_int_select
ldap_msgfree
lf:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_fileno (self:0x7f6ce9d82708)[desc:8]
DBG: ldapconnection_result (self:0x7f6ce9d82708, args:0x7f6cea55cfd0, kwds:(nil))[msgid:7]
DBG: LDAPConnection_Result (self:0x7f6ce9d82708, msgid:7, millisec:-1)
DBG: LDAPConnectIter_Next (self:0x7f6ce99c0c90, timeout:-1) [tls:0, state:4]

...

noirello commented 5 years ago

It seems like that OpenLDAP 2.4.47 has some bugs with async TLS, that have been fixed in the new 2.4.48 release according to the changelog.

While my TLS test fails on Fedora 30 + OpenLDAP 2.4.47, it ran successfully with a manually compiled and installed OpenLDAP 2.4.48. So the new OpenLDAP release looks promising.

But again I ran the same TLS test on an Ubuntu 19.04 + OpenLDAP 2.4.47 and it was successful. I also checked it with the latest Alpine that has OpenLDAP 2.4.47 in its repo and the test was green as well. 😕

nosammai commented 5 years ago

Can confirm I had the same issue on CentOS7 and updating to the openldap 2.4.48 fixed it for me 👍

mhdonnelly commented 5 years ago

@noirello can you please provide the compile options you used to manually compile OpenLDAP 2.4.48?

I am still trying to get this to work in a custom yocto based distro. I have tried 2.4.48 with GnuTLS and OpenSSL and in both cases I get an immediate time out error. In the case of GnuTLS the error code is (0xFFFF [-1]) and when using OpenSSL gives (0xFFFB [-5]).

noirello commented 5 years ago

Sure. Used a Fedora:30 base docker image with the bonsai source files mounted under /opt/bonsai:

dnf update -y
dnf install -y openssl-devel cyrus-sasl-devel zlib-devel krb5-devel \
               pam-devel gcc make findutils groff python3-devel
cd /opt
curl -sL https://www.openldap.org/software/download/OpenLDAP/openldap-release/openldap-2.4.48.tgz | tar xzf -
cd openldap-2.4.48/
./configure --with-tls=openssl --disable-slapd --enable-backends=no
make depend
make
make install

Then before building the module set the include and library dirs in the setup.cfg:

[build_ext]
library_dirs = /usr/local/lib
include_dirs = /usr/local/include

The /usr/local is the default prefix for openldap to put its libraries and header files. After this, build the module:

cd ../bonsai
export LD_LIBRARY_PATH=/usr/local/lib/
python3 setup.py install

Setting the LD_LIBRARY_PATH is important, because otherwise the module will be linked with the system provided libldap library and not with the recently built one.

You can check with ldd that a module uses the correct library:

ldd build/lib.linux-x86_64-3.7/bonsai/_bonsai.cpython-37m-x86_64-linux-gnu.so
 linux-vdso.so.1 (0x00007ffe39bf0000)
 libldap-2.4.so.2 => /usr/local/lib/libldap-2.4.so.2 (0x00007fdbbd97b000)
 liblber-2.4.so.2 => /usr/local/lib/liblber-2.4.so.2 (0x00007fdbbd96c000)

noirello / bonsai

Setting bonsai.set_connect_async(True) causes LDAPS connection to hang until the timeout is reached #30