2

I configured my up-to-date Debian (v10.5) Server with samba, winbind, sssd, krb5 and nfs-common to authenticate against an AD in my domain and mount its /home via nfs4.

On the client side (windows with putty, ssh from linux) i have my private key in my ssh agent and attempt to log into the server. I only permit private key logins and disabled password logins.

Now when ssh to the server, the first time i get prompted for my password, i use my AD password and am in. Then i log out again. the second time i log in my private key is used and i am in.

why does this work? i want only ssh private key logins to work. If i understand nfsv4 correctly, sshd (and root) should not be able to read my home directory or my authorized keys, and i could understand if private key logins would fail. So in a way i am happy that they work - i just dont understand why.

And what can i do that only private key logins work, even the first time around?

here is the verbose sshd debug output of my second login attempt:

Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: oom_adjust_restore
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: Set /proc/self/oom_score_adj to 0
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: inetd sockets after dupping: 3, 3
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: Connection from 10.21.1.74 port 44732 on 195.37.235.121 port 22
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: Client protocol version 2.0; client software version OpenSSH_7.9p1 Debian-10+deb10u2
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: match: OpenSSH_7.9p1 Debian-10+deb10u2 pat OpenSSH* compat 0x04000000
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Debian-10+deb10u2
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: fd 3 setting O_NONBLOCK
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: Network child is on pid 12687
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: preauth child monitor started
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: privsep user:group 105:65534 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: permanently_set_uid: 105/65534 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: send packet: type 20 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: receive packet: type 20 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: SSH2_MSG_KEXINIT received [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: local server KEXINIT proposal [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: compression ctos: none,zlib@openssh.com [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: compression stoc: none,zlib@openssh.com [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: languages ctos:  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: languages stoc:  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: first_kex_follows 0  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: reserved 0  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: peer client KEXINIT proposal [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: compression ctos: none,zlib@openssh.com,zlib [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: compression stoc: none,zlib@openssh.com,zlib [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: languages ctos:  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: languages stoc:  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: first_kex_follows 0  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: reserved 0  [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: receive packet: type 30 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_sshkey_sign entering [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 6 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 6
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_answer_sign
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_answer_sign: hostkey proof signature 0x56470fc89c70(100)
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 7
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: monitor_read: 6 used once, disabling now
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 7 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: send packet: type 31 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: send packet: type 21 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug2: set_newkeys: mode 1 [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: rekey after 134217728 blocks [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Sep 24 11:44:26 jmp-ei-01 sshd[12686]: debug3: send packet: type 7 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: receive packet: type 21 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: set_newkeys: mode 0 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: rekey after 134217728 blocks [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: KEX done [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: receive packet: type 5 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: send packet: type 6 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: receive packet: type 50 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: userauth-request for user schuldeia service ssh-connection method none [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: attempt 0 failures 0 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_getpwnamallow entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 8 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 8
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_pwnamallow
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: parse_server_config: config reprocess config len 272
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 9
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: monitor_read: 8 used once, disabling now
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 9 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: input_userauth_request: setting up authctxt for schuldeia [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_start_pam entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 100 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 100
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: PAM: initializing for "schuldeia"
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: PAM: setting PAM_RHOST to "10.21.1.74"
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: PAM: setting PAM_TTY to "ssh"
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: monitor_read: 100 used once, disabling now
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_inform_authserv entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 4 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: input_userauth_request: try method none [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: ensure_minimum_time_since: elapsed 6.083ms, delaying 2.229ms (requested 8.313ms) [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 4
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_authserv: service=ssh-connection, style=, role=
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: monitor_read: 4 used once, disabling now
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: send packet: type 51 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: receive packet: type 50 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: userauth-request for user schuldeia service ssh-connection method publickey [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: attempt 1 failures 0 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: input_userauth_request: try method publickey [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_key_allowed entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 22 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 23 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 22
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyallowed entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyallowed: key_from_blob: 0x56470fc9e5f0
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: temporarily_use_uid: 50709/10004 (e=0/0)
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: trying public key file /home/schuldeia/.ssh/authorized_keys
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: fd 9 clearing O_NONBLOCK
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: /home/schuldeia/.ssh/authorized_keys:2: matching key found: RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: /home/schuldeia/.ssh/authorized_keys:2: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: Accepted key RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE found at /home/schuldeia/.ssh/authorized_keys:2
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: restore_uid: 0/0
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyallowed: publickey authentication test: RSA key is allowed
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 23
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: send packet: type 60 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-512 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: ensure_minimum_time_since: elapsed 3.132ms, delaying 5.181ms (requested 8.313ms) [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: Postponed publickey for schuldeia from 10.21.1.74 port 44732 ssh2 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: receive packet: type 50 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: userauth-request for user schuldeia service ssh-connection method publickey [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: attempt 2 failures 0 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: input_userauth_request: try method publickey [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: userauth_pubkey: have rsa-sha2-512 signature for RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_key_allowed entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 22 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 23 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 22
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyallowed entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyallowed: key_from_blob: 0x56470fca0f50
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: temporarily_use_uid: 50709/10004 (e=0/0)
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: trying public key file /home/schuldeia/.ssh/authorized_keys
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: fd 9 clearing O_NONBLOCK
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: /home/schuldeia/.ssh/authorized_keys:2: matching key found: RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: /home/schuldeia/.ssh/authorized_keys:2: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: Accepted key RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE found at /home/schuldeia/.ssh/authorized_keys:2
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: restore_uid: 0/0
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyallowed: publickey authentication: RSA key is allowed
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 23
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_sshkey_verify entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 24 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_sshkey_verify: waiting for MONITOR_ANS_KEYVERIFY [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 25 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 24
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_keyverify: publickey 0x56470fc9e5f0 signature verified
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: auth_activate_options: setting new authentication options
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 25
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 102
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: do_pam_account: called
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: do_pam_account: auth information in SSH_AUTH_INFO_0
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 103
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: Accepted publickey for schuldeia from 10.21.1.74 port 44732 ssh2: RSA SHA256:5sI4OvJOs6+7RcD76iomtR6geCSBoZ5397jeWzNlspE
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: monitor_child_preauth: schuldeia has been authenticated by privileged process
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_get_keystate: Waiting for new keys
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 26
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_get_keystate: GOT new keys
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: auth_activate_options: setting new authentication options [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: userauth_pubkey: authenticated 1 pkalg rsa-sha2-512 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: ensure_minimum_time_since: elapsed 1.791ms, delaying 6.522ms (requested 8.313ms) [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_do_pam_account entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 102 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive_expect entering: type 103 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_do_pam_account returning 1 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: send packet: type 52 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 26 [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_send_keystate: Finished sending state [preauth]
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: monitor_read_log: child log fd closed
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: ssh_sandbox_parent_finish: finished
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: PAM: establishing credentials
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: PAM: opening session
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: do_pam_session: auth information in SSH_AUTH_INFO_0
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: pam_unix(sshd:session): session opened for user schuldeia by (uid=0)
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: PAM: sshpam_store_conv called with 1 messages
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: PAM: sshpam_store_conv called with 1 messages
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: User child is on pid 12692
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_receive entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: monitor_read: checking request 28
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_pty entering
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug2: session_new: allocate (allocated 0 max 10)
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: session_unused: session id 0 unused
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: session_new: session 0
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug1: SELinux support disabled
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_request_send entering: type 29
Sep 24 11:44:27 jmp-ei-01 sshd[12686]: debug3: mm_answer_pty: tty /dev/pts/3 ptyfd 5
4

Let's first look at how NFS with sec=sys handles this, and then we'll see why NFS with sec=krb5* security fails. In this example, we'll have an SSH server and an NFS server running on two different computers.

The SSH daemon generally runs as root on the SSH server. Assuming your NFS server is configured to squash root, and your home directory is only readable by you, the SSH daemon running as root would not be allowed to read the public key stored in your home directory. When the SSH server needs to examine the public key, it spawns another process as the user you're trying to log in as, where that user then has permission to read the public key file. The user is then able to log in if they possess the correct private key.

This method works fine for NFS with sec=sys, as the computer tells the NFS server who is connecting, and the NFS server blindly trusts it.

Now we'll look at sec=krb5*. In this security model, the NFS server requires that the client present a ticket confirming their identity. Lets assume you haven't logged into the SSH server yet. Just as before, the root account is not able to read the SSH public key. But unlike before, spawning a process as the correct user does not help, as user does not possess an NFS service ticket or a TGT. This authentication method then fails and the SSH daemon tries to use another authentication method like password.

Now after authenticating with the password, you've picked up a Kerberos TGT, and possibly an NFS service ticket. After logging out, my guess is that the credential cache is still valid on the SSH server. When attempting to log back in again, this time after the SSH daemon spawns a process as the user, it is able to read the public key, as it still has valid credentials for that user.

Hope this helps!

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.