Key exchange issue on Debian 12 (Bookworm)

[dcivera]

Following up on this issue: php/pecl-networking-ssh2#74

Describe the bug
Libssh2 seems to have issues with handling or exchanging keys. Certain types of keys that should be accepted aren't, while those that are shown as accepted still trigger a disconnection. I'm trying to use SSH2 to install and update WordPress but it keeps saying that there's a problem with the keys.

To Reproduce
Relying on the PECL/SSH2 wrapper, I used this application created by the author of the issue listed above

$user 			= 'root';
$host 			= 'remote-server.com';
$private_key 	= '/root/.ssh/id_rsa';
$public_key 	= '/root/.ssh/id_rsa.pub';

if(!is_readable($private_key) || !is_readable($public_key)){
	echo "RSA keys not found\n";
}

echo 'private key: '.file_get_contents($private_key)."\n";
echo 'public key: '.file_get_contents($public_key)."\n";
echo "host: $host\n";
echo "user: $user\n";

if(!$session = ssh2_connect($host)){
	echo "Could not connect to '$host'\n";
}

if(!ssh2_auth_pubkey_file($session, $user, $public_key, $private_key)){
	echo "Could not authenticate to '$host'\n";
}

To generate keys, I use ssh-keygen -m PEM -t $type

When using type rsa-sha2-512 rsa-sha2-256, or rsa-sha, sshd logs report the error userauth_pubkey: signature algorithm ssh-rsa not in PubkeyAcceptedAlgorithms [preauth]

When using type ecdsa-sha2-nistp256 or ssh-ed25519, the keys seem to be accepted at first, but then something goes wrong, and I get a disconnection.

In all cases, WordPress reports Installation failed: Public and Private keys incorrect for username when trying to install a plugin and under Site Health I get Unable to connect to the filesystem. Please confirm your credentials.

Expected behavior
A clear and concise description of what you expected to happen.

Version (please complete the following information):

• OS and version: Debian 12.5 (Bookworm)
• libssh2 version: 1.10.0-3+b1 (Debian Package https://packages.debian.org/bookworm/libssh2-1)
• crypto backend and version: [OpenSSH_9.2p1 Debian-2+deb12u2, OpenSSL 3.0.11 19 Sep 2023]
• PHP 8.2.18
• WordPress 6.5.3

Additional context
Here's sshd's logs when using an accepted key-pair. Notice that despite the keyexchange technically accepted, ssh2 sends a disconnect (Received disconnect) and I get an error saying the keys don't work, seemingly indicating an issue with the exchange within libssh2.

May 21 12:38:15 hostname sshd[3808]: Connection from remoteserverIP port 60804 on 172.26.7.64 port 09876 rdomain ""
May 21 12:38:15 hostname sshd[3808]: debug1: Local version string SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u2
May 21 12:38:15 hostname sshd[3808]: debug1: Remote protocol version 2.0, remote software version libssh2_1.10.0 PHP
May 21 12:38:15 hostname sshd[3808]: debug1: compat_banner: no match: libssh2_1.10.0 PHP
May 21 12:38:15 hostname sshd[3808]: debug1: permanently_set_uid: 103/65534 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: SSH2_MSG_KEXINIT sent [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: SSH2_MSG_KEXINIT received [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: kex: algorithm: curve25519-sha256 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: rekey out after 4294967296 blocks [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: SSH2_MSG_NEWKEYS received [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: rekey in after 4294967296 blocks [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: KEX done [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: userauth-request for user username service ssh-connection method publickey [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: attempt 0 failures 0 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: PAM: initializing for "username"
May 21 12:38:15 hostname sshd[3808]: debug1: PAM: setting PAM_RHOST to "remoteserverIP"
May 21 12:38:15 hostname sshd[3808]: debug1: PAM: setting PAM_TTY to "ssh"
May 21 12:38:15 hostname sshd[3808]: debug1: userauth_pubkey: publickey test pkalg ssh-ed25519 pkblob ED25519 SHA256:RW9nn7v0hzO51UWj2WaSwtY0Z+/xJC/HuEGb53MuqE8 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
May 21 12:38:15 hostname sshd[3808]: debug1: trying public key file /home/username/.ssh/authorized_keys
May 21 12:38:15 hostname sshd[3808]: debug1: fd 5 clearing O_NONBLOCK
May 21 12:38:15 hostname sshd[3808]: debug1: /home/username/.ssh/authorized_keys:3: matching key found: ED25519 SHA256:RW9nn7v0hzO51UWj2WaSwtY0Z+/xJC/HuEGb53MuqE8
May 21 12:38:15 hostname sshd[3808]: debug1: /home/username/.ssh/authorized_keys:3: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
May 21 12:38:15 hostname sshd[3808]: Accepted key ED25519 SHA256:RW9nn7v0hzO51UWj2WaSwtY0Z+/xJC/HuEGb53MuqE8 found at /home/username/.ssh/authorized_keys:3
May 21 12:38:15 hostname sshd[3808]: debug1: restore_uid: 0/0
May 21 12:38:15 hostname sshd[3808]: Postponed publickey for username from remoteserverIP port 60804 ssh2 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: userauth-request for user username service ssh-connection method publickey [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: attempt 1 failures 0 [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
May 21 12:38:15 hostname sshd[3808]: debug1: trying public key file /home/username/.ssh/authorized_keys
May 21 12:38:15 hostname sshd[3808]: debug1: fd 5 clearing O_NONBLOCK
May 21 12:38:15 hostname sshd[3808]: debug1: /home/username/.ssh/authorized_keys:3: matching key found: ED25519 SHA256:RW9nn7v0hzO51UWj2WaSwtY0Z+/xJC/HuEGb53MuqE8
May 21 12:38:15 hostname sshd[3808]: debug1: /home/username/.ssh/authorized_keys:3: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
May 21 12:38:15 hostname sshd[3808]: Accepted key ED25519 SHA256:RW9nn7v0hzO51UWj2WaSwtY0Z+/xJC/HuEGb53MuqE8 found at /home/username/.ssh/authorized_keys:3
May 21 12:38:15 hostname sshd[3808]: debug1: restore_uid: 0/0
May 21 12:38:15 hostname sshd[3808]: debug1: auth_activate_options: setting new authentication options
May 21 12:38:15 hostname sshd[3808]: debug1: do_pam_account: called
May 21 12:38:15 hostname sshd[3808]: Accepted publickey for username from remoteserverIP port 60804 ssh2: ED25519 SHA256:RW9nn7v0hzO51UWj2WaSwtY0Z+/xJC/HuEGb53MuqE8
May 21 12:38:15 hostname sshd[3808]: debug1: monitor_child_preauth: user username authenticated by privileged process
May 21 12:38:15 hostname sshd[3808]: debug1: auth_activate_options: setting new authentication options [preauth]
May 21 12:38:15 hostname sshd[3808]: debug1: monitor_read_log: child log fd closed
May 21 12:38:15 hostname sshd[3808]: debug1: PAM: establishing credentials
May 21 12:38:15 hostname sshd[3808]: pam_unix(sshd:session): session opened for user username(uid=1000) by (uid=0)
May 21 12:38:15 hostname systemd-logind[502]: New session 26 of user username.
May 21 12:38:15 hostname systemd[1]: Created slice user-1000.slice - User Slice of UID 1000.
May 21 12:38:15 hostname systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...
May 21 12:38:16 hostname systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000.
May 21 12:38:16 hostname systemd[1]: Starting user@1000.service - User Manager for UID 1000...
May 21 12:38:16 hostname (systemd)[3811]: pam_unix(systemd-user:session): session opened for user username(uid=1000) by (uid=0)
May 21 12:38:16 hostname systemd[3811]: Queued start job for default target default.target.
May 21 12:38:16 hostname systemd[3811]: Created slice app.slice - User Application Slice.
May 21 12:38:16 hostname systemd[3811]: Reached target paths.target - Paths.
May 21 12:38:16 hostname systemd[3811]: Reached target timers.target - Timers.
May 21 12:38:16 hostname systemd[3811]: Listening on dirmngr.socket - GnuPG network certificate management daemon.
May 21 12:38:16 hostname systemd[3811]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 21 12:38:16 hostname systemd[3811]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted).
May 21 12:38:16 hostname systemd[3811]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation).
May 21 12:38:16 hostname systemd[3811]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache.
May 21 12:38:16 hostname systemd[3811]: Reached target sockets.target - Sockets.
May 21 12:38:16 hostname systemd[3811]: Reached target basic.target - Basic System.
May 21 12:38:16 hostname systemd[3811]: Reached target default.target - Main User Target.
May 21 12:38:16 hostname systemd[3811]: Startup finished in 73ms.
May 21 12:38:16 hostname systemd[1]: Started user@1000.service - User Manager for UID 1000.
May 21 12:38:16 hostname systemd[1]: Started session-26.scope - Session 26 of User username.
May 21 12:38:16 hostname sshd[3808]: pam_env(sshd:session): deprecated reading of user environment enabled
May 21 12:38:16 hostname sshd[3808]: User child is on pid 3832
May 21 12:38:16 hostname sshd[3832]: debug1: SELinux support disabled
May 21 12:38:16 hostname sshd[3832]: debug1: PAM: establishing credentials
May 21 12:38:16 hostname sshd[3832]: debug1: permanently_set_uid: 1000/1000
May 21 12:38:16 hostname sshd[3832]: debug1: rekey in after 4294967296 blocks
May 21 12:38:16 hostname sshd[3832]: debug1: rekey out after 4294967296 blocks
May 21 12:38:16 hostname sshd[3832]: debug1: ssh_packet_set_postauth: called
May 21 12:38:16 hostname sshd[3832]: debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
May 21 12:38:16 hostname sshd[3832]: debug1: Entering interactive session for SSH2.
May 21 12:38:16 hostname sshd[3832]: debug1: server_init_dispatch
May 21 12:38:16 hostname sshd[3832]: Received disconnect from remoteserverIP port 60804:11: PECL/ssh2 (http://pecl.php.net/packages/ssh2)
May 21 12:38:16 hostname sshd[3832]: Disconnected from user username remoteserverIP port 60804
May 21 12:38:16 hostname sshd[3832]: debug1: do_cleanup
May 21 12:38:16 hostname sshd[3832]: debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
May 21 12:38:16 hostname sshd[3832]: debug1: restore_uid: (unprivileged)
May 21 12:38:16 hostname sshd[3808]: debug1: do_cleanup
May 21 12:38:16 hostname sshd[3808]: debug1: PAM: cleanup
May 21 12:38:16 hostname sshd[3808]: debug1: PAM: closing session
May 21 12:38:16 hostname sshd[3808]: pam_unix(sshd:session): session closed for user username
May 21 12:38:16 hostname sshd[3808]: debug1: PAM: deleting credentials
May 21 12:38:16 hostname sshd[3808]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
May 21 12:38:16 hostname sshd[3808]: debug1: restore_uid: 0/0
May 21 12:38:16 hostname sshd[3808]: debug1: audit_event: unhandled event 12
May 21 12:38:16 hostname systemd[1]: session-26.scope: Deactivated successfully.
May 21 12:38:16 hostname systemd-logind[502]: Session 26 logged out. Waiting for processes to exit.
May 21 12:38:16 hostname systemd-logind[502]: Removed session 26.
May 21 12:38:26 hostname systemd[1]: Stopping user@1000.service - User Manager for UID 1000...

[willco007]

This is doing a bunch of PAM auth which is where it's failing. Looks like a configuration issue.

[dcivera]

Thank you @willco007. I truly appreciate you looking into it.

I've been playing with sshd_config, but I'm still getting the same error message. I've even disabled PAM in sshd, but I'm still getting the same error message.

Any idea what logs I can check or what config file I can play with?

What I see is that all is going well, then it creates a child process, enters into an interactive session for SSH2 and boom, I get disconnected.

May 21 18:52:30 hostname sshd[4941]: User child is on pid 4943
May 21 18:52:30 hostname sshd[4943]: debug1: SELinux support disabled
May 21 18:52:30 hostname sshd[4943]: debug1: permanently_set_uid: 1000/1000
May 21 18:52:30 hostname sshd[4943]: debug1: rekey in after 4294967296 blocks
May 21 18:52:30 hostname sshd[4943]: debug1: rekey out after 4294967296 blocks
May 21 18:52:30 hostname sshd[4943]: debug1: ssh_packet_set_postauth: called
May 21 18:52:30 hostname sshd[4943]: debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
May 21 18:52:30 hostname sshd[4943]: debug1: Entering interactive session for SSH2.
May 21 18:52:30 hostname sshd[4943]: debug1: server_init_dispatch
May 21 18:52:30 hostname sshd[4943]: Received disconnect from remoteserverIP port 38814:11: PECL/ssh2 (http://pecl.php.net/packages/ssh2)

Here's my sshd_config

# This is the sshd server system-wide configuration file.  See
# sshd_config(5) for more information.

# This sshd was compiled with PATH=/usr/local/bin:/usr/bin:/bin:/usr/games

# The strategy used for options in the default sshd_config shipped with
# OpenSSH is to specify options with their default value where
# possible, but leave them commented.  Uncommented options override the
# default value.

Include /etc/ssh/sshd_config.d/*.conf

Port 12345
#AddressFamily any
#ListenAddress 0.0.0.0
#ListenAddress ::

#HostKey /etc/ssh/ssh_host_rsa_key
#HostKey /etc/ssh/ssh_host_ecdsa_key
#HostKey /etc/ssh/ssh_host_ed25519_key

# Ciphers and keying
#RekeyLimit default none

# Logging
#SyslogFacility AUTH
LogLevel DEBUG

# Authentication:

#LoginGraceTime 2m
PermitRootLogin no
AllowUsers username
#StrictModes yes
#MaxAuthTries 6
#MaxSessions 10

PubkeyAuthentication yes

# Expect .ssh/authorized_keys2 to be disregarded by default in future.
#AuthorizedKeysFile     .ssh/authorized_keys .ssh/authorized_keys2

#AuthorizedPrincipalsFile none

#AuthorizedKeysCommand none
#AuthorizedKeysCommandUser nobody

# For this to work you will also need host keys in /etc/ssh/ssh_known_hosts
HostbasedAuthentication no
# Change to yes if you don't trust ~/.ssh/known_hosts for
# HostbasedAuthentication
#IgnoreUserKnownHosts no
# Don't read the user's ~/.rhosts and ~/.shosts files
#IgnoreRhosts yes

# To disable tunneled clear text passwords, change to no here!
PasswordAuthentication no
PermitEmptyPasswords no

# Change to yes to enable challenge-response passwords (beware issues with
# some PAM modules and threads)
KbdInteractiveAuthentication no

# Kerberos options
#KerberosAuthentication no
#KerberosOrLocalPasswd yes
#KerberosTicketCleanup yes
#KerberosGetAFSToken no

# GSSAPI options
#GSSAPIAuthentication no
#GSSAPICleanupCredentials yes
#GSSAPIStrictAcceptorCheck yes
#GSSAPIKeyExchange no

# Set this to 'yes' to enable PAM authentication, account processing,
# and session processing. If this is enabled, PAM authentication will
# be allowed through the KbdInteractiveAuthentication and
# PasswordAuthentication.  Depending on your PAM configuration,
# PAM authentication via KbdInteractiveAuthentication may bypass
# the setting of "PermitRootLogin prohibit-password".
# If you just want the PAM account and session checks to run without
# PAM authentication, then enable this but set PasswordAuthentication
# and KbdInteractiveAuthentication to 'no'.
UsePAM no

AllowAgentForwarding yes
AllowTcpForwarding yes
#GatewayPorts no
X11Forwarding yes
#X11DisplayOffset 10
X11UseLocalhost yes
PermitTTY yes
PrintMotd yes
PrintLastLog yes
#TCPKeepAlive yes
PermitUserEnvironment yes
#Compression delayed
ClientAliveInterval 100
ClientAliveCountMax 3
#UseDNS no
#PidFile /run/sshd.pid
#MaxStartups 10:30:100
PermitTunnel yes
#ChrootDirectory none
#VersionAddendum none

# no default banner path
#Banner none

# Allow client to pass locale environment variables
AcceptEnv LANG LC_*

# override default of no subsystems
Subsystem       sftp    /usr/lib/openssh/sftp-server

# Example of overriding settings on a per-user basis
#Match User anoncvs
#       X11Forwarding no
#       AllowTcpForwarding no
#       PermitTTY no
#       ForceCommand cvs server

[dcivera]

Alright, still scratching my head. I wrote this little program to test libssh2 and hopefully figure out if I could get an error message, somehow.

<?php
$user                   = 'username';
$host                   = 'IP';
$port                   = '12345';
$private_key    = '/home/username/.ssh/id_ed25519_wordpress';
$public_key     = '/home/username/.ssh/id_ed25519_wordpress.pub';

if(!is_readable($private_key) || !is_readable($public_key)){
        echo "RSA keys not found\n";
}

/*Show debug messages*/
function ssh2_debug($message, $language, $always_display) {
   printf("%s %s %s\n",$message,$language,$always_display);
}

/* Notify the user if the server terminates the connection */
function my_ssh_disconnect($reason, $message, $language) {
  printf("Server disconnected with reason code [%d] and message: %s\n", $reason, $message);
}

$methods = array('hostkey' => 'ssh-ed25519, ssh-ed25519-cert-v01@openssh.com, ecdsa-sha2-nistp521, ecdsa-sha2-nistp384, ecdsa-sha2-nistp256, ssh-rsa, ssh-dss');


$callbacks = array('disconnect' => 'my_ssh_disconnect', 'debug' => 'ssh2_debug');

echo 'private key: '.file_get_contents($private_key)."\n";
echo 'public key: '.file_get_contents($public_key)."\n";
echo "host: $host\n";
echo "port: $port\n";
echo "user: $user\n";

#if(!$session = ssh2_connect($host, $port)){
#       echo "Could not connect to '$host'\n";
#}
#
#if(!ssh2_auth_pubkey_file($session, $user, $public_key, $private_key)){
#       echo "Could not authenticate to '$host'\n";
#}

$session = ssh2_connect($host, $port, $methods, $callbacks);

ssh2_auth_pubkey_file($session, $user, $public_key, $private_key);

$stream = ssh2_exec($session, 'free -m');
stream_set_blocking($stream, true);
$stream_out = ssh2_fetch_stream($stream, SSH2_STREAM_STDIO);
echo stream_get_contents($stream_out);
?>

Except that when I run it, it looks like it does what it's supposed to do. Here's the output:

private key: -----BEGIN OPENSSH PRIVATE KEY-----
b3BlbnNzaC.....
-----END OPENSSH PRIVATE KEY-----

public key: ssh-ed25519 AAAAC3NzaC1lZDI1NTEEEEEEEzV0TSwNepKiWQbY+90KG9J1wiuMUyB0dcfKuzb/Rm username@hostname

host: xx.xx.xxx.xx
port: 12345
user: username
/home/username/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding  0
/home/username/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding  0
               total        used        free      shared  buff/cache   available
Mem:            3871        1443        1746           4         928        2428

So, am I missing something or is everything working as expected? That would mean the disconnection previously is normal. Since I'm not sending any command after the connection, it just disconnects. However, that means I have to look somewhere else for my problem in WordPress 😢

[dcivera]

It was indeed a configuration issue. Since it's really Debian and WP-related, I'll just share the link to the answer in case it can help someone in need :)
https://wordpress.org/support/topic/ssh2-not-working-wont-accept-keys/#post-17772194