Forum / Remote Desktop Manager Mac - Support

ssh agent authentication failed - 5.3.0.0 free

  • Create an Issue
  • Cancel

So I was very glad to see a checkbox in advanced to use the local SSH agent. Unfortunately, it doesn't work. Authentication is successful according to the client log, but it returns code -3 FAIL_PERMISSION_DENIED. Server side just sees a disconnect during auth.

$ cat logs/ssh-agent-auth.log
[5/7/2018 2:10:14 PM] Starting SSH negociation
[5/7/2018 2:10:14 PM] ssh_connect: libssh 0.7.5 (c) 2003-2014 Aris Adamantiadis, Andreas Schneider, and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_noop
[5/7/2018 2:10:14 PM] ssh_connect: Socket connecting, now waiting for the callbacks to work
[5/7/2018 2:10:14 PM] socket_callback_connected: Socket connection callback: 1 (0)
[5/7/2018 2:10:14 PM] ssh_client_connection_callback: SSH server banner: SSH-2.0-OpenSSH_6.6.1
[5/7/2018 2:10:14 PM] ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_6.6.1
[5/7/2018 2:10:14 PM] ssh_analyze_banner: We are talking to an OpenSSH client version: 6.6 (60600)
[5/7/2018 2:10:15 PM] ssh_packet_dh_reply: Received SSH_KEXDH_REPLY
[5/7/2018 2:10:15 PM] ssh_client_curve25519_reply: SSH_MSG_NEWKEYS sent
[5/7/2018 2:10:15 PM] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
[5/7/2018 2:10:15 PM] ssh_packet_newkeys: Signature verified and valid
[5/7/2018 2:10:15 PM] Server authenticated
[5/7/2018 2:10:15 PM] ssh_agent_get_ident_count: Answer type: 12, expected answer: 12
[5/7/2018 2:10:15 PM] Error authenticating user on server by agent: [5/7/2018 2:10:15 PM] [5/7/2018 2:10:15 PM] Disconnecting from SSH server

Clock7 mths

Hi Jo,

This is weird, I'll have to forward this to the engineer working on the SSH Shell component and see if he has more input on this.

Best regards,

Xavier Fortin

signaturesignature

Clock7 mths

Sure, FYI same results Enterprise and Free. Consistently works if I disable that checkbox and type my password to unlock the key each time. But the agent usage appears to be non-functional.

...or under-documented if the agent or app needs configuration that isn't mentioned anywhere.

Clock8 mths

Hi Jo,

You shouldn't need more configuration. I did reproduce the issue though the engineer working on the terminal couldn't. We're still investigating what could cause the difference in behavior.

Best regards,

Xavier Fortin

signaturesignature

Clock8 mths

Hi Jo,

I did find how I was failing to make my ssh-agent work. I'm not sure this is your issue though.

When I was testing the ssh-agent, I ended up doing a eval "$(ssh-agent -s)" which was launching another ssh-agent process to one that was already launched. I'm guessing that the subsequent ssh-add were adding the keys in the second process while RDM was using the first (which had no keys), hence the failure from RDM but the success directly from the terminal. Ensuring that I have only one ssh-agent made it works.

To be fair, I hit some situations where RDM itself seems to launch another ssh-agent process, causing the issue. The ssh-agent mechanism is handled by libssh though, so I don't know how much control we have over this.

Best regards,

Xavier Fortin

signaturesignature

Clock8 mths

So that's not my problem-- only a single agent. But that brings up the question-- how does RDM find the active agent? Because I don't save my agent password in the keychain-- I manually start up ssh-agent after every reboot. The shell terminals all inherit the environment variables so ssh can find the agent, but how does RDM identify the agent socket?

Clock8 mths

RDM uses the environment variable SSH_AUTH_SOCK to get the name of the unix domain socket for the agent. This is the same mechanism as any OpenSSH tool. If you have only one instance of ssh-agent running and RDM can not find it, it could be a permission issue.
I have added more verbose in the case where authentication by agent fails. I don't know how much it will be helpful, I have limited information when this operation fails.

Regards.

Denis Vincent

signaturesignature

Clock8 mths

Is there a way to see what environment variables RDM sees? I'm wondering if my terminals have access to the value, but RDM doesn't because it wasn't set until after boot was complete / e.g. the GUI environment?

Might be a useful feature to allow this to be specified (I have a symlink that always points to the active socket)

Clock8 mths

Hi Jo,

This is what Denis has just added in the verbose. I'll build a preview version to see if we can see more details.

Best regards,

Xavier Fortin

signaturesignature

Clock8 mths

So I figured out how to find out the environment variables used by the GUI, etc and it does show the right socket:


$ /bin/launchctl getenv SSH_AUTH_SOCK
/private/tmp/com.apple.launchd.x1q2dDm5Z1/Listeners

Clock7 mths

Hi Jo,

Here is the version in which the verbose will inform us of which socket was used by RDM: https://www.dropbox.com/s/c94tzrnaq8bw6j2/Devolutions.RemoteDesktopManager.Mac.5.3.2.1526482227.dmg?dl=0

Could you regenerate those log (you just need the verbose level 1)?

Best regards,

Xavier Fortin

signaturesignature

Clock7 mths

Xavier Fortin wrote:

Hi Jo,

Here is the version in which the verbose will inform us of which socket was used by RDM: https://www.dropbox.com/s/c94tzrnaq8bw6j2/Devolutions.RemoteDesktopManager.Mac.5.3.2.1526482227.dmg?dl=0

Could you regenerate those log (you just need the verbose level 1)?


Well you're gonna laugh now, but this new version works. Yay!

The old binary recovered from Trash still doesn't work, so it's not an environment change here. There's some code difference between the two.

Clock7 mths

Well, that's actually surprising (while quite welcome).

Maybe something else was changed since the last version. I'll inform Denis.

Best regards,

Xavier Fortin

signaturesignature

Clock7 mths

Also, the process now works for direct login but it isn't logging the environment variable:


[5/16/2018 11:30:19 AM] Starting SSH negociation
[5/16/2018 11:30:19 AM] ssh_connect: libssh 0.7.5 (c) 2003-2014 Aris Adamantiadis, Andreas Schneider, and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_noop
[5/16/2018 11:30:19 AM] ssh_connect: Socket connecting, now waiting for the callbacks to work
[5/16/2018 11:30:19 AM] socket_callback_connected: Socket connection callback: 1 (0)
[5/16/2018 11:30:19 AM] ssh_client_connection_callback: SSH server banner: SSH-2.0-OpenSSH_6.6.1
[5/16/2018 11:30:19 AM] ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_6.6.1
[5/16/2018 11:30:19 AM] ssh_analyze_banner: We are talking to an OpenSSH client version: 6.6 (60600)
[5/16/2018 11:30:19 AM] ssh_packet_dh_reply: Received SSH_KEXDH_REPLY
[5/16/2018 11:30:19 AM] ssh_client_curve25519_reply: SSH_MSG_NEWKEYS sent
[5/16/2018 11:30:19 AM] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
[5/16/2018 11:30:19 AM] ssh_packet_newkeys: Signature verified and valid
[5/16/2018 11:30:19 AM] Server authenticated
[5/16/2018 11:30:19 AM] ssh_agent_get_ident_count: Answer type: 12, expected answer: 12
[5/16/2018 11:30:19 AM] ssh_userauth_request_service: Failed to request "ssh-userauth" service
[5/16/2018 11:30:19 AM] User authenticated successfuly by agent
[5/16/2018 11:30:19 AM] channel_open: Creating a channel 43 with 64000 window and 32768 max packet
[5/16/2018 11:30:19 AM] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
[5/16/2018 11:30:19 AM] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
[5/16/2018 11:30:19 AM] channel_request: Channel request env success
[5/16/2018 11:30:19 AM] Language set to: en_US.UTF-8
[5/16/2018 11:30:19 AM] channel_request: Channel request pty-req success
[5/16/2018 11:30:19 AM] Agent forwarding channel opened
[5/16/2018 11:30:19 AM] channel_rcv_change_window: Adding 2097152 bytes to channel (43:0) (from 0 bytes)
[5/16/2018 11:30:19 AM] channel_request: Channel request shell success
[5/16/2018 11:30:19 AM] grow_window: growing window (channel 43:0) to 1280000 bytes

Clock7 mths

FYI, it appears to ignore the agent for jumphost configuration. When I configure an SSH jumphost, it fails and then identifies the correct agent location. So I guess that log only shows up when there's a failure.


[5/16/2018 11:51:30 AM] Starting SSH negociation
[5/16/2018 11:51:30 AM] ssh_connect: libssh 0.7.5 (c) 2003-2014 Aris Adamantiadis, Andreas Schneider, and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_noop
[5/16/2018 11:51:30 AM] ssh_connect: Socket connecting, now waiting for the callbacks to work
[5/16/2018 11:51:30 AM] socket_callback_connected: Socket connection callback: 1 (0)
[5/16/2018 11:51:30 AM] ssh_client_connection_callback: SSH server banner: SSH-2.0-OpenSSH_6.6.1
[5/16/2018 11:51:30 AM] ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_6.6.1
[5/16/2018 11:51:30 AM] ssh_analyze_banner: We are talking to an OpenSSH client version: 6.6 (60600)
[5/16/2018 11:51:30 AM] ssh_packet_dh_reply: Received SSH_KEXDH_REPLY
[5/16/2018 11:51:30 AM] ssh_client_curve25519_reply: SSH_MSG_NEWKEYS sent
[5/16/2018 11:51:30 AM] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
[5/16/2018 11:51:30 AM] ssh_packet_newkeys: Signature verified and valid
[5/16/2018 11:51:30 AM] Server authenticated
[5/16/2018 11:51:30 AM] ssh_agent_get_ident_count: Answer type: 12, expected answer: 12
[5/16/2018 11:51:30 AM] ssh_userauth_request_service: Failed to request "ssh-userauth" service
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] Error authenticating user on server by agent: [5/16/2018 11:51:31 AM] Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password[5/16/2018 11:51:31 AM] Tried this socket for the agent: /private/tmp/com.apple.launchd.x7q8DDm5Z1/Listeners
[5/16/2018 11:51:31 AM] Disconnecting from SSH server
[5/16/2018 11:51:31 AM] Disconnecting from SSH server

Clock7 mths

Hi,

I verified my code and agent authentication is used for both the jumphost and host when it is selected. From the log you submitted, I see that 4 keys were tried with the jumphost but none were accepted.

I confirm that the socket used for the agent is logged only if agent authentication fails. Maybe it could be logged in all case, I'll check that out in my next version of the SSH protocol implementation.

Thanks for your comments.

Regards.

Denis Vincent

signaturesignature

Clock7 mths

Denis Vincent wrote:

I verified my code and agent authentication is used for both the jumphost and host when it is selected. From the log you submitted, I see that 4 keys were tried with the jumphost but none were accepted.

So if the jumphost is my direct target it works fine. When it's the SSH gateway the agent auth fails.

Denis Vincent wrote:

I confirm that the socket used for the agent is logged only if agent authentication fails. Maybe it could be logged in all case, I'll check that out in my next version of the SSH protocol implementation.


I don't think that's a problem, but there's clearly a few missing linefeeds in the log when a failure occurs which would be nice to clean up wink

[5/16/2018 11:51:31 AM] Error authenticating user on server by agent: [5/16/2018 11:51:31 AM] Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password[5/16/2018 11:51:31 AM] Tried this socket for the agent: /private/tmp/com.apple.launchd.x7q8DDm5Z1/Listeners

Clock7 mths

Denis Vincent wrote:

I verified my code and agent authentication is used for both the jumphost and host when it is selected. From the log you submitted, I see that 4 keys were tried with the jumphost but none were accepted.


So this is now working. With no logout, restart of the app or anything.

My best guess is that perhaps I hadn't set the users correctly? My local username is different from the remote, is different from the gateway. It would be really useful to see the attempted username in the log...

Another logging or implementation anomaly: I did some explicit successes and failures, and for each key in the ring two different failures were logged. For example, with a single key that isn't going to be accepted, you see two failures. If the 3rd key in the ring will succeed, you see four failures before success. Not sure if it's a logging duplication, or a duplicate attempt.


[5/16/2018 11:51:30 AM] Server authenticated
[5/16/2018 11:51:30 AM] ssh_agent_get_ident_count: Answer type: 12, expected answer: 12
[5/16/2018 11:51:30 AM] ssh_userauth_request_service: Failed to request "ssh-userauth" service
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
[5/16/2018 11:51:31 AM] ssh_packet_userauth_failure: Access denied. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password

Clock7 mths

Thanks for the feedback.

Those logs are from the third party library we're using for the SSH protocol. My guess is that they use the same log text for both key request and key signature. When authenticating with keys, it is usually performed in 2 steps: first a request is made sending the public key in order to know if the server knows that key, then, if the first request succeed, a second request is sent that provides a signature for the real authentication. It is done this way to avoid expensive computing of a signature that the server wouldn't even check because the key is not allowed in its authorized_keys file.

We're in the process of replacing that library, I'll make sure to have clearer message.

Best regards.

Denis Vincent

signaturesignature

Clock7 mths

Denis Vincent wrote:

Those logs are from the third party library we're using for the SSH protocol. My guess is that they use the same log text for both key request and key signature. When authenticating with keys, it is usually performed in 2 steps: first a request is made sending the public key in order to know if the server knows that key, then, if the first request succeed, a second request is sent that provides a signature for the real authentication. It is done this way to avoid expensive computing of a signature that the server wouldn't even check because the key is not allowed in its authorized_keys file.


I was writing "oh that makes sense" when I realized it doesn't. My tests had keys that were not in the authorized_keys file. So it seems both attempts are tried, even if the key's not in the file. For example, if I have a single key not in the remote's authorized keys file I see two messages. Your statement says it should "avoid the cost" of the 2nd attempt, right?

Clock7 mths