Unable to enable LDAP Authentication on 9.3

[Mindwarper]

The system is running FreeNAS-9.3-STABLE-201504100216. Fresh install, nothing fancy. I've configured the hostname and domain. I enter the applicable data into the GUI for the LDAP configuration, and attempt to save. The GUI pops up with a 'The service failed to restart'. I'm sure I'm missing something simple...

I don't see anything that is a specific error during the event, the /var/log/debug.log output during that timeframe:

Code:

Apr 13 13:48:42 freenas manage.py: [middleware.notifier:224] Calling: start(ldap)
Apr 13 13:48:42 freenas manage.py: [middleware.notifier:190] Executing: /etc/directoryservice/LDAP/ctl start
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:938] FreeNAS_LDAP.__init__: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:512] FreeNAS_LDAP_Base.__init__: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:487] FreeNAS_LDAP_Base.__set_defaults: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:499] FreeNAS_LDAP_Base.__set_defaults: leave
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:125] FreeNAS_LDAP_Directory.__init__: enter
Apr 13 13:48:44 freenas ldaptool: [common.frenascache:305] FreeNAS_LDAP_QueryCache.__init__: enter
Apr 13 13:48:44 freenas ldaptool: [common.frenascache:97] FreeNAS_BaseCache._init__: enter
Apr 13 13:48:44 freenas ldaptool: [common.frenascache:112] FreeNAS_BaseCache._init__: cachedir = /var/tmp/.cache/.query
Apr 13 13:48:44 freenas ldaptool: [common.frenascache:114] FreeNAS_BaseCache._init__: cachefile = /var/tmp/.cache/.query/.cache.db
Apr 13 13:48:44 freenas ldaptool: [common.frenascache:115] FreeNAS_BaseCache._init__: leave
Apr 13 13:48:44 freenas ldaptool: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:169] FreeNAS_LDAP_Directory.__init__: host = dc04.olympus.mysite.com, port = 389, binddn = cn=_ldap,OU=Service Accounts,OU=Users,OU=IT,DC=olympus,DC=mysite,DC=com, basedn = dc=olympus,dc=mysite,dc=com, ssl = off
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:170] FreeNAS_LDAP_Directory.__init__: leave
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:250] FreeNAS_LDAP_Directory.open: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:257] FreeNAS_LDAP_Directory.open: uri = ldap://dc04.olympus.mysite.com:389
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:260] FreeNAS_LDAP_Directory.open: initialized
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:297] FreeNAS_LDAP_Directory.open: trying to bind
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:215] FreeNAS_LDAP_Directory.open: (authenticated bind) trying to bind to dc04.olympus.mysite.com:389
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:299] FreeNAS_LDAP_Directory.open: binded
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:311] FreeNAS_LDAP_Directory.open: connection open
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:313] FreeNAS_LDAP_Directory.open: leave
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:696] FreeNAS_LDAP_Base.get_user_by_DN: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:697] FreeNAS_LDAP_Base.get_user_by_DN: DN = cn=_ldap,OU=Service Accounts,OU=Users,OU=IT,DC=olympus,DC=mysite,DC=com
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:250] FreeNAS_LDAP_Directory.open: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:331] FreeNAS_LDAP_Directory._search: enter
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:333] FreeNAS_LDAP_Directory._search: basedn = 'cn=_ldap,OU=Service Accounts,OU=Users,OU=IT,DC=olympus,DC=mysite,DC=com', filter = '(objectclass=*)'
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:406] FreeNAS_LDAP_Directory._search: pagesize = 0
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:435] FreeNAS_LDAP_Directory._search: 1 results
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:436] FreeNAS_LDAP_Directory._search: leave
Apr 13 13:48:44 freenas ldaptool: [common.freenasldap:725] FreeNAS_LDAP_Base.get_user_by_DN: leave
Apr 13 13:48:44 freenas manage.py: [middleware.notifier:204] Executed: /etc/directoryservice/LDAP/ctl start; returned 1
Apr 13 13:48:44 freenas manage.py: [middleware.notifier:190] Executing: /usr/sbin/service ix-ldap status
Apr 13 13:48:46 freenas manage.py: [middleware.notifier:204] Executed: /usr/sbin/service ix-ldap status; returned 1

Thanks in advance!

-MW

 

[dlavigne]

I think you are hitting this (from the UPGRADING file):

3. Authenticating via LDAP now requires that the connection to the LDAP server be SSL/TLS. This prevents account passwords from being sent in clear-text but may be an unexpected change in behavior for users upgrading from older releases of FreeNAS.

Does importing the cert for the LDAP server using System -> Certificates, then selecting that cert in the Certificates drop-down menu in the Advanced Mode of Directory -> LDAP fix it?

 

[Mindwarper]

Good catch, I did test that a bit ago, but I had forgotten about it. It appears to have the same issue. Debug output:

Code:

Apr 13 15:47:19 freenas3 manage.py: [middleware.notifier:190] Executing: /usr/sbin/service ix-ldap status
Apr 13 15:47:21 freenas3 manage.py: [middleware.notifier:204] Executed: /usr/sbin/service ix-ldap status; returned 1
Apr 13 15:47:21 freenas3 manage.py: [middleware.notifier:224] Calling: start(ldap)
Apr 13 15:47:21 freenas3 manage.py: [middleware.notifier:190] Executing: /etc/directoryservice/LDAP/ctl start
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:938] FreeNAS_LDAP.__init__: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:512] FreeNAS_LDAP_Base.__init__: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:487] FreeNAS_LDAP_Base.__set_defaults: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:499] FreeNAS_LDAP_Base.__set_defaults: leave
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:125] FreeNAS_LDAP_Directory.__init__: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.frenascache:305] FreeNAS_LDAP_QueryCache.__init__: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.frenascache:97] FreeNAS_BaseCache._init__: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.frenascache:112] FreeNAS_BaseCache._init__: cachedir = /var/tmp/.cache/.query
Apr 13 15:47:23 freenas3 ldaptool: [common.frenascache:114] FreeNAS_BaseCache._init__: cachefile = /var/tmp/.cache/.query/.cache.db
Apr 13 15:47:23 freenas3 ldaptool: [common.frenascache:115] FreeNAS_BaseCache._init__: leave
Apr 13 15:47:23 freenas3 ldaptool: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:169] FreeNAS_LDAP_Directory.__init__: host = dc03.olympus.mysite.com, port = 636, binddn = cn=_ldap,OU=Service Accounts,OU=Users,OU=IT,DC=olympus,DC=mysite,DC=com, basedn = dc=olympus,dc=mysite,dc=com, ssl = on
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:170] FreeNAS_LDAP_Directory.__init__: leave
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:593] FreeNAS_LDAP_Base.__init__: leave
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:942] FreeNAS_LDAP.__init__: leave
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:250] FreeNAS_LDAP_Directory.open: enter
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:257] FreeNAS_LDAP_Directory.open: uri = ldaps://dc03.olympus.mysite.com:636
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:260] FreeNAS_LDAP_Directory.open: initialized
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:297] FreeNAS_LDAP_Directory.open: trying to bind
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:215] FreeNAS_LDAP_Directory.open: (authenticated bind) trying to bind to dc03.olympus.mysite.com:636
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:299] FreeNAS_LDAP_Directory.open: binded
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:311] FreeNAS_LDAP_Directory.open: connection open
Apr 13 15:47:23 freenas3 ldaptool: [common.freenasldap:313] FreeNAS_LDAP_Directory.open: leave
Apr 13 15:47:23 freenas3 alert.py: [middleware.notifier:208] Popen()ing: /sbin/zpool status -x freenas-boot
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:938] FreeNAS_LDAP.__init__: enter
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:512] FreeNAS_LDAP_Base.__init__: enter
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:487] FreeNAS_LDAP_Base.__set_defaults: enter
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:499] FreeNAS_LDAP_Base.__set_defaults: leave
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:125] FreeNAS_LDAP_Directory.__init__: enter
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.frenascache:305] FreeNAS_LDAP_QueryCache.__init__: enter
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.frenascache:97] FreeNAS_BaseCache._init__: enter
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.frenascache:112] FreeNAS_BaseCache._init__: cachedir = /var/tmp/.cache/.query
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.frenascache:114] FreeNAS_BaseCache._init__: cachefile = /var/tmp/.cache/.query/.cache.db
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.frenascache:115] FreeNAS_BaseCache._init__: leave
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:169] FreeNAS_LDAP_Directory.__init__: host = dc03.olympus.mysite.com, port = 636, binddn = cn=_ldap,OU=Service Accounts,OU=Users,OU=IT,DC=olympus,DC=mysite,DC=com, basedn = dc=olympus,dc=mysite,dc=com, ssl = on
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:170] FreeNAS_LDAP_Directory.__init__: leave
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:593] FreeNAS_LDAP_Base.__init__: leave
Apr 13 15:47:30 freenas3 generate_sssd_conf.py: [common.freenasldap:942] FreeNAS_LDAP.__init__: leave
Apr 13 15:47:42 freenas3 manage.py: [middleware.notifier:204] Executed: /etc/directoryservice/LDAP/ctl start; returned 1
Apr 13 15:47:42 freenas3 manage.py: [middleware.notifier:190] Executing: /usr/sbin/service ix-ldap status
Apr 13 15:47:45 freenas3 manage.py: [middleware.notifier:204] Executed: /usr/sbin/service ix-ldap status; returned 1

 

[dlavigne]

Just to confirm, the LDAP server is running ldaps on port 636?

 

[Mindwarper]

Yesum. Logs on both sides show the bind success and the lookup of the bind user account (when using a Kerberos realm)

 

[dlavigne]

Please create a bug report at bugs.freenas.org and post the issue number here.

 

[Mindwarper]

Bug #9186