Hello!
Another day, another issue which I can't resolve so far.
We switched our user from local /etc/passwd to samba AD.
And it was apparently a big mistake, since nothing work
besides samba now.
Well, auth does not work anymore. The only way to login locally
so far is to use ssh keys. Or it is possible to enable
KerberosAuthentication in sshd_config, that one works too.
Installing pam_winbind which - I thought - is supposed to make
local logins possible. Debian installer made this seamless.
This is the pam config it added (the pam_winbind line):
auth [success=2 default=ignore] pam_unix.so nullok
auth [success=1 default=ignore] pam_winbind.so krb5_auth krb5_ccache_type=FILE
cached_login try_first_pass
when trying to log in over ssh (without enabling KerberosAuthentication),
after entering the password, I see this in the auth.log:
Feb 14 16:07:23 tsrv sshd[179020]: pam_unix(sshd:auth): authentication failure;
logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.177.130 user=mjt
Feb 14 16:07:23 tsrv sshd[179020]: pam_winbind(sshd:auth): getting password
(0x00000388)
Feb 14 16:07:23 tsrv sshd[179020]: pam_winbind(sshd:auth): pam_get_item returned
a password
Feb 14 16:07:23 tsrv sshd[179020]: pam_winbind(sshd:auth): request wbcLogonUser
failed: WBC_ERR_DOMAIN_NOT_FOUND, PAM error: PAM_AUTHINFO_UNAVAIL (9)!
Feb 14 16:07:23 tsrv sshd[179020]: pam_winbind(sshd:auth): internal module error
(retval = PAM_AUTHINFO_UNAVAIL(9), user = 'mjt')
Feb 14 16:07:25 tsrv sshd[179020]: Failed password for mjt from 192.168.177.130
port 41252 ssh2
Feb 14 16:07:27 tsrv sshd[179020]: Connection closed by authenticating user mjt
192.168.177.130 port 41252 [preauth]
After enabling debug=10 at winbind level, I see this at the same time in
log.winbind:
...
[2022/02/14 16:07:23.108587, 1, pid=178279, effective(0, 0), real(0, 0),
class=rpc_parse] ../../librpc/ndr/ndr.c:478(ndr_print_function_debug)
wbint_GetNssInfo: struct wbint_GetNssInfo
out: struct wbint_GetNssInfo
info : *
info: struct wbint_userinfo
domain_name : *
domain_name : 'TLS'
acct_name : *
acct_name : 'mjt'
full_name : *
full_name : '?????? ???????'
homedir : *
homedir : '/home/%U'
shell : *
shell : '/bin/bash'
uid : 0x00000000000003e8 (1000)
primary_gid : 0x00000000000003e8 (1000)
primary_group_name : NULL
user_sid :
S-1-5-21-411424318-379842365-2075518510-3000
group_sid :
S-1-5-21-411424318-379842365-2075518510-513
result : NT_STATUS_OK
[2022/02/14 16:07:23.108816, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:801(process_request_done)
process_request_done: [nss_winbind(179020):GETPWNAM]: NT_STATUS_OK
[2022/02/14 16:07:23.108883, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:846(process_request_written)
process_request_written: [nss_winbind(179020):GETPWNAM]: delivered response
to client
[2022/02/14 16:07:23.109060, 6, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:915(new_connection)
accepted socket 28
[2022/02/14 16:07:23.109167, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:762(process_request_send)
process_request_send: process_request: request fn INTERFACE_VERSION
[2022/02/14 16:07:23.109203, 3, pid=178279, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_misc.c:429(winbindd_interface_version)
winbindd_interface_version: [nss_winbind (179020)]: request interface version
(version = 31)
[2022/02/14 16:07:23.109261, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:846(process_request_written)
process_request_written: [nss_winbind(179020):INTERFACE_VERSION]: delivered
response to client
[2022/02/14 16:07:23.109334, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:733(process_request_send)
process_request_send: process_request: Handling async request
nss_winbind(179020):PAM_AUTH
[2022/02/14 16:07:23.109368, 3, pid=178279, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_pam_auth.c:55(winbindd_pam_auth_send)
winbindd_pam_auth_send: [nss_winbind (179020)]: pam auth mjt
[2022/02/14 16:07:23.278506, 0, pid=178279, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_cred_cache.c:819(store_memory_creds)
failed to mlock memory: Operation not permitted (1)
[2022/02/14 16:07:23.278623, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_pam_auth.c:160(winbindd_pam_auth_recv)
winbindd_add_memory_creds returned: NT_STATUS_ACCESS_DENIED
[2022/02/14 16:07:23.278658, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:801(process_request_done)
process_request_done: [nss_winbind(179020):PAM_AUTH]: NT_STATUS_ACCESS_DENIED
[2022/02/14 16:07:23.278722, 10, pid=178279, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd.c:846(process_request_written)
process_request_written: [nss_winbind(179020):PAM_AUTH]: delivered response
to client
[2022/02/14 16:07:23.278924, 6, pid=178279, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd.c:963(winbind_client_request_read)
closing socket 28, client exited
Kerberos auth works fine, samba shares works too. But "regular" (what
is that? samlogon?)
auth does not work.
I tried to strace the process in question (178279), in order to see what/how it
tries
to mlock memory. But it does not, even more, there's no single failed
syscall in there.
Is it logging with the wrong pid? I tried other winbind processes, but found
none which
tries mlock or whose syscalls returned -1.
log.wb-TLS shows this:
[2022/02/14 16:07:23.263162, 10, pid=178282, effective(1000, 0), real(1000, 0)]
../../source3/libads/kerberos.c:211(kerberos_kinit_password_ext)
kerberos_kinit_password_ext: mjt at TLS.MSK.RU mapped to mjt at TLS.MSK.RU
[2022/02/14 16:07:23.263351, 10, pid=178282, effective(1000, 0), real(1000, 0)]
../../source3/libads/authdata.c:117(kerberos_return_pac)
got TGT for mjt at TLS.MSK.RU in FILE:/tmp/krb5cc_1000
valid until: Tue, 15 Feb 2022 02:07:23 MSK (1644880043)
renewable till: Mon, 21 Feb 2022 16:07:23 MSK (1645448843)
...
[2022/02/14 16:07:23.275497, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_pam.c:829(winbindd_raw_kerberos_login)
winbindd_raw_kerberos_login: winbindd validated ticket of mjt at TLS.MSK.RU
[2022/02/14 16:07:23.275552, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_cred_cache.c:528(add_ccache_to_list)
add_ccache_to_list: ref count on entry TLS\mjt is now 6
[2022/02/14 16:07:23.275582, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_pam.c:2189(winbindd_dual_pam_auth)
winbindd_dual_pam_auth_kerberos succeeded
..
[2022/02/14 16:07:23.277020, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd_cache.c:467(fetch_cache_seqnum)
fetch_cache_seqnum: timeout [TLS][6321 @ 1644843702]
[2022/02/14 16:07:23.277060, 3, pid=178282, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd_ads.c:1333(sequence_number)
ads: fetch sequence_number for TLS
[2022/02/14 16:07:23.277091, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd_ads.c:254(ads_cached_connection)
ads_cached_connection
[2022/02/14 16:07:23.277118, 7, pid=178282, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_ads.c:63(ads_cached_connection_reuse)
Current tickets expire in 34641 seconds (at 1644878684, time is now
1644844043)
[2022/02/14 16:07:23.277830, 5, pid=178282, effective(0, 0), real(0, 0)]
../../source3/libads/ldap_utils.c:80(ads_do_search_retry_internal)
Search for (objectclass=*) in <> gave 1 replies
[2022/02/14 16:07:23.277922, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd_cache.c:507(wcache_store_seqnum)
wcache_store_seqnum: success [TLS][6321 @ 1644844043]
[2022/02/14 16:07:23.277968, 10, pid=178282, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_cache.c:593(refresh_sequence_number)
refresh_sequence_number: TLS seq number is now 6321
[2022/02/14 16:07:23.278011, 10, pid=178282, effective(0, 0), real(0, 0),
class=tdb] ../../source3/lib/gencache.c:279(gencache_set_data_blob)
gencache_set_data_blob: Adding cache entry with key=[NAME2SID/TLS\MJT] and
timeout=[Mon Feb 14 16:12:23 2022 MSK] (300 seconds ahead)
[2022/02/14 16:07:23.278074, 5, pid=178282, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd_pam.c:224(append_unix_username)
Setting unix username to [mjt]
[2022/02/14 16:07:23.278122, 5, pid=178282, effective(0, 0), real(0, 0),
class=winbind]
../../source3/winbindd/winbindd_pam.c:2463(winbindd_dual_pam_auth)
Plain-text authentication for user TLS\mjt returned NT_STATUS_OK (PAM: 0)
[2022/02/14 16:07:23.278175, 3, pid=178282, effective(0, 0), real(0, 0),
class=auth_audit]
../../auth/auth_log.c:635(log_authentication_event_human_readable)
Auth: [winbind,PAM_AUTH, nss_winbind, 178279] user [TLS]\[mjt] at [Mon, 14
Feb 2022 16:07:23.278159 MSK] with [Plaintext] status [NT_STATUS_OK]
workstation [(null)] remote host [unix:] became [TLS]\[mjt]
[S-1-5-21-411424318-379842365-2075518510-3000]. local host [unix:]
{"timestamp": "2022-02-14T16:07:23.278232+0300",
"type": "Authentication", "Authentication":
{"version": {"major": 1, "minor": 2},
"eventId": 4624,
"logonId": "3810d097477331ee", "logonType": 8,
"status": "NT_STATUS_OK", "localAddress":
"unix:", "remoteAddress": "unix:",
"serviceDescription":
"winbind", "authDescription": "PAM_AUTH, nss_winbind,
178279", "clientDomain": "TLS",
"clientAccount": "mjt", "workstation": null,
"becameAccount":
"mjt", "becameDomain": "TLS",
"becameSid": "S-1-5-21-411424318-379842365-2075518510-3000",
"mappedAccount": null, "mappedDomain": null,
"netlogonComputer": null, "netlogonTrustAccount": null,
"netlogonNegotiateFlags": "0x00000000",
"netlogonSecureChannelType": 0,
"netlogonTrustAccountSid": null, "passwordType":
"Plaintext", "duration": 168641}}
[2022/02/14 16:07:23.278292, 4, pid=178282, effective(0, 0), real(0, 0),
class=winbind] ../../source3/winbindd/winbindd_dual.c:1666(child_handler)
Finished processing child request 13
what it does not like, why it does not let me in?
Thanks,
/mjt