ldap3.core.exceptions.LDAPStartTLSError: automatic start_tls befored bind not successful

[1kastner]

Bug description

A JupyterHub configuration that has worked in the past stopped working after I have pulled the newest library versions.

Expected behaviour

My previous configuration continues to work.

Actual behaviour

LDAP login leads to the exception ldap3.core.exceptions.LDAPStartTLSError: automatic start_tls befored bind not successful with the following stacktrace

[E 2020-08-10 16:12:04.735 JupyterHub web:1670] Uncaught exception POST /hub/login?next= (134.28.117.8)
    HTTPServerRequest(protocol='http', host='XXXX', method='POST', uri='/hub/login?next=', version='HTTP/1.1', remote_ip='134.28.117.8')
    Traceback (most recent call last):
      File "/opt/conda/lib/python3.6/site-packages/tornado/web.py", line 1592, in _execute
        result = yield result
      File "/opt/conda/lib/python3.6/site-packages/jupyterhub/handlers/login.py", line 81, in post
        user = await self.login_user(data)
      File "/opt/conda/lib/python3.6/site-packages/jupyterhub/handlers/base.py", line 473, in login_user
        authenticated = await self.authenticate(data)
      File "/opt/conda/lib/python3.6/site-packages/jupyterhub/auth.py", line 257, in get_authenticated_user
        authenticated = await maybe_future(self.authenticate(handler, data))
      File "/opt/conda/lib/python3.6/types.py", line 248, in wrapped
        coro = func(*args, **kwargs)
      File "/opt/conda/lib/python3.6/site-packages/ldapauthenticator/ldapauthenticator.py", line 382, in authenticate
        conn = self.get_connection(userdn, password)
      File "/opt/conda/lib/python3.6/site-packages/ldapauthenticator/ldapauthenticator.py", line 315, in get_connection
        server, user=userdn, password=password, auto_bind=auto_bind
      File "/opt/conda/lib/python3.6/site-packages/ldap3/core/connection.py", line 356, in __init__
        self._do_auto_bind()
      File "/opt/conda/lib/python3.6/site-packages/ldap3/core/connection.py", line 391, in _do_auto_bind
        raise LDAPStartTLSError(error)
    ldap3.core.exceptions.LDAPStartTLSError: automatic start_tls befored bind not successful

How to reproduce

I used the simple config lines:

c.JupyterHub.authenticator_class = 'ldapauthenticator.LDAPAuthenticator'
c.LDAPAuthenticator.server_address = 'ldaps://XXX'
c.LDAPAuthenticator.bind_dn_template = [
    "uid={username},ou=people,dc=XXX,dc=de"
]
c.LDAPAuthenticator.use_ssl = True

Your personal set up

• OS: Ubuntu
• Version: latest

[welcome]

Thank you for opening your first issue in this project! Engagement like this is essential for open source projects! 🤗

If you haven't done so already, check out Jupyter's Code of Conduct. Also, please try to follow the issue template as it helps other other community members to contribute more effectively.

You can meet the other Jovyans by joining our Discourse forum. There is also an intro thread there where you can stop by and say Hi! 👋

Welcome to the Jupyter community! 🎉

[manics]

Is it only the ldapauthenticator package that was updated, or other packages too?

[1kastner]

Sorry I can't tell because the JupyterHub docker container was freshly created without any fixed versions. I can do some digging there. I can say that the LDAPS server continues to work since a small script that directly imports the ldap package continues to work as intended.

[manics]

There were a few large PRs in the last release https://github.com/jupyterhub/ldapauthenticator/blob/master/CHANGELOG.md
Would you mind turning on debug logging and pasting the logs here?

[jrse]

@1kastner did you make it work? i have the same problem.

[1kastner]

Well, @manics, I tried the following adjustment at the configuration to get more information:

c.JupyterHub.log_level = 'DEBUG'
c.LDAPAuthenticator.debug = True
from ldap3.utils.log import set_library_log_detail_level, OFF, BASIC, NETWORK, EXTENDED
set_library_log_detail_level(EXTENDED)  # https://ldap3.readthedocs.io/en/latest/logging.html

But nothing showed up in the logs. I guess the reason is that maybe everything dies before the real action (exchange of information over network) even starts? Or were I missing something about the logs? I just checked the Jupyter logs that show up when I run docker-compose up. Is there any other source that might be of help for you?

The following script that uses vanilla ldap works:

connection = ldap.initialize("ldaps://XXX")
connection.bind_s(
    "uid={},ou=People,dc=XXX,dc=de".format(username),
    password
)
fields = ['uid', 'givenName', 'sn', 'mail']
result = connection.search_s(
    "ou=People,dc=XXX,dc=de",
    ldap.SCOPE_SUBTREE,
    "uid={}".format(username),
    fields,
)
connection.unbind_s()

[1kastner]

@jrse I have several other jobs as well so if you want to take over to share some logs that help here, feel free to do so! If at some point I make it work I will let everyone know.

[guillaumeeb]

Hi everyone, I have also the same problem. Running jupyterhub in debug mode does not give many more lines...

[I 2020-08-11 15:11:38.399 JupyterHub log:174] 302 GET /hub/ -> /hub/login (@132.149.8.29) 1.41ms
[I 2020-08-11 15:11:38.458 JupyterHub log:174] 200 GET /hub/login (@132.149.8.29) 35.67ms
[D 2020-08-11 15:11:45.909 JupyterHub ldapauthenticator:379] Attempting to bind eynardbg with uid=eynardbg,cn=users,cn=accounts,dc=SIS,dc=CNES,dc=FR
[E 2020-08-11 15:11:45.935 JupyterHub web:1792] Uncaught exception POST /hub/login?next= (132.149.8.29)
    HTTPServerRequest(protocol='https', host='jupyterhub-qualif.sis.cnes.fr', method='POST', uri='/hub/login?next=', version='HTTP/1.1', remote_ip='132.149.8.29')
    Traceback (most recent call last):
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/tornado/web.py", line 1703, in _execute
        result = await result
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/jupyterhub/handlers/login.py", line 144, in post
        user = await self.login_user(data)
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/jupyterhub/handlers/base.py", line 699, in login_user
        authenticated = await self.authenticate(data)
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/jupyterhub/auth.py", line 383, in get_authenticated_user
        authenticated = await maybe_future(self.authenticate(handler, data))
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/ldapauthenticator/ldapauthenticator.py", line 382, in authenticate
        conn = self.get_connection(userdn, password)
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/ldapauthenticator/ldapauthenticator.py", line 315, in get_connection
        server, user=userdn, password=password, auto_bind=auto_bind
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/ldap3/core/connection.py", line 356, in __init__
        self._do_auto_bind()
      File "/srv/conda-2020-08-11-14-21-39/lib/python3.7/site-packages/ldap3/core/connection.py", line 391, in _do_auto_bind
        raise LDAPStartTLSError(error)
    ldap3.core.exceptions.LDAPStartTLSError: automatic start_tls befored bind not successful
    
[D 2020-08-11 15:11:45.939 JupyterHub base:1197] No template for 500
[E 2020-08-11 15:11:45.945 JupyterHub log:166] {
      "X-Forwarded-Host": "jupyterhub-qualif.sis.cnes.fr",
      "X-Forwarded-Proto": "https",
      "X-Forwarded-Port": "443",
      "X-Forwarded-For": "132.149.8.29",
      "Upgrade-Insecure-Requests": "1",
      "Connection": "close",
      "Dnt": "1",
      "Origin": "https://jupyterhub-qualif.sis.cnes.fr",
      "Content-Length": "41",
      "Content-Type": "application/x-www-form-urlencoded",
      "Referer": "https://jupyterhub-qualif.sis.cnes.fr/hub/login",
      "Accept-Encoding": "gzip, deflate, br",
      "Accept-Language": "fr,fr-FR;q=0.8,en-US;q=0.5,en;q=0.3",
      "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8",
      "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:79.0) Gecko/20100101 Firefox/79.0",
      "Host": "jupyterhub-qualif.sis.cnes.fr"
    }
[E 2020-08-11 15:11:45.945 JupyterHub log:174] 500 POST /hub/login?next= (@132.149.8.29) 38.24ms

What I don't know, is where the IP 132.149.8.29 in my case comes from.

[1kastner]

At https://ldap3.readthedocs.io/en/latest/changelog.html they also mention that there were several changes just some days ago when a new library version has been published. At https://github.com/cannatag/ldap3/blob/191667cff76e874164dce94dafebf0acf344bd41/ldap3/core/connection.py#L391 we can see how the error message is created and there seem to be plenty of options what can go wrong. The changes at https://github.com/jupyterhub/ldapauthenticator/blob/master/ldapauthenticator/ldapauthenticator.py#L311 seem not that recent but the way LDAP interprets it has changed. If I have use_ssl=True, then the value of auto_bind will be True and according to https://github.com/cannatag/ldap3/blob/191667cff76e874164dce94dafebf0acf344bd41/ldap3/core/connection.py#L250 now it should not be a boolean anymore!

Therefore https://github.com/cannatag/ldap3/blob/191667cff76e874164dce94dafebf0acf344bd41/ldap3/core/connection.py#L250 is not a smart solution anymore because it relies on backward-compability. If use_ssl=True, then at https://github.com/cannatag/ldap3/blob/191667cff76e874164dce94dafebf0acf344bd41/ldap3/core/connection.py#L252 it defaults to AUTO_BIND_NO_TLS and since I wanted to use SSL, I am not sure whether that is a smart decision.

This is just a quick static manual code analysis, the weather is hot, and I am not deeply rooted in any of the projects, so there might be flaws in my reasoning. But I believe https://github.com/jupyterhub/ldapauthenticator/blame/master/ldapauthenticator/ldapauthenticator.py#L312 needs some adjustments.

[guillaumeeb]

I'll try redeploying my Jupyterhub and pinning ldap3 lib to 2.7 version to see if it works. Thanks for the analysis.

[manics]

@1kastner Thanks for investigating! One of the problems with LDAP is it can be extremely complex, and prior to the last release there were no CI tests which made maintainance very difficult.

Thanks to #134 which added Travis tests this is much improved but unfortunately it looks like some bugs crept in. Would you mind opening a PR if you figure out the cause, and/or perhaps add a failing test case to https://github.com/jupyterhub/ldapauthenticator/blob/master/ldapauthenticator/tests/test_ldapauthenticator.py? Thanks!

[1kastner]

@manics I will see when I find time for it. If somebody else urgently needs a solution, better don't wait for me.

[guillaumeeb]

I'll try redeploying my Jupyterhub and pinning ldap3 lib to 2.7 version to see if it works. Thanks for the analysis.

Pinning ldap3 to 2.7 in the Python environment where the Jupyterhub is started did the trick for me.

[1kastner]

@manics Maybe then for the meantime we should also pin the version in the setup.py?