Env vars are not passed to the extension host as expected after 1.53 update

[hyangah]

Our extension tests started to fail after 1.53 update because they couldn't find the tools the extension depends on from PATH any more. In our CI, we configure PATH to include the directory for those tools, and then run the test script that uses 'vscode-test''s runTests. A bit of logging revealed that the test code no longer sees the PATH value we configured.

The tests still pass with 1.52.1.

I cannot find the relevant change description from the release note yet.
Sorry if I missed related announcement.

I am not sure yet this change of behavior actually affects our extension users, or this is just a problem when running the test script that uses the runTests library.

[hyangah]

Observed this issue affects only PATH env var, and other user-defined environment variables are left intact.
Using Ubuntu 8.2.0-21ubuntu1, docker.

I got verbose logging by passing the --verbose flag to the runTests:

		await runTests({
		         ...
			launchArgs: [ ..., '--verbose', `-log=info'],
		});

Full log

```

Found .vscode-test/vscode-1.53.0. Skipping download.
Fontconfig warning: "/etc/fonts/fonts.conf", line 100: unknown element "blank"

(electron) Sending uncompressed crash reports is deprecated and will be removed in a future version of Electron. Set { compress: true } to opt-in to the new behavior. Crash reports will be uploaded gzipped, which most crash reporting servers support.

Warning: 'sandbox' is not in the list of known options, but still passed to Electron/Chromium.

[main 2021-02-05T06:48:45.647Z] Starting VS Code

[main 2021-02-05T06:48:45.647Z] from: /workspace/.vscode-test/vscode-1.53.0/VSCode-linux-x64/resources/app

[main 2021-02-05T06:48:45.648Z] args: {
  _: [],
  diff: false,
  add: false,
  goto: false,
  'new-window': false,
  'reuse-window': false,
  wait: false,
  'user-data-dir': '${workspaceFolder}/.user-data-dir-test',
  help: false,
  'list-extensions': false,
  'show-versions': false,
  version: false,
  verbose: true,
  log: 'info',
  status: false,
  'prof-startup': false,
  'prof-v8-extensions': false,
  'disable-extensions': true,
  'disable-gpu': false,
  telemetry: false,
  extensionDevelopmentPath: [ '/workspace' ],
  extensionTestsPath: '/workspace/out/test/gopls/index',
  debugRenderer: false,
  logExtensionHostCommunication: false,
  'skip-release-notes': false,
  'disable-telemetry': false,
  'disable-updates': false,
  'disable-crash-reporter': false,
  'crash-reporter-id': 'XXX',
  'skip-add-to-recently-opened': false,
  'unity-launch': false,
  'open-url': false,
  'file-write': false,
  'file-chmod': false,
  'driver-verbose': false,
  force: false,
  'do-not-sync': false,
  trace: false,
  'force-user-env': false,
  'force-disable-user-env': false,
  'open-devtools': false,
  __sandbox: false,
  'no-proxy-server': false,
  nolazy: false,
  'force-renderer-accessibility': false,
  'ignore-certificate-errors': false,
  'allow-insecure-localhost': false,
  logsPath: '/workspace/${workspaceFolder}/.user-data-dir-test/logs/20210205T064845'
}

[main 2021-02-05T06:48:45.657Z] Resolving machine identifier...

[main 2021-02-05T06:48:45.657Z] Resolved machine identifier: XXX

[main 2021-02-05T06:48:45.657Z] Main->SharedProcess#connect

[main 2021-02-05T06:48:45.689Z] lifecycle (main): phase changed (value: 2)

[main 2021-02-05T06:48:45.689Z] windowsManager#open

[main 2021-02-05T06:48:45.689Z] windowsManager#open pathsToOpen [ [Object: null prototype] {} ]

[main 2021-02-05T06:48:45.691Z] window#validateWindowState: validating window state on 1 display(s) {
  width: 1024,
  height: 768,
  mode: 1,
  x: 0,
  y: 0,
  hasDefaultState: true
}

[main 2021-02-05T06:48:45.691Z] window#validateWindowState: 1 monitor working area { x: 0, y: 0, width: 1024, height: 768 }

[main 2021-02-05T06:48:45.691Z] window#ctor: using window state {
  width: 1024,
  height: 768,
  mode: 1,
  x: 0,
  y: 0,
  hasDefaultState: true
}

[main 2021-02-05T06:48:45.738Z] windowsManager#open used window count 1 (workspacesToOpen: 0, foldersToOpen: 0, emptyToRestore: 0, emptyToOpen: 1)

[main 2021-02-05T06:48:45.739Z] lifecycle (main): phase changed (value: 3)

[main 2021-02-05T06:48:45.739Z] update#setState idle

[main 2021-02-05T06:48:45.739Z] resolveShellEnv(): running (macOS/Linux)

[main 2021-02-05T06:48:45.739Z] getUnixShellEnvironment#runAsNode undefined
[main 2021-02-05T06:48:45.739Z] getUnixShellEnvironment#noAttach undefined

[main 2021-02-05T06:48:45.740Z] getUnixShellEnvironment#env {
  npm_config_user_agent: 'npm/7.5.1 node/v15.8.0 linux x64',
  NODE_VERSION: '15.8.0',
  YARN_VERSION: '1.22.5',
  HOSTNAME: 'XXX',
  npm_node_execpath: '/usr/local/bin/node',
  SHLVL: '1',
  OLDPWD: '/workspace',
  HOME: '/home/vscodego',
  npm_package_json: '/workspace/package.json',
  npm_config_userconfig: '/home/vscodego/.npmrc',
  COLOR: '0',
  npm_config_metrics_registry: 'https://registry.npmjs.org/',
  _: '/usr/local/bin/npm',
  npm_config_prefix: '/usr/local',
  npm_config_cache: '/home/vscodego/.npm',
  npm_config_node_gyp: '/usr/local/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js',
  PATH: '/workspace/node_modules/.bin:/node_modules/.bin:/usr/local/lib/node_modules/npm/node_modules/@npmcli/run-script/lib/node-gyp-bin:/home/vscodego/go/bin:/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin',
  NODE: '/usr/local/bin/node',
  npm_package_name: 'go',
  DISPLAY: ':99',
  npm_config_loglevel: 'silent',
  npm_lifecycle_script: 'npm run test-compile && node ./out/test/runTest.js',
  DEBIAN_FRONTEND: 'noninteractive',
  PREFIX: '/usr/local',
  npm_package_version: '0.22.0-dev',
  npm_lifecycle_event: 'test',
  npm_config_init_module: '/home/vscodego/.npm-init.js',
  npm_config_globalconfig: '/usr/local/etc/npmrc',
  PWD: '/workspace',
  npm_execpath: '/usr/local/lib/node_modules/npm/bin/npm-cli.js',
  npm_command: 'test',
  npm_package_engines_vscode: '^1.46.0',
  INIT_CWD: '/workspace',
  EDITOR: 'vi',
  VSCODE_GO_IN_TEST: '1',
  DBUS_SESSION_BUS_ADDRESS: 'disabled:',
  CHROME_DESKTOP: 'code-url-handler.desktop',
  ORIGINAL_XDG_CURRENT_DESKTOP: 'undefined',
  NO_AT_BRIDGE: '1',
  VSCODE_NLS_CONFIG: '{"locale":"en-us","availableLanguages":{},"_languagePackSupport":true}',
  VSCODE_NODE_CACHED_DATA_DIR: '/workspace/${workspaceFolder}/.user-data-dir-test/CachedData/8490d3dde47c57ba65ec40dd192d014fd2113496',
  VSCODE_IPC_HOOK: '/workspace/${workspaceFolder}/.user-data-dir-test/1.53.0-main.sock',
  VSCODE_PID: '738',
  ELECTRON_RUN_AS_NODE: '1',
  ELECTRON_NO_ATTACH_CONSOLE: '1'
}

[main 2021-02-05T06:48:45.740Z] getUnixShellEnvironment#spawn '/workspace/.vscode-test/vscode-1.53.0/VSCode-linux-x64/code' -p '"c3a200a04cc5" + JSON.stringify(process.env) + "c3a200a04cc5"'

bash: cannot set terminal process group (-1): Inappropriate ioctl for device

bash: no job control in this shell

(node:738) electron: The default of contextIsolation is deprecated and will be changing from false to true in a future release of Electron.  See https://github.com/electron/electron/issues/23506 for more information

[main 2021-02-05T06:48:45.873Z] getUnixShellEnvironment#raw c3a200a04cc5{"VSCODE_NODE_CACHED_DATA_DIR":"/workspace/${workspaceFolder}/.user-data-dir-test/CachedData/8490d3dde47c57ba65ec40dd192d014fd2113496","npm_package_engines_vscode":"^1.46.0","npm_config_node_gyp":"/usr/local/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js","VSCODE_NLS_CONFIG":"{\"locale\":\"en-us\",\"availableLanguages\":{},\"_languagePackSupport\":true}","YARN_VERSION":"1.22.5","npm_execpath":"/usr/local/lib/node_modules/npm/bin/npm-cli.js","VSCODE_GO_IN_TEST":"1","DISPLAY":":99","HOSTNAME":"XXX","ORIGINAL_XDG_CURRENT_DESKTOP":"undefined","OLDPWD":"/workspace","EDITOR":"vi","npm_package_json":"/workspace/package.json","CHROME_DESKTOP":"code-url-handler.desktop","npm_config_user_agent":"npm/7.5.1 node/v15.8.0 linux x64","NO_AT_BRIDGE":"1","npm_config_init_module":"/home/vscodego/.npm-init.js","npm_config_loglevel":"silent","PREFIX":"/usr/local","npm_config_userconfig":"/home/vscodego/.npmrc","npm_lifecycle_event":"test","PWD":"/workspace","HOME":"/home/vscodego","npm_config_cache":"/home/vscodego/.npm","npm_command":"test","DEBIAN_FRONTEND":"noninteractive","NODE_VERSION":"15.8.0","ELECTRON_NO_ATTACH_CONSOLE":"1","npm_config_metrics_registry":"https://registry.npmjs.org/","npm_config_globalconfig":"/usr/local/etc/npmrc","npm_lifecycle_script":"npm run test-compile && node ./out/test/runTest.js","VSCODE_PID":"738","INIT_CWD":"/workspace","COLOR":"0","ELECTRON_RUN_AS_NODE":"1","SHLVL":"2","npm_config_prefix":"/usr/local","npm_node_execpath":"/usr/local/bin/node","npm_package_version":"0.22.0-dev","DBUS_SESSION_BUS_ADDRESS":"disabled:","PATH":"/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games","VSCODE_IPC_HOOK":"/workspace/${workspaceFolder}/.user-data-dir-test/1.53.0-main.sock","NODE":"/usr/local/bin/node","npm_package_name":"go","_":"/workspace/.vscode-test/vscode-1.53.0/VSCode-linux-x64/code"}c3a200a04cc5

[main 2021-02-05T06:48:45.874Z] getUnixShellEnvironment#result {
  VSCODE_NODE_CACHED_DATA_DIR: '/workspace/${workspaceFolder}/.user-data-dir-test/CachedData/8490d3dde47c57ba65ec40dd192d014fd2113496',
  npm_package_engines_vscode: '^1.46.0',
  npm_config_node_gyp: '/usr/local/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js',
  VSCODE_NLS_CONFIG: '{"locale":"en-us","availableLanguages":{},"_languagePackSupport":true}',
  YARN_VERSION: '1.22.5',
  npm_execpath: '/usr/local/lib/node_modules/npm/bin/npm-cli.js',
  VSCODE_GO_IN_TEST: '1',
  DISPLAY: ':99',
  HOSTNAME: 'XXX',
  ORIGINAL_XDG_CURRENT_DESKTOP: 'undefined',
  OLDPWD: '/workspace',
  EDITOR: 'vi',
  npm_package_json: '/workspace/package.json',
  CHROME_DESKTOP: 'code-url-handler.desktop',
  npm_config_user_agent: 'npm/7.5.1 node/v15.8.0 linux x64',
  NO_AT_BRIDGE: '1',
  npm_config_init_module: '/home/vscodego/.npm-init.js',
  npm_config_loglevel: 'silent',
  PREFIX: '/usr/local',
  npm_config_userconfig: '/home/vscodego/.npmrc',
  npm_lifecycle_event: 'test',
  PWD: '/workspace',
  HOME: '/home/vscodego',
  npm_config_cache: '/home/vscodego/.npm',
  npm_command: 'test',
  DEBIAN_FRONTEND: 'noninteractive',
  NODE_VERSION: '15.8.0',
  npm_config_metrics_registry: 'https://registry.npmjs.org/',
  npm_config_globalconfig: '/usr/local/etc/npmrc',
  npm_lifecycle_script: 'npm run test-compile && node ./out/test/runTest.js',
  VSCODE_PID: '738',
  INIT_CWD: '/workspace',
  COLOR: '0',
  SHLVL: '2',
  npm_config_prefix: '/usr/local',
  npm_node_execpath: '/usr/local/bin/node',
  npm_package_version: '0.22.0-dev',
  DBUS_SESSION_BUS_ADDRESS: 'disabled:',
  PATH: '/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games',
  VSCODE_IPC_HOOK: '/workspace/${workspaceFolder}/.user-data-dir-test/1.53.0-main.sock',
  NODE: '/usr/local/bin/node',
  npm_package_name: 'go',
  _: '/workspace/.vscode-test/vscode-1.53.0/VSCode-linux-x64/code'
}

[main 2021-02-05T06:48:45.882Z] resolveShellEnv(): running (macOS/Linux)

(node:795) Electron: Loading non-context-aware native module in renderer: '/workspace/.vscode-test/vscode-1.53.0/VSCode-linux-x64/resources/app/node_modules.asar.unpacked/vscode-sqlite3/build/Release/sqlite.node'. This is deprecated, see https://github.com/electron/electron/issues/18397.

[lifecycle] starting up (startup kind: 1)

lifecycle: phase changed (value: 2)

Renderer->SharedProcess#connect

[main 2021-02-05T06:48:46.634Z] SharedProcess: on vscode:createSharedProcessMessageChannel

Skipping initializing user data in desktop

Layout#layout, height: 742, width: 1023

In the log, the getUnixShellEnvironment#env shows the PATH the test script started with:

[main 2021-02-05T06:48:45.740Z] getUnixShellEnvironment#env {
  npm_config_user_agent: 'npm/7.5.1 node/v15.8.0 linux x64',
  ...
  PATH: '/workspace/node_modules/.bin:/node_modules/.bin:/usr/local/lib/node_modules/npm/node_modules/@npmcli/run-script/lib/node-gyp-bin:/home/vscodego/go/bin:/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin',
  ...

The getUnixShellEnvironment#raw shows the system default PATH.

[main 2021-02-05T06:48:45.873Z] getUnixShellEnvironment#raw 
...
"PATH":"/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games",
...

Our tests failed because they got the system default PATH. I don't know why though.
Please let me know if more information is needed or, if there is any additional testing/workaround I should try.

Our current temporary workaround is switch back to 1.52.1.

[joaomoreno]

I really could only find this as affecting the env resolution: dce22cf, from 1.52 to 1.53

@roblourens Let me know if you can't find anything related to your changes.

[hyangah]

Thanks! It's also likely that this is specific to our docker container or
the environment with which the test is running.
Only missing PATH but having other env vars inherited seems still strange to me.

[roblourens]

If you start vscode with the flag --force-disable-user-env, is it fixed?

Could you attach the same log from a run in 1.52?

One possibility is that your container is affected by the same issue in https://github.com/github/codespaces/issues/1639, where previously this process of probing environment vars wouldn't have happened at all because we weren't able to look up the shell. Now in 1.53 we are able to. And your container probably has a bashrc or profile or something else that sets the PATH to this default without appending to it.

[hyangah]

Thanks a lot @roblourens. Our tests are now passing with the flag!

Is this flag recommended though? If so, feel free to close this issue.
(I wonder if there is any important scenario we would miss if we use this flag 🤔...)

We use the standard node docker and the user from the definition.

user info = {"uid":1000,"gid":1000,"username":"node","homedir":"/home/node","shell":"/bin/bash"}

Here is the requested log from a run in 1.52.1

[main 2021-02-05T21:55:38.577Z] Starting VS Code

[main 2021-02-05T21:55:38.578Z] from: /workspace/.vscode-test/vscode-1.52.1/VSCode-linux-x64/resources/app

[main 2021-02-05T21:55:38.578Z] args: {
_: [],
diff: false,
add: false,
goto: false,
'new-window': false,
'reuse-window': false,
wait: false,
'user-data-dir': '${workspaceFolder}/.user-data-dir-test',
help: false,
'list-extensions': false,
'show-versions': false,
version: false,
verbose: true,
log: 'info',
status: false,
'prof-startup': false,
'disable-extensions': true,
'disable-gpu': false,
telemetry: false,
extensionDevelopmentPath: [ '/workspace' ],
extensionTestsPath: '/workspace/out/test/integration/index',
debugRenderer: false,
logExtensionHostCommunication: false,
'skip-release-notes': false,
'disable-telemetry': false,
'disable-updates': false,
'disable-crash-reporter': false,
'skip-add-to-recently-opened': false,
'unity-launch': false,
'open-url': false,
'file-write': false,
'file-chmod': false,
'driver-verbose': false,
force: false,
'do-not-sync': false,
trace: false,
'force-user-env': false,
'force-disable-user-env': false,
'open-devtools': false,
'no-proxy-server': false,
nolazy: false,
'force-renderer-accessibility': false,
'ignore-certificate-errors': false,
'allow-insecure-localhost': false,
logsPath: '/workspace/${workspaceFolder}/.user-data-dir-test/logs/20210205T215538'
}

[main 2021-02-05T21:55:38.582Z] Resolving machine identifier...

[main 2021-02-05T21:55:38.631Z] Resolved machine identifier: XXX

[main 2021-02-05T21:55:38.656Z] [storage :memory:] open(:memory:, retryOnBusy: true)

[main 2021-02-05T21:55:38.660Z] lifecycle (main): phase changed (value: 2)

[main 2021-02-05T21:55:38.661Z] windowsManager#open

[main 2021-02-05T21:55:38.661Z] windowsManager#open pathsToOpen [ [Object: null prototype] {} ]

[main 2021-02-05T21:55:38.663Z] window#validateWindowState: validating window state on 1 display(s) {
width: 1024,
height: 768,
mode: 1,
x: 0,
y: 0,
hasDefaultState: true
}

[main 2021-02-05T21:55:38.663Z] window#validateWindowState: 1 monitor working area { x: 0, y: 0, width: 1024, height: 768 }

[main 2021-02-05T21:55:38.663Z] window#ctor: using window state {
width: 1024,
height: 768,
mode: 1,
x: 0,
y: 0,
hasDefaultState: true
}

[main 2021-02-05T21:55:38.721Z] windowsManager#open used window count 1 (workspacesToOpen: 0, foldersToOpen: 0, emptyToRestore: 0, emptyToOpen: 1)

[main 2021-02-05T21:55:38.721Z] lifecycle (main): phase changed (value: 3)

[main 2021-02-05T21:55:38.722Z] update#setState idle

[main 2021-02-05T21:55:38.723Z] resolveShellEnv(): running (macOS/Linux)

[main 2021-02-05T21:55:38.723Z] getUnixShellEnvironment#runAsNode undefined

[main 2021-02-05T21:55:38.723Z] getUnixShellEnvironment#noAttach undefined

[main 2021-02-05T21:55:38.723Z] getUnixShellEnvironment#env {
npm_config_user_agent: 'npm/7.5.1 node/v15.8.0 linux x64',
NODE_VERSION: '15.8.0',
YARN_VERSION: '1.22.5',
HOSTNAME: 'XXX',
npm_node_execpath: '/usr/local/bin/node',
SHLVL: '1',
OLDPWD: '/workspace',
HOME: '/workspace/vscodego',
npm_package_json: '/workspace/package.json',
npm_config_userconfig: '/workspace/vscodego/.npmrc',
COLOR: '0',
npm_config_metrics_registry: 'https://registry.npmjs.org/',
_: '/usr/local/bin/npm',
npm_config_prefix: '/usr/local',
npm_config_cache: '/workspace/vscodego/.npm',
npm_config_node_gyp: '/usr/local/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js',
PATH: '/workspace/node_modules/.bin:/node_modules/.bin:/usr/local/lib/node_modules/npm/node_modules/@npmcli/run-script/lib/node-gyp-bin:/workspace/vscodego/go/bin:/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin',
NODE: '/usr/local/bin/node',
npm_package_name: 'go',
DISPLAY: ':99',
npm_config_loglevel: 'silent',
npm_lifecycle_script: 'npm run test-compile && node ./out/test/runTest.js',
DEBIAN_FRONTEND: 'noninteractive',
PREFIX: '/usr/local',
npm_package_version: '0.22.0-dev',
npm_lifecycle_event: 'test',
npm_config_init_module: '/workspace/vscodego/.npm-init.js',
npm_config_globalconfig: '/usr/local/etc/npmrc',
PWD: '/workspace',
npm_execpath: '/usr/local/lib/node_modules/npm/bin/npm-cli.js',
npm_command: 'test',
npm_package_engines_vscode: '^1.46.0',
INIT_CWD: '/workspace',
EDITOR: 'vi',
VSCODE_GO_IN_TEST: '1',
DBUS_SESSION_BUS_ADDRESS: 'disabled:',
CHROME_DESKTOP: 'code-url-handler.desktop',
ORIGINAL_XDG_CURRENT_DESKTOP: 'undefined',
NO_AT_BRIDGE: '1',
VSCODE_NLS_CONFIG: '{"locale":"en-us","availableLanguages":{},"_languagePackSupport":true}',
VSCODE_NODE_CACHED_DATA_DIR: '/workspace/${workspaceFolder}/.user-data-dir-test/CachedData/ea3859d4ba2f3e577a159bc91e3074c5d85c0523',
VSCODE_IPC_HOOK: '/workspace/${workspaceFolder}/.user-data-dir-test/1.52.1-main.sock',
VSCODE_PID: '182',
ELECTRON_RUN_AS_NODE: '1',
ELECTRON_NO_ATTACH_CONSOLE: '1'
}

[main 2021-02-05T21:55:38.724Z] getUnixShellEnvironment#spawn '/workspace/.vscode-test/vscode-1.52.1/VSCode-linux-x64/code' -p '"e2e3ba25ade9" + JSON.stringify(process.env) + "e2e3ba25ade9"'

[main 2021-02-05T21:55:38.730Z] getUnixShellEnvironment#error The "file" argument must be of type string. Received type undefined

[main 2021-02-05T21:55:38.737Z] [File Watcher (node.js)] [ADDED] /workspace/${workspaceFolder}/.user-data-dir-test/User/workspaceStorage

[main 2021-02-05T21:55:38.739Z] [storage :memory:] Trace (event): SELECT * FROM ItemTable

[main 2021-02-05T21:55:38.744Z] [storage :memory:] getItems(): 0 rows

[main 2021-02-05T21:55:38.822Z] resolveShellEnv(): running (macOS/Linux)

...

[roblourens]

Thanks, the 1.52 log confirms what I suspected. Yes I think this flag would be the recommendation for when you are launching VS Code to inherit its environment instead of discovering a clean env from the user's shell configuration. It should give the exact same behavior as what you had in 1.52.