Logging level is set after features are created and initialized, not before

[glennsarti]

System Details

• Operating system name and version: Windows 10 - 1803
• VS Code version: 1.24.0
• PowerShell extension version: Commit ddc75b8
• Output from $PSVersionTable: N/A

Issue Description

While working on a new feature for the extension, I noticed that I was unable to call writeError etc. on the logger object during Feature initialisation. I found this was due to a race-ish condition.

1. We create the logging object here

vscode-powershell/src/main.ts

Line 107 in ddc75b8

logger = new Logger();

2. We then create the features here

vscode-powershell/src/main.ts

Lines 114 to 134 in ddc75b8

	// Create features
	extensionFeatures = [
	new ConsoleFeature(),
	new ExamplesFeature(),
	new OpenInISEFeature(),
	new GenerateBugReportFeature(sessionManager),
	new ExpandAliasFeature(),
	new ShowHelpFeature(),
	new FindModuleFeature(),
	new PesterTestsFeature(sessionManager),
	new ExtensionCommandsFeature(logger),
	new SelectPSSARulesFeature(),
	new CodeActionsFeature(),
	new NewFileOrProjectFeature(),
	new DocumentFormatterFeature(logger, documentSelector),
	new RemoteFilesFeature(),
	new DebugSessionFeature(context, sessionManager),
	new PickPSHostProcessFeature(),
	new SpecifyScriptArgsFeature(context),
	new HelpCompletionFeature(logger),
	new CustomViewsFeature(),

3. However, the debug log level is is only set at;

vscode-powershell/src/session.ts

Line 111 in ddc75b8

this.log.startNewLog(this.sessionSettings.developer.editorServicesLogLevel);

4. Which is called from;
   

   vscode-powershell/src/main.ts

   Line 141 in ddc75b8

   sessionManager.start();

which is AFTER the features are created.

The race condition comes from how node schedules things on threads. Sometimes it was set in time for the feature creation, sometimes not.

[glennsarti]

Perhaps the log level code should be moved from the session manager into the logger itself.

[rkeithhill]

Well, except that at some point you want to set the log level to the setting the user may have set in their user/workspace settings file. That setting value can only be read after the SessionManager has started. What we could do is start logging with a default log-level of say normal and then when we get into the SessionManager.Start() method, have it set the log level to what was specified by the settings.

[glennsarti]

That's exactly what it's doing right now.

And that's the racey bit. As a feature you don't know when the loglevel is set correctly. So should I call logger.write or logger.writeVerbose. It's a little unclear.

Also the log level is coming from the workspace/user settings, so there's nothing really "Session-y" about it.

[rkeithhill]

I suppose we could have the logger do a Settings.load() to get the desired log level. If that works then we're set. Just start logger right after we create the Logger.

[glennsarti]

Yup, just move the start call out of the session Manager and into main.ts

OR

allow the logger to have .start called idempotently

OR

have a property on the logger to indicate it has already started

[rkeithhill]

This was fixed in the 1.8.0 release.