Connect to Domain

[BERKUT]

FreeNas 11.1
From GUI we connect Windows shares to Domain without error.
root@test:~ # wbinfo -t
checking the trust secret for domain NOC via RPC calls succeeded
After test, we get that error:
root@test:~ # net ads join -S XXX -U nas.admin
Enter nas.admin's password:
kinit succeeded but ads_sasl_spnego_gensec_bind(KRB5) failed for ldap/XXX with user[nas.admin] realm[XXX]: An invalid parameter was passed to a service or function.
Failed to join domain: failed to connect to AD: An invalid parameter was passed to a service or function.

What do we do wrong?

 

[dlavigne]

Anything in /var/log/messages hinting at the invalid parameter?

 

[andrew.p]

Hope I'm not replying on too old of a thread, but I'm getting the same error both on FreeNAS-11.1-U6 and U5 before I updated last week. @OP were you able to figure out the cause? I don't see any hints in /var/log/messages, see below. A few users including my own account are unable to even browse to the FreeNAS smb shares because of this and I'm hoping more people aren't affected on Monday. I've tried the troubleshooting steps in the guide and I will paste those results below as well.

Also, when I connect with a user that does work, I noticed the share permissions which used to show my user as owner and full control, now shows as "32652 (Unix User\32652)". I tried setting the owner again back to my domain user account on one of the shares under storage > volumes > change permissions for that dataset, but it reverts back to root as the owner after saving.

Also tried removing from AD, deleting and recreating the object in AD, and rebooting the server, which also had no effect.

root@FREENAS:~ # tail -n 70 /var/log/messages

Aug 26 22:17:24 FREENAS ActiveDirectory: /usr/sbin/service ix-pam quietstop

Aug 26 22:17:25 FREENAS ActiveDirectory: /usr/sbin/service ix-cache quietstop &

Aug 26 22:17:47 FREENAS ActiveDirectory: /usr/sbin/service ix-hostname quietstart

Aug 26 22:17:48 FREENAS ActiveDirectory: /usr/sbin/service ix-kerberos quietstart default XXX.DOMAIN.COM

Aug 26 22:17:49 FREENAS ActiveDirectory: /usr/sbin/service ix-nsswitch quietstart

Aug 26 22:17:49 FREENAS ActiveDirectory: /usr/sbin/service ix-ldap quietstart

Aug 26 22:17:49 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit quietstart

Aug 26 22:17:50 FREENAS ActiveDirectory: kerberos_start: /usr/bin/kinit --renewable --password-file=/tmp/tmp.CD8DJQWd freenasldap@XXX.DOMAIN.COM

Aug 26 22:17:51 FREENAS ActiveDirectory: kerberos_start: Successful

Aug 26 22:17:51 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit status

Aug 26 22:17:51 FREENAS ActiveDirectory: kerberos_status: klist -t

Aug 26 22:17:51 FREENAS ActiveDirectory: kerberos_status: Successful

Aug 26 22:17:51 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.start cifs

Aug 26 22:17:52 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.stop cifs

Aug 26 22:17:53 FREENAS ActiveDirectory: /usr/sbin/service ix-hostname quietstart

Aug 26 22:17:53 FREENAS ActiveDirectory: /usr/sbin/service ix-kerberos quietstart default XXX.DOMAIN.COM

Aug 26 22:17:54 FREENAS ActiveDirectory: /usr/sbin/service ix-nsswitch quietstart

Aug 26 22:17:54 FREENAS ActiveDirectory: /usr/sbin/service ix-ldap quietstart

Aug 26 22:17:55 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit quietstart

Aug 26 22:17:55 FREENAS ActiveDirectory: kerberos_start: /usr/bin/kinit --renewable --password-file=/tmp/tmp.TO4XKSZD freenasldap@XXX.DOMAIN.COM

Aug 26 22:17:55 FREENAS ActiveDirectory: /usr/sbin/service ix-activedirectory quietstart

Aug 26 22:17:56 FREENAS ActiveDirectory: kerberos_start: Successful

Aug 26 22:17:56 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit status

Aug 26 22:17:56 FREENAS ActiveDirectory: activedirectory_start: checking if we are joined already

Aug 26 22:17:56 FREENAS ActiveDirectory: AD_testjoin_domain: net -k ads testjoin xxx.domain.com -S dc-003.xxx.domain.com -p 389

Aug 26 22:17:57 FREENAS ActiveDirectory: kerberos_status: klist -t

Aug 26 22:17:57 FREENAS ActiveDirectory: kerberos_status: Successful

Aug 26 22:17:57 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.start cifs

Aug 26 22:17:57 FREENAS ActiveDirectory: AD_testjoin_domain: Successful

Aug 26 22:17:57 FREENAS ActiveDirectory: activedirectory_start: skipping join, already joined

Aug 26 22:17:57 FREENAS ActiveDirectory: /usr/sbin/service ix-activedirectory status

Aug 26 22:17:58 FREENAS ActiveDirectory: activedirectory_status: checking status

Aug 26 22:17:58 FREENAS ActiveDirectory: AD_status_domain: net -k ads status xxx.domain.com

Aug 26 22:17:59 FREENAS ActiveDirectory: AD_status_domain: Not okay

Aug 26 22:18:01 FREENAS ActiveDirectory: /usr/sbin/service ix-activedirectory quietstart

Aug 26 22:18:01 FREENAS ActiveDirectory: /usr/sbin/service ix-activedirectory status

Aug 26 22:20:33 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.stop cifs

Aug 26 22:20:35 FREENAS ActiveDirectory: /usr/sbin/service samba_server forcestop

Aug 26 22:20:36 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.start cifs

Aug 26 22:20:39 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit forcestop

Aug 26 22:20:39 FREENAS ActiveDirectory: /usr/sbin/service ix-hostname quietstart

Aug 26 22:20:40 FREENAS ActiveDirectory: /usr/sbin/service ix-kerberos restart

Aug 26 22:20:40 FREENAS ActiveDirectory: /usr/sbin/service ix-nsswitch quietstop

Aug 26 22:20:41 FREENAS ActiveDirectory: /usr/sbin/service ix-pam quietstop

Aug 26 22:20:41 FREENAS ActiveDirectory: /usr/sbin/service ix-cache quietstop &

Aug 26 22:21:03 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.stop cifs

Aug 26 22:21:05 FREENAS ActiveDirectory: /usr/sbin/service ix-hostname quietstart

Aug 26 22:21:06 FREENAS ActiveDirectory: /usr/sbin/service ix-kerberos quietstart default XXX.DOMAIN.COM

Aug 26 22:21:06 FREENAS ActiveDirectory: /usr/sbin/service ix-nsswitch quietstart

Aug 26 22:21:07 FREENAS ActiveDirectory: /usr/sbin/service ix-ldap quietstart

Aug 26 22:21:07 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit quietstart

Aug 26 22:21:07 FREENAS ActiveDirectory: kerberos_start: /usr/bin/kinit --renewable --password-file=/tmp/tmp.UGwCn3Fg freenasldap@XXX.DOMAIN.COM

Aug 26 22:21:09 FREENAS ActiveDirectory: kerberos_start: Successful

Aug 26 22:21:09 FREENAS ActiveDirectory: /usr/sbin/service ix-kinit status

Aug 26 22:21:09 FREENAS ActiveDirectory: kerberos_status: klist -t

Aug 26 22:21:09 FREENAS ActiveDirectory: kerberos_status: Successful

Aug 26 22:21:09 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.start cifs

Aug 26 22:21:13 FREENAS ActiveDirectory: /usr/sbin/service ix-activedirectory quietstart

Aug 26 22:21:14 FREENAS ActiveDirectory: activedirectory_start: checking if we are joined already

Aug 26 22:21:14 FREENAS ActiveDirectory: AD_testjoin_domain: net -k ads testjoin xxx.domain.com -S dc-003.xxx.domain.com -p 389

Aug 26 22:21:15 FREENAS ActiveDirectory: AD_testjoin_domain: Successful

Aug 26 22:21:15 FREENAS ActiveDirectory: activedirectory_start: skipping join, already joined

Aug 26 22:21:15 FREENAS ActiveDirectory: /usr/sbin/service ix-activedirectory status

Aug 26 22:21:16 FREENAS ActiveDirectory: activedirectory_status: checking status

Aug 26 22:21:16 FREENAS ActiveDirectory: AD_status_domain: net -k ads status xxx.domain.com

Aug 26 22:21:17 FREENAS ActiveDirectory: AD_status_domain: Okay

Aug 26 22:21:17 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.stop cifs

Aug 26 22:21:18 FREENAS ActiveDirectory: /usr/local/bin/python /usr/local/bin/midclt call notifier.start cifs

Aug 26 22:21:22 FREENAS ActiveDirectory: /usr/sbin/service ix-pam quietstart

Aug 26 22:21:23 FREENAS ActiveDirectory: /usr/sbin/service ix-cache quietstart &



root@FREENAS:~ # sqlite3 /data/freenas-v1.db "update directoryservice_activedirectory set ad_enable=1;"

root@FREENAS:~ # echo $?

0

root@FREENAS:~ # service ix-kerberos start

root@FREENAS:~ # service ix-nsswitch start

root@FREENAS:~ # service ix-kinit start

root@FREENAS:~ # service ix-kinit status

root@FREENAS:~ # echo $?

0

root@FREENAS:~ # klist

Credentials cache: FILE:/tmp/krb5cc_0

Principal: freenasldap@XXX.DOMAIN.COM


Issued Expires Principal

Aug 27 06:11:19 2018 Aug 27 16:11:19 2018 krbtgt/XXX.DOMAIN.COM@XXX.DOMAIN.COM
Aug 27 06:11:27 2018 Aug 27 16:11:19 2018 ldap/dc-001.xxx.domain.com@XXX.DOMAIN.COM


root@FREENAS:~ # service ix-activedirectory start

Join is OK

root@FREENAS:~ # service ix-activedirectory status

root@FREENAS:~ # echo $?

0

root@FREENAS:~ # python /usr/local/www/freenasUI/middleware/notifier.py restart cifs

True

root@FREENAS:~ # service ix-pam start

root@FREENAS:~ # service ix-cache start &

[1] 39149

 

[andrew.p]

Here is what I saw come up in /var/log/samba4/log.smbd when I tried browsing to the IP in windows (7) explorer:


[2018/08/27 04:34:34.222947, 5, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth_util.c:126(make_user_info_map)
Mapping user [domain]\[user.name] from workstation [PC-001]
[2018/08/27 04:34:34.222961, 5, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/user_info.c:64(make_user_info)
attempting to make a user_info for user.name (user.name)
[2018/08/27 04:34:34.222971, 5, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/user_info.c:72(make_user_info)
making strings for user.name's user_info struct
[2018/08/27 04:34:34.222984, 5, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/user_info.c:125(make_user_info)
making blobs for user.name's user_info struct
[2018/08/27 04:34:34.222996, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/user_info.c:176(make_user_info)
made a user_info for user.name (user.name)
[2018/08/27 04:34:34.223006, 3, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:189(auth_check_ntlm_password)
check_ntlm_password: Checking password for unmapped user [domain]\[user.name]@[PC-001] with the new password interface
[2018/08/27 04:34:34.223018, 3, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:192(auth_check_ntlm_password)
check_ntlm_password: mapped user is: [domain]\[user.name]@[PC-001]
[2018/08/27 04:34:34.223033, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:202(auth_check_ntlm_password)
check_ntlm_password: auth_context challenge created by random
[2018/08/27 04:34:34.223059, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:204(auth_check_ntlm_password)
challenge is:
[2018/08/27 04:34:34.223070, 5, pid=7104, effective(0, 0), real(0, 0)] ../lib/util/util.c:515(dump_data)
[0000] 22 2C 85 0E E8 BC FE 3E ",.....>
[2018/08/27 04:34:34.223095, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth_builtin.c:41(check_guest_security)
Check auth for: [user.name]
[2018/08/27 04:34:34.223106, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:237(auth_check_ntlm_password)
auth_check_ntlm_password: guest had nothing to say
[2018/08/27 04:34:34.223123, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth_sam.c:75(auth_samstrict_auth)
Check auth for: [user.name]
[2018/08/27 04:34:34.223135, 8, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/util.c:1252(is_myname)
is_myname("domain") returns 0
[2018/08/27 04:34:34.223154, 6, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth_sam.c:88(auth_samstrict_auth)
check_samstrict_security: domain is not one of my local names (ROLE_DOMAIN_MEMBER)
[2018/08/27 04:34:34.223166, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:237(auth_check_ntlm_password)
auth_check_ntlm_password: sam had nothing to say
[2018/08/27 04:34:34.223182, 10, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth_winbind.c:50(check_winbind_security)
Check auth for: [user.name]
[2018/08/27 04:34:34.223194, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2018/08/27 04:34:34.223206, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx)
push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2018/08/27 04:34:34.223223, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2018/08/27 04:34:34.223234, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.223249, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.229381, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/08/27 04:34:34.229433, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/username.c:181(Get_Pwnam_alloc)
Finding user domain\user.name
[2018/08/27 04:34:34.229447, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/username.c:120(Get_Pwnam_internals)
Trying _Get_Pwnam(), username as lowercase is domain\user.name
[2018/08/27 04:34:34.230945, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/username.c:159(Get_Pwnam_internals)
Get_Pwnam_internals did find user [domain\user.name]!
[2018/08/27 04:34:34.230966, 3, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:256(auth_check_ntlm_password)
auth_check_ntlm_password: winbind authentication for user [user.name] succeeded
[2018/08/27 04:34:34.230989, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2018/08/27 04:34:34.230999, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx)
push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2018/08/27 04:34:34.231014, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2018/08/27 04:34:34.231020, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.231035, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.231058, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:483(smb_pam_start)
smb_pam_start: PAM: Init user: domain\user.name
[2018/08/27 04:34:34.234167, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:492(smb_pam_start)
smb_pam_start: PAM: setting rhost to: 192.168.1.62
[2018/08/27 04:34:34.234182, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:501(smb_pam_start)
smb_pam_start: PAM: setting tty
[2018/08/27 04:34:34.234190, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:509(smb_pam_start)
smb_pam_start: PAM: Init passed for user: domain\user.name
[2018/08/27 04:34:34.234203, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:567(smb_pam_account)
smb_pam_account: PAM: Account Management for User: domain\user.name
[2018/08/27 04:34:34.238845, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:586(smb_pam_account)
smb_pam_account: PAM: Account OK for User: domain\user.name
[2018/08/27 04:34:34.239272, 4, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/pampass.c:465(smb_pam_end)
smb_pam_end: PAM: PAM_END OK.
[2018/08/27 04:34:34.239305, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/08/27 04:34:34.239317, 5, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:283(auth_check_ntlm_password)
check_ntlm_password: PAM Account for user [domain\user.name] succeeded
[2018/08/27 04:34:34.239349, 3, pid=7104, effective(0, 0), real(0, 0)] ../auth/auth_log.c:760(log_authentication_event_human_readable)
Auth: [SMB2,(null)] user [domain]\[user.name] at [Mon, 27 Aug 2018 04:34:34.239338 CST] with [NTLMv2] status [NT_STATUS_OK] workstation [PC-001] remote host [ipv4:192.168.1.62:61068] became [domain]\[user.name] [S-1-5-21-1382999390-1295409725-1631389064-12652]. local host [ipv4:192.168.1.110:445]
[2018/08/27 04:34:34.239372, 3, pid=7104, effective(0, 0), real(0, 0)] ../auth/auth_log.c:591(log_no_json)
log_no_json: JSON auth logs not available unless compiled with jansson
[2018/08/27 04:34:34.239398, 2, pid=7104, effective(0, 0), real(0, 0), class=auth] ../source3/auth/auth.c:314(auth_check_ntlm_password)
check_ntlm_password: authentication for user [user.name] -> [user.name] -> [domain\user.name] succeeded
[2018/08/27 04:34:34.239419, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/auth_ntlmssp.c:227(auth3_check_password)
Got NT session key of length 16
[2018/08/27 04:34:34.239429, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/auth_ntlmssp.c:234(auth3_check_password)
Got LM session key of length 8
[2018/08/27 04:34:34.239562, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:247(create_local_nt_token_from_info3)
Create local NT token for user.name
[2018/08/27 04:34:34.239619, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid)
Parsing value for key [IDMAP/SID2XID/S-1-5-21-1382999390-1295409725-1631389064-12652]: value=[32652:B]
[2018/08/27 04:34:34.239632, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid)
Parsing value for key [IDMAP/SID2XID/S-1-5-21-1382999390-1295409725-1631389064-12652]: id=[32652], endptr=[:B]
[2018/08/27 04:34:34.239646, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/passdb/lookup_sid.c:1503(sid_to_uid)
sid S-1-5-21-1382999390-1295409725-1631389064-12652 -> uid 32652
[2018/08/27 04:34:34.241585, 1, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:442(add_local_groups)
SID S-1-5-21-1382999390-1295409725-1631389064-12652 -> getpwuid(32652) failed
[2018/08/27 04:34:34.241609, 3, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:328(create_local_nt_token_from_info3)
Failed to finalize nt token
[2018/08/27 04:34:34.241641, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/auth_ntlmssp.c:86(auth3_generate_session_info)
create_local_token failed: NT_STATUS_UNSUCCESSFUL
[2018/08/27 04:34:34.241655, 10, pid=7104, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_server.c:874(ntlmssp_server_postauth)
ntlmssp_server_auth: Using unmodified nt session key.
[2018/08/27 04:34:34.241705, 3, pid=7104, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
NTLMSSP Sign/Seal - Initialising with flags:
[2018/08/27 04:34:34.241717, 3, pid=7104, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
Got NTLMSSP neg_flags=0xe2088215
NTLMSSP_NEGOTIATE_UNICODE
NTLMSSP_REQUEST_TARGET
NTLMSSP_NEGOTIATE_SIGN
NTLMSSP_NEGOTIATE_NTLM
NTLMSSP_NEGOTIATE_ALWAYS_SIGN
NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
NTLMSSP_NEGOTIATE_VERSION
NTLMSSP_NEGOTIATE_128
NTLMSSP_NEGOTIATE_KEY_EXCH
NTLMSSP_NEGOTIATE_56
[2018/08/27 04:34:34.241813, 10, pid=7104, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_sign.c:255(ntlmssp_check_packet)
ntlmssp_check_packet: NTLMSSP signature OK !
[2018/08/27 04:34:34.241835, 3, pid=7104, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
NTLMSSP Sign/Seal - Initialising with flags:
[2018/08/27 04:34:34.241850, 3, pid=7104, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
Got NTLMSSP neg_flags=0xe2088215
NTLMSSP_NEGOTIATE_UNICODE
NTLMSSP_REQUEST_TARGET
NTLMSSP_NEGOTIATE_SIGN
NTLMSSP_NEGOTIATE_NTLM
NTLMSSP_NEGOTIATE_ALWAYS_SIGN
NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
NTLMSSP_NEGOTIATE_VERSION
NTLMSSP_NEGOTIATE_128
NTLMSSP_NEGOTIATE_KEY_EXCH
NTLMSSP_NEGOTIATE_56
[2018/08/27 04:34:34.241914, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
smbd_smb2_request_pending_queue: req->current_idx = 1
req->in.vector[0].iov_len = 0
req->in.vector[1].iov_len = 0
req->in.vector[2].iov_len = 64
req->in.vector[3].iov_len = 24
req->in.vector[4].iov_len = 573
req->out.vector[0].iov_len = 4
req->out.vector[1].iov_len = 0
req->out.vector[2].iov_len = 64
req->out.vector[3].iov_len = 8
req->out.vector[4].iov_len = 0
[2018/08/27 04:34:34.242010, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/08/27 04:34:34.242023, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx)
push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/08/27 04:34:34.242040, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/08/27 04:34:34.242070, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.242080, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.242107, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/08/27 04:34:34.242232, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:247(create_local_nt_token_from_info3)
Create local NT token for user.name
[2018/08/27 04:34:34.242256, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid)
Parsing value for key [IDMAP/SID2XID/S-1-5-21-1382999390-1295409725-1631389064-12652]: value=[32652:B]
[2018/08/27 04:34:34.242267, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid)
Parsing value for key [IDMAP/SID2XID/S-1-5-21-1382999390-1295409725-1631389064-12652]: id=[32652], endptr=[:B]
[2018/08/27 04:34:34.242286, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/passdb/lookup_sid.c:1503(sid_to_uid)
sid S-1-5-21-1382999390-1295409725-1631389064-12652 -> uid 32652
[2018/08/27 04:34:34.244295, 1, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:442(add_local_groups)
SID S-1-5-21-1382999390-1295409725-1631389064-12652 -> getpwuid(32652) failed
[2018/08/27 04:34:34.244314, 3, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:328(create_local_nt_token_from_info3)
Failed to finalize nt token
[2018/08/27 04:34:34.244322, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/auth_ntlmssp.c:86(auth3_generate_session_info)
create_local_token failed: NT_STATUS_UNSUCCESSFUL
[2018/08/27 04:34:34.244341, 3, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3115(smbd_smb2_request_error_ex)
smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_UNSUCCESSFUL] || at ../source3/smbd/smb2_sesssetup.c:134
[2018/08/27 04:34:34.244360, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3006(smbd_smb2_request_done_ex)
smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_UNSUCCESSFUL] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:3163
[2018/08/27 04:34:34.244378, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:918(smb2_set_operation_credit)
smb2_set_operation_credit: requested 31, charge 1, granted 1, current possible/max 512/512, total granted/max/low/range 1/8192/3/1
[2018/08/27 04:34:34.244402, 5, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:160(dbwrap_check_lock_order)
check lock order 1 for /var/lock/smbXsrv_session_global.tdb
[2018/08/27 04:34:34.244425, 10, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
lock order: 1:/var/lock/smbXsrv_session_global.tdb 2:<none> 3:<none>
[2018/08/27 04:34:34.244441, 10, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
Locking key FE41DBA3
[2018/08/27 04:34:34.244455, 10, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal)
Allocated locked data 0x0x812874ae0
[2018/08/27 04:34:34.244482, 5, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:128(dbwrap_lock_order_state_destructor)
release lock order 1 for /var/lock/smbXsrv_session_global.tdb
[2018/08/27 04:34:34.244493, 10, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
lock order: 1:<none> 2:<none> 3:<none>
[2018/08/27 04:34:34.244507, 10, pid=7104, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
Unlocking key FE41DBA3
[2018/08/27 04:34:34.244806, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:1075(smbd_server_connection_terminate_ex)
smbd_server_connection_terminate_ex: conn[ipv4:192.168.1.62:61068] reason[NT_STATUS_CONNECTION_RESET] at ../source3/smbd/smb2_server.c:3930
[2018/08/27 04:34:34.244832, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/08/27 04:34:34.244845, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.244860, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.244879, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/08/27 04:34:34.244891, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/08/27 04:34:34.244898, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.244906, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.244920, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/08/27 04:34:34.244939, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/08/27 04:34:34.244949, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.244963, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.244993, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/08/27 04:34:34.245006, 4, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/08/27 04:34:34.245017, 5, pid=7104, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.245026, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.245049, 5, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/08/27 04:34:34.245088, 10, pid=7104, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm_ref.c:157(msg_dgm_ref_destructor)
msg_dgm_ref_destructor: refs=0x0
[2018/08/27 04:34:34.245471, 3, pid=7104, effective(0, 0), real(0, 0)] ../source3/smbd/server_exit.c:248(exit_server_common)
Server exit (NT_STATUS_CONNECTION_RESET)
[2018/08/27 04:34:34.300142, 10, pid=51531, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:1344(messaging_dgm_send)
messaging_dgm_send: Sending message to 51555
[2018/08/27 04:34:34.300243, 10, pid=51555, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:203(messaging_recv_cb)
messaging_recv_cb: Received message 0x314 len 0 (num_fds:0) from 51531
[2018/08/27 04:34:34.300327, 3, pid=51555, effective(0, 0), real(0, 0)] ../source3/lib/util_procid.c:54(pid_to_procid)
pid_to_procid: messaging_dgm_get_unique failed: No such file or directory
[2018/08/27 04:34:34.300345, 5, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:160(dbwrap_check_lock_order)
check lock order 2 for /var/lock/serverid.tdb
[2018/08/27 04:34:34.300353, 10, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
lock order: 1:<none> 2:/var/lock/serverid.tdb 3:<none>
[2018/08/27 04:34:34.300364, 10, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
Locking key C01B000000000000FFFF
[2018/08/27 04:34:34.300374, 10, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal)
Allocated locked data 0x0x81284fc60
[2018/08/27 04:34:34.300388, 10, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
Unlocking key C01B000000000000FFFF
[2018/08/27 04:34:34.300395, 5, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:128(dbwrap_lock_order_state_destructor)
release lock order 2 for /var/lock/serverid.tdb
[2018/08/27 04:34:34.300400, 10, pid=51555, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
lock order: 1:<none> 2:<none> 3:<none>
[2018/08/27 04:34:34.300408, 10, pid=51555, effective(0, 0), real(0, 0)] ../source3/smbd/smbd_cleanupd.c:210(smbd_cleanupd_process_exited)
smbd_cleanupd_process_exited: cleaned up pid 7104
[2018/08/27 04:34:34.346319, 10, pid=75197, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:42(smbd_idle_event_handler)
smbd_idle_event_handler: idle_evt(deadtime) 0x0 called
[2018/08/27 04:34:34.346348, 10, pid=75197, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:53(smbd_idle_event_handler)
smbd_idle_event_handler: idle_evt(deadtime) 0x0 rescheduled
[2018/08/27 04:34:34.346363, 10, pid=75197, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:42(smbd_idle_event_handler)
smbd_idle_event_handler: idle_evt(housekeeping) 0x0 called
[2018/08/27 04:34:34.346380, 5, pid=75197, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2897(housekeeping_fn)
housekeeping
[2018/08/27 04:34:34.346391, 4, pid=75197, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/08/27 04:34:34.346404, 5, pid=75197, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
Security token: (NULL)
[2018/08/27 04:34:34.346416, 5, pid=75197, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2018/08/27 04:34:34.346480, 5, pid=75197, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/08/27 04:34:34.346529, 6, pid=75197, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2313(lp_file_list_changed)
lp_file_list_changed()
file /usr/local/etc/smb4.conf -> /usr/local/etc/smb4.conf last mod_time: Sun Aug 26 22:21:20 2018

[2018/08/27 04:34:34.346585, 10, pid=75197, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:53(smbd_idle_event_handler)
smbd_idle_event_handler: idle_evt(housekeeping) 0x0 rescheduled

 

[andrew.p]

Update for future google arrivals, this particular issue was resolved by clearing the AD cache by running "net cache flush", but the error in the OP still persists when I run that command.