Delay in minutes before systray icon appears after startup of the agent - and vice-versa about wsl-ssh-agent HOT 10 CLOSED

Often you could see what is going on by running https://docs.microsoft.com/en-us/sysinternals/downloads/debugview and adding "--debug" key to the command line. Program is instrumented to output a lot of information.

I cannot even imagine what would cause such delays - antivirus? some Windows shell extension? So unless I would be able to reproduce it somehow I am afraid it would be difficult for me to help.

Also I am puzzled - to the best of my knowledge 1909 does not have WSL2 yet, does it?

from wsl-ssh-agent.

Also I am puzzled - to the best of my knowledge 1909 does not have WSL2 yet, does it?

You are right - I was assuming WSL2 came with W10 v1903 update, but apparently it didn't.

I cannot even imagine what would cause such delays - antivirus? some Windows shell extension? So unless I would be able to reproduce it somehow I am afraid it would be difficult for me to help.

I've tried disabling Windows Defender real-time protection with no real change.
Starting the agent without any command line parameters shows up the systray icon immediately though - and exiting via systray stops the process right away too.

Then I've tried narrowing down to specific param one by one and it looks like -setenv causes the slow startup and shutdown. Starts quick with all the others.

I will try the debugview to see what I get.

from wsl-ssh-agent.

"--setenv" does 2 things - it modifies HKCU registry setting up new environment variables and broadcasts WM_SETTINGCHANGE to let main windows know that environment has been changed. On exit it removes modifications and broadcasts again. The only place I think program could get in troubles - when parsing existing environment looking for variable to set/remove. You should see some debug output on that. If this is the case - it should be easily fixable.

from wsl-ssh-agent.

Did some debugging via sysinternal's dbgview, below is the log showing that it takes ~9 minutes before the agent confirms listening to the Unix socket. I have cleaned up irrelevant idle type of logs entries. The agent was run with -debug param too. dbgview.exe set to listen to all types of events (

00000001	0.00000000	[8580] [wsl-ssh-agent-gui] Windows - CurrentMajorVersionNumber: 10, CurrentBuild: 18363	
00000002	0.00063120	[8580] [wsl-ssh-agent-gui] Set 'WSL_AUTH_SOCK=e:\ssh-agent.sock'	
00000003	0.00065500	[8580] [wsl-ssh-agent-gui] Was 'WSLENV=WSL_AUTH_SOCK/up'	
00000004	0.00068270	[8580] [wsl-ssh-agent-gui] Set 'WSLENV=WSL_AUTH_SOCK/up'	
00000005	2.10842156	[26372] MSAFD: Pending APCs in cleanup! Waiting...	
00000006	3.10930610	[26372] MSAFD: (cleanup) ... No APCs fired, keeping DLL ref count	
00000021	209.98515320	[6740] CNoteStoreClient::getSyncStateWithMetrics: executed in 0.199691 sec	
00000022	210.18276978	[6740] CNoteStoreClient::getSyncState: executed in 0.162935 sec	
00000023	210.19224548	[6740] 0.002376 sec	
00000024	210.27000427	[6740] CNavPaneTree::AddShortcutItems: executed in 0.001860 sec	
00000045	510.45181274	[6740] CNoteStoreClient::getSyncStateWithMetrics: executed in 0.188766 sec	
00000046	510.65829468	[6740] CNoteStoreClient::getSyncState: executed in 0.176517 sec	
00000047	510.66909790	[6740] 0.002842 sec	
00000048	510.80484009	[6740] CNavPaneTree::AddShortcutItems: executed in 0.002398 sec	
00000049	516.22863770	[6740] CUserIdleActivityPurgeNoteContent::Execute: executed in 0.000002 sec	
00000050	531.22869873	[6740] CUserIdleActivityPurgeNoteContent::Execute: executed in 0.000001 sec	
00000051	532.14093018	[6396] CIntelCpLSPCONSvcModule::OnPowerEvent() 0xa 	
00000052	532.17456055	[8580] [wsl-ssh-agent-gui] Listening on Unix socket: e:\ssh-agent.sock	

Shutdown via systray log:

00000001	0.00000000	[8580] [wsl-ssh-agent-gui] Exiting systray	
00000002	0.00729570	[8580] [wsl-ssh-agent-gui] Listener Accept error on \\.\pipe\openssh-ssh-agent - 'accept unix e:\ssh-agent.sock: use of closed network connection'	
00000003	0.00737850	[8580] [wsl-ssh-agent-gui] Quiting - serve on e:\ssh-agent.sock ended	
00000004	0.00760000	[8580] [wsl-ssh-agent-gui] Del 'WSL_AUTH_SOCK'	
00000005	0.00764000	[8580] [wsl-ssh-agent-gui] Was 'WSLENV=WSL_AUTH_SOCK/up'	
00000006	0.00773040	[8580] [wsl-ssh-agent-gui] Del 'WSLENV'	

Does that help at all?

from wsl-ssh-agent.

Not really. I could see all "normal" log entries, no errors - except with with very long delay, probably at the point when settings change is broadcast. I could also see various messages from different apps - Microsoft Winsock2 provider, Evernote, Intel HDCP drivers... Have no idea how normal those messages are on your system.

After reading documentation I think delay happens when SendMessage is being used to notify other windows in the system about environment change. We could try to use either SendMessageTimeout or SendMessageCallback instead to confirm this. But it also means that one of the apps on your system has main window windows proc hanging or delaying processing.

from wsl-ssh-agent.

@Romasato - please, try latest version 1.4. I replaced SendMessage call with SendMessageTimeout and added additional diagnostic around it. If I am right this should take care of your problem. Here is log on my box:

[9420] [wsl-ssh-agent-gui] Windows - CurrentMajorVersionNumber: 10, CurrentBuild: 18363
[9420] [wsl-ssh-agent-gui] Starting lemonade server on '2489;127.0.0.1/24'
[9420] [wsl-ssh-agent-gui] Serving lemonade
[9420] [wsl-ssh-agent-gui] Set 'WSL_AUTH_SOCK=C:\Users\rupor\AppData\Local\Temp\ssh-948102883.sock'
[9420] [wsl-ssh-agent-gui] Was 'WSLENV=USERPROFILE/up'
[9420] [wsl-ssh-agent-gui] Set 'WSLENV=USERPROFILE/up:WSL_AUTH_SOCK/up'
[9420] [wsl-ssh-agent-gui] Broadcasting environment change. From 2019-11-28 22:15:33.3863189 -0500 EST m=+0.018000001
[9420] [wsl-ssh-agent-gui] Broadcasting environment change. To   2019-11-28 22:15:33.4161724 -0500 EST m=+0.047853501, Elapsed 29.8535ms
[9420] [wsl-ssh-agent-gui] Listening on Unix socket: C:\Users\rupor\AppData\Local\Temp\ssh-948102883.sock

from wsl-ssh-agent.

Hi @rupor-github - awesome, just tried the new version and the agent starts up right away ;-)

from wsl-ssh-agent.

Looks like your Evernote is doing something very long - like 10 minutes long on environment change...

from wsl-ssh-agent.

Resolved

from wsl-ssh-agent.

Looks like your Evernote is doing something very long - like 10 minutes long on environment change...

Tried with Evernote not running with the same result of long delay.

In any case - thank you for finding a workaround!

from wsl-ssh-agent.