Vscode-remote-release: Reconnection without overlay

Created on 3 Sep 2019  路  4Comments  路  Source: microsoft/vscode-remote-release

On the connector wifi I saw this happen

  • Was in "trying to reconnect" mode with the overlay
  • It looked like reconnection failed. The overlay went away and the status bar item said "disconnected from..."
  • But after a few seconds it reconnected without showing the reconnection overlay.

Is that a valid state change now or a bug?

Window:

[2019-09-03 07:29:23.928] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] waiting for 5 seconds before reconnecting...
[2019-09-03 07:29:28.923] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] resolving connection...
[2019-09-03 07:29:28.931] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] resolving connection...
[2019-09-03 07:29:34.491] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] connecting to 127.0.0.1:64378...
[2019-09-03 07:29:34.493] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] connecting to 127.0.0.1:64378...
[2019-09-03 07:30:04.492] [renderer2] [error] [remote-connection] The time limit has been reached for a connection. Error:
[2019-09-03 07:30:04.494] [renderer2] [error] Error: Time limit reached
    at setTimeout (file:///Applications/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/workbench/workbench.desktop.main.js:1678:101)
[2019-09-03 07:30:04.495] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] A network error occured while trying to reconnect, will try again...
[2019-09-03 07:30:04.513] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] waiting for 10 seconds before reconnecting...
[2019-09-03 07:30:04.524] [renderer2] [error] [remote-connection] The time limit has been reached for a connection. Error:
[2019-09-03 07:30:04.525] [renderer2] [error] Error: Time limit reached
    at setTimeout (file:///Applications/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/workbench/workbench.desktop.main.js:1678:101)
[2019-09-03 07:30:04.527] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] A network error occured while trying to reconnect, will try again...
[2019-09-03 07:30:04.528] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] waiting for 10 seconds before reconnecting...
[2019-09-03 07:30:14.509] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] resolving connection...
[2019-09-03 07:30:14.534] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] resolving connection...
[2019-09-03 07:30:16.683] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] connecting to 127.0.0.1:64478...
[2019-09-03 07:30:16.685] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] connecting to 127.0.0.1:64478...
[2019-09-03 07:30:17.131] [renderer2] [info] [remote-connection][Management   ][6795b鈥[reconnect] reconnected!
[2019-09-03 07:30:17.141] [renderer2] [info] [remote-connection][ExtensionHost][b94d8鈥[reconnect] reconnected!

Remote-SSH

[14:29:34.494] [Forwarding server 64378] Got connection 1
[14:29:34.494] [Forwarding server 64378] Got connection 2
[14:29:45.813] > packet_write_wait: Connection to 168.62.29.176 port 22: Broken pipe
[14:29:46.066] "install" terminal command done
[14:29:46.066] Install terminal quit with output: packet_write_wait: Connection to 168.62.29.176 port 22: Broken pipe
[14:30:04.474] Failed to set up socket for dynamic port forward to remote port 43593: Proxy connection timed out. Is the remote port correct?
[14:30:04.475] Failed to set up socket for dynamic port forward to remote port 33193: Proxy connection timed out. Is the remote port correct?
[14:30:04.495] Failed to set up socket for dynamic port forward to remote port 43593: Proxy connection timed out. Is the remote port correct?
[14:30:04.495] Failed to set up socket for dynamic port forward to remote port 43593: Proxy connection timed out. Is the remote port correct?
[14:30:14.516] SSH Resolver called for "ssh-remote+robfast", attempt 25
[14:30:14.516] SSH Resolver called for host: robfast
[14:30:14.516] Setting up SSH remote "robfast"
[14:30:14.517] Using commit id "dcc01858d3f75696568eb751238d01b30a1e7d33" and quality "insider" for server
[14:30:14.523] Running script with connection command: ssh -D 64476 -o ConnectTimeout=15 robfast bash
[14:30:14.523] Install and start server if needed
[14:30:16.577] > Running remote connection script
[14:30:16.577] Got some output, clearing connection timeout
[14:30:16.580] > Acquiring lock on /home/roblou/.vscode-server-insiders/bin/dcc01858d3f75696568eb751238d01b30a1e7d33/vscode-remote-lock.dcc01858d3f75696568eb751238d01b30a1e7d33
[14:30:16.591] > Found existing installation at /home/roblou/.vscode-server-insiders/bin/dcc01858d3f75696568eb751238d01b30a1e7d33...
[14:30:16.605] > Found running server...
>  
> *
> * Reminder: You may only use this software with Visual Studio family products,
> * as described in the license (https://go.microsoft.com/fwlink/?linkid=2077057)
> *
>  
[14:30:16.616] > Checking server status on port 43593 with wget
[14:30:16.624] > f1000f7b-be1e-4c75-817a-c7ee3071a265: start
> sshAuthSock====
[14:30:16.662] > agentPort==43593==
> webViewServerPort==33193==
> osReleaseId==ubuntu==
> arch==x86_64==
> webUiAccessToken==f2b88618-0e44-4a3f-9e90-f642bda7091a==
> f1000f7b-be1e-4c75-817a-c7ee3071a265: end
[14:30:16.662] Received install output: 
sshAuthSock====
agentPort==43593==
webViewServerPort==33193==
osReleaseId==ubuntu==
arch==x86_64==
webUiAccessToken==f2b88618-0e44-4a3f-9e90-f642bda7091a==

[14:30:16.663] Remote server is listening on port 43593
[14:30:16.663] Parsed server configuration: {"agentPort":43593,"webViewServerPort":33193,"osReleaseId":"ubuntu","arch":"x86_64","webUiAccessToken":"f2b88618-0e44-4a3f-9e90-f642bda7091a","sshAuthSock":""}
[14:30:16.664] Starting forwarding server. localPort 64478 -> socksPort 64476 -> remotePort 43593
[14:30:16.665] Forwarding server listening on 64478
[14:30:16.665] Waiting for ssh tunnel to be ready
[14:30:16.665] [Forwarding server 64478] Got connection 0
[14:30:16.666] Tunneled remote port 43593 to local port 64478
[14:30:16.666] Starting forwarding server. localPort 64481 -> socksPort 64476 -> remotePort 33193
[14:30:16.666] Forwarding server listening on 64481
[14:30:16.666] Waiting for ssh tunnel to be ready
[14:30:16.667] Tunneled remote port 33193 to local port 64481
[14:30:16.667] Resolved "ssh-remote+robfast" to "127.0.0.1:64478"
[14:30:16.667] TELEMETRY: {"eventName":"resolver","properties":{"outcome":"success","osReleaseId":"ubuntu","arch":"x86_64"},"measures":{"resolveAttempts":25,"retries":1}}
[14:30:16.667] ------




[14:30:16.668] [Forwarding server 64481] Got connection 0
[14:30:16.686] [Forwarding server 64478] Got connection 1
[14:30:16.686] [Forwarding server 64478] Got connection 2
bug verified
Source
picture roblourens

All 4 comments

I think that since reconnection isn't canceled, it will still run in the background after The time limit has been reached for a connection

roblourens picture roblourens on 3 Sep 2019

AFAICT the log looks pretty good:

  • it enters the reconnecting loop
  • it invokes the resolver
  • the resolver replies with 127.0.0.1:64378
  • but then it takes more than 30s to open a socket to 127.0.0.1:64378, so it times out with the The time limit has been reached for a connection error.
  • then it sleeps again for 10 seconds this time
  • then it invokes the resolver again, which now replies with 127.0.0.1:64478
  • it finally manages to connect

So AFAICT the business logic looks good. Looking at the _runReconnectingLoop method, the state changes it emits would be:

  • ConnectionLostEvent
  • ReconnectionWaitEvent
  • ReconnectionRunningEvent
  • ReconnectionWaitEvent
  • ReconnectionRunningEvent
  • ConnectionGainEvent

This code has become a lot more complex recently. @sbatten Do you think the UI handles correctly the above state change order ? Why would the UI disappear unless a ConnectionGainEvent occurs ... ?

alexdima picture alexdima on 11 Sep 2019

That flow of events seems very normal. Reviewing the code, I am not sure what could cause this, I will have to try to reproduce. There are only 2 cases to remove the reconnection overlay without user interaction and those are ConnectionGain and ReconnectionPermanentFailure. All other cases have a showProgress call to reflect the current state.

sbatten picture sbatten on 11 Sep 2019
👍1

We figured it out. Steps for verification

From https://github.com/Microsoft/vscode/commit/263312b6ddb97a464bed0d53b55b473d8a7fab1e

  • Connect to a remote
  • Go offline
  • Reconnection overlay appears
  • Click dismiss
  • Wait for a round of "reconnecting in 5 seconds" and "Attempting to reconnect"
  • The next "reconnecting in x seconds" notification appears for an instant then disappears
roblourens picture roblourens on 12 Sep 2019
🎉1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

JacksonKearl picture JacksonKearl  路  3Comments
jkoritzinsky picture jkoritzinsky  路  3Comments
kzawad1 picture kzawad1  路  3Comments
peterkappelt picture peterkappelt  路  3Comments
nphmuller picture nphmuller  路  3Comments