search

noirello / bonsai

Simple Python 3 module for LDAP, using libldap2 and winldap C libraries.
MIT License
117 stars 33 forks source link

Unexpected behavior on macOS 10.12.3 (Python 3.6) #10

Closed Gr1N closed 6 years ago

Gr1N commented 7 years ago

Hi!

I got some very strange behavior with bonsai on macOS, first connection never works properly. Here my code example:

import asyncio
import bonsai

@asyncio.coroutine
def do():
    client = bonsai.LDAPClient('ldaps://secret')
    client.set_credentials('SIMPLE', ('secret', 'secret'))
    client.set_cert_policy('allow')

    with (yield from client.connect(is_async=True, timeout=10.0)) as conn:
        res = yield from conn.search('ou=nerdherd,dc=bonsai,dc=test', 2)
        print(res)
        who = yield from conn.whoami()
        print(who)

if __name__ == '__main__':
    loop = asyncio.get_event_loop()
    loop.run_until_complete(do())
    loop.run_until_complete(do())

And console output with enabled PYTHONASYNCIODEBUG env var:

➔ PYTHONASYNCIODEBUG=1 python test_bonsai.py
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.108 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.107 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.111 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.103 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.106 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.110 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.112 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.113 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.105 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.110 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.103 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.103 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.107 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.105 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.103 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.101 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.111 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.107 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.106 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.102 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.106 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.110 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.102 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.111 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.105 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.105 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.102 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.107 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.104 seconds
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:298> took 0.293 seconds
[]
dn:cn=secret
Executing <Handle cancelled AIOLDAPConnection._ready(7, <Future pendi...nection.py:31>) created at /usr/local/Cellar/python3/3.6.0/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262> took 0.263 seconds
[]
dn:cn=secret

Sometimes first connection doesn't work at all...

Same code on Linux works well:

root@e2c92ff9d4f6:/tmp# PYTHONASYNCIODEBUG=1 python test_bonsai.py
Executing <Handle cancelled AIOLDAPConnection._ready(9, <Future pendi...nection.py:31>) created at /usr/local/lib/python3.6/asyncio/selector_events.py:298> took 0.437 seconds
[]
dn:cn=secret
Executing <Handle cancelled AIOLDAPConnection._ready(9, <Future pendi...nection.py:31>) created at /usr/local/lib/python3.6/asyncio/selector_events.py:262> took 0.368 seconds
[]
dn:cn=secret
root@e2c92ff9d4f6:/tmp#

Any ideas?

noirello commented 7 years ago

I think that could be some kind of deadlock of threads. On Mac checking that a pthread lock is released is a little different than on Linux.

I ran into this infinite looping issue in earlier version of the module, but not recently. I've thought that I got rid of this after some refactorization.

I've tried to reproduce it now, but no luck. Unfortunately, these thread related bugs are usually hard to reproduce and even more difficult to me to fix them. :( But I will try my best.

Gr1N commented 7 years ago

This is not a big problem, because macOS isn't production platform. But it would be great to find issue.

noirello commented 6 years ago

I added a new set_debug function in 0.9.1, and annotated some functions with debug messages. The annotations are not very exhaustive currently, but they might provide some insights where things go wrong in the future.