microsoft / vscode

Visual Studio Code
https://code.visualstudio.com
MIT License
164.28k stars 29.31k forks source link

`LogOutputChannel` LogLevel property race condition if Global Log Level and Output Panel Log Level are not the same #232862

Open JustinGrote opened 1 week ago

JustinGrote commented 1 week ago

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

Reproduction

  1. Start this branch in Codespaces and use Launch task Run Extension [Isolated Profile] https://github.com/JustinGrote/vscode-extension-issues/tree/issue/logOutputWindowTraceChange
  2. Change log level to something other than info
  3. Choose "Restart Extension Host"

Relevant Code: https://github.com/JustinGrote/vscode-extension-issues/blob/issue/logOutputWindowTraceChange/src/extension.ts

Expected

A LogOutputChannel starts with the logLevel that the user preference has specified

Actual

Always starts at Info and gets set sometime later, however logs seem to filter normally.

EDIT: This only happens if the default log level and the output pane log level are not the same, and "Set as Default" has not been used to modify the argv.json. If default log level and output pane log level are the same, the ondidChange does not fire later and the startup log level is correct.

https://github.com/user-attachments/assets/f7e53748-d024-40cf-a8cb-b47eb7418a0d

Relevance

I have a custom logger that relies on checking the logLevel and do a noop if it does not meet the required level.

Potential Fixes

JustinGrote commented 1 week ago

I dug into this a little bit further:

It appears to be due to an interaction between three settings locations:

  1. Global Log Level (changed via Set Log Level command and top list)
  2. Output Window Log Level (changed via either Set Log Level command and middle list or by output pane "Gear" dropdown
  3. Extension Log Level (changed oddly by output pane "Gear" dropdown and choosing "Set as Default"), which gets stored in argv.json under log-level for the extension

If an extension has multiple output panes, using Set as Default sets it for all of them, which is not ideal behavior. It is also observed that, if it is set in argv.json via Set as Default, it seems to break the logic and always sets the output pane to info even though its individual display says otherwise.