Question

Solved1.87K views11th July 2023OpenSSH SSH SSH Key

3

Saddam Zourob [DevOps Advocate]363 25th March 2021 0 Comments

Hi All,

I am developing an SSH driver that communicates with a host with OpenSSH 8.0. I had an issue with the keys which I finally fixed by following the details in [This Question].

The list of algorithms is as follow:

requestInfo[2] = new string[5] { "ecdh-sha2-nistp256", "diffie-hellman-group14-sha1", "ssha-rsa", "diffie-hellman-group-exchange-sha1", "diffie-hellman-group1-sha1" };

However, I am currently facing a new the following new issue:

2021-03-25 13:37:14 - -1 - Sent SSH_MSG_USERAUTH_REQUEST for user 'System.Byte[]' (query abilities)
2021-03-25 13:37:14 - -1 - publickey auth failure for 'C:\SSH_Keys\bcamadm_r_test' (SSH_MSG_USERAUTH_FAILURE received after SSH_MSG_USERAUTH_REQUEST)

I enabled Debug mode at the remote server and here are the logs:

[root@ut016296 ssh]# tail -f /var/log/secure
Mar 25 13:35:10 ut016296 sshd[845385]: debug1: PAM: cleanup
Mar 25 13:35:10 ut016296 sshd[845385]: debug1: PAM: closing session
Mar 25 13:35:10 ut016296 sshd[845385]: pam_unix(sshd:session): session closed for user oracle
Mar 25 13:35:10 ut016296 sshd[845385]: debug1: PAM: deleting credentials
Mar 25 13:36:54 ut016296 sshd[845014]: Received signal 15; terminating.
Mar 25 13:36:54 ut016296 sshd[846967]: debug1: Set /proc/self/oom_score_adj from 0 to -1000
Mar 25 13:36:54 ut016296 sshd[846967]: debug1: Bind to port 22 on 0.0.0.0.
Mar 25 13:36:54 ut016296 sshd[846967]: Server listening on 0.0.0.0 port 22.
Mar 25 13:36:54 ut016296 sshd[846967]: debug1: Bind to port 22 on ::.
Mar 25 13:36:54 ut016296 sshd[846967]: Server listening on :: port 22.
Mar 25 13:37:14 ut016296 sshd[846967]: debug1: Forked child 846993.
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: Set /proc/self/oom_score_adj to 0
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: inetd sockets after dupping: 4, 4
Mar 25 13:37:14 ut016296 sshd[846993]: Connection from 10.253.196.222 port 53379 on 10.139.25.84 port 22
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: Local version string SSH-2.0-OpenSSH_8.0
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: Remote protocol version 2.0, remote software version SharpSSH-1.1.1.13-JSCH-0.1.28
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: no match: SharpSSH-1.1.1.13-JSCH-0.1.28
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: SELinux support enabled [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: ssh_selinux_change_context: setting context from 'system_u:system_r:sshd_t:s0-s0:c0.c1023' to 'system_u:system_r:sshd_net_t:s0-s0:c0.c1023' [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: permanently_set_uid: 74/74 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: SSH2_MSG_KEXINIT sent [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: SSH2_MSG_KEXINIT received [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: kex: algorithm: ecdh-sha2-nistp256 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: kex: host key algorithm: ssh-rsa [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: kex: client->server cipher: aes128-cbc MAC: hmac-sha1 compression: none [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: kex: server->client cipher: aes128-cbc MAC: hmac-sha1 compression: none [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: kex: ecdh-sha2-nistp256 need=20 dh_need=20 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: kex: ecdh-sha2-nistp256 need=20 dh_need=20 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: rekey out after 4294967296 blocks [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: SSH2_MSG_NEWKEYS sent [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: expecting SSH2_MSG_NEWKEYS [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: SSH2_MSG_NEWKEYS received [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: rekey in after 4294967296 blocks [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: KEX done [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: userauth-request for user bcamadm_r service ssh-connection method none [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: attempt 0 failures 0 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: PAM: initializing for "bcamadm_r"
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: PAM: setting PAM_RHOST to "10.253.196.222"
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: PAM: setting PAM_TTY to "ssh"
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: userauth-request for user bcamadm_r service ssh-connection method publickey [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: attempt 1 failures 0 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: userauth_pubkey: test pkalg ssh-rsa pkblob RSA SHA256:6qy8Zmbi9dC87Ht66I8D1yc88Q0OK4DnZznKf4FOSgU [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: temporarily_use_uid: 1001/1001 (e=0/0)
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: trying public key file /home/bcamadm_r/.ssh/authorized_keys
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: fd 5 clearing O_NONBLOCK
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: restore_uid: 0/0
Mar 25 13:37:14 ut016296 sshd[846993]: Failed publickey for bcamadm_r from 10.253.196.222 port 53379 ssh2: RSA SHA256:[KEY] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: userauth-request for user bcamadm_r service ssh-connection method password [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: attempt 2 failures 1 [preauth] Mar 25 13:37:14 ut016296 sshd[846993]: debug1: PAM: password authentication accepted for bcamadm_r
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: do_pam_account: called
Mar 25 13:37:14 ut016296 sshd[846993]: Accepted password for bcamadm_r from 10.253.196.222 port 53379 ssh2
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: monitor_child_preauth: bcamadm_r has been authenticated by privileged process
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: monitor_read_log: child log fd closed
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: audit_event: unhandled event 2
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: temporarily_use_uid: 1001/1001 (e=0/0)
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: ssh_gssapi_storecreds: Not a GSSAPI mechanism
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: restore_uid: 0/0
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: SELinux support enabled
Mar 25 13:37:14 ut016296 sshd[846993]: debug1: PAM: establishing credentials
Mar 25 13:37:14 ut016296 sshd[846993]: pam_unix(sshd:session): session opened for user bcamadm_r by (uid=0)
Mar 25 13:37:14 ut016296 sshd[846993]: User child is on pid 846997
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: PAM: establishing credentials
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: permanently_set_uid: 1001/1001
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: rekey in after 4294967296 blocks
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: rekey out after 4294967296 blocks
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: ssh_packet_set_postauth: called
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: Entering interactive session for SSH2.
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: server_init_dispatch
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: server_input_channel_open: ctype session rchan 50 win 1048576 max 16384
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: input_session_request
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: channel 0: new [server-session] Mar 25 13:37:14 ut016296 sshd[846997]: debug1: session_new: session 0
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: session_open: channel 0
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: session_open: session 0: link with channel 0
Mar 25 13:37:14 ut016296 sshd[846997]: debug1: server_input_channel_open: confirm session
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: server_input_channel_req: channel 0 request pty-req reply 0
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_by_channel: session 0 channel 0
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_input_channel_req: session 0 req pty-req
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: Allocating pty.
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: session_new: session 0
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: SELinux support enabled
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_pty_req: session 0 alloc /dev/pts/1
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: server_input_channel_req: channel 0 request shell reply 0
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_by_channel: session 0 channel 0
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_input_channel_req: session 0 req shell
Mar 25 13:37:15 ut016296 sshd[846997]: Starting session: shell on pts/1 for bcamadm_r from 10.253.196.222 port 53379 id 0
Mar 25 13:37:15 ut016296 sshd[846998]: debug1: Setting controlling tty using TIOCSCTTY.
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_by_channel: session 0 channel 0
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_close_by_channel: channel 0 child 846998
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_close_by_channel: channel 0: has child, ttyfd 10
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_by_channel: session 0 channel 0
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_close_by_channel: channel 0 child 846998
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: session_close_by_channel: channel 0: has child, ttyfd -1
Mar 25 13:37:15 ut016296 sshd[846997]: Read error from remote host 10.253.196.222 port 53379: Connection reset by peer
Mar 25 13:37:15 ut016296 sshd[846997]: debug1: do_cleanup
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: session_by_tty: session 0 tty /dev/pts/1
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: session_pty_cleanup2: session 0 release /dev/pts/1
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: do_cleanup
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: PAM: cleanup
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: PAM: closing session
Mar 25 13:37:15 ut016296 sshd[846993]: pam_unix(sshd:session): session closed for user bcamadm_r
Mar 25 13:37:15 ut016296 sshd[846993]: debug1: PAM: deleting credentials

The public key is added to the "Authorised_keys" file and I can use the private key to access through Putty.

The private key layout is as follow:

-----BEGIN RSA PRIVATE KEY-----
THE KEY
-----END RSA PRIVATE KEY-----

I tried to do change the permissions on the server and many other things. However, we are only able to use the password.

Marieke Goethals [SLC] [DevOps Catalyst] Selected answer as best 11th July 2023

1 Answer

score 0 · Answer 1 · 2021-04-01T07:49:53+00:00

0

Jeroen Neyt [SLC] [DevOps Advocate]2.16K Posted 31st March 2021 1 Comment

The server logging on debug1 currently only tells you the fact that it failed:

Mar 25 13:37:14 ut016296 sshd[846993]: Failed publickey for bcamadm_r from 10.253.196.222 port 53379 ssh2: RSA SHA256:[public key omitted]

Can you try increasing the server logging to debug3 which hopefully should give you more information on the reason of the failure.

You mentioned that you added the public key to the authorised_keys file. Not sure if that's just a typo in the question but it's worth to double check that the file name should be authorized_keys.

Marieke Goethals [SLC] [DevOps Catalyst] Selected answer as best 11th July 2023

Saddam Zourob [DevOps Advocate] commented 1st April 2021

Hi Jeroen,

Something that I noticed in the logs, the public key that it prints during the debug is not the same public key that is listed in the Authorized_keys file.

Here are the dubug3 logs:

Apr 1 06:41:19 ut016296 sshd[330580]: debug1: PAM: initializing for “bcamadm_r”
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: PAM: setting PAM_RHOST to “10.253.196.222”
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: PAM: setting PAM_TTY to “ssh”
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: monitor_read: 100 used once, disabling now
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive entering
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: monitor_read: checking request 4
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_answer_authserv: service=ssh-connection, style=
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: monitor_read: 4 used once, disabling now
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive entering
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: monitor_read: checking request 80
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_answer_authrole: role=
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: monitor_read: 80 used once, disabling now
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: userauth_finish: failure partial=0 next methods=”publickey,gssapi-keyex,gssapi-with-mic,password” [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: send packet: type 51 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: receive packet: type 50 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: userauth-request for user bcamadm_r service ssh-connection method publickey [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: attempt 1 failures 0 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: input_userauth_request: try method publickey [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: userauth_pubkey: valid user bcamadm_r querying public key ssh-rsa AAAAB3NzaC1yc2EAAAADA************************************************************************************************************************
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: userauth_pubkey: test pkalg ssh-rsa pkblob RSA SHA256:6qy8Zmbi9dC87Ht*************4DnZznKf4FOSgU [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_key_allowed entering [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_send entering: type 22 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive_expect entering: type 23 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive entering [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive entering
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: monitor_read: checking request 22
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_answer_keyallowed entering
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_answer_keyallowed: key_from_blob: 0x5605912088a0
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: temporarily_use_uid: 1001/1001 (e=0/0)
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: trying public key file /home/bcamadm_r/.ssh/authorized_keys
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: fd 5 clearing O_NONBLOCK
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: restore_uid: 0/0
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_answer_keyallowed: publickey authentication test: RSA key is not allowed
Apr 1 06:41:19 ut016296 sshd[330580]: Failed publickey for bcamadm_r from 10.253.196.222 port 49921 ssh2: RSA SHA256: [KEY]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_send entering: type 23
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: userauth_pubkey: authenticated 0 pkalg ssh-rsa [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: ensure_minimum_time_since: elapsed 2.770ms, delaying 4.299ms (requested 7.068ms) [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: userauth_finish: failure partial=0 next methods=”publickey,gssapi-keyex,gssapi-with-mic,password” [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: send packet: type 51 [preauth]
Apr 1 06:41:19 ut016296 sshd[316879]: debug1: server_input_channel_req: channel 0 request winadj@putty.projects.tartarus.org reply 1
Apr 1 06:41:19 ut016296 sshd[316879]: debug1: session_by_channel: session 0 channel 0
Apr 1 06:41:19 ut016296 sshd[316879]: debug1: session_input_channel_req: session 0 req winadj@putty.projects.tartarus.org
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: receive packet: type 50 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: userauth-request for user bcamadm_r service ssh-connection method password [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug1: attempt 2 failures 1 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug2: input_userauth_request: try method password [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_auth_password entering [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_send entering: type 12 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive_expect entering: type 13 [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive entering [preauth]
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: mm_request_receive entering
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: monitor_read: checking request 12
Apr 1 06:41:19 ut016296 sshd[330580]: debug3: PAM: sshpam_passwd_conv called with 1 messages
Apr 1 06:41:20 ut016296 sshd[330580]: debug1: PAM: password authentication accepted for bcamadm_r
Apr 1 06:41:20 ut016296 sshd[330580]: debug3: mm_answer_authpassword: sending result 1
Apr 1 06:41:20 ut016296 sshd[330580]: debug3: mm_request_send entering: type 13
Apr 1 06:41:20 ut016296 sshd[330580]: debug3: mm_request_receive_expect entering: type 102
Apr 1 06:41:20 ut016296 sshd[330580]: debug3: mm_request_receive entering
Apr 1 06:41:20 ut016296 sshd[330580]: debug1: do_pam_account: called

SSH “publickey auth failure”

1 Answer