Issue joining Univention domain server based on domain name?

[patrickgf]

Having an issue getting FreeNAS joined to a domain.
The Domain Control is a Univention Corporate Server (UCS) and uses SAMBA4 to act as a Active Directory server.

I originally tested joining/binding FreeNAS successfully to a test domain (digicut.intranet).
Now I have setup and configured the domain I planned to use (ad.digicut.com) but can not get FreeNAS to bind.
I get no errors in the GUI but do see errors in the logs.

I am wondering if there is an issue with the domain I have chosen being a sub sub domain
but then seems to be the recommended process for new AD domains.
(http://serverfault.com/questions/76715/windows-active-directory-naming-best-practices)

I have tried a fresh install (and a different version) of FreeNAS and get the same results,
It will join the testing domain (digicut.intranet) and will not join the desired domain (ad.digicut.com).
The Master Domain Controller is dc1.ad.digicut.com and seems to resolve correctly both ways.
And I also see a DNS entry for the FreeNAS system added in the Domain Controller,
and the FreeNAS logs show the user and group names so they are seeing each other. (but with errors like below)
Dec 29 14:08:23 brainiac cachetool.py: [common.freenasldap:2574] Error on getpwnam: 'getpwnam(): name not found: AD\\Administrator'

FreeNAS Version: FreeNAS-9.10.1-U2 (f045a8b)
(and also tried on FreeNAS-9.3-STABLE-201509022158 )

Below are the logs I know to check. Let me know if there are others that would be helpful.


Some Troubleshooting commands and results:

# host dc1.ad.digicut.com
dc1.ad.digicut.com has address 10.77.10.9
dc1.ad.digicut.com has IPv6 address 2607:f568:1002:7700:250:56ff:fe34:5a10

# host 10.77.10.9
9.10.77.10.in-addr.arpa domain name pointer dc1.ad.digicut.com.

# wbinfo -u
Error looking up domain users

# wbinfo -g
# (No result returned from command)

# wbinfo -t
checking the trust secret for domain AD via RPC calls failed
failed to call wbcCheckTrustCredentials: WBC_ERR_WINBIND_NOT_AVAILABLE
Could not check secret


Result of script found here for testing: https://forums.freenas.org/index.php?threads/activedirectory-did-not-bind-to-the-domain.45066/
————————————————— Script ——————————————

Code:

#!/bin/csh
echo "Setting AD to enabled in the FreeNAS Database..."
sqlite3 /data/freenas-v1.db "update directoryservice_activedirectory set ad_enable=1;"
echo "The AD enable returned code: $?"
echo "Restarting kerberos..."
service ix-kerberos restart
echo "Restarting NSS..."
service ix-nsswitch restart
echo "Restarting kerberos init..."
service ix-kinit restart
echo "Status from the kerberos init restart..."
service ix-kinit status
echo "The status command returned code: $?"
echo "Kerberos found the following security principals:"
klist
echo "Restarting the CIFS process..."
python /usr/local/www/freenasUI/middleware/notifier.py restart cifs
echo "The CIFS restart returned code:  $?"
echo "Restarting the Active Directory service..."
service ix-activedirectory restart
echo "Active Directory Service returned code: $?"
echo "The status of the Active Directory service"
service ix-activedirectory status
echo "Active Directory Server returned code: $?"
echo "The Active Directory SRV record Summary"
host -t srv _ldap._tcp.ad.digicut.com
echo "The Active Directory user listing:"
wbinfo -u
echo "The Active Directory group listing:"
wbinfo -g
echo "Finished"

—————————————— Results ——————————————

Code:

Setting AD to enabled in the FreeNAS Database...
The AD enable returned code: 0
Restarting kerberos...
Restarting NSS...
Restarting kerberos init...
Status from the kerberos init restart...
The status command returned code: 0
Kerberos found the following security principals:
Credentials cache: FILE:/tmp/krb5cc_0
		Principal: pfincannon@AD.DIGICUT.COM

  Issued		   Expires		  Principal
Dec 29 14:21:53  Dec 30 00:21:53  krbtgt/AD.DIGICUT.COM@AD.DIGICUT.COM
Restarting the CIFS process...
True
The CIFS restart returned code:  0
Restarting the Active Directory service...
Using short domain name -- AD
Joined 'BRAINIAC' to dns domain 'ad.digicut.com'
DNS Update for brainiac.ad.digicut.com failed: ERROR_DNS_GSS_ERROR
DNS update failed: NT_STATUS_UNSUCCESSFUL
Active Directory Service returned code: 0
The status of the Active Directory service
Active Directory Server returned code: 0
The Active Directory SRV record Summary
_ldap._tcp.ad.digicut.com has SRV record 0 100 389 dc1.ad.digicut.com.
The Active Directory user listing:
The Active Directory group listing:
Finished

 

[patrickgf]

/var/log/messages
Dec 29 14:05:33 brainiac manage.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:05:42 brainiac manage.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:05:43 brainiac ActiveDirectory: /usr/local/bin/python /usr/local/www/freenasUI/middleware/notifier.py stop cifs
Dec 29 14:05:45 brainiac notifier: Stopping winbindd.
Dec 29 14:06:05 brainiac winbindd[6501]: [2016/12/29 14:06:05.650906, 0] ../source3/winbindd/winbindd.c:234(winbindd_sig_term_handler)
Dec 29 14:06:05 brainiac winbindd[6501]: Got sig[15] terminate (is_parent=1)
Dec 29 14:06:05 brainiac winbindd[8251]: STATUS=daemon 'winbindd' finished starting up and ready to serve connectionsGot sig[15] terminate (is_parent=0)
Dec 29 14:06:05 brainiac winbindd[8252]: STATUS=daemon 'winbindd' finished starting up and ready to serve connectionsGot sig[15] terminate (is_parent=0)
Dec 29 14:06:05 brainiac notifier: Waiting for PIDS: 6501.
Dec 29 14:06:05 brainiac notifier: Stopping smbd.
Dec 29 14:06:05 brainiac notifier: Waiting for PIDS: 6495.
Dec 29 14:06:05 brainiac notifier: Stopping nmbd.
Dec 29 14:06:05 brainiac nmbd[6491]: STATUS=daemon 'nmbd' finished starting up and ready to serve connectionsGot SIGTERM: going down...
Dec 29 14:06:05 brainiac notifier: Waiting for PIDS: 6491.
Dec 29 14:06:05 brainiac ActiveDirectory: /usr/sbin/service ix-kerberos quietstop
Dec 29 14:06:05 brainiac ActiveDirectory: /usr/sbin/service ix-nsswitch quietstop
Dec 29 14:06:07 brainiac ActiveDirectory: /usr/sbin/service ix-pam quietstop
Dec 29 14:06:07 brainiac ActiveDirectory: /usr/sbin/service ix-activedirectory forcestop
Dec 29 14:06:11 brainiac adtool: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:06:12 brainiac ActiveDirectory: /usr/sbin/service ix-cache quietstop &
Dec 29 14:06:13 brainiac ActiveDirectory: /usr/sbin/service samba_server forcestop
Dec 29 14:06:13 brainiac ActiveDirectory: /usr/sbin/service ix-pre-samba start
Dec 29 14:06:15 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/net getlocalsid
Dec 29 14:06:15 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Dec 29 14:06:15 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: zfs list -H -o mountpoint
Dec 29 14:06:15 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/net getlocalsid
Dec 29 14:06:15 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/pdbedit -d 0 -i smbpasswd:/tmp/tmpi02pVn -s /usr/local/etc/smb4.conf -e tdbsam:/var/etc/private/passdb.tdb
Dec 29 14:06:15 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/pdbedit -L
Dec 29 14:06:15 brainiac ActiveDirectory: /usr/sbin/service ix-kinit forcestop
Dec 29 14:06:15 brainiac ActiveDirectory: /usr/sbin/service ix-hostname quietstart
Dec 29 14:06:17 brainiac adtool: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:06:17 brainiac adtool: [common.pipesubr:71] Popen()ing: /usr/bin/kinit --renewable --password-file=/tmp/tmpTOyIvx pfincannon@AD.DIGICUT.COM
Dec 29 14:06:19 brainiac ActiveDirectory: /usr/sbin/service ix-hostname quietstart
Dec 29 14:06:20 brainiac ActiveDirectory: /usr/sbin/service ix-kerberos quietstart
Dec 29 14:06:21 brainiac generate_krb5_conf.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:06:22 brainiac ActiveDirectory: /usr/sbin/service ix-nsswitch quietstart
Dec 29 14:06:23 brainiac ActiveDirectory: /usr/sbin/service ix-ldap quietstart
Dec 29 14:06:23 brainiac ActiveDirectory: /usr/sbin/service ix-kinit quietstart
Dec 29 14:06:25 brainiac ActiveDirectory: /usr/sbin/service ix-kinit status
Dec 29 14:06:26 brainiac ActiveDirectory: /usr/local/bin/python /usr/local/www/freenasUI/middleware/notifier.py start cifs
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/net getlocalsid
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: zfs list -H -o mountpoint
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/net getlocalsid
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/pdbedit -d 0 -i smbpasswd:/tmp/tmpVRF7Jc -s /usr/local/etc/smb4.conf -e tdbsam:/var/etc/private/passdb.tdb
Dec 29 14:06:29 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/pdbedit -L
Dec 29 14:06:30 brainiac notifier: Performing sanity check on Samba configuration: OK
Dec 29 14:06:30 brainiac notifier: Starting nmbd.
Dec 29 14:06:30 brainiac notifier: Starting smbd.
Dec 29 14:06:30 brainiac nmbd[14977]: [2016/12/29 14:06:30.214541, 0] ../lib/util/become_daemon.c:136(daemon_ready)
Dec 29 14:06:30 brainiac notifier: Starting winbindd.
Dec 29 14:06:30 brainiac smbd[14981]: [2016/12/29 14:06:30.259966, 0] ../lib/util/become_daemon.c:136(daemon_ready)
Dec 29 14:06:30 brainiac winbindd[14985]: [2016/12/29 14:06:30.304969, 0] ../lib/util/become_daemon.c:136(daemon_ready)
Dec 29 14:06:30 brainiac ActiveDirectory: /usr/sbin/service ix-activedirectory quietstart
Dec 29 14:06:33 brainiac generate_ldap_conf.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:06:37 brainiac ActiveDirectory: /usr/sbin/service ix-activedirectory status
Dec 29 14:06:44 brainiac ActiveDirectory: /usr/local/bin/python /usr/local/www/freenasUI/middleware/notifier.py stop cifs
Dec 29 14:06:45 brainiac notifier: Stopping winbindd.
Dec 29 14:07:07 brainiac winbindd[14985]: STATUS=daemon 'winbindd' finished starting up and ready to serve connectionsGot sig[15] terminate (is_parent=1)
Dec 29 14:07:07 brainiac notifier: Waiting for PIDS: 14985.
Dec 29 14:07:07 brainiac notifier: Stopping smbd.
Dec 29 14:07:08 brainiac notifier: Waiting for PIDS: 14981, 14981.
Dec 29 14:07:08 brainiac notifier: Stopping nmbd.
Dec 29 14:07:08 brainiac nmbd[14977]: STATUS=daemon 'nmbd' finished starting up and ready to serve connectionsGot SIGTERM: going down...
Dec 29 14:07:08 brainiac notifier: Waiting for PIDS: 14977.
Dec 29 14:07:08 brainiac ActiveDirectory: /usr/local/bin/python /usr/local/www/freenasUI/middleware/notifier.py start cifs
Dec 29 14:07:12 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/net getlocalsid
Dec 29 14:07:12 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Dec 29 14:07:12 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:07:13 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: zfs list -H -o mountpoint
Dec 29 14:07:13 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/net getlocalsid
Dec 29 14:07:13 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/pdbedit -d 0 -i smbpasswd:/tmp/tmpt6YTvx -s /usr/local/etc/smb4.conf -e tdbsam:/var/etc/private/passdb.tdb
Dec 29 14:07:13 brainiac generate_smb4_conf.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/pdbedit -L
Dec 29 14:07:13 brainiac notifier: Performing sanity check on Samba configuration: OK
Dec 29 14:07:13 brainiac notifier: Starting nmbd.
Dec 29 14:07:13 brainiac notifier: Starting smbd.
Dec 29 14:07:13 brainiac nmbd[16092]: [2016/12/29 14:07:13.819608, 0] ../lib/util/become_daemon.c:136(daemon_ready)
Dec 29 14:07:13 brainiac notifier: Starting winbindd.
Dec 29 14:07:13 brainiac smbd[16096]: [2016/12/29 14:07:13.882259, 0] ../lib/util/become_daemon.c:136(daemon_ready)
Dec 29 14:07:13 brainiac winbindd[16100]: [2016/12/29 14:07:13.933156, 0] ../lib/util/become_daemon.c:136(daemon_ready)
Dec 29 14:07:14 brainiac ActiveDirectory: /usr/sbin/service ix-pam quietstart
Dec 29 14:07:16 brainiac ActiveDirectory: /usr/sbin/service ix-cache quietstart &
Dec 29 14:07:18 brainiac cachetool.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:08:23 brainiac cachetool.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:08:34 brainiac manage.py: [common.pipesubr:71] Popen()ing: klist
Dec 29 14:10:45 brainiac kernel: sonewconn: pcb 0xfffff8001c2504b0: Listen queue overflow: 8 already in queue awaiting acceptance (1 occurrences)

 

[patrickgf]

/var/log/debug.log (first few and last lines)
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:1086] FreeNAS_ActiveDirectory_Base.get_SRV_records: looking up SRV records for _ldap._tcp.dc._msdcs.ad.digicut.com
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:957] FreeNAS_LDAP.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:538] FreeNAS_LDAP_Base.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:513] FreeNAS_LDAP_Base.__set_defaults: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:525] FreeNAS_LDAP_Base.__set_defaults: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:126] FreeNAS_LDAP_Directory.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:305] FreeNAS_LDAP_QueryCache.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:97] FreeNAS_BaseCache._init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:112] FreeNAS_BaseCache._init__: cachedir = /var/tmp/.cache/.query
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:114] FreeNAS_BaseCache._init__: cachefile = /var/tmp/.cache/.query/.cache.db
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:115] FreeNAS_BaseCache._init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:171] FreeNAS_LDAP_Directory.__init__: host = dc1.ad.digicut.com, port = 389, binddn = pfincannon@ad.digicut.com, basedn = None, ssl = start_tls
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:172] FreeNAS_LDAP_Directory.__init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:618] FreeNAS_LDAP_Base.__init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:961] FreeNAS_LDAP.__init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:252] FreeNAS_LDAP_Directory.open: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:259] FreeNAS_LDAP_Directory.open: uri = ldap://dc1.ad.digicut.com:389
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:262] FreeNAS_LDAP_Directory.open: initialized
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:284] FreeNAS_LDAP_Directory.open: started TLS
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:301] FreeNAS_LDAP_Directory.open: trying to bind
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:217] FreeNAS_LDAP_Directory.open: (authenticated bind) trying to bind to dc1.ad.digicut.com:389
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:303] FreeNAS_LDAP_Directory.open: binded
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:315] FreeNAS_LDAP_Directory.open: connection open
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:317] FreeNAS_LDAP_Directory.open: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:2306] FreeNAS_ActiveDirectory.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:1451] FreeNAS_ActiveDirectory_Base.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:1310] FreeNAS_ActiveDirectory_Base.__set_defaults: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:1341] FreeNAS_ActiveDirectory_Base.__set_defaults: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:126] FreeNAS_LDAP_Directory.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:305] FreeNAS_LDAP_QueryCache.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:97] FreeNAS_BaseCache._init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:112] FreeNAS_BaseCache._init__: cachedir = /var/tmp/.cache/.query
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:114] FreeNAS_BaseCache._init__: cachefile = /var/tmp/.cache/.query/.cache.db
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:115] FreeNAS_BaseCache._init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:171] FreeNAS_LDAP_Directory.__init__: host = dc1.ad.digicut.com, port = 389, binddn = pfincannon@AD.DIGICUT.COM, basedn = None, ssl = start_tls
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:172] FreeNAS_LDAP_Directory.__init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:252] FreeNAS_LDAP_Directory.open: enter
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:259] FreeNAS_LDAP_Directory.open: uri = ldap://dc1.ad.digicut.com:389
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:262] FreeNAS_LDAP_Directory.open: initialized
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:284] FreeNAS_LDAP_Directory.open: started TLS
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:301] FreeNAS_LDAP_Directory.open: trying to bind
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:217] FreeNAS_LDAP_Directory.open: (authenticated bind) trying to bind to dc1.ad.digicut.com:389
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:303] FreeNAS_LDAP_Directory.open: binded
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:315] FreeNAS_LDAP_Directory.open: connection open
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:317] FreeNAS_LDAP_Directory.open: leave
Dec 29 14:05:33 brainiac manage.py: [common.freenasldap:126] FreeNAS_LDAP_Directory.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:305] FreeNAS_LDAP_QueryCache.__init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:97] FreeNAS_BaseCache._init__: enter
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:112] FreeNAS_BaseCache._init__: cachedir = /var/tmp/.cache/.query
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:114] FreeNAS_BaseCache._init__: cachefile = /var/tmp/.cache/.query/.cache.db
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:115] FreeNAS_BaseCache._init__: leave
Dec 29 14:05:33 brainiac manage.py: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
---- ----- ----- Snip
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2802] FreeNAS_ActiveDirectory_Groups.__get_groups: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:1086] FreeNAS_ActiveDirectory_Base.get_SRV_records: looking up SRV records for _ldap._tcp.dc._msdcs.ad.digicut.com
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2845] FreeNAS_ActiveDirectory_Groups.__get_groups: AD [AD] groups not in cache
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2130] FreeNAS_ActiveDirectory_Base.get_groups: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:335] FreeNAS_LDAP_Directory._search: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:337] FreeNAS_LDAP_Directory._search: basedn = 'DC=ad,DC=digicut,DC=com', filter = '(&(objectclass=group)(sAMAccountName=*))'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:367] FreeNAS_LDAP_Directory._search: pagesize = 1024
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:372] FreeNAS_LDAP_Directory._search: getting page 0
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:439] FreeNAS_LDAP_Directory._search: 71 results
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:440] FreeNAS_LDAP_Directory._search: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2148] FreeNAS_ActiveDirectory_Base.get_groups: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Allowed RODC Password Replication Group'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Enterprise Read-Only Domain Controllers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Denied RODC Password Replication Group'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Read-Only Domain Controllers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group Policy Creator Owners'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_fm_vacationtracker'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\RAS and IAS Servers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Domain Controllers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Enterprise Admins'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_Development'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Domain Computers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_Accounting'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Cert Publishers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\DC Backup Hosts'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_templates'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_executive'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_marketing'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\DC Slave Hosts'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\DnsUpdateProxy'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_Wireless'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_training'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_punchmgr'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_shipping'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Domain Admins'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Domain Guests'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_Digicut'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Schema Admins'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Domain Users'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\ard_interact'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_fs_rth'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Backup Join'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_Tulsa'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\ESX Admins'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Slave Join'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\ard_manage'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Computers'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\DnsAdmins'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_AMC'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_VPN'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\Group_all'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\ard_admin'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_fsa'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_rth'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_am'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_hr'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_it'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2869] Error on getgrnam: 'getgrnam(): name not found: AD\\group_qa'
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2882] FreeNAS_ActiveDirectory_Groups.__get_groups: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasldap:2753] FreeNAS_ActiveDirectory_Groups.__init__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:183] FreeNAS_Group.__new__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:184] FreeNAS_Group.__new__: group = bin
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:135] FreeNAS_Local_Group.__new__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:136] FreeNAS_Local_Group.__new__: group = bin
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:142] FreeNAS_Local_Group.__new__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:146] FreeNAS_Local_Group.__init__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:147] FreeNAS_Local_Group.__init__: group = bin
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:160] FreeNAS_local_Group.__get_group: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:161] FreeNAS_local_Group.__get_group: group = bin
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:178] FreeNAS_local_Group.__get_group: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:157] FreeNAS_Local_Group.__init__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:212] FreeNAS_Group.__new__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:183] FreeNAS_Group.__new__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:184] FreeNAS_Group.__new__: group = tty
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:135] FreeNAS_Local_Group.__new__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:136] FreeNAS_Local_Group.__new__: group = tty
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:142] FreeNAS_Local_Group.__new__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:146] FreeNAS_Local_Group.__init__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:147] FreeNAS_Local_Group.__init__: group = tty
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:160] FreeNAS_local_Group.__get_group: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:161] FreeNAS_local_Group.__get_group: group = tty
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:178] FreeNAS_local_Group.__get_group: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:157] FreeNAS_Local_Group.__init__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:212] FreeNAS_Group.__new__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:183] FreeNAS_Group.__new__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:184] FreeNAS_Group.__new__: group = webdav
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:135] FreeNAS_Local_Group.__new__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:136] FreeNAS_Local_Group.__new__: group = webdav
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:142] FreeNAS_Local_Group.__new__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:146] FreeNAS_Local_Group.__init__: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:147] FreeNAS_Local_Group.__init__: group = webdav
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:160] FreeNAS_local_Group.__get_group: enter
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:161] FreeNAS_local_Group.__get_group: group = webdav
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:178] FreeNAS_local_Group.__get_group: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:157] FreeNAS_Local_Group.__init__: leave
Dec 29 14:08:24 brainiac cachetool.py: [common.freenasusers:212] FreeNAS_Group.__new__: leave
----- ----- ----- Snip
Dec 29 14:08:34 brainiac manage.py: [common.frenascache:313] FreeNAS_LDAP_QueryCache.__init__: leave
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:171] FreeNAS_LDAP_Directory.__init__: host = dc1.ad.digicut.com, port = 389, binddn = pfincannon@AD.DIGICUT.COM, basedn = None, ssl = start_tls
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:172] FreeNAS_LDAP_Directory.__init__: leave
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:618] FreeNAS_LDAP_Base.__init__: leave
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:961] FreeNAS_LDAP.__init__: leave
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:252] FreeNAS_LDAP_Directory.open: enter
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:259] FreeNAS_LDAP_Directory.open: uri = ldap://dc1.ad.digicut.com:389
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:262] FreeNAS_LDAP_Directory.open: initialized
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:284] FreeNAS_LDAP_Directory.open: started TLS
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:301] FreeNAS_LDAP_Directory.open: trying to bind
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:217] FreeNAS_LDAP_Directory.open: (authenticated bind) trying to bind to dc1.ad.digicut.com:389
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:303] FreeNAS_LDAP_Directory.open: binded
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:315] FreeNAS_LDAP_Directory.open: connection open
Dec 29 14:08:34 brainiac manage.py: [common.freenasldap:317] FreeNAS_LDAP_Directory.open: leave

 

[dlavigne]

It will join the testing domain (digicut.intranet) and will not join the desired domain (ad.digicut.com).

That's interesting. Assuming that an update to 9.10.2 does not fix it, please create a bug report at bugs.freenas.org and post the issue number here.

 

[patrickgf]

Okay updated to FreeNAS-9.10.2 (a476f16).
It does not appear to have changed the results.

Attached are the logs when I try to access a datasets permissions after "successfully" binding.

 

[dlavigne]

In that case, please create the bug report and post the issue number here.

 

[patrickgf]

Bug 19977 created. Thanks for your assistance.

https://bugs.freenas.org/issues/19977

 

[BeeFGee]

I also had some issues with joining my Univention AD after the upgrade to 9.10. Check out here how I solved my problems: https://forums.freenas.org/index.php?threads/ad-auth-fails-after-upgrade.42836/

 

[patrickgf]

I also had some issues with joining my Univention AD after the upgrade to 9.10. Check out here how I solved my problems: https://forums.freenas.org/index.php?threads/ad-auth-fails-after-upgrade.42836/

Thanks for your helpful post. I found it a few weeks back and helped with my initial testing.
As far as I can tell this current issue is separate.

I have changed my planned forest domain name to NOT be a sub-domain and am moving forward with testing.
For anyone following along, I had to downgrade back to version FreeNAS-9.10.1-U2 (f045a8b) so I could add a new CAs for the "new" Univention Server.
Per bug reported here: https://bugs.freenas.org/issues/19855
Switched to a secondary TLD we owned EXAMPLE.info