Proxmox 8 after reboot SSH password login does not work

W

wave

Member
Jun 21, 2022
9
0
6
This is a fresh Proxmox 8 install. I have installed and enabled UFW and added a rule to allow my IP.
After a reboot using password authentication fails, but then after a login with an SSH key then after logging in with a password works fine.

I notice it does say pam_env(sshd:session): deprecated reading of user environment enabled after it is working.
So I disabled as a test in /etc/pam.d/sshd by commenting it out but that does not change it:
Code: 
# In Debian 4.0 (etch), locale-related environment variables were moved to
# /etc/default/locale, so read that as well.
#session    required     pam_env.so user_readenv=1 envfile=/etc/default/locale

(I changed sensitive info in the below logs to MYIP, MYFINGERPRINT, and MYHOSTNAME)

This is from journalctl _COMM=sshd:
Code: 
-- Boot 44303c1c472346d985bda5c32b12c948 --
Aug 09 23:54:20 MYHOSTNAME sshd[1050]: Server listening on 0.0.0.0 port 22.
Aug 09 23:54:20 MYHOSTNAME sshd[1050]: Server listening on :: port 22.
Aug 09 23:55:06 MYHOSTNAME sshd[1547]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=MYIP  user=root
Aug 09 23:55:08 MYHOSTNAME sshd[1547]: Failed password for root from MYIP port 54440 ssh2
Aug 09 23:55:17 MYHOSTNAME sshd[1547]: Connection closed by authenticating user root MYIP port 54440 [preauth]
Aug 09 23:55:29 MYHOSTNAME sshd[1613]: Accepted publickey for root from MYIP port 54465 ssh2: MYFINGERPRINT
Aug 09 23:55:29 MYHOSTNAME sshd[1613]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
Aug 09 23:55:29 MYHOSTNAME sshd[1613]: pam_env(sshd:session): deprecated reading of user environment enabled
Aug 09 23:55:34 MYHOSTNAME sshd[1613]: Received disconnect from MYIP port 54465:11: disconnected by user
Aug 09 23:55:34 MYHOSTNAME sshd[1613]: Disconnected from user root MYIP port 54465
Aug 09 23:55:34 MYHOSTNAME sshd[1613]: pam_unix(sshd:session): session closed for user root
Aug 09 23:55:37 MYHOSTNAME sshd[1664]: Accepted password for root from MYIP port 54473 ssh2

From journalctl for context:
Code: 
Aug 09 23:54:26 MYHOSTNAME systemd[1]: Startup finished in 5.290s (kernel) + 12.583s (userspace) = 17.873s.
Aug 09 23:54:32 MYHOSTNAME kernel: kvm_intel: L1TF CPU bug present and SMT on, data leak possible. See CVE-2018-3646 and https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/l1tf.html for details.
Aug 09 23:54:34 MYHOSTNAME chronyd[884]: Selected source 103.144.177.88 (2.debian.pool.ntp.org)
Aug 09 23:54:34 MYHOSTNAME chronyd[884]: System clock TAI offset set to 37 seconds
Aug 09 23:54:46 MYHOSTNAME systemd[1]: systemd-fsckd.service: Deactivated successfully.
Aug 09 23:55:06 MYHOSTNAME sshd[1547]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=MYIP  user=root
Aug 09 23:55:08 MYHOSTNAME sshd[1547]: Failed password for root from MYIP port 54440 ssh2
Aug 09 23:55:17 MYHOSTNAME sshd[1547]: Connection closed by authenticating user root MYIP port 54440 [preauth]
Aug 09 23:55:29 MYHOSTNAME sshd[1613]: Accepted publickey for root from MYIP port 54465 ssh2: MYFINGERPRINT
Aug 09 23:55:29 MYHOSTNAME sshd[1613]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
Aug 09 23:55:29 MYHOSTNAME systemd-logind[927]: New session 1 of user root.
Aug 09 23:55:29 MYHOSTNAME systemd[1]: Created slice user-0.slice - User Slice of UID 0.
Aug 09 23:55:29 MYHOSTNAME systemd[1]: Starting user-runtime-dir@0.service - User Runtime Directory /run/user/0...
Aug 09 23:55:29 MYHOSTNAME systemd[1]: Finished user-runtime-dir@0.service - User Runtime Directory /run/user/0.
Aug 09 23:55:29 MYHOSTNAME systemd[1]: Starting user@0.service - User Manager for UID 0...
Aug 09 23:55:29 MYHOSTNAME (systemd)[1616]: pam_unix(systemd-user:session): session opened for user root(uid=0) by (uid=0)
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Queued start job for default target default.target.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Created slice app.slice - User Application Slice.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Reached target paths.target - Paths.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Reached target timers.target - Timers.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Starting dbus.socket - D-Bus User Message Bus Socket...
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Listening on dirmngr.socket - GnuPG network certificate management daemon.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers).
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted).
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation).
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Listening on dbus.socket - D-Bus User Message Bus Socket.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Reached target sockets.target - Sockets.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Reached target basic.target - Basic System.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Reached target default.target - Main User Target.
Aug 09 23:55:29 MYHOSTNAME systemd[1616]: Startup finished in 131ms.
Aug 09 23:55:29 MYHOSTNAME systemd[1]: Started user@0.service - User Manager for UID 0.
Aug 09 23:55:29 MYHOSTNAME systemd[1]: Started session-1.scope - Session 1 of User root.
Aug 09 23:55:29 MYHOSTNAME sshd[1613]: pam_env(sshd:session): deprecated reading of user environment enabled
Aug 09 23:55:34 MYHOSTNAME sshd[1613]: Received disconnect from MYIP port 54465:11: disconnected by user
Aug 09 23:55:34 MYHOSTNAME sshd[1613]: Disconnected from user root MYIP port 54465
Aug 09 23:55:34 MYHOSTNAME sshd[1613]: pam_unix(sshd:session): session closed for user root
Aug 09 23:55:34 MYHOSTNAME systemd[1]: session-1.scope: Deactivated successfully.
Aug 09 23:55:34 MYHOSTNAME systemd-logind[927]: Session 1 logged out. Waiting for processes to exit.
Aug 09 23:55:34 MYHOSTNAME systemd-logind[927]: Removed session 1.
Aug 09 23:55:37 MYHOSTNAME sshd[1664]: Accepted password for root from MYIP port 54473 ssh2
Aug 09 23:55:37 MYHOSTNAME sshd[1664]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
Aug 09 23:55:37 MYHOSTNAME systemd-logind[927]: New session 3 of user root.
Aug 09 23:55:37 MYHOSTNAME systemd[1]: Started session-3.scope - Session 3 of User root.
Aug 09 23:55:37 MYHOSTNAME sshd[1664]: pam_env(sshd:session): deprecated reading of user environment enabled
Aug 09 23:55:41 MYHOSTNAME sshd[1664]: Received disconnect from MYIP port 54473:11: disconnected by user
Aug 09 23:55:41 MYHOSTNAME sshd[1664]: Disconnected from user root MYIP port 54473
Aug 09 23:55:41 MYHOSTNAME sshd[1664]: pam_unix(sshd:session): session closed for user root
Aug 09 23:55:41 MYHOSTNAME systemd[1]: session-3.scope: Deactivated successfully.
Aug 09 23:55:41 MYHOSTNAME systemd-logind[927]: Session 3 logged out. Waiting for processes to exit.
Aug 09 23:55:41 MYHOSTNAME systemd-logind[927]: Removed session 3.

This might be a bug in debian or in proxmox. It possibly is related to systemd and what systemd sets up, or PAM.
I will continue to look into this and post a fix here if I find one.
 
I made a test user to try to replicate the issue. The user is able to login fine with SSH using the password, but root is not able to until I login with the ssh key.

Command used to create the test user:
Bash: 
adduser --no-create-home --gecos '' sshtestdummy

Log after reboot of test user logging in successfully over ssh using the password:
Code: 
Aug 10 02:06:06 MYHOSTNAME systemd[1]: Startup finished in 5.588s (kernel) + 12.467s (userspace) = 18.055s.
Aug 10 02:06:12 MYHOSTNAME kernel: kvm_intel: L1TF CPU bug present and SMT on, data leak possible. See CVE-2018-3646 and https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/l1tf.html for details.
Aug 10 02:06:14 MYHOSTNAME chronyd[882]: Selected source 66.49.222.68 (2.debian.pool.ntp.org)
Aug 10 02:06:14 MYHOSTNAME chronyd[882]: System clock TAI offset set to 37 seconds
Aug 10 02:06:26 MYHOSTNAME systemd[1]: systemd-fsckd.service: Deactivated successfully.
Aug 10 02:06:40 MYHOSTNAME sshd[1522]: Accepted password for sshtestdummy from MYIP port 59575 ssh2
Aug 10 02:06:40 MYHOSTNAME sshd[1522]: pam_unix(sshd:session): session opened for user sshtestdummy(uid=1000) by (uid=0)
Aug 10 02:06:40 MYHOSTNAME systemd-logind[926]: New session 1 of user sshtestdummy.
Aug 10 02:06:40 MYHOSTNAME systemd[1]: Created slice user-1000.slice - User Slice of UID 1000.
Aug 10 02:06:40 MYHOSTNAME systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...
Aug 10 02:06:40 MYHOSTNAME systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000.
Aug 10 02:06:40 MYHOSTNAME systemd[1]: Starting user@1000.service - User Manager for UID 1000...
Aug 10 02:06:40 MYHOSTNAME (systemd)[1525]: pam_unix(systemd-user:session): session opened for user sshtestdummy(uid=1000) by (uid=0)
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Queued start job for default target default.target.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Created slice app.slice - User Application Slice.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Reached target paths.target - Paths.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Reached target timers.target - Timers.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Starting dbus.socket - D-Bus User Message Bus Socket...
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Listening on dirmngr.socket - GnuPG network certificate management daemon.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers).
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted).
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation).
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Listening on dbus.socket - D-Bus User Message Bus Socket.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Reached target sockets.target - Sockets.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Reached target basic.target - Basic System.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Reached target default.target - Main User Target.
Aug 10 02:06:40 MYHOSTNAME systemd[1525]: Startup finished in 143ms.
Aug 10 02:06:40 MYHOSTNAME systemd[1]: Started user@1000.service - User Manager for UID 1000.
Aug 10 02:06:40 MYHOSTNAME systemd[1]: Started session-1.scope - Session 1 of User sshtestdummy.
Aug 10 02:06:40 MYHOSTNAME sshd[1522]: pam_env(sshd:session): deprecated reading of user environment enabled
Aug 10 02:07:02 MYHOSTNAME sshd[1585]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=MYIP  user=root
Aug 10 02:07:04 MYHOSTNAME sshd[1585]: Failed password for root from MYIP port 59580 ssh2
Aug 10 02:07:38 MYHOSTNAME sshd[1585]: Connection closed by authenticating user root MYIP port 59580 [preauth]
Aug 10 02:07:41 MYHOSTNAME sshd[1733]: Accepted publickey for root from MYIP port 59626 ssh2: MYFINGERPRINT
Aug 10 02:07:41 MYHOSTNAME sshd[1733]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
Aug 10 02:07:41 MYHOSTNAME systemd-logind[926]: New session 3 of user root.
Aug 10 02:07:41 MYHOSTNAME systemd[1]: Created slice user-0.slice - User Slice of UID 0.
Aug 10 02:07:41 MYHOSTNAME systemd[1]: Starting user-runtime-dir@0.service - User Runtime Directory /run/user/0...
Aug 10 02:07:41 MYHOSTNAME systemd[1]: Finished user-runtime-dir@0.service - User Runtime Directory /run/user/0.
Aug 10 02:07:41 MYHOSTNAME systemd[1]: Starting user@0.service - User Manager for UID 0...
Aug 10 02:07:41 MYHOSTNAME (systemd)[1736]: pam_unix(systemd-user:session): session opened for user root(uid=0) by (uid=0)
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Queued start job for default target default.target.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Created slice app.slice - User Application Slice.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Reached target paths.target - Paths.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Reached target timers.target - Timers.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Starting dbus.socket - D-Bus User Message Bus Socket...
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Listening on dirmngr.socket - GnuPG network certificate management daemon.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers).
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted).
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation).
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Listening on dbus.socket - D-Bus User Message Bus Socket.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Reached target sockets.target - Sockets.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Reached target basic.target - Basic System.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Reached target default.target - Main User Target.
Aug 10 02:07:41 MYHOSTNAME systemd[1736]: Startup finished in 124ms.
Aug 10 02:07:41 MYHOSTNAME systemd[1]: Started user@0.service - User Manager for UID 0.
Aug 10 02:07:41 MYHOSTNAME systemd[1]: Started session-3.scope - Session 3 of User root.
Aug 10 02:07:41 MYHOSTNAME sshd[1733]: pam_env(sshd:session): deprecated reading of user environment enabled

uname -a:
Code: 
Linux MYHOSTNAME 6.8.12-1-pve #1 SMP PREEMPT_DYNAMIC PMX 6.8.12-1 (2024-08-05T16:17Z) x86_64 GNU/Linux

Adding debug to /etc/pam.d/common-auth didn't seem to output anything more in journalctl.
 
Logging into the web environment and also accessing the shell does not make it possible to login as root over ssh with a password in the way that logging in as root over ssh with a key file does.

Using the "Shell" in the web environment to attach strace to the sshd process with strace -o sshd_pam_trace.log -ff -p 1042
1. First to capture trying to login with a password and it failing,
2. then Ctrl-C on strace and logging in with a key,
3. then attaching strace a second time to capture a successful login as root over ssh

And comparing the logs is not immediately obvious where it is failing.

It easily could be something in the strace logs that I do not recognize, or it could be something outside of sshd itself, and the pam .so files that sshd uses.
 
It's not the ssh.socket issue mentioned about earlier versions of Proxmox.

Code: 
# systemctl status ssh.socket
○ ssh.socket - OpenBSD Secure Shell server socket
     Loaded: loaded (/lib/systemd/system/ssh.socket; disabled; preset: enabled)
     Active: inactive (dead)
   Triggers: ● ssh.service
     Listen: [::]:22 (Stream)

Code: 
# systemctl status ssh.service
● ssh.service - OpenBSD Secure Shell server
     Loaded: loaded (/lib/systemd/system/ssh.service; enabled; preset: enabled)
     Active: active (running) since Sat 2024-08-10 03:37:01 UTC; 27s ago
       Docs: man:sshd(8)
             man:sshd_config(5)
    Process: 921 ExecStartPre=/usr/sbin/sshd -t (code=exited, status=0/SUCCESS)
   Main PID: 1042 (sshd)
      Tasks: 1 (limit: 38055)
     Memory: 2.1M
        CPU: 24ms
     CGroup: /system.slice/ssh.service
             └─1042 "sshd: /usr/sbin/sshd -D [listener] 0 of 10-100 startups"

Also systemctl restart ssh.service doesn't replicate / re-trigger the issue, so far the only way I've found is a reboot.

To connect using password auth I use: ssh -o PubkeyAuthentication=no root@MYIP
 
Changing limit to allow in ufw had no effect.

I tried passwd from the Proxmox web interface shell and immediately was able to login with the new password.

After a reboot, logins now work immediately with the password.

I will point out that in /etc/shadow the salt previously was $6$ indicating SHA-512, but now it is $y$ indicating yescrypt.

If I change the /etc/shadow line for root back to the previous line set, password login is unable to work once more.
But if I restore the file with the $y$ yescrypt then it immediately allows me to login with the password.

So some part/aspect of the system is not quite friendly with the old SHA-512 style of passwords and the system appears to set up a SHA-512 style password during the install.
 
Creating two new test users one with an explicitly set SHA-512 password and one with a yescrypt password,

using openssl passwd -6 to generate the hash
and then creating a user with it with useradd --no-create-home -p '$6$zMwd2m5p$RquA6FGpPqZGA3Up1J/u.EyU7WJWhqVn9dh0lLLZb4WeYJD5LU/OeX8ypq4UHOIQNzN6oFv9PmT1zlsb3.y5n/' -c '' testssh2
and creating another user with
adduser --no-create-home --gecos '' testssh3

Both users were able to login with the password right away before and after a reboot.

I verified in /etc/shadow that testssh2 has a $6$ salt and testssh3 has a $y$ salt.

So it seems to be specific to the root user.
 
Minor datapoint, I was unable to replicate the issue on a fresh install of Debian 12 with default settings, though in Debian 12 I did have to put PermitRootLogin yes in sshd_config
 
Turns out the source of the $6$ that I had was from my server vendor setting that. I do not believe the install sets that.

The bug is still present if someone goes out of their way to set a SHA-512 salted password hash though. Also if they still have one after an upgrade.

Further steps are to replicate this in a controlled vanilla install of Proxmox 8.
 
Hello,
when setting a password through the web interface it actually uses sha512 in /etc/shadow but this does not appear to be the problem: after reboot with all password yescrypt hashed no user can login. After I use passwd to change the password of one user all users can ssh with their passwd.
Tobias
 
You must log in or register to reply here.
Top Bottom