ssh-agent doesn't work if the server side components (sshd) are not installed

[charabaruk]

Whenever trying to add or list identities in ssh-agent, the ssh-add process fails with the message "communication with agent failed". For example:

> Get-Service ssh-agent

Status   Name               DisplayName
------   ----               -----------
Running  ssh-agent          ssh-agent


> ssh-add .ssh\some_identity
Enter passphrase for .ssh\some_identity:
Could not add identity ".ssh\some_identity": communication with agent failed
> ssh-add -l
error fetching identities for protocol 2: communication with agent failed
The agent has no identities.

[manojampalam]

Can you check if the process id under the following
reg query HKEY_LOCAL_MACHINE\SOFTWARE\SSH\Agent

matches that of ssh-agent.exe process? If not delete the above entry and restart ssh-agent. This problem should go away in next drop as these checks were removed in code.

[charabaruk]

The ProcessID value did match the ssh-agent.exe PID, but even after removing the property and restarting the ssh-agent service, the problem remains with the same output from the ssh-add commands.

Does the ssh-agent service require that the SSHD service is also required? I have OpenSSH installed with the agent but not the server (via Chocolatey package param /SSHAgentFeature).

[manojampalam]

It should not. Do you have ssh-agent logs? Looks at Wiki Troubleshooting link.

[charabaruk]

I did look at the Troubleshooting wiki page, but it exclusively refers to sshd, not ssh-agent. As far as I can tell, there's no enhanced logging for ssh-agent the way there is for ssh and sshd.

[manojampalam]

https://github.com/PowerShell/Win32-OpenSSH/wiki/Troubleshooting%20Steps
ssh-agent.log should be there under logs folder

[charabaruk]

There was no logs folder, either, but after creating one a ssh-agent.log file was generated in it. I put LogLevel to DEBUG3, and here's what showed up in the log file (using same scenario as above):

13640 08:47:04 204 agent_start pid:13640, dbg:0, child:0, pipe:0
13640 08:47:19 454 client pid 7020 connected
13640 08:47:19 455 debug1: spawned worker 23476 for agent client pid 7020 
23476 08:47:19 463 agent_start pid:23476, dbg:0, child:1, pipe:104
23476 08:47:19 463 debug3: connection io 000002CD080F4300 #bytes:0 state:0
23476 08:47:29 237 debug3: connection io 000002CD080F4300 #bytes:4 state:1
23476 08:47:29 237 debug3: connection io 000002CD080F4300 #bytes:1863 state:2
23476 08:47:29 238 debug1: connection 000002CD080F4300 clean up
23476 08:47:29 238 debug1: iocp error: 6 on 0000000000000000 \n
13640 08:47:32 159 client pid 24612 connected
13640 08:47:32 160 debug1: spawned worker 16740 for agent client pid 24612 
16740 08:47:32 168 agent_start pid:16740, dbg:0, child:1, pipe:104
16740 08:47:32 168 debug3: connection io 000002415C2A6600 #bytes:0 state:0
16740 08:47:32 168 debug3: connection io 000002415C2A6600 #bytes:4 state:1
16740 08:47:32 168 debug3: connection io 000002415C2A6600 #bytes:1 state:2
16740 08:47:32 168 debug1: connection 000002415C2A6600 clean up
16740 08:47:32 168 debug1: iocp error: 6 on 0000000000000000 \n

[DarwinJS]

@manojampalam - I am thinking the chocolatey package could just create the logs folder all the time so that this confusion could be avoided? Maybe you could also put an empty flag file in the logs folder in the zip so it is created? I wouldn't do just an empty folder as many unzippers have to be explicitly told to create empty folders.

[charabaruk]

@DarwinJS maybe just create it whenever the sshd or ssh-agent options are used? Unless ssh uses the same directory for client logs (which doesn't sound right).

[manojampalam]

@DarwinJS yes please.

[DarwinJS]

@manojampalam - already added along with a couple additional logging features: #577

[manojampalam]

@coldacid do you still see this issue? Did you try out the latest version?

[charabaruk]

@manojampalam just updated to 0.0.10.0 now and gave it a shot. Same results:

260 07:27:54 893 agent_start pid:260, dbg:0, child:0, pipe:0
260 07:28:02 150 client pid 16568 connected
260 07:28:02 151 debug1: spawned worker 8612 for agent client pid 16568 
8612 07:28:02 160 agent_start pid:8612, dbg:0, child:1, pipe:536
8612 07:28:02 160 debug3: connection io 0000019310779F90 #bytes:0 state:0
8612 07:28:08 265 debug3: connection io 0000019310779F90 #bytes:4 state:1
8612 07:28:08 266 debug3: connection io 0000019310779F90 #bytes:1850 state:2
8612 07:28:08 266 debug1: connection 0000019310779F90 clean up
8612 07:28:08 266 debug1: iocp error: 6 on 0000000000000000 \n
260 07:28:12 797 client pid 11008 connected
260 07:28:12 798 debug1: spawned worker 11928 for agent client pid 11008 
11928 07:28:12 808 agent_start pid:11928, dbg:0, child:1, pipe:536
11928 07:28:12 808 debug3: connection io 0000012E14CCA950 #bytes:0 state:0
11928 07:28:12 808 debug3: connection io 0000012E14CCA950 #bytes:4 state:1
11928 07:28:12 808 debug3: connection io 0000012E14CCA950 #bytes:1 state:2
11928 07:28:12 808 debug1: connection 0000012E14CCA950 clean up
11928 07:28:12 808 debug1: iocp error: 6 on 0000000000000000 \n

[charabaruk]

Probably doesn't actually need to be said, but after testing 0.0.11.0 I can report that the problem here persists. ssh-agent.log contents:

12412 20:57:35 772 agent_start pid:12412, dbg:0, child:0, pipe:0
12412 21:00:04 744 client pid 5284 connected
12412 21:00:04 745 debug1: spawned worker 2200 for agent client pid 5284 
2200 21:00:04 754 agent_start pid:2200, dbg:0, child:1, pipe:128
2200 21:00:04 754 debug3: connection io 00000278E0DF8FD0 #bytes:0 state:0
2200 21:00:11 335 debug3: connection io 00000278E0DF8FD0 #bytes:4 state:1
2200 21:00:11 335 debug3: connection io 00000278E0DF8FD0 #bytes:1850 state:2
2200 21:00:11 336 debug1: connection 00000278E0DF8FD0 clean up
2200 21:00:11 336 debug1: iocp error: 6 on 0000000000000000 \n
12412 21:00:16 481 client pid 4520 connected
12412 21:00:16 482 debug1: spawned worker 1476 for agent client pid 4520 
1476 21:00:16 490 agent_start pid:1476, dbg:0, child:1, pipe:128
1476 21:00:16 490 debug3: connection io 000001DA148D9570 #bytes:0 state:0
1476 21:00:16 490 debug3: connection io 000001DA148D9570 #bytes:4 state:1
1476 21:00:16 490 debug3: connection io 000001DA148D9570 #bytes:1 state:2
1476 21:00:16 491 debug1: connection 000001DA148D9570 clean up
1476 21:00:16 491 debug1: iocp error: 6 on 0000000000000000 \n

[manojampalam]

Thanks for your patience @coldacid. I'm working on this now.
Can you dump the output of the following, in the session you are running ssh-add on ?
set SSH_AUTH_SOCK

[charabaruk]

> set SSH_AUTH_SOCK
Environment variable SSH_AUTH_SOCK not defined

EDIT: Just realized that 0.0.12.0 is now available. I tried this with 0.0.11.0. I'll provide updated log and details once the Chocolatey package is updated and installed.

[charabaruk]

Okay, so with 0.0.12.0, nothing seems to have changed.

Shell commands/output:

> reg query HKEY_LOCAL_MACHINE\SOFTWARE\SSH\Agent

HKEY_LOCAL_MACHINE\SOFTWARE\SSH\Agent
    ProcessID    REG_DWORD    0x3f8


> tasklist | grep ssh-agent
ssh-agent.exe                 1016 Services                   0      6,936 K

> set SSH_AUTH_SOCK
Environment variable SSH_AUTH_SOCK not defined

> ssh-add .ssh\id_rsa
Enter passphrase for .ssh\id_rsa:
Could not add identity ".ssh\id_rsa": communication with agent failed

> ssh-add -l
error fetching identities for protocol 2: communication with agent failed
The agent has no identities.

ssh-agent.log:

1016 21:47:47 280 agent_start pid:1016, dbg:0, child:0, pipe:0
1016 21:49:37 488 client pid 6180 connected
1016 21:49:37 489 debug1: spawned worker 14664 for agent client pid 6180 
14664 21:49:37 497 agent_start pid:14664, dbg:0, child:1, pipe:548
14664 21:49:37 498 debug3: connection io 0000017580CCB880 #bytes:0 state:0
14664 21:49:44 764 debug3: connection io 0000017580CCB880 #bytes:4 state:1
14664 21:49:44 764 debug3: connection io 0000017580CCB880 #bytes:1849 state:2
14664 21:49:44 765 debug1: connection 0000017580CCB880 clean up
14664 21:49:44 765 debug1: iocp error: 6 on 0000000000000000 \n
1016 21:49:50 865 client pid 19600 connected
1016 21:49:50 866 debug1: spawned worker 15224 for agent client pid 19600 
15224 21:49:50 875 agent_start pid:15224, dbg:0, child:1, pipe:548
15224 21:49:50 875 debug3: connection io 000001BC0CB2D720 #bytes:0 state:0
15224 21:49:50 875 debug3: connection io 000001BC0CB2D720 #bytes:4 state:1
15224 21:49:50 875 debug3: connection io 000001BC0CB2D720 #bytes:1 state:2
15224 21:49:50 875 debug1: connection 000001BC0CB2D720 clean up
15224 21:49:50 875 debug1: iocp error: 6 on 0000000000000000 \n

[manojampalam]

OK. I added additional tracing in ssh-agent.exe. Can you replace with the attached one and regenerate traces?

ssh-agent.zip

[charabaruk]

Shell:

> reg query HKEY_LOCAL_MACHINE\SOFTWARE\SSH\Agent

HKEY_LOCAL_MACHINE\SOFTWARE\SSH\Agent
    ProcessID    REG_DWORD    0x4c8c


> tasklist | grep ssh-agent
ssh-agent.exe                19596 Services                   0      7,360 K

> set SSH_AUTH_SOCK
Environment variable SSH_AUTH_SOCK not defined

> ssh-add .ssh\id_rsa
Enter passphrase for .ssh\id_rsa:
Could not add identity ".ssh\id_rsa": communication with agent failed

> ssh-add -l
error fetching identities for protocol 2: communication with agent failed
The agent has no identities.

ssh-agent.log:

19596 08:21:18 007 agent_start pid:19596, dbg:0, child:0, pipe:0
19596 08:22:21 078 client pid 16480 connected
19596 08:22:21 079 debug1: spawned worker 12444 for agent client pid 16480 
12444 08:22:21 088 agent_start pid:12444, dbg:0, child:1, pipe:540
12444 08:22:21 088 debug3: connection io 000001FCB440E550 #bytes:0 state:0
12444 08:22:22 235 debug3: connection io 000001FCB440E550 #bytes:4 state:1
12444 08:22:22 235 debug3: connection io 000001FCB440E550 #bytes:1849 state:2
12444 08:22:22 235 debug1: LookupAccountNameW failed with 1332
12444 08:22:22 236 debug1: connection 000001FCB440E550 clean up
12444 08:22:22 236 debug1: iocp error: 6 on 0000000000000000 \n
19596 08:22:27 306 client pid 8600 connected
19596 08:22:27 307 debug1: spawned worker 15804 for agent client pid 8600 
15804 08:22:27 317 agent_start pid:15804, dbg:0, child:1, pipe:540
15804 08:22:27 317 debug3: connection io 0000022853580530 #bytes:0 state:0
15804 08:22:27 317 debug3: connection io 0000022853580530 #bytes:4 state:1
15804 08:22:27 317 debug3: connection io 0000022853580530 #bytes:1 state:2
15804 08:22:27 317 debug1: LookupAccountNameW failed with 1332
15804 08:22:27 317 debug1: connection 0000022853580530 clean up
15804 08:22:27 317 debug1: iocp error: 6 on 0000000000000000 \n

Looks like LookupAccountName doesn't like whatever name is being passed to it. If it helps, my system is not on a domain (seems to a common issue from a quick search of that error code) but it does use a Microsoft account login.

[manojampalam]

LookupAccountName is looking for "NT Service\SSHD"
Can you start sshd service and see what account its running under?

You could do this in Powershell
PS E:\temp> gps sshd -IncludeUserName
150 7376 0.22 21104 NT SERVICE\sshd sshd

[charabaruk]

Ah, I don't have the sshd service set up on this system. My expectation was that like on other platforms, ssh-agent would be usable without running the daemon as well.

[manojampalam]

You are right. Client side should work independently. I'll fix this for next drop. For the time being as a work around - install the server side components too.

[manojampalam]

Fix for this included in PowerShell/openssh-portable#121 and committed as part of
#681

[manojampalam]

We found some reliability issues with recent changes and will need time to do stabilization. This issue has been fixed but a drop wont be available till Mid May. Thanks for your patience.

[charabaruk]

Thanks for keeping me updated, @manojampalam. I'll hold my horses a little while longer!

[charabaruk]

Just tried out 0.14.0.0 and happy to say that I can add my SSH keys to ssh-agent without a problem now. Thanks @manojampalam! 🥇

[kevingentile]

I ran into this exact issue today. I've installed openssh following the first-use article

Add-WindowsCapability -Online -Name OpenSSH.Client~~~~0.0.1.0

using ssh-add or ssh-add -l yielded "communication with agent failed"

Installing OpenSSH Server resolved this issue

Add-WindowsCapability -Online -Name OpenSSH.Server~~~~0.0.1.0
Start-Service sshd

Is the client intended to handle this or will sshd always be required?