Vscode-powershell: 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 ddc75b8f1625022726a6f7f478ee415293e2
• 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

https://github.com/PowerShell/vscode-powershell/blob/ddc75b8f1625022726a6f7f478ee415293e2b5c7/src/main.ts#L107

1. We then create the features here

https://github.com/PowerShell/vscode-powershell/blob/ddc75b8f1625022726a6f7f478ee415293e2b5c7/src/main.ts#L114-L134

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

https://github.com/PowerShell/vscode-powershell/blob/ddc75b8f1625022726a6f7f478ee415293e2b5c7/src/session.ts#L111

1. Which is called from;
   https://github.com/PowerShell/vscode-powershell/blob/ddc75b8f1625022726a6f7f478ee415293e2b5c7/src/main.ts#L141

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.