Certain log output channel only show up in the first vscode window

[eamodio]

Issue Type: Bug

First window:

Any window after the first:

VS Code version: Code - Insiders 1.42.0-insider (c4b6a6b, 2020-01-28T05:38:41.922Z)
OS version: Windows_NT x64 10.0.19041

System Info

Item	Value
CPUs	AMD Ryzen 9 3900X 12-Core Processor (24 x 3800)
GPU Status	2d_canvas: enabled flash_3d: enabled flash_stage3d: enabled flash_stage3d_baseline: enabled gpu_compositing: enabled metal: disabled_off multiple_raster_threads: enabled_on oop_rasterization: disabled_off protected_video_decode: unavailable_off rasterization: enabled skia_renderer: disabled_off surface_control: disabled_off surface_synchronization: enabled_on video_decode: enabled viz_display_compositor: enabled_on viz_hit_test_surface_layer: disabled_off webgl: enabled webgl2: enabled
Load (avg)	undefined
Memory (System)	31.95GB (19.55GB free)
Process Argv	-n
Screen Reader	no
VM	0%

[sandy081]

@eamodio Cant reproduce this. Any specific steps?

[eamodio]

Hrm, seems to work fine if you open a new window from inside vscode, but if you do it from outside (via taskbar button) then it always reproduces for me.

[sandy081]

Does the command Toggle Shared Process works for you on the second window?

[eamodio]

Yeah, both open:

[vscodebot]

This issue has been closed automatically because it needs more information and has not had recent activity. See also our issue reporting guidelines.

Happy Coding!

[sandy081]

@bpasero Is there anything special if opening a window from taskbar that the environment is not set correctly?

[bpasero]

@sandy081 I think we try to fetch the shell environment later on:

vscode/src/vs/code/electron-main/app.ts

Line 262 in 2548906

ipc.on('vscode:fetchShellEnv', async (event: IpcMainEvent) => {

[joaomoreno]

The env only runs when Code starts. If another instance of Code comes along, it just talks to the first one. No further env resolution happens.

[sandy081]

@eamodio Can you please help in debugging this and find the root cause?

Here is the code pointer where we register the output channels for the log files -

https://github.com/microsoft/vscode/blob/master/src/vs/workbench/contrib/logs/common/logs.contribution.ts#L48

Please check if the channels are getting created?

[eamodio]

@sandy081 I debugged this a bit and it seems like the issue is that we don't create the channel if the log file doesn't exist yet:

Because we are not getting into that exists case:

vscode/src/vs/workbench/contrib/logs/common/logs.contribution.ts

Lines 77 to 81 in 7aa60ae

	if (exists) {
	outputChannelRegistry.registerChannel({ id, label, file, log: true });
	return;
	}

But I'm not sure why the file Uri is different (or at least I'm assuming it is, since it doesn't exist)

[sandy081]

Right, we create the channel only after file is created. But in this case the logs which were missing shall have files exist as they shall be same for all windows.

But I'm not sure why the file Uri is different (or at least I'm assuming it is, since it doesn't exist)

Can you please let me know what the URIs are ?

[eamodio]

@sandy081 It looks like the timestamps are different.

First window:

file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T165027/userDataSync.log
file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T165027/renderer1.log
file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T165027/main.log
file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T165027/sharedprocess.log

2nd window:

file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T194923/userDataSync.log
file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T194923/renderer3.log
file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T194923/main.log
file:///c%3A/Users/Eric/AppData/Roaming/code-oss-dev/logs/20200612T194923/sharedprocess.log

[sandy081]

Thanks @eamodio. This logPath is read from IEnvironmentService and on window this is read from process env. It seems this process env variable is not set for second window.

vscode/src/vs/platform/environment/node/environmentService.ts

Lines 268 to 276 in 99a0740

	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']!;
	}
	}

@bpasero Your help is appreciated.

[bpasero]

@sandy081 very unlikely that a value you put into process in one window ends up on the process object of another window. I am not sure I follow what you are trying to achieve here, I suggest you call me once available to talk it through and you can show me the code.

[sandy081]

This value is put into process in electron main and I assume that all windows shall get this value?

[sandy081]

It seems VSCODE_LOGS env is not being set in other windows environment and these windows are trying to set different logPath as of main and hence these windows are missing application level logs (shared process, main, sync).

After discussing @bpasero suggested to pass logsPath to other windows including shared process as window configuration instead through environment.

@joaomoreno any opinions as you came up with this pattern and not sure if there is any other reason.

[joaomoreno]

It seems VSCODE_LOGS env is not being set in other windows environment and these windows are trying to set different logPath as of main and hence these windows are missing application level logs (shared process, main, sync).

Do we know why it's not being set?

[sandy081]

Sorry I did not know why, @bpasero do you have any clue?

[bpasero]

@sandy081 again, please move away from using process environment for this purpose, it asks for trouble.

The issue is this:

• you open a first window and it sets VSCODE_LOGS path accordingly as environment
• you open a second window from the command line
  • we explicitly want all of process.env of this second window to reach that window because a user might have configured some environments that need to travel to other processes such as extensions
  • the second window is a fresh process and thus will set a VSCODE_LOGS again that is different from the main one
  • the fresh process communicates to the first process and sends over the environment to use
  • that second window opens with the logs folder that is different from the first

[bpasero]

To further debug, check this line which sends the process environment over:

vscode/src/vs/code/electron-main/main.ts

Line 313 in 8d699df

await launchService.start(args, process.env as IProcessEnvironment);

Deleting VSCODE_LOGS from the environment is a hacky workaround, but a proper fix should be made.

[sandy081]

@bpasero

@sandy081 again, please move away from using process environment for this purpose, it asks for trouble.

Yes, I am in that process. Since @joaomoreno added this, checking with him to know any special reasons for doing this.

[joaomoreno]

Process environment is usually the least friction route: it requires no code to have environment variables propagate across spawned processes.

[rzhao271]

Still happens for me on both stable and insiders on Windows

0. Close open folders (not sure if this part matters) and editors
1. Open VS Code Insiders from taskbar/start menu
2. Open panel, go to Output panel, check channels
3. Repeat steps 1 and 2 again

When running those steps with Insiders, the second window for me has 3 log options, whereas the first window has 6.