AD authentication issues using Linux

emiguy

Cadet
Joined
Oct 14, 2021
Messages
9
Hi.

I have something very strange going on that I thought was fixed a couple times now, but keeps recurring.

We have our truenas server bound to our AD -- and it works flawlessly on windows. However, something very strange is happening under linux, using the mount command.

For Example:
Code:
mount -t cifs //my-truenas/images /mnt/misc -o username=myuser,domain=mydomain  
Password for myuser@//my-truenas/images:  ***********             
mount error(13): Permission denied
Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) and kernel log messages (dmesg)


Of course, the credentials are 100% correct, and I use them all the time on windows system without error. The entries we have in our fstab to mount these shares fail similarly.

The really odd thing is, that if I use dolphin, and I enter my credentials in the old netbios fasion of DOMAINNAME/USERNAME -- it will likewise fail -- BUT if I enter them as UPN (myname@mydomain.com) it works! Of course, the mount command cannot do the latter, so there is no way to do this in fstab or on the command line.

What is even more strange to me, is if I use wbinfo on the console of Truenas, I can pull my sid just fine, and I can look at all the users. It looks like winbindd is doing its job...

The other weird thing is that IF I reboot the truenas server -- it works! For a little while anyway... I can mount on the command line as I normally would. I can use my fstab entries just fine. It will keep those shares mounted indefinitely. If I come back a few hours later, unmount them and try to remount them, they will fail -- indefinitely (until the truenas server is rebooted again, then I will again have a small window in which they will work). Because our truenas server is heavily utilized, I cannot just reboot it whenever I want. I have to coordinate a schedule to do so... which makes this extra difficult.

I have tried using the "REDBUILD DIRECTORY SERVICE CACHE" button under Directory Services -- but it changes nothing. We restart the winbind daemon, but it does nothing. The only thing that seems to help is to reboot the TrueNas Server. I suspect if I disjoined and rejoind the domain, it would probably work too -- but again, this is a live system, I cannot just do that. Restarting the samba service likewise does not help. It seems nothing short of a reboot will fix it (for a short while anyway).

Again, using windows -- we have absolutely no issues like this. It is just weird, like it loses its connection to the DC or something... but winbind commands still work... or maybe munges the credentials maybe... but why would it work after a reboot?

I'm looking in the event logs on the domain controller, but I'm not seeing anything weird. I look in the logs on the TrueNas server and I don't get a lot, but I do get the following:

Code:
  
  auth_audit.log
  {"timestamp": "2022-03-22T11:50:14.195037-0400", "type": "Authentication", "Authentication": {"version": {"major": 1, "minor": 2}, "eventId": 4625, "logonId": "47062a26f238cd72", "logonType": 3, "status": "NT_STATUS_ACCESS_DENIED", "localAddress": "unix:", "remoteAddress": "unix:", "serviceDescription": "winbind", "authDescription": "NTLM_AUTH, nss_winbind, 77817", "clientDomain": "mydomain.COM", "clientAccount": "myuser", "workstation": "EMI-TRUENAS", "becameAccount": "", "becameDomain": "", "becameSid": null, "mappedAccount": null, "mappedDomain": null, "netlogonComputer": null, "netlogonTrustAccount": null, "netlogonNegotiateFlags": "0x00000000", "netlogonSecureChannelType": 0, "netlogonTrustAccountSid": null, "passwordType": "NTLMv2", "duration": 231529}}
  {"timestamp": "2022-03-22T11:50:14.196100-0400", "type": "Authentication", "Authentication": {"version": {"major": 1, "minor": 2}, "eventId": 4625, "logonId": "0", "logonType": 3, "status": "NT_STATUS_ACCESS_DENIED", "localAddress": "ipv4:192.168.168.47:445", "remoteAddress": "ipv4:192.168.198.111:34512", "serviceDescription": "SMB2", "authDescription": null, "clientDomain": "mydomain.COM", "clientAccount": "myuser", "workstation": "", "becameAccount": null, "becameDomain": null, "becameSid": null, "mappedAccount": "myuser", "mappedDomain": "mydomain.COM", "netlogonComputer": null, "netlogonTrustAccount": null, "netlogonNegotiateFlags": "0x00000000", "netlogonSecureChannelType": 0, "netlogonTrustAccountSid": null, "passwordType": "NTLMv2", "duration": 234808}}

  
  log.smbd
  [2022/03/22 11:51:20.537290,  2] ../../source3/lib/tallocmsg.c:84(register_msg_pool_usage)
  Registered MSG_REQ_POOL_USAGE
[2022/03/22 11:51:21.007308,  2] ../../source3/auth/auth.c:347(auth_check_ntlm_password)
  check_ntlm_password:  Authentication for user [myuser] -> [myuser] FAILED with error NT_STATUS_ACCESS_DENIED, authoritative=1
[2022/03/22 11:51:21.007552,  2] ../../auth/auth_log.c:653(log_authentication_event_human_readable)
  Auth: [SMB2,(null)] user [mydomain.COM]\[myuser] at [Tue, 22 Mar 2022 11:51:21.007508 EDT] with [NTLMv2] status [NT_STATUS_ACCESS_DENIED] workstation [] remote host [ipv4:192.168.198.111:34514] mapped to [mydomain.COM]\[myuser]. local host [ipv4:192.168.168.47:445]


In the Directory Services -> Active Directory section of TN I have:

Enable (requires password or Kerberos Principal) --- Checked
Verblose Logging --- Unchecked (though I did turn it on to capture the above)
User Default Domain --- Unchecked (though I have tried toggling this to no avail)
Allow DNS Updates --- Checked
Disable FreeNas Cache --- Checked (though was also tired unchecking)
Restrict PAM --- Unchecked
Site Name: Default-First-Site-Name
Kerberos Realm: MYDOMAIN.COM
Kerberos Principal: MY-TRUENAS$@MYDOMAIN.COM
Computer Account OU: MY\\ OU
AD Timeout: 60
DNS Timeout: 10
Winbind NSS info: RFC2307
Netbios Name: my-truenas
Netbios Alias: my-truenas




I'm not sure where else to look on this.

Thank you for your assistance.
 

emiguy

Cadet
Joined
Oct 14, 2021
Messages
9
I am thinking this is a bug... but I wanted to make sure there wasn't something silly I missing. Anyone?
 

anodos

Sambassador
iXsystems
Joined
Mar 6, 2014
Messages
9,554
UPN may be using kerberos. In above example you're using NTLMv2 auth. If TrueNAS is for any reason unable to keep reliable time then auth attempts may be unreliable in AD as well.
 

Nick2253

Wizard
Joined
Apr 21, 2014
Messages
1,633
Time is a likely culprit here.

A common mistake I see regularly is that many sys-admins fail to establish a cohesive time structure. By default, domain-joined Windows systems use the domain controllers as authoritative time devices, but Linux does not auto-configure this. You must manually set whichever NTP daemon you are using (e.g. Chrony) to use your local time servers.

For a small network, the easiest thing is to use your PDC as your network's authoritative time server. Only it should reach out and get time from somewhere in the interwebs. All other DCs should use the PDC as their time server, and all other devices should use these DCs. If you have a regulatory requirement that prevents DCs from accessing the Internet, then you can use an edge device, like your Firewall/Router, as your authoritative time server, and then have all DCs use that.

Pro tip: create domain aliases like ntp0, ntp1, etc, so that it's easy to change time devices without having to reconfigure every client. If you have lots of timekeeping devices, then you may want a more complex structure that mirrors the NTP pool, like 0.building1.mydomain.tld.
 

emiguy

Cadet
Joined
Oct 14, 2021
Messages
9
Time is a likely culprit here.

A common mistake I see regularly is that many sys-admins fail to establish a cohesive time structure. By default, domain-joined Windows systems use the domain controllers as authoritative time devices, but Linux does not auto-configure this. You must manually set whichever NTP daemon you are using (e.g. Chrony) to use your local time servers.

For a small network, the easiest thing is to use your PDC as your network's authoritative time server. Only it should reach out and get time from somewhere in the interwebs. All other DCs should use the PDC as their time server, and all other devices should use these DCs. If you have a regulatory requirement that prevents DCs from accessing the Internet, then you can use an edge device, like your Firewall/Router, as your authoritative time server, and then have all DCs use that.

Pro tip: create domain aliases like ntp0, ntp1, etc, so that it's easy to change time devices without having to reconfigure every client. If you have lots of timekeeping devices, then you may want a more complex structure that mirrors the NTP pool, like 0.building1.mydomain.tld.
Hmm... I admit, I'm not doing as you suggested, but the time is kept in sync on the DC and the truenas box accurate to less than 1 second (both sync to same external source).

Shouldn't that be enough?
 

Nick2253

Wizard
Joined
Apr 21, 2014
Messages
1,633
I'm not sure exactly what the time accuracy requirement is, but I'm sure that 1 second is well within that window. However, it's not just the DC and TrueNAS that have to be in sync; the client (Linux machine) must also be in sync as well.

However, given that a restart of the TrueNAS server seems to fix that problem, I'm going to guess that the client time isn't out of whack either. Which means we have some more troubleshooting to do.

First, I'd check that Samba isn't the problem. If you create a new share, and give permission to a test local account, can you access that share? If you give a share permissions to both a local and an AD user, can you access it with either account? That will tell us if the problem is Samba's ability to authenticate, or somewhere in the Samba<-->DC path.

Assuming that works well, then we'll want some other way to test and troubleshoot the AD connection bypassing Samba. I'm not sure of a good way to do that just now; I'll have to do some thinking, since nothing pops into mind for TrueNAS.
 

emiguy

Cadet
Joined
Oct 14, 2021
Messages
9
Yes, you are correct. The linux client is also within 1 second.

I have created a local user to the same share, and I can mount it with the local user with no problems using that local user... its weird...
 

Nick2253

Wizard
Joined
Apr 21, 2014
Messages
1,633
Once you're in a state where AD accounts can't authenticate, if you create a new share with AD permissions, do you still have the same problem on that new share?

Just trying to see if maybe refreshing the Samba config can "reset" our problem.
 

nterupt

Cadet
Joined
Oct 17, 2022
Messages
3
Were you able to get any resolution to this? I am seeing something very similar. I can access a very simple network share from both a Windows and Mac client that are a member of an active directory domain, but trying to connect to the same share with the 'mount' command on Linux results in an error.

log.smbd output after trying to authentication with the following command:
Code:
sudo mount -t cifs //test_nas.test_domain.com/cifs_test_open /home/local_linux_user/cifs_testing/cifs_test_open/ -o credentials=/home/local_linux_user/cifs_testing/.smbcredentials_cifs_test_open2,gid=local_linux_user,uid=local_linux_user,vers=3.11

Code:
[2022/10/17 03:39:51.261164,  3] ../../auth/ntlmssp/ntlmssp_util.c:72(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0xe0080225
[2022/10/17 03:39:51.261780,  3] ../../auth/ntlmssp/ntlmssp_server.c:513(ntlmssp_server_preauth)
  Got user=[test_user] domain=[TEST_DOMAIN] workstation=[] len1=0 len2=192
[2022/10/17 03:39:51.261872,  3] ../../source3/auth/auth.c:202(auth_check_ntlm_password)
  check_ntlm_password:  Checking password for unmapped user [TEST_DOMAIN]\[test_user]@[] with the new password interface
[2022/10/17 03:39:51.261902,  3] ../../source3/auth/auth.c:205(auth_check_ntlm_password)
  check_ntlm_password:  mapped user is: [TEST_DOMAIN]\[test_user]@[]
[2022/10/17 03:39:51.536867,  2] ../../source3/auth/auth.c:348(auth_check_ntlm_password)
  check_ntlm_password:  Authentication for user [test_user] -> [test_user] FAILED with error NT_STATUS_ACCESS_DENIED, authoritative=1
[2022/10/17 03:39:51.536964,  2] ../../auth/auth_log.c:665(log_authentication_event_human_readable)
  Auth: [SMB2,(null)] user [TEST_DOMAIN]\[test_user] at [Mon, 17 Oct 2022 03:39:51.536943 CDT] with [NTLMv2] status [NT_STATUS_ACCESS_DENIED] workstation [] remote host [ipv4:192.168.0.66:51124] mapped to [TEST_DOMAIN]\[test_user]. local host [ipv4:19>[2022/10/17 03:39:51.537180,  3] ../../source3/smbd/smb2_server.c:3955(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_ACCESS_DENIED] || at ../../source3/smbd/smb2_sesssetup.c:147


If I connect to that same share via Windows with the same AD user the logs are as follows (this is a successful connection):
Code:
[2022/10/17 03:51:08.993890,  3] ../../source3/auth/auth_generic.c:172(auth3_generate_session_info_pac)
  Kerberos ticket principal name is [test_user@TEST_DOMAIN.COM]
[2022/10/17 03:51:08.996901,  3] ../../source3/param/loadparm.c:3967(lp_load_ex)
  lp_load_ex: refreshing parameters
[2022/10/17 03:51:08.997140,  3] ../../source3/param/loadparm.c:558(init_globals)
  Initialising global parameters
[2022/10/17 03:51:08.997706,  3] ../../source3/param/loadparm.c:2869(lp_do_section)
  Processing section "[global]"
[2022/10/17 03:51:09.005707,  2] ../../source3/param/loadparm.c:2886(lp_do_section)
  Processing section "[cifs_test_open]"
[2022/10/17 03:51:09.006606,  3] ../../source3/param/loadparm.c:1670(lp_add_ipc)
  adding IPC service
[2022/10/17 03:51:09.006966,  3] ../../source3/smbd/password.c:85(register_homes_share)
  Adding homes service for user 'TEST_DOMAIN\test_user' using home directory: '/home/TEST_DOMAIN/test_user'
[2022/10/17 03:51:09.009083,  3] ../../lib/util/access.c:374(allow_access)
  Allowed connection from 192.168.0.67 (192.168.0.67)
[2022/10/17 03:51:09.009567,  3] ../../source3/smbd/service.c:611(make_connection_snum)
  make_connection_snum: Connect path is '/tmp' for service [IPC$]
[2022/10/17 03:51:09.009718,  3] ../../source3/smbd/vfs.c:115(vfs_init_default)
  Initialising default vfs hooks
[2022/10/17 03:51:09.009810,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2022/10/17 03:51:09.010290,  3] ../../source3/smbd/service.c:865(make_connection_snum)
  192.168.0.67 (ipv4:192.168.0.67:50512) connect to service IPC$ initially as user TEST_DOMAIN\test_user (uid=100001108, gid=100000514) (pid 16103)
[2022/10/17 03:51:09.156788,  1] ../../source3/printing/printer_list.c:255(printer_list_get_last_refresh)
  Failed to fetch record!
[2022/10/17 03:51:09.156883,  1] ../../source3/smbd/server_reload.c:67(delete_and_reload_printers)
  pcap cache not loaded
[2022/10/17 03:51:09.157205,  2] ../../source3/param/loadparm.c:2886(lp_do_section)
  Processing section "[cifs_test_open]"
[2022/10/17 03:51:13.870168,  3] ../../lib/util/access.c:374(allow_access)
  Allowed connection from 192.168.0.67 (192.168.0.67)
[2022/10/17 03:51:13.870484,  3] ../../source3/smbd/service.c:611(make_connection_snum)
  make_connection_snum: Connect path is '/mnt/alexandria/cifs_test_open' for service [cifs_test_open]
[2022/10/17 03:51:13.870577,  3] ../../source3/smbd/vfs.c:115(vfs_init_default)
  Initialising default vfs hooks
[2022/10/17 03:51:13.870605,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2022/10/17 03:51:13.870634,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [aio_fbsd]
[2022/10/17 03:51:13.870658,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [zfs_core]
[2022/10/17 03:51:13.870680,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [ixnas]
[2022/10/17 03:51:13.870978,  2] ../../source3/smbd/service.c:865(make_connection_snum)
  192.168.0.67 (ipv4:192.168.0.67:50512) connect to service cifs_test_open initially as user TEST_DOMAIN\test_user (uid=100001108, gid=100000514) (pid 16103)
  [2022/10/17 03:51:13.874691,  3] ../../source3/smbd/smb2_server.c:3955(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../../source3/smbd/smb2_create.c:337
[2022/10/17 03:51:13.876501,  3] ../../source3/smbd/dir.c:1034(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found . fname=. (.)
[2022/10/17 03:51:13.876604,  3] ../../source3/smbd/dir.c:1034(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found .. fname=.. (..)
[2022/10/17 03:51:13.876693,  3] ../../source3/smbd/dir.c:1034(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found test2.txt fname=test2.txt (test2.txt)
[2022/10/17 03:51:13.876763,  3] ../../source3/smbd/dir.c:1034(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found test fname=test (test)
[2022/10/17 03:51:13.876840,  3] ../../source3/smbd/dir.c:1034(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found test3.txt fname=test3.txt (test3.txt)
[2022/10/17 03:51:13.876920,  3] ../../source3/smbd/dir.c:1034(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found test.txt fname=test.txt (test.txt)
[2022/10/17 03:51:13.877020,  3] ../../source3/smbd/smb2_server.c:3955(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[9] status[STATUS_NO_MORE_FILES] || at ../../source3/smbd/smb2_query_directory.c:160
[2022/10/17 03:51:13.877979,  3] ../../source3/smbd/smb2_notify.c:253(smbd_smb2_notify_send)
  smbd_smb2_notify_send: notify change called on ., filter = DIR_NAME, recursive = 0
[2022/10/17 03:51:13.879515,  3] ../../source3/smbd/smb2_notify.c:253(smbd_smb2_notify_send)
  smbd_smb2_notify_send: notify change called on ., filter = FILE_NAME|ATTRIBUTES|LAST_WRITE, recursive = 0
 

nterupt

Cadet
Joined
Oct 17, 2022
Messages
3
I actually think I figured it out, but not sure why it changed the behavior. I went to Directory Services -> Idmap -> Idmap Edit. Under Options I selected SSSD Compat (was previously unchecked) and followed the prompts. Afterward authentication worked correctly as in this log result:
Code:
[2022/10/17 09:26:41.722214,  3] ../../lib/util/access.c:374(allow_access)
  Allowed connection from 192.168.0.66 (192.168.0.66)
[2022/10/17 09:26:41.722380,  3] ../../source3/smbd/service.c:611(make_connection_snum)
  make_connection_snum: Connect path is '/tmp' for service [IPC$]
[2022/10/17 09:26:41.722436,  3] ../../source3/smbd/vfs.c:115(vfs_init_default)
  Initialising default vfs hooks
[2022/10/17 09:26:41.722460,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2022/10/17 09:26:41.722636,  3] ../../source3/smbd/service.c:865(make_connection_snum)
   (ipv4:192.168.0.66:51090) connect to service IPC$ initially as user TEST_DOMAIN\test_user (uid=280801107, gid=280800513) (pid 21328)
[2022/10/17 09:26:41.723048,  3] ../../lib/util/access.c:374(allow_access)
  Allowed connection from 192.168.0.66 (192.168.0.66)
[2022/10/17 09:26:41.723148,  3] ../../source3/smbd/service.c:611(make_connection_snum)
  make_connection_snum: Connect path is '/mnt/alexandria/cifs_test_open' for service [cifs_test_open]
[2022/10/17 09:26:41.723213,  3] ../../source3/smbd/vfs.c:115(vfs_init_default)
  Initialising default vfs hooks
[2022/10/17 09:26:41.723236,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2022/10/17 09:26:41.723258,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [aio_fbsd]
[2022/10/17 09:26:41.723279,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [zfs_core]
[2022/10/17 09:26:41.723304,  3] ../../source3/smbd/vfs.c:141(vfs_init_custom)
  Initialising custom vfs hooks from [ixnas]
[2022/10/17 09:26:41.723548,  2] ../../source3/smbd/service.c:865(make_connection_snum)
   (ipv4:192.168.0.66:51090) connect to service cifs_test_open initially as user TEST_DOMAIN\test_user (uid=280801107, gid=280800513) (pid 21328)
[2022/10/17 09:26:41.726426,  3] ../../source3/smbd/smb2_server.c:3955(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_INVALID_DEVICE_REQUEST] || at ../../source3/smbd/smb2_ioctl.c:353
[2022/10/17 09:26:41.726776,  3] ../../source3/smbd/trans2.c:3506(smbd_do_qfsinfo)
  smbd_do_qfsinfo: level = 1005
[2022/10/17 09:26:41.727064,  3] ../../source3/smbd/trans2.c:3506(smbd_do_qfsinfo)
  smbd_do_qfsinfo: level = 1004
[2022/10/17 09:26:41.727303,  3] ../../source3/smbd/trans2.c:3506(smbd_do_qfsinfo)
  smbd_do_qfsinfo: level = 1001
[2022/10/17 09:26:41.727543,  3] ../../source3/smbd/trans2.c:3506(smbd_do_qfsinfo)
  smbd_do_qfsinfo: level = 1011
 

nterupt

Cadet
Joined
Oct 17, 2022
Messages
3
Any idea why this would resolve my issue? I'm glad it's working but wondering if there is a bigger root cause concern to be worried about that will strike my system later.
 
Top