[Remote-SSH Bug]: Race condition when parsing ssh.exe -V output on Windows

[revorm]

Is there an existing issue for this bug?

• I have searched the existing issues

Required Troubleshooting Steps

• I have followed these troubleshooting steps
• I have tried both values of the remote.SSH.useLocalServer setting (more info here)

Connect Locally

It connects successfully

->

No response

Expected Behavior

Connection with the remote-ssh extension should work without issues when the target host is reachable.

I have a hacky code workaround I've validated and a suggestion for how to fix this, please see below!

Steps To Reproduce

1. Windows 10 in a corp environment
2. Large number of strange antivirus programs installed
3. Try to connect vs code to a remote linux server
4. For some reason the 'exit' event of the ssh version string check subprocess fires before the stderr data of the ssh process is received
5. Connection attempt hangs indefinitely

Remote-SSH Log

I'm unable to provide the log due to corporate restrictions.

Anything else?

The problem exists in the below code in the extension (ran the js through a beautifier to make it readable)

                        t.debug(`Checking ssh with "${e} -V"`);
                        const i = [],
                            s = [];
                        let a, c = e;
                        f.isWindows && (c.endsWith(".bat") || c.endsWith(".cmd")) && (c = `"${c}"`, a = {
                            shell: !0
                        });
                        const l = n.spawn(c, ["-V"], a);
                        l.stdout.on("data", (e => {
                            i.push(e), t.debug("stdout> " + e.toString())
                        })), l.stderr.on("data", (e => {
                            s.push(e), t.debug("> " + e.toString())
                        })), l.on("error", (e => {
                            t.debug("Got error from ssh: " + e.message), clearTimeout(d), r(I.NotFound)
                        }));
                        let u = !1;
                        const d = setTimeout((() => {
                            u = !0, t.debug("ssh is not exiting, continuing"), r(I.NotFound), l.kill()
                        }), 1e4);
                        l.on("exit", (e => { // XXX we get here before s.push above has been called with the version string data
                            if (u) return;
                            if (clearTimeout(d), e) return t.debug("ssh exited with code: " + e), void r(I.NotFound);
                            const n = Buffer.concat(i).toString("utf8").trim(),
                                o = Buffer.concat(s).toString("utf8").trim() || n;
                            o && (o.match(/OpenSSH_for_Windows/i) ? r(I.WindowsSsh) : o.match(/OpenSSH/i) ? r(I.Other) : (t.debug("ssh output did not match /OpenSSH/"), r(I.NotFound)))
                        }))

In my case, just calling r(I.WindowsSsh) on exit is sufficient to make connections work every time.

As a longer term fix, perhaps there is a way to use a promise instead of relying on the ordering of the stderr data and exit events to parse the version string. The nodejs docs say that 'When the 'exit' event is triggered, child process stdio streams might still be open.' but I'm unable to tell if that suggests that stderr may still contain data when 'exit' is triggered or not.

Additionally, it's not entirely clear to me why the failure mode is no progress instead of I.NotFound being passed to the result callback.

[joshspicer]

Thanks for the details.

I agree that it's not clear to me why you aren't hitting I.NotFound. You don't see ssh is not exiting, continuing in your logs, do you? Could you share the snippet of the log that has any of these t.debug strings?

I've found a handful of old issues around this code (eg: #3731 (comment))

[joshspicer]

Oh, I suppose we aren't resolving the listener if we get nothing back from stderr or stdout. Here's the non-minified 'exit' callback that you already shared

// ...
// ...

        if (code) {
      		logger.debug('ssh exited with code: ' + code);
      		resolve(SshType.NotFound);
      		return;
        }

	const stdout = Buffer.concat(stdoutBuffers).toString('utf8').trim();
	const stderr = Buffer.concat(stderrBuffers).toString('utf8').trim();

	// SSH writes -V output to stderr
	const resultOutput = stderr || stdout;
	if (resultOutput) {
		if (!!resultOutput.match(/OpenSSH_for_Windows/i)) {
			resolve(SshType.WindowsSsh);
		} else if (!!resultOutput.match(/OpenSSH/i)) {
			resolve(SshType.Other);
		} else {
			logger.debug('ssh output did not match /OpenSSH/');
			resolve(SshType.NotFound);
		}
	}
// End

[revorm]

Hi!
Here's the last lines of the log:

[06:55:09.404] Install and start server if needed
[06:55:09.411] Checking ssh with "C:\Windows\System32\OpenSSH\ssh.exe -V"
[06:55:09.472] > OpenSSH_for_Windows_9.5p1, LibreSSL 3.8.2

The next expected line (from when it's working) is

[06:55:09.484] Running script with connection command: "C:\Windows\System32\OpenSSH\ssh.exe" -T -D 51952 devbox sh

but that one never appears and instead the connection attempt simply hangs.

The local extension host in turn logs
2024-12-11 06:55:10.349 [info] [resolveAuthority(ssh-remote,1)][1403ms] waiting...
with an ever increasing wait time in milliseconds.

[revorm]

I have a fairly non-invasive workaround for now, where I set "remote.SSH.path" to point to a CMD script which if launched with -V runs ssh.exe -V and sleeps for a second before exiting and this appears to be sufficient to make the race condition go away on the hosts where we've seen this issue.