Vscode: VSCode sets VSCODE_LOGS on spawned 3rd party processes

[GabeDeBacker]

• VSCode Version: 1.29.1
• OS Version: Windows 10 RS5 x64

Steps to Reproduce:

1.Clone VSCode
2.Setup to build VSCode

1. Build VSCode
2. Launch VSCode to under debugger

Results -> Logging exceptions occur (such as)

Error: Failed opening file C:\Users\emclemen\AppData\Roaming\Code\logs\20181209T201113\cli.log for writing: Permission denied
    at new RotatingLogger (C:\Users\emclemen\AppData\Local\Programs\Microsoft VS Code\_\resources\app\node_modules.asar\spdlog\index.js:16:3)
    at Object.t.createSpdLogService (C:\Users\emclemen\AppData\Local\Programs\Microsoft VS Code\_\resources\app\out\vs\code\node\cliProcessMain.js:70:564)
    at Object.t.main (C:\Users\emclemen\AppData\Local\Programs\Microsoft VS Code\_\resources\app\out\vs\code\node\cliProcessMain.js:177:299)
    at C:\Users\emclemen\AppData\Local\Programs\Microsoft VS Code\_\resources\app\out\vs\code\node\cli.js:123:343

Does this issue occur when all extensions are disabled?: Yes

The log-file service (src\vs\platform\environment\node\environmentService.ts) is setting the log-file directory path into the process environment block.

    constructor(private _args: ParsedArgs, private _execPath: string) {
        if (!process.env['VSCODE_LOGS']) {
            const key = toLocalISOString(new Date()).replace(/-|:|\.\d+Z$/g, '');
            process.env['VSCODE_LOGS'] = path.join(this.userDataPath, 'logs', key);
        }

        this.logsPath = process.env['VSCODE_LOGS']!;
    }

As a result, if VSCode ever gets reloaded (which only really reloads a portion of VSCode), or launches a process (in the case of debugging), then the logging tries to open up a file that is already in use. The permission denied you are getting is not really an accurate error from the spdlog. What it is really getting is an sharing violation.

I believe the fix for this is quite simple which is to store a static inside the class rather than trying to use the environment block.

    private static processLogFilePath : string | undefined;

    constructor(private _args: ParsedArgs, private _execPath: string) {
        if (!EnvironmentService.processLogFilePath) {
            const key = toLocalISOString(new Date()).replace(/-|:|\.\d+Z$/g, '');
            EnvironmentService.processLogFilePath = path.join(this.userDataPath, 'logs', key);
        }

        this.logsPath = EnvironmentService.processLogFilePath;
    }
}

[GabeDeBacker]

This should also cover that it also affects instances of where VSCode launches itself (or an extension launches VSCode) since the newly launched instances cannot create log files in the same path.

[sandy081]

@GabeDeBacker What does this step mean

Launch VSCode to under debugger ?

[GabeDeBacker]

Typo. That was supposed to say "When debugging VSCode from VSCode". This occurs during development of VSCode as well is what this was supposed to capture.

[joaomoreno]

@GabeDeBacker The fact that child processes inherit the parent's environment is not a coincidental one. It's actually a pretty decent way of controlling a specific environment for a process tree.

The problem occurs when external processes are spawned from that tree: the environment needs to get back to the state that it was at the tree's root. This is what @Tyriar does in the terminal, for example.

What is happening is that any processes launched from VSCode (even other VSCode proceses in the case of debugging say an extension) end up trying to use the same logging path.

Is debugging the only execution path that makes you hit this issue?

I believe we must add the same environment cleaning code @Tyriar has in terminal (https://github.com/Microsoft/vscode/pull/64899#issuecomment-447025850) over to debug.

[GabeDeBacker]

No, we also hit this issue when updating our extension. Our extension is not in the public extension marketpklace as it is internal to Microsoft. Our extension has an auto-update mechanism whereby it downloads a new vsix, and spawns VSCode again to update the extension. This is done essentially by doing this:

        const vsCodeBinName: string = path.basename(process.execPath);
        const cmdFileName: string = (vsCodeBinName.toUpperCase() === 'CODE - INSIDERS.EXE') ? 'code-insiders.cmd' : 'code.cmd';
        const vsCodeCommandFile: string = path.join(path.dirname(process.execPath), 'bin', cmdFileName);

        if (!fs.existsSync(vsCodeCommandFile)) {
            window.showErrorMessage('Unable to update the WAVE extension because the installation location of VSCode cannot be found.');
            return;
        }

        const errorStrings: string[] = [];
        const outStrings: string[] = [];
        const childProcess: ChildProcess = exec(`"${vsCodeCommandFile}" --log error --install-extension "${downloadResponse.vsixPath}`, (err, stdout, stderr) => {

We log going to stderr as a failure to update the extension.

Other extensions are following the same technique. I.E.
https://github.com/Microsoft/vscode-cpptools/search?q=installVsix&unscoped_q=installVsix

I have also seen this exception hit simply by reloading VSCode through Ctrl+Shift+P reload.

We also have an active open issue about the terminal launching with environment variables inherited through parent processes as well #64731.

For our build process (which is out of process from VSCode), we employ a sequence of creating a clean environment block for the new process launch by calling the Win32 API CreateEnvironmentBlock which allows us a clean slate (this technique will not inherited environment variables from processes).

Using the environment block as a method to pass information from process to process in Windows can lead to unexpected results and should be avoided. The inheriting process does not know the provenance of the environment variables and in essence should be treated as untrusted input. For example, just setting VSCODE_LOGS to something that isn't a path before launching VSCode will likely cause all logging to fail (I have not confirmed this). Or even more worrisome is setting the environment variable path to something valid, but is not VSCode's desired logging location (i.e. what happens if an extension sets this environment variable in the extension host?)

Typically communication between processes is either done through a command line argument, application owned settings file, some type of IPC mechanism, etc.

[sandy081]

@GabeDeBacker I tried to launch VS Code from VS Code dev set up using the launch Launch VS Code and I do not see any errors you described. Am I missing any steps here?

[GabeDeBacker]

Sorry fo not replying sooner, been out of office for a bit.

All I do is turn on "All Exceptions", "Uncaught Exceptions", and "Promise Rejects" in VSCode's debugger.

I hit this today while debugging our extension (callstack below)

The logging exception is "Caught" and VSCode continues. But what this means is that VSCode is losing logging information. It also causes an error to be written to the stderr which causes some tools and extensions to think VSCode actually failed to perform an operation when it didn't.

Exception has occurred: Error
Error: EEXIST: file already exists, mkdir 'c:\Users\gabrield\AppData\Roaming\Code\logs\20190109T081532\exthost6\output_logging_20190109T082440'
at fs.mkdirSync (fs.js:885:18)
at Object.exports.wrapFsWithAsar.fs.mkdirSync (ELECTRON_ASAR.js:702:16)
at Function.sync (c:\Program Files (x86)\Microsoft VS Code\resources\app\node_modules.asar\mkdirp\index.js:71:13)
at new RotatingLogger (c:\Program Files (x86)\Microsoft VS Code\resources\app\node_modules.asar\spdlog\index.js:13:11)
at Object.t.createRotatingLogger (c:\Program Files (x86)\Microsoft VS Code\resources\app\out\vs\workbench\node\extensionHostProcess.js:303:259)
at new e (c:\Program Files (x86)\Microsoft VS Code\resources\app\out\vs\workbench\node\extensionHostProcess.js:307:468)
at new t (c:\Program Files (x86)\Microsoft VS Code\resources\app\out\vs\workbench\node\extensionHostProcess.js:582:309)
at e._createOutputChannel (c:\Program Files (x86)\Microsoft VS Code\resources\app\out\vs\workbench\node\extensionHostProcess.js:583:757)
at e.createOutputChannel (c:\Program Files (x86)\Microsoft VS Code\resources\app\out\vs\workbench\node\extensionHostProcess.js:583:535)
at Object.createOutputChannel (c:\Program Files (x86)\Microsoft VS Code\resources\app\out\vs\workbench\node\extensionHostProcess.js:740:852)
at LanguageClient.get outputChannel [as outputChannel] (C:\Users\gabrield.vscode\extensions\streetsidesoftware.code-spell-checker-1.6.10\node_modules\vscode-languageclient\lib\client.js:1611:51)
at Socket.client_1.BaseLanguageClient.createMessageTransports.encoding._getServerWorkingDir.then.electron.fork.serverProcess.stderr.on.data (C:\Users\gabrield.vscode\extensions\streetsidesoftware.code-spell-checker-1.6.10\node_modules\vscode-languageclient\lib\main.js:293:82)
at emitOne (events.js:116:13)
at Socket.emit (events.js:211:7)
at Socket.Readable.read (_stream_readable.js:475:10)
at Socket.read (net.js:366:15)
at flow (_stream_readable.js:846:34)
at resume_ (_stream_readable.js:828:3)
at _combinedTickCallback (internal/process/next_tick.js:138:11)
at process._tickCallback (internal/process/next_tick.js:180:9)

[sandy081]

Ok, now I understand the inheritance of these environment variables to the child process.

[GabeDeBacker]

@sandy081 - So are there plans to address this?

[Tyriar]

FYI I fixed this once and for all for the terminal:

https://github.com/Microsoft/vscode/blob/9301aefe0f5b8c2505421ee57721e5bcfde2e117/src/vs/workbench/parts/terminal/node/terminalEnvironment.ts#L54-L70

[joaomoreno]

I am tempted to just do that for all places where we spawn processes, instead of bigger change of letting go environment variables at all.

@Tyriar Could you organize with @weinand and @alexr00 to have a single place where this code would live and Terminal, Debug and Tasks would all utilize it?

[Tyriar]

@alexr00 @weinand I moved the function to sanitizeProcessEnvironment in processes.ts, please pick it up when you can.

[GabeDeBacker]

As a note, you should be launching processes using a fresh user environment block. VSCode could inherit all kinds of badness in the environment block as it does not know the process chain that led up to its launching.

Typically looking for and removing "what you don't like" is not the correct approach. You should start with what you know you like.

[GabeDeBacker]

To be very clear by a "clean user environment block" we do this for our build environment for Windows (this is C# pinvoke - error handling removed). This removes ALL traces of previous processes environment variables.

        IntPtr envBlock = IntPtr.Zero;
        IntPtr processToken = IntPtr.Zero;

            // Open the process token for "query, duplicate and impersonate" so that it can be used by
            // CreateEnvironmentBlock to obtain the user's security ID (sid) and construct things like the
            // USERNAME, USERDOMAIN, etc. environment variables.
            if (!OpenProcessToken(GetCurrentProcess(), TokenFlags.TOKEN_DUPLICATE | TokenFlags.TOKEN_QUERY | TokenFlags.TOKEN_IMPERSONATE, ref processToken))
            {
                throw new Win32Exception(Marshal.GetLastWin32Error());
            }

            if (!CreateEnvironmentBlock(out envBlock, processToken, bInherit: false))
            {
                throw new Win32Exception(Marshal.GetLastWin32Error());
            }

[Tyriar]

Maybe we should be doing that on Windows, it's a pretty big change and I'm not sure what it would break though. For example extensions may rely on the fact that the window's environment is inherited?

[GabeDeBacker]

@Tyriar - Relying on the Windows environment can actually wreak havoc on applications. In general we advise folks to not use environment variables as an IPC mechanism. However, yes, some environment variables are required hence why we create an environment block based on what the user has set. (which is the best we can do)

[GabeDeBacker]

@Tyriar
This still happens for me every time I debug the extension. You can see this in the console logs of the developers tools while debugging the extension.

We are also seeing it reported in our telemetry as well.

[Tyriar]

Duplicate of https://github.com/microsoft/vscode/issues/38428?

[connor4312]

Found this grooming issues. We've had cases where this happened before; right now in js-debug we're unsetting ELECTRON_RUN_AS_NODE and the app insights environment variable, but in the linked commit I adopt the more thorough sanitization that Daniel added to VS Code which should fix the debugging case, which looks like the only remaining problem here.