[Samba] account locks not working ssh/winbind?

Thu Apr 26 07:53:33 UTC 2018

Hai. 

Config. 
Debian Stretch, samba 4.7.7. member server AD backend. 
Network setup like in the howtos here. : https://github.com/thctlo/samba4/tree/master/howtos  

Today i discovered that somehow a disabled user was able to login after a few retries. 

I run a SSH/SFTP server for data exchange with the customer of the company here.

The SSH/SFTP server is restricted by groups, this includes a windows (AD) group and linux groups, with an GID assigned. 
Other important settings are these these from sshd_config

UsePAM yes  
ChallengeResponseAuthentication no
GSSAPIAuthentication yes
GSSAPICleanupCredentials yes
GSSAPIStrictAcceptorCheck yes
GSSAPIKeyExchange yes
GSSAPIStoreCredentialsOnRekey yes

/etc/pam.d had the following.  ( all settings are done with pam-auth-update ) 
samba
@include common-auth
@include common-account
@include common-session-noninteractive

common-auth
auth    [success=5 default=ignore]      pam_krb5.so minimum_uid=1000
auth    [success=4 default=ignore]      pam_unix.so nullok_secure try_first_pass
auth    [success=3 default=ignore]      pam_winbind.so krb5_auth krb5_ccache_type=FILE cached_login try_first_pass
auth    [success=2 default=ignore]      pam_ccreds.so minimum_uid=1000 action=validate use_first_pass
auth    [default=ignore]                pam_ccreds.so minimum_uid=1000 action=update
auth    requisite                       pam_deny.so
auth    required                        pam_permit.so
auth    optional                        pam_ccreds.so minimum_uid=1000 action=store
auth    optional                        pam_cap.so

common-account
account [success=2 new_authtok_reqd=done default=ignore]        pam_unix.so
account [success=1 new_authtok_reqd=done default=ignore]        pam_winbind.so
account requisite                       pam_deny.so
account required                        pam_permit.so
account required                        pam_krb5.so minimum_uid=1000

common-session-noninteractive
session [default=1]                     pam_permit.so
session requisite                       pam_deny.so
session required                        pam_permit.so
session optional                        pam_krb5.so minimum_uid=1000
session required                        pam_unix.so
session optional                        pam_winbind.so

common-password
password        [success=3 default=ignore]      pam_krb5.so minimum_uid=1000
password        [success=2 default=ignore]      pam_unix.so obscure use_authtok try_first_pass sha512
password        [success=1 default=ignore]      pam_winbind.so use_authtok try_first_pass
password        requisite                       pam_deny.so
password        required                        pam_permit.so

On Begin feb 2018, i disabled an account in the AD. Just checked again and yes its still set to "Account disabled"  
Today i noticed the following.  

From my SFTP server log.  and this should not be possible. 
2018-04-25 07:00:05 [27504][username][1.2.3.4][10500]Start download file '/folder1/file1.csv'
2018-04-25 07:00:05 [27504][username][1.2.3.4][10500]End download file '/folder1/file1.csv' (82 bytes) : 100%
2018-04-25 07:00:05 [27504][username][1.2.3.4][10500]Start download file '/folder1/file1.csv'
2018-04-25 07:00:06 [27504][username][1.2.3.4][10500]End download file '/folder1/file1.csv' (82 bytes) : 100%
2018-04-25 07:00:06 [27504][username][1.2.3.4][10500]Try to remove file '/folder1/file1.csv' : success

Now the strange thing is the follow from my auth logs. 
Apr 25 07:00:02 hostname1 sshd[27413]: reverse mapping checking getaddrinfo for unknown.domain.tld [1.2.3.4] failed.
Apr 25 07:00:02 hostname1 sshd[27413]: pam_krb5(sshd:auth): authentication failure; logname=username uid=0 euid=0 tty=ssh ruser= rhost=1.2.3.4
Apr 25 07:00:02 hostname1 sshd[27413]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=1.2.3.4  user=username
Apr 25 07:00:02 hostname1 sshd[27413]: pam_winbind(sshd:auth): getting password (0x00000388)
Apr 25 07:00:02 hostname1 sshd[27413]: pam_winbind(sshd:auth): pam_get_item returned a password
Apr 25 07:00:02 hostname1 sshd[27413]: pam_winbind(sshd:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_MAXTRIES (11), NTSTATUS: NT_STATUS_ACCOUNT_LOCKED_OUT, Error message was: The user account has been automatically locked because too many invalid logon attempts or password change attempts have been requested.
Apr 25 07:00:02 hostname1 sshd[27413]: pam_winbind(sshd:auth): internal module error (retval = PAM_MAXTRIES(11), user = 'username')
Apr 25 07:00:02 hostname1 sshd[27413]: Accepted password for username from 1.2.3.4 port 10400 ssh2
Apr 25 07:00:02 hostname1 sshd[27413]: pam_unix(sshd:session): session opened for user username by (uid=0)
Apr 25 07:00:02 hostname1 systemd-logind[25400]: New session 4871 of user username.
Apr 25 07:00:02 hostname1 systemd: pam_unix(systemd-user:session): session opened for user username by (uid=0)
Apr 25 07:00:02 hostname1 CRON[27410]: pam_unix(cron:session): session closed for user nobody
Apr 25 07:00:03 hostname1 sshd[27413]: pam_unix(sshd:session): session closed for user username
Apr 25 07:00:03 hostname1 sshd[27413]: pam_winbind(sshd:setcred): user 'username' OK
Apr 25 07:00:03 hostname1 systemd-logind[25400]: Removed session 4871.
Apr 25 07:00:04 hostname1 sshd[27490]: reverse mapping checking getaddrinfo for unknown.domain.tld [1.2.3.4] failed.
Apr 25 07:00:04 hostname1 sshd[27490]: pam_krb5(sshd:auth): authentication failure; logname=username uid=0 euid=0 tty=ssh ruser= rhost=1.2.3.4
Apr 25 07:00:04 hostname1 sshd[27490]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=1.2.3.4  user=username
Apr 25 07:00:04 hostname1 sshd[27490]: pam_winbind(sshd:auth): getting password (0x00000388)
Apr 25 07:00:04 hostname1 sshd[27490]: pam_winbind(sshd:auth): pam_get_item returned a password
Apr 25 07:00:04 hostname1 sshd[27490]: pam_winbind(sshd:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_MAXTRIES (11), NTSTATUS: NT_STATUS_ACCOUNT_LOCKED_OUT, Error message was: The user account has been automatically locked because too many invalid logon attempts or password change attempts have been requested.
Apr 25 07:00:04 hostname1 sshd[27490]: pam_winbind(sshd:auth): internal module error (retval = PAM_MAXTRIES(11), user = 'username')
Apr 25 07:00:04 hostname1 sshd[27490]: Accepted password for username from 1.2.3.4 port 10500 ssh2
Apr 25 07:00:04 hostname1 sshd[27490]: pam_unix(sshd:session): session opened for user username by (uid=0)
Apr 25 07:00:04 hostname1 systemd-logind[25400]: New session 4873 of user username.
Apr 25 07:00:04 hostname1 systemd: pam_unix(systemd-user:session): session opened for user username by (uid=0)
Apr 25 07:00:07 hostname1 sshd[27490]: pam_unix(sshd:session): session closed for user username
Apr 25 07:00:07 hostname1 sshd[27490]: pam_winbind(sshd:setcred): user 'username' OK
Apr 25 07:00:07 hostname1 systemd-logind[25400]: Removed session 4873.
Apr 25 07:00:07 hostname1 systemd: pam_unix(systemd-user:session): session closed for user username
Apr 25 07:00:10 hostname1 sshd[27625]: reverse mapping checking getaddrinfo for unknown.domain.tld [1.2.3.4] failed.
Apr 25 07:00:10 hostname1 sshd[27625]: pam_krb5(sshd:auth): authentication failure; logname=username uid=0 euid=0 tty=ssh ruser= rhost=1.2.3.4
Apr 25 07:00:10 hostname1 sshd[27625]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=1.2.3.4  user=username
Apr 25 07:00:10 hostname1 sshd[27625]: pam_winbind(sshd:auth): getting password (0x00000388)
Apr 25 07:00:10 hostname1 sshd[27625]: pam_winbind(sshd:auth): pam_get_item returned a password
Apr 25 07:00:10 hostname1 sshd[27625]: pam_winbind(sshd:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_MAXTRIES (11), NTSTATUS: NT_STATUS_ACCOUNT_LOCKED_OUT, Error message was: The user account has been automatically locked because too many invalid logon attempts or password change attempts have been requested.
Apr 25 07:00:10 hostname1 sshd[27625]: pam_winbind(sshd:auth): internal module error (retval = PAM_MAXTRIES(11), user = 'username')
Apr 25 07:00:10 hostname1 sshd[27625]: Accepted password for username from 1.2.3.4 port 10600 ssh2
Apr 25 07:00:10 hostname1 sshd[27625]: pam_unix(sshd:session): session opened for user username by (uid=0)
Apr 25 07:00:10 hostname1 systemd-logind[25400]: New session 4875 of user username.
Apr 25 07:00:10 hostname1 systemd: pam_unix(systemd-user:session): session opened for user username by (uid=0)
Apr 25 07:00:10 hostname1 sshd[27625]: pam_unix(sshd:session): session closed for user username
Apr 25 07:00:10 hostname1 sshd[27625]: pam_winbind(sshd:setcred): user 'username' OK
Apr 25 07:00:10 hostname1 systemd-logind[25400]: Removed session 4875.
Apr 25 07:00:10 hostname1 systemd: pam_unix(systemd-user:session): session closed for user username

I suspect that : Ccreds credential caching - password saving part in pam is the cause or did i misconfigure something here, can happen, nobody is perfect..  :-( 
I cannot disabled ccreds right now, i use the caching also for my logins from lan. 

So if anyone has ideas please tell me. 

Greetz, 

Louis