thr3ads.net - samba - [Samba] making pam_winbind to work [Feb 2022]

If this information is useful, please help other people find it:
Share via:

Michael Tokarev

2022-Feb-14 13:22 UTC

[Samba] making pam_winbind to work

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

Rowland Penny

2022-Feb-14 13:32 UTC

head link

[Samba] making pam_winbind to work

On Mon, 2022-02-14 at 16:22 +0300, Michael Tokarev via samba
wrote:> 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.
Anything that uses nsswitch should work, provided that everything is
set up correctly.> 
> 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.
What OS are you using on your Unix domain member ? and can you post the
global part of the smb.conf currently in use.

Rowland

Michael Tokarev

2022-Feb-14 14:51 UTC

head link

[Samba] making pam_winbind to work

14.02.2022 16:22, Michael Tokarev via samba wrote:
...> 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]
> 
> [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
So, this was the issue.

After digging in the source. Sigh.

This is a container, -- as said in the wiki, single machine can not be
both file server and an AD DC, so I created a new machine, actually a
container, using systemd-nspawn.

As it turned out, by default systemd-nspawn does not enable CAP_IPC_LOCK
capability by default. So eg mlock() system call fails with ENOPERM.
After adding this capability to the fileserver container, it started
working.

And now, HOW can we map this ENOPERM into WBC_ERR_DOMAIN_NOT_FOUND?
This is just insane.

Thanks,

/mjt

samba - Feb 2022 - making pam_winbind to work

[Samba] making pam_winbind to work

[Samba] making pam_winbind to work

[Samba] making pam_winbind to work