Wsl2 / Windows 11 Extremely slow agent communication times

[VibroAxe]

So I've been using this for a long time on windows 10 and have had absolutely no issues, well done for a really awesome piece of software.

However, since upgrading my laptop to windows 11 and reinstalling WSL2 (with WLSg if that makes a difference) the communication to the agent is EXTREMELY slow. From typing ssh at the command line to actually getting the gpg pincode prompt (/touch to auth flash on my yubikey) is taking over 20s, ssh-add -L is also taking a similar amount of time.

Performing the same operation from windows connecting to the gpg agent and I get the prompt instantly from both putty and winssh, implying this is an issue with the WSL2 connection somewhere.

Any ideas?

[BlackReloaded]

I have no win 11 on any device actual but @tobiaskohlbau. Can you confirm this behavior?

[tobiaskohlbau]

I did not experience this on my machine running the latest insider build.

By any chance this only happens on the first try? Thats most likely caused by the gpg-connect-agent not launched and needed to be relaunched.

[VibroAxe]

Nope, seems to happen everytime. I originally came here to complain it was taking over a minute, but that was actually my issue to do with running ssh-add too many times in a bash script. However the above 20s were based on runing ssh/ssh-agent directly.

Any debug I can run?

edit
gpg-agent is running at windows startup so should be available, and is available to the winssh/putty sessions without this lag/ issue

[tobiaskohlbau]

Can you try and run the attached utility program either by the provided binary or the attached sourcecode? It tries to find the pageant window and prints it's window handle.

pageant-check.zip

main.go

package main

import (
        "fmt"
        "syscall"

        "github.com/lxn/win"
)

func main() {
        hwnd := win.FindWindow(syscall.StringToUTF16Ptr("Pageant"), syscall.StringToUTF16Ptr("Pageant"))
        fmt.Println(hwnd)
}

go.mod

module pageant-check

go 1.16

require (
        github.com/lxn/win v0.0.0-20210218163916-a377121e959e // indirect
        golang.org/x/sys v0.0.0-20201018230417-eeed37f84f13 // indirect
)

[VibroAxe]

C:\Users\kinsman.PASCALL\Downloads>.\pageant-check.exe
66862

vibs@J-KINSMAN-2019:/mnt/c/Users/kinsman.PASCALL/downloads $ time ./pageant-check.exe
66862

real    0m1.502s

Pretty much immediate in windows, reasonably quick from linux (i'd slay a fraction slower)
i'm using the gpg-agent with putty support if that makes a difference?

[tobiaskohlbau]

Sorry for the late response.

I'm still nowhere near an idea why this happens to you. That beeing a little bit slower on linux is most likely caused by the interop layer in WSL.

I'm using the gpg-agent with putty support as well on my Windows 11 machine. Is your machine an updated one or a clean install? Maybe it's only happening if it's a clean install.

[VibroAxe]

@tobiaskohlbau So i've just done another clean install on another laptop and have exactly the same issue, so this might be a clean install thing?

Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.

Install the latest PowerShell for new features and improvements! https://aka.ms/PSWindows

PS C:\Users\kinsman> wsl -l
Windows Subsystem for Linux Distributions:
Ubuntu-20.04 (Default)

PS C:\Users\kinsman> wsl --install -d Ubuntu
Downloading: Ubuntu
Installing: Ubuntu
Ubuntu has been installed.
Launching Ubuntu...

PS C:\Users\kinsman> wsl -l
Windows Subsystem for Linux Distributions:
Ubuntu-20.04 (Default)
Ubuntu

PS C:\Users\kinsman> wsl -d Ubuntu
To run a command as administrator (user "root"), use "sudo <command>".
See "man sudo_root" for details.

vibs@J-KINSMAN-2021:/mnt/c/Users/kinsman$ sudo apt install socat
[sudo] password for vibs:
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following NEW packages will be installed:
  socat
0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Need to get 323 kB of archives.
After this operation, 1394 kB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu focal/main amd64 socat amd64 1.7.3.3-2 [323 kB]
Fetched 323 kB in 0s (2723 kB/s)
Selecting previously unselected package socat.
(Reading database ... 31836 files and directories currently installed.)
Preparing to unpack .../socat_1.7.3.3-2_amd64.deb ...
Unpacking socat (1.7.3.3-2) ...
Setting up socat (1.7.3.3-2) ...
Processing triggers for man-db (2.9.1-1) ...


vibs@J-KINSMAN-2021:/mnt/c/Users/kinsman$ cd

vibs@J-KINSMAN-2021:~$ mkdir .ssh
vibs@J-KINSMAN-2021:~$ destination="$HOME/.ssh/wsl2-ssh-pageant.exe"
t -O "vibs@J-KINSMAN-2021:~$ wget -O "$destination" "https://github.com/BlackReloaded/wsl2-ssh-pageant/releases/latest/download/wsl2-ssh-pageant.exe"
 Set the executable bit.
chmod +x "$destination"--2021-09-27 13:51:31--  https://github.com/BlackReloaded/wsl2-ssh-pageant/releases/latest/download/wsl2-ssh-pageant.exe
Resolving github.com (github.com)... 140.82.121.3
Connecting to github.com (github.com)|140.82.121.3|:443... connected.
HTTP request sent, awaiting response... 302 Found
Location: https://github.com/BlackReloaded/wsl2-ssh-pageant/releases/download/v1.3.0/wsl2-ssh-pageant.exe [following]
--2021-09-27 13:51:31--  https://github.com/BlackReloaded/wsl2-ssh-pageant/releases/download/v1.3.0/wsl2-ssh-pageant.exe
Reusing existing connection to github.com:443.
HTTP request sent, awaiting response... 302 Found
Location: https://github-releases.githubusercontent.com/231393429/22f91200-cf6f-11eb-8d36-4f1f1c2c3996?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIWNJYAX4CSVEH53A%2F20210927%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210927T125131Z&X-Amz-Expires=300&X-Amz-Signature=61538fb262fdd8b9822b4cf5b9974be9cee75951a5d70ef8f7fe1bee14396bb9&X-Amz-SignedHeaders=host&actor_id=0&key_id=0&repo_id=231393429&response-content-disposition=attachment%3B%20filename%3Dwsl2-ssh-pageant.exe&response-content-type=application%2Foctet-stream [following]
--2021-09-27 13:51:31--  https://github-releases.githubusercontent.com/231393429/22f91200-cf6f-11eb-8d36-4f1f1c2c3996?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIWNJYAX4CSVEH53A%2F20210927%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210927T125131Z&X-Amz-Expires=300&X-Amz-Signature=61538fb262fdd8b9822b4cf5b9974be9cee75951a5d70ef8f7fe1bee14396bb9&X-Amz-SignedHeaders=host&actor_id=0&key_id=0&repo_id=231393429&response-content-disposition=attachment%3B%20filename%3Dwsl2-ssh-pageant.exe&response-content-type=application%2Foctet-stream
Resolving github-releases.githubusercontent.com (github-releases.githubusercontent.com)... 185.199.111.154, 185.199.108.154, 185.199.110.154, ...
Connecting to github-releases.githubusercontent.com (github-releases.githubusercontent.com)|185.199.111.154|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 3727872 (3.6M) [application/octet-stream]
Saving to: ‘/home/vibs/.ssh/wsl2-ssh-pageant.exe’

/home/vibs/.ssh/wsl2-ssh-pageant.exe           100%[==================================================================================================>]   3.55M  9.26MB/s    in 0.4s

2021-09-27 13:51:32 (9.26 MB/s) - ‘/home/vibs/.ssh/wsl2-ssh-pageant.exe’ saved [3727872/3727872]

vibs@J-KINSMAN-2021:~$ # Set the executable bit.
vibs@J-KINSMAN-2021:~$ chmod +x "$destination"

vibs@J-KINSMAN-2021:~$ export SSH_AUTH_SOCK="$HOME/.ssh/agent.sock"
s -a | vibs@J-KINSMAN-2021:~$ if ! ss -a | grep -q "$SSH_AUTH_SOCK"; then
>   rm -f "$SSH_AUTH_SOCK"
>   wsl2_ssh_pageant_bin="$HOME/.ssh/wsl2-ssh-pageant.exe"
>   if test -x "$wsl2_ssh_pageant_bin"; then
>     (setsid nohup socat UNIX-LISTEN:"$SSH_AUTH_SOCK,fork" EXEC:"$wsl2_ssh_pageant_bin" >/dev/null 2>&1 &)
>   else
>     echo >&2 "WARNING: $wsl2_ssh_pageant_bin is not executable."
>   fi
 unset w>   unset wsl2_ssh_pageant_bin
> fi

vibs@J-KINSMAN-2021:~$ time ssh-add -L
ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAz5PwTwgjvwfvXg/GoaK9sbaP2El4U9/pxdSyv76XoT cardno:15 207 117

real    0m26.239s
user    0m0.002s
sys     0m0.000s

vibs@J-KINSMAN-2021:~$
vibs@J-KINSMAN-2021:~$

[VibroAxe]

Also of note, I tried opening pageant to see if that was any quicker, it;s definitely faster, but still taking 10s for an ssh-add -L, interestingly, the pageant-check is now taking ~20s to complete (for both)

Pageant

vibs@J-KINSMAN-2021:~$ time ssh-add -L
The agent has no identities.

real    0m9.067s
user    0m0.002s
sys     0m0.000s

vibs@J-KINSMAN-2021:~$ time ./pageant-check.exe
525766

real    0m22.944s
user    0m0.001s
sys     0m0.000s

GPG

vibs@J-KINSMAN-2021:~$ time ./pageant-check.exe
527614

real    0m26.119s
user    0m0.001s
sys     0m0.000s

vibs@J-KINSMAN-2021:~$ time ssh-add -L
ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAz5PwTwgjvwfvXg/GoaK9sbaP2El4U9/pxdSyv76XoT cardno:15 207 117

real    0m11.968s
user    0m0.001s
sys     0m0.000s

[dschaper]

Adding in another data point:

Edition	Windows 11 Pro
Version	21H2
Installed on	‎7/‎30/‎2021
OS build	22000.194
Experience	Windows Feature Experience Pack 1000.22000.194.0

dan@Viking-1:~/.ssh$ time ./pageant-check.exe
721522

real    0m14.925s
user    0m0.002s
sys     0m0.000s
dan@Viking-1:~/.ssh$ time ./pageant-check.exe
721522

real    0m18.263s
user    0m0.001s
sys     0m0.000s
dan@Viking-1:~/.ssh$ time ssh-add -L
ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGg3e898ea02z8yhDgo3n/8HJacyLpgY1aC4GDAqKWG6 cardno:

real    0m15.052s
user    0m0.002s
sys     0m0.000s

[alanaasmaa]

Can't test with pageant-check.exe my antivirus wont allow.
But i have same issue:

ssh-add -L 0.00s user 0.00s system 0% cpu 20.663 total
gpg --card-status 0.00s user 0.00s system 0% cpu 15.485 total

My windows is updated, not clean install.

[tobiaskohlbau]

Thanks for all the datapoints. With the upcoming release of Windows 11 I think it's worth digging into this. I'm still not experiencing this in my setup. Just out of curiosity do you all have:

/touch to auth flash on my yubikey

enabled, so that every request must be confirmed by a press on the yubikey? Maybe that is causing this issue, as I've not enabled that for now. Will test my theory on the next weekend.

[alanaasmaa]

Thanks for all the datapoints. With the upcoming release of Windows 11 I think it's worth digging into this. I'm still not experiencing this in my setup. Just out of curiosity do you all have:

/touch to auth flash on my yubikey

enabled, so that every request must be confirmed by a press on the yubikey? Maybe that is causing this issue, as I've not enabled that for now. Will test my theory on the next weekend.

No, I do not have to confirm the request.

[jliedy]

I am experiencing the same thing as to slowness.
Another symptom is after an indeterminate period of time the WSL2 process pegs the CPU until the socat job is killed.
All appropriate agents are running. I've got verbose logging enabled.

initialization script being used for this:

#!/usr/bin/bash

pageant_bin="${HOME}/.ssh/wsl2-ssh-pageant.exe"

export SSH_AUTH_SOCK="${HOME}/.ssh/agent.sock"
if ! ss -a | grep -q "${SSH_AUTH_SOCK}"; then
  rm -f "${SSH_AUTH_SOCK}"
  if test -x "${pageant_bin}"; then
    (setsid nohup socat UNIX-LISTEN:"${SSH_AUTH_SOCK},fork" EXEC:"${pageant_bin} --verbose=true --logfile=${HOME}/.ssh/pageant.log" >/dev/null 2>&1 &)
  else
    echo >&2 "WARNING: ${pageant_bin} is not executable."
  fi
fi

export GPG_AGENT_SOCK="${HOME}/.gnupg/S.gpg-agent"
if ! ss -a | grep -q "${GPG_AGENT_SOCK}"; then
  rm -rf "${GPG_AGENT_SOCK}"
  if test -x "${pageant_bin}"; then
    (setsid nohup socat UNIX-LISTEN:"${GPG_AGENT_SOCK},fork" EXEC:"${pageant_bin} --verbose=true --logfile=${HOME}/.gnupg/pageant.log --gpg=S.gpg-agent" >/dev/null 2>&1 &)
  else
    echo >&2 "WARNING: ${pageant_bin} is not executable."
  fi
fi

unset pageant_bin

Yubikey settings:

PS C:\Program Files\Yubico\YubiKey Manager> ./ykman.exe openpgp info
OpenPGP version: 3.4
Application version: 5.4.3

PIN tries remaining: 3
Reset code tries remaining: 0
Admin PIN tries remaining: 3

Touch policies
Signature key           Off
Encryption key          Off
Authentication key      Off
Attestation key         Off

pageant-check.exe:

~$ date;time .ssh/pageant-check.exe;date
Mon Oct  4 10:47:49 EDT 2021
462748

real    1m4.934s
user    0m0.002s
sys     0m0.000s
Mon Oct  4 10:48:54 EDT 2021

ssh-add -L while tailing agent logs:

:~$ date;ssh-add -L;date
Mon Oct  4 10:50:15 EDT 2021
2021/10/04 10:50:46 Starting exe
2021/10/04 10:50:46 Reading length: 1
2021/10/04 10:50:46 Querying pageant
ssh-rsa RSAPUBLICKEYBLAHBLAH cardno:blah
2021/10/04 10:50:46 io.ReadFull length error 'EOF'
Mon Oct  4 10:50:46 EDT 2021

gpg --card-status while tailing agent logs:

~$ date;gpg --card-status;date
Mon Oct  4 10:54:00 EDT 2021
2021/10/04 10:54:50 Starting exe
Reader ...........: Yubico YubiKey OTP FIDO CCID 0
Application ID ...: BLAH
Application type .: OpenPGP
Version ..........: 3.4
Manufacturer .....: Yubico
Serial number ....: BLAH
Name of cardholder: BLAH
Language prefs ...: [not set]
Salutation .......:
URL of public key : BLAH
Login data .......: [not set]
Signature PIN ....: not forced
Key attributes ...: rsa4096 rsa4096 rsa4096
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 0 3
Signature counter : 10
KDF setting ......: off
Signature key ....: BLAH
      created ....: BLAH
Encryption key....: BLAH
      created ....: BLAH
Authentication key: BLAH
      created ....: BLAH
General key info..: [none]
Mon Oct  4 10:55:10 EDT 2021

On that one, please note the 20 second difference between the log showing "Starting exe" and output actually showing for the card-status command.

I'm going to see if I can revert to an earlier release of socat in case that is an issue.

[jliedy]

Running ubuntu 20.04 (Focal) and the release of socat is 1.7.3.3-2 which was released on 20 Feb 2020 and it doesn't look like there's any previous release to try in Focal.

Also: Pegged CPU may be due to trying to run ssh via git through WSL2 vscode integration. I'm gonna mess with it a bit to see if anything pops up in the log.