putty freezes when authenticating

[pakud]

i've run into an issue where putty frequently, although not always, freezes when i'm trying to log into linux servers using winssh-pageant and openssh with ecdsa-sk key backed by Yubikey 5 acting as FIDO2 token.

i'm worndering if you have any suggestions how to find the root cause of it, enable more verbosity in different elements of this stack.

this is what happens oftentimes when i'm trying to log in via putty which uses winssh-pageant - putty window freezes with 'Not responding' in its title bar:

and after ~20s i get below, but it's too late for key touching - login via that method already failed:

versions:

• Windows 11
• OpenSSH-Win64-v9.2.2.0
• putty 0.79 64 bit
• winssh-pageant 2.3.1 64bit

when i've found out:

• if ssh-agent on windows is using file-based key, without involvement of token - all seems good - i can log in both via openssh ssh and via putty without issues, multiple times,
• if ssh-agent on windows is using ecdsa-sk key and i'm using openssh's ssh client - all works smoothly as well

thank you in advance for your suggestions and thank you for winssh-pagent!

[ndbeals]

Thanks for the detailed report, apologies for the slow response.

I have some ideas but its stabbing in the dark. Could you run winssh-pageant manually from a CLI and then try authenticating? hopefully winssh-pageant will output some helpful info.

I'm realizing the lack of verbose logging is a glaring hole in, so I'm writing some code to add verbose logging, hopefully I'll get it out before you see this reply.

[pakud]

thanks for getting back to me! sadly with the recent Windows 11 update things got even worse. now i'm getting this pop-up, in which i cannot click on any of choices if i'm using putty combined with winssh-pageant.

logging in via openssh's ssh works fine [ well.. now i have an extra click in the popup, but the click is possible at least ].

winssh-pageant shows "Timeout waiting for user input \.\pipe\openssh-ssh-agent: i/o timeout"

thx!

[ndbeals]

That info did help, I've added a lot of debug logging to this in a new branch If you want to build it yourself.

here's a built binary, extract it and run it with winssh-pageant.exe --verbose and try again and copy + paste the logs back here.

winssh-pageant-verbose-logging.zip

Thanks.

[pakud]

thanks a lot! i've:

• built from source code taken from https://github.com/ndbeals/winssh-pageant/tree/verbose-logging
• ensured that no winssh-pageant.exe is running
• started winssh-pageant.exe --verbose from the freshly made build

sadly there's no output on the console and with 2nd or 3rd use of putty i'm getting this:

after ~60s followed by this:

there are no logs in the cmd where i've started winssh-pageant.exe --verbose

as before - ssh client from https://github.com/PowerShell/Win32-OpenSSH/releases/tag/v9.4.0.0p1-Beta - works fine with ssh-agent and yubikey that i'm trying to use with putty and winssh-pagent.

thank you!

[sascha-schieferdecker]

I can confirm this is the case with WinSCP as well, it is rather slow before you can use the Windows dialogue for selecting the security key. I am also using Win11 and OpenSSH_for_Windows_9.4p1, LibreSSL 3.7.3. It only happens via pageant access, cannot identify any slowdown when using windows terminal for SSH connections.

BTW: Very helpful piece of software 👍😊

[ndbeals]

Thanks for trying that build @pakud but something went wrong with the --verbose flag, there should have been some log lines from the startup of winssh-pageant. I'll provide better instructions below.

This is what the startup should look like:

PS H:\Home\code\winssh-pageant> go run ./ --verbose
2023-12-27 13:40:53 INF Starting winssh-pageant
2023-12-27 13:40:53 INF Pageant pipe proxy started
2023-12-27 13:40:53 DBG Locked OS Thread
2023-12-27 13:40:53 DBG Allocated global memory for message data, Starting message loop

How to run winssh-pageant using the verbose-logging branch

Open a cmd or powershell window:

1. Clone the repo

Navigate to a folder and run:

git clone https://github.com/ndbeals/winssh-pageant.git

2. Checkout the verbose logging branch

CD into the newly cloned repo:

cd winssh-pageant

Checkout the branch

git checkout verbose-logging

Confirm you're on the correct branch:

git branch --show-current -> Should output verbose-logging

3. Use "go run" to run the code

From the same directory as the earlier steps, run:

go run ./ --verbose

Alternatively, you could build it and run it:

go build ./ IMPORTANT: The exe name from this command is winssh-pageant.exe

./winssh-pageant.exe --verbose

Here's what it looks like all together:

PS H:\Home\code\delme> git clone https://github.com/ndbeals/winssh-pageant.git
Cloning into 'winssh-pageant'...
remote: Enumerating objects: 293, done.
remote: Counting objects: 100% (171/171), done.
remote: Compressing objects: 100% (99/99), done.
Receiving objects:  89% (261/293)sed 105 (delta 65), pack-reused 122
Receiving objects: 100% (293/293), 166.11 KiB | 2.72 MiB/s, done.
Resolving deltas: 100% (120/120), done.
PS H:\Home\code\delme> cd .\winssh-pageant\
PS H:\Home\code\delme\winssh-pageant> git checkout verbose-logging
Switched to a new branch 'verbose-logging'
branch 'verbose-logging' set up to track 'origin/verbose-logging'.
PS H:\Home\code\delme\winssh-pageant> git branch --show-current
verbose-logging
PS H:\Home\code\delme\winssh-pageant> go run ./ --verbose
2023-12-27 13:50:43 INF Starting winssh-pageant
2023-12-27 13:50:43 INF Pageant pipe proxy started
2023-12-27 13:50:43 DBG Locked OS Thread
2023-12-27 13:50:43 DBG Allocated global memory for message data, Starting message loop

---

Once you've done that successfully, could you try once more to get me some debug logs? I'd appreciate it if you copy+pasted the log outputs (instead of a screenshot, but I'm not picky if you cannot copy+paste).

I'm looking into getting my hands on a yubikey so I can replicate and test this issue myself.

[pakud]

thanks a lot for detailed instruction @ndbeals and looking into it!

i've followed it and was able to connect ~2-4 times by running putty.exe user@hostname and then closing putty.

then i got this:

but this time touching the yubikey token to confirm sign it did not make the standard popup [which shows with every FIDO2-based ssh authentication] go away and putty froze.

exact output from the console:

C:\temp\winssh-pageant\winssh-pageant>go run ./ --verbose
2023-12-27 23:33:53 INF Starting winssh-pageant
2023-12-27 23:33:53 INF Pageant pipe proxy started
2023-12-27 23:33:53 DBG Locked OS Thread
2023-12-27 23:33:53 DBG Allocated global memory for message data, Starting message loop
2023-12-27 23:33:59 DBG Received WM_COPYDATA message
2023-12-27 23:33:59 DBG Passed security checks
2023-12-27 23:33:59 DBG Received pageant request message of size: 5
2023-12-27 23:33:59 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:33:59 DBG Dialing agent pipe
2023-12-27 23:33:59 DBG Dialed successfully
2023-12-27 23:33:59 DBG Writing putty request to openssh pipe
2023-12-27 23:33:59 DBG request wrote successfully, reading response
2023-12-27 23:33:59 DBG message size: 153
2023-12-27 23:33:59 DBG reply code: 12
2023-12-27 23:33:59 DBG message contents length: 152
2023-12-27 23:33:59 DBG response size: 157
2023-12-27 23:33:59 DBG Sent request to openssh handler, result size: 157
2023-12-27 23:33:59 DBG Copied 157 elements to shared memory
2023-12-27 23:33:59 DBG Received WM_COPYDATA message
2023-12-27 23:33:59 DBG Passed security checks
2023-12-27 23:33:59 DBG Received pageant request message of size: 422
2023-12-27 23:33:59 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:33:59 DBG Dialing agent pipe
2023-12-27 23:33:59 DBG Dialed successfully
2023-12-27 23:33:59 DBG Writing putty request to openssh pipe
2023-12-27 23:33:59 DBG request wrote successfully, reading response
2023-12-27 23:34:05 DBG message size: 125
2023-12-27 23:34:05 DBG reply code: 14
2023-12-27 23:34:05 DBG message contents length: 124
2023-12-27 23:34:05 DBG response size: 129
2023-12-27 23:34:05 DBG Sent request to openssh handler, result size: 129
2023-12-27 23:34:05 DBG Copied 129 elements to shared memory
2023-12-27 23:34:09 DBG Received WM_COPYDATA message
2023-12-27 23:34:09 DBG Passed security checks
2023-12-27 23:34:09 DBG Received pageant request message of size: 5
2023-12-27 23:34:09 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:34:09 DBG Dialing agent pipe
2023-12-27 23:34:09 DBG Dialed successfully
2023-12-27 23:34:09 DBG Writing putty request to openssh pipe
2023-12-27 23:34:09 DBG request wrote successfully, reading response
2023-12-27 23:34:09 DBG message size: 153
2023-12-27 23:34:09 DBG reply code: 12
2023-12-27 23:34:09 DBG message contents length: 152
2023-12-27 23:34:09 DBG response size: 157
2023-12-27 23:34:09 DBG Sent request to openssh handler, result size: 157
2023-12-27 23:34:09 DBG Copied 157 elements to shared memory
2023-12-27 23:34:09 DBG Received WM_COPYDATA message
2023-12-27 23:34:09 DBG Passed security checks
2023-12-27 23:34:09 DBG Received pageant request message of size: 422
2023-12-27 23:34:09 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:34:09 DBG Dialing agent pipe
2023-12-27 23:34:09 DBG Dialed successfully
2023-12-27 23:34:09 DBG Writing putty request to openssh pipe
2023-12-27 23:34:09 DBG request wrote successfully, reading response
2023-12-27 23:34:11 DBG message size: 124
2023-12-27 23:34:11 DBG reply code: 14
2023-12-27 23:34:11 DBG message contents length: 123
2023-12-27 23:34:11 DBG response size: 128
2023-12-27 23:34:11 DBG Sent request to openssh handler, result size: 128
2023-12-27 23:34:11 DBG Copied 128 elements to shared memory
2023-12-27 23:34:17 DBG Received WM_COPYDATA message
2023-12-27 23:34:17 DBG Passed security checks
2023-12-27 23:34:17 DBG Received pageant request message of size: 5
2023-12-27 23:34:17 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:34:17 DBG Dialing agent pipe
2023-12-27 23:34:17 DBG Dialed successfully
2023-12-27 23:34:17 DBG Writing putty request to openssh pipe
2023-12-27 23:34:17 DBG request wrote successfully, reading response
2023-12-27 23:34:17 DBG message size: 153
2023-12-27 23:34:17 DBG reply code: 12
2023-12-27 23:34:17 DBG message contents length: 152
2023-12-27 23:34:17 DBG response size: 157
2023-12-27 23:34:17 DBG Sent request to openssh handler, result size: 157
2023-12-27 23:34:17 DBG Copied 157 elements to shared memory
2023-12-27 23:34:17 DBG Received WM_COPYDATA message
2023-12-27 23:34:17 DBG Passed security checks
2023-12-27 23:34:17 DBG Received pageant request message of size: 422
2023-12-27 23:34:17 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:34:17 DBG Dialing agent pipe
2023-12-27 23:34:17 DBG Dialed successfully
2023-12-27 23:34:17 DBG Writing putty request to openssh pipe
2023-12-27 23:34:17 DBG request wrote successfully, reading response
2023-12-27 23:35:17 ERR cannot read response message size from openssh pipe error="i/o timeout"
2023-12-27 23:35:17 DBG Sent request to openssh handler, result size: 5
2023-12-27 23:35:17 DBG Copied 5 elements to shared memory

log from another case where login failed on the first attempt after starting winssh-pageant:

C:\temp\winssh-pageant\winssh-pageant>go run ./ --verbose
2023-12-27 23:51:04 INF Starting winssh-pageant
2023-12-27 23:51:04 INF Pageant pipe proxy started
2023-12-27 23:51:04 DBG Locked OS Thread
2023-12-27 23:51:04 DBG Allocated global memory for message data, Starting message loop
2023-12-27 23:51:07 DBG Received WM_COPYDATA message
2023-12-27 23:51:07 DBG Passed security checks
2023-12-27 23:51:07 DBG Received pageant request message of size: 5
2023-12-27 23:51:07 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:51:07 DBG Dialing agent pipe
2023-12-27 23:51:07 DBG Dialed successfully
2023-12-27 23:51:07 DBG Writing putty request to openssh pipe
2023-12-27 23:51:07 DBG request wrote successfully, reading response
2023-12-27 23:51:07 DBG message size: 153
2023-12-27 23:51:07 DBG reply code: 12
2023-12-27 23:51:07 DBG message contents length: 152
2023-12-27 23:51:07 DBG response size: 157
2023-12-27 23:51:07 DBG Sent request to openssh handler, result size: 157
2023-12-27 23:51:07 DBG Copied 157 elements to shared memory
2023-12-27 23:51:07 DBG Received WM_COPYDATA message
2023-12-27 23:51:07 DBG Passed security checks
2023-12-27 23:51:07 DBG Received pageant request message of size: 422
2023-12-27 23:51:07 DBG Querying OpenSSH Agent pipe_name="\\\\.\\pipe\\openssh-ssh-agent"
2023-12-27 23:51:07 DBG Dialing agent pipe
2023-12-27 23:51:07 DBG Dialed successfully
2023-12-27 23:51:07 DBG Writing putty request to openssh pipe
2023-12-27 23:51:07 DBG request wrote successfully, reading response
2023-12-27 23:52:07 ERR cannot read response message size from openssh pipe error="i/o timeout"
2023-12-27 23:52:07 DBG Sent request to openssh handler, result size: 5
2023-12-27 23:52:07 DBG Copied 5 elements to shared memory

verbose log, also from the ssh-agent, could help here. [ https://github.com/PowerShell/Win32-OpenSSH/issues/2137 ].

also - i'm using the latest available version of ssh-agent from https://github.com/PowerShell/Win32-OpenSSH/releases, right now it's v9.5.0.0p1-Beta. as before - when using ssh user@host from cmd and the same project, no matter how may times i try - it works without hiccups.

[ndbeals]

Thanks for getting back to me, these logs were very helpful.

I've ordered my own Yubikey 5 to test this.

The logs you've posted show an ERR cannot read response message size from openssh pipe error="i/o timeout" which happens if it takes 1 minute to read response data. I have a suspicion that the Windows Hello popup just isn't "popping up", it's still there but hidden behind other windows. The random nature of this not working for you does support that suspicion, but I'll learn more once I get my own yubikey

[pakud]

@ndbeals - thanks! i'm happy to test in the next iterations.

once you get hold of the yubikey or other FIDO2-compatible hardware token you can:

run ssh-keygen -t ecdsa-sk -C "my-yubikey" -f .ssh/privatekey-id_ecdsa_sk to generate a pair of SSH keys [ or rather handles, since part of private key will reside on the token ]. some devices dont support scdsa-sk, you can replace it with more widely available ed25519-sk.

than handle privatekey-id_ecdsa_sk.pub like usual public key - add it to .ssh/authorized_keys and on widows run .ssh/privatekey-id_ecdsa_sk