Kallithea doesn't populate profile from LDAP

Mon Sep 5 04:20:22 UTC 2016

Here is the part I find relevant. As far as I can see, no errors, just empty profile data from LDAP.

> 2016-09-05 09:11:14.717 DEBUG [kallithea.lib.auth_modules] Importing kallithea.lib.auth_modules.auth_internal
> 2016-09-05 09:11:14.717 DEBUG [kallithea.lib.auth_modules] Loaded auth plugin from kallithea.lib.auth_modules.auth_internal (module:kallithea.lib.auth_modules.auth_internal, file:/home/public_html/kallithea/s
> rc/kallithea/lib/auth_modules/auth_internal.pyc)
> 2016-09-05 09:11:14.718 DEBUG [kallithea.lib.auth_modules] Importing kallithea.lib.auth_modules.auth_ldap
> 2016-09-05 09:11:14.718 DEBUG [kallithea.lib.auth_modules] Loaded auth plugin from kallithea.lib.auth_modules.auth_ldap (module:kallithea.lib.auth_modules.auth_ldap, file:/home/public_html/kallithea/src/kalli
> thea/lib/auth_modules/auth_ldap.pyc)
> 2016-09-05 09:11:14.719 DEBUG [kallithea.lib.auth] Auth User lookup by database user None
> 2016-09-05 09:11:14.720 DEBUG [kallithea.lib.auth] Auth User is now <AuthUser('id:None[None] auth:False')>
> 2016-09-05 09:11:14.720 INFO  [kallithea.lib.base] IP: 192.168.0.2 User: <AuthUser('id:None[None] auth:False')> accessed /_admin/login
> 2016-09-05 09:11:14.721 DEBUG [pylons.controllers.core] Calling '__before__' method with keyword args: **{}
> 2016-09-05 09:11:14.748 DEBUG [pylons.controllers.core] Looking for u'index' method to handle the request
> 2016-09-05 09:11:14.749 DEBUG [pylons.controllers.core] Calling 'index' method with keyword args: **{}
> 2016-09-05 09:11:14.750 DEBUG [kallithea.lib.auth] checking if ip:192.168.0.2 is subnet of set(['0.0.0.0/0', '::/0'])
> 2016-09-05 09:11:14.750 DEBUG [kallithea.lib.auth] IP 192.168.0.2 is network 0.0.0.0/0
> 2016-09-05 09:11:14.751 DEBUG [kallithea.lib.auth] IP:192.168.0.2 is in range of set(['0.0.0.0/0', '::/0'])
> 2016-09-05 09:11:14.754 DEBUG [kallithea.lib.auth_modules] Authentication against [u'kallithea.lib.auth_modules.auth_internal', u'kallithea.lib.auth_modules.auth_ldap'] plugins
> 2016-09-05 09:11:14.754 DEBUG [kallithea.lib.auth_modules] Importing kallithea.lib.auth_modules.auth_internal
> 2016-09-05 09:11:14.755 DEBUG [kallithea.lib.auth_modules] Loaded auth plugin from kallithea.lib.auth_modules.auth_internal (module:kallithea.lib.auth_modules.auth_internal, file:/home/public_html/kallithea/s
> rc/kallithea/lib/auth_modules/auth_internal.pyc)
> 2016-09-05 09:11:14.755 DEBUG [kallithea.lib.auth_modules] Trying authentication using ** kallithea.lib.auth_modules.auth_internal **
> 2016-09-05 09:11:14.758 DEBUG [kallithea.lib.auth_modules] Plugin settings
> {
>     "enabled": true
> }
> 2016-09-05 09:11:14.758 DEBUG [kallithea.lib.auth_modules] Trying to fetch user `username` from Kallithea database
> 2016-09-05 09:11:14.762 DEBUG [kallithea.lib.auth_modules] Plugin kallithea.lib.auth_modules.auth_internal extracted user is `<User('id:5:username')>`
> 2016-09-05 09:11:14.763 DEBUG [kallithea.lib.auth_modules] User <User('id:5:username')> should authenticate using ldap this is internal, skipping
> 2016-09-05 09:11:14.764 DEBUG [kallithea.lib.auth_modules] Plugin kallithea.lib.auth_modules.auth_internal does not accept user `<User('id:5:username')>` for authentication
> 2016-09-05 09:11:14.764 DEBUG [kallithea.lib.auth_modules] Importing kallithea.lib.auth_modules.auth_ldap
> 2016-09-05 09:11:14.765 DEBUG [kallithea.lib.auth_modules] Loaded auth plugin from kallithea.lib.auth_modules.auth_ldap (module:kallithea.lib.auth_modules.auth_ldap, file:/home/public_html/kallithea/src/kallithea/lib/auth_modules/auth_ldap.pyc)
> 2016-09-05 09:11:14.765 DEBUG [kallithea.lib.auth_modules] Trying authentication using ** kallithea.lib.auth_modules.auth_ldap **
> 2016-09-05 09:11:14.800 DEBUG [kallithea.lib.auth_modules] Plugin settings
> {
>     "attr_email": "mail",
>     "attr_firstname": "givenName",
>     "attr_lastname": "sn",
>     "attr_login": "sAMAccountName",
>     "base_dn": "",
>     "dn_pass": "***",
>     "dn_user": "kallithea",
>     "enabled": "True",
>     "filter": "",
>     "host": "192.168.0.1",
>     "port": "389",
>     "search_scope": "BASE",
>     "tls_kind": "PLAIN",
>     "tls_reqcert": "NEVER"
> }
> 2016-09-05 09:11:14.800 DEBUG [kallithea.lib.auth_modules] Trying to fetch user `username` from Kallithea database
> 2016-09-05 09:11:14.806 DEBUG [kallithea.lib.auth_modules] Plugin kallithea.lib.auth_modules.auth_ldap extracted user is `<User('id:5:username')>`
> 2016-09-05 09:11:14.807 DEBUG [kallithea.lib.auth_modules] Plugin kallithea.lib.auth_modules.auth_ldap accepted user `<User('id:5:username')>` for authentication
> 2016-09-05 09:11:14.807 INFO  [kallithea.lib.auth_modules] Authenticating user using kallithea.lib.auth_modules.auth_ldap plugin
> 2016-09-05 09:11:14.808 DEBUG [kallithea.lib.auth_modules.auth_ldap] Checking for ldap authentication
> 2016-09-05 09:11:14.809 DEBUG [kallithea.lib.auth_modules.auth_ldap] Trying simple_bind with password and given DN: kallithea
> 2016-09-05 09:11:14.819 DEBUG [kallithea.lib.auth_modules.auth_ldap] Authenticating '' filter (&(sAMAccountName=username)) at ldap://192.168.0.1:389
> 2016-09-05 09:11:14.820 DEBUG [kallithea.lib.auth_modules.auth_ldap] Trying simple bind with
> 2016-09-05 09:11:14.822 DEBUG [kallithea.lib.auth_modules.auth_ldap] Got ldap DN response
> 2016-09-05 09:11:14.827 DEBUG [kallithea.lib.auth] Auth User lookup by database user <User('id:1:default')>
> 2016-09-05 09:11:14.828 DEBUG [kallithea.lib.auth] Auth User is now <AuthUser('id:None[None] auth:False')>
> 2016-09-05 09:11:14.828 DEBUG [kallithea.lib.auth] Getting PERMISSION tree
> 2016-09-05 09:11:14.903 INFO  [kallithea.lib.auth_modules.auth_ldap] user username authenticated correctly
> 2016-09-05 09:11:14.904 DEBUG [kallithea.lib.auth_modules] Updating or creating user info from ldap plugin
> 2016-09-05 09:11:14.905 DEBUG [kallithea.model.user] Checking for username account in Kallithea database
> 2016-09-05 09:11:14.911 DEBUG [kallithea.model.user] updating user username
> 2016-09-05 09:11:15.089 DEBUG [kallithea.model.user] Updating password reason=>new password
> 2016-09-05 09:11:15.240 DEBUG [kallithea.model.user_group] Enforcing groups <User('id:5:username')> on user []
> 2016-09-05 09:11:15.247 DEBUG [kallithea.lib.auth_modules] PLUGIN USER DATA: {'username': u'username', 'active': True, 'groups': [], 'firstname': u'', 'admin': False, 'lastname': u'', 'email': None, 'active_from_extern': None, 'extern_name': ''}
> 2016-09-05 09:11:15.247 DEBUG [kallithea.lib.auth_modules] Plugin returned proper authentication data
> 2016-09-05 09:11:15.251 DEBUG [kallithea.model.db] updated user username lastlogin
> 2016-09-05 09:11:15.257 DEBUG [kallithea.lib.auth] Auth User lookup by database user <User('id:5:username')>
> 2016-09-05 09:11:15.260 DEBUG [kallithea.lib.auth] filling <User('id:5:username')> data
> 2016-09-05 09:11:15.264 DEBUG [kallithea.lib.auth] Auth User is now <AuthUser('id:5[username] auth:False')>
> 2016-09-05 09:11:15.265 DEBUG [beaker.container] data file /home/public_html/kallithea/src/data/sessions/container_file/f/f5/f514f09fc1c14a658280250726c767e7.cache
> 2016-09-05 09:11:15.266 INFO  [kallithea.lib.base] user username is now authenticated and stored in session, session attrs {'is_authenticated': True, 'is_external_auth': False, 'user_id': 5}