Startup fails when incorrect Serilog assembly picked up from the GAC

[Robbie-sys]

System Details Output

3/9/2020 9:43:57 AM [NORMAL] - Visual Studio Code v1.42.1 64-bit
3/9/2020 9:43:57 AM [NORMAL] - PowerShell Extension v2020.3.0
3/9/2020 9:43:57 AM [NORMAL] - Operating System: Windows 64-bit
3/9/2020 9:43:57 AM [NORMAL] - Language server starting --
3/9/2020 9:43:57 AM [NORMAL] -     PowerShell executable: C:\WINDOWS\SysWOW64\WindowsPowerShell\v1.0\powershell.exe
3/9/2020 9:43:57 AM [NORMAL] -     PowerShell args: -NoProfile -NonInteractive -ExecutionPolicy Bypass -Command Import-Module 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\modules\PowerShellEditorServices\PowerShellEditorServices.psd1'; Start-EditorServices -HostName 'Visual Studio Code Host' -HostProfileId 'Microsoft.VSCode' -HostVersion '2020.3.0' -AdditionalModules @('PowerShellEditorServices.VSCode') -BundledModulesPath 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\modules' -EnableConsoleRepl -LogLevel 'Normal' -LogPath 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\logs\1583765037-2b1f8bdb-41e1-437c-8715-1fb9f64306201583765036935\EditorServices.log' -SessionDetailsPath 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\sessions\PSES-VSCode-24472-560475' -FeatureFlags @() 
3/9/2020 9:43:57 AM [NORMAL] -     PowerShell Editor Services args: Import-Module 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\modules\PowerShellEditorServices\PowerShellEditorServices.psd1'; Start-EditorServices -HostName 'Visual Studio Code Host' -HostProfileId 'Microsoft.VSCode' -HostVersion '2020.3.0' -AdditionalModules @('PowerShellEditorServices.VSCode') -BundledModulesPath 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\modules' -EnableConsoleRepl -LogLevel 'Normal' -LogPath 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\logs\1583765037-2b1f8bdb-41e1-437c-8715-1fb9f64306201583765036935\EditorServices.log' -SessionDetailsPath 'c:\Users\Robbie Johnson\.vscode\extensions\ms-vscode.powershell-2020.3.0\sessions\PSES-VSCode-24472-560475' -FeatureFlags @() 
3/9/2020 9:43:57 AM [NORMAL] - powershell.exe started.
3/9/2020 9:43:57 AM [NORMAL] - Waiting for session file
3/9/2020 9:45:58 AM [NORMAL] - Error occurred retrieving session file
3/9/2020 9:45:58 AM [NORMAL] - Language server startup failed.
3/9/2020 9:45:58 AM [ERROR] - The language service could not be started: 
3/9/2020 9:45:58 AM [ERROR] - Timed out waiting for session file to appear.

Issue Description

Hey everyone, running into an issue where I can't execute from the editor.
Powershell works as expected from the terminal. I've uninstalled and reinstalled the extension as well as Visual Studio Code. Any help would be greatly appreciated!

[Robbie-sys]

Update;
Uninstalling PowerShell Extension v2020.3.0 and reinstalling PowerShell Extension v2019.12.0 fixed the issue.

[TylerLeonhardt]

Thanks for the info! Can you also attach the logs here so we can get a better idea of what's going on?

[Robbie-sys]

Logs attached. The issue appears to only happen with the most recent version.

vscode-powershell.log
StartEditorServices.log

[rjmholt]

[ERR]: Exception encountered starting EditorServices. Exception logged in D:\a\1\s\src\PowerShellEditorServices.Hosting\Commands\StartEditorServicesCommand.cs on line 247 in EndProcessing:
System.MissingMethodException: Method not found: 'Serilog.LoggerConfiguration Serilog.FileLoggerConfigurationExtensions.File(Serilog.Configuration.LoggerSinkConfiguration, System.String, Serilog.Events.LogEventLevel, System.String, System.IFormatProvider, System.Nullable`1<Int64>, Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1<System.TimeSpan>, Serilog.RollingInterval, Boolean, System.Nullable`1<Int32>, System.Text.Encoding, Serilog.Sinks.File.FileLifecycleHooks)'.
   at Microsoft.PowerShell.EditorServices.Hosting.EditorServicesServerFactory.<>c__DisplayClass0_0.<Create>b__0(LoggerSinkConfiguration config)
   at Serilog.Configuration.LoggerSinkConfiguration.Wrap(LoggerSinkConfiguration loggerSinkConfiguration, Func`2 wrapSink, Action`1 configureWrappedSink, LogEventLevel restrictedToMinimumLevel, LoggingLevelSwitch levelSwitch)
   at Serilog.LoggerConfigurationAsyncExtensions.Async(LoggerSinkConfiguration loggerSinkConfiguration, Action`1 configure, IAsyncLogEventSinkMonitor monitor, Int32 bufferSize, Boolean blockWhenFull)
   at Microsoft.PowerShell.EditorServices.Hosting.EditorServicesServerFactory.Create(String logPath, Int32 minimumLogLevel, IObservable`1 hostLogger)
   at Microsoft.PowerShell.EditorServices.Hosting.EditorServicesRunner..ctor(HostLogger logger, EditorServicesConfig config, ISessionFileWriter sessionFileWriter, IReadOnlyCollection`1 loggersToUnsubscribe)
   at Microsoft.PowerShell.EditorServices.Hosting.EditorServicesLoader.LoadAndRunEditorServicesAsync()
   at Microsoft.PowerShell.EditorServices.Commands.StartEditorServicesCommand.EndProcessing()

This looks like something to go on!

[rjmholt]

This is quite mysterious. Perhaps we're picking up the wrong version of a dependency from the GAC?

[rjmholt]

@Robbie-sys can you try following the steps in #2397 (comment) and letting me know if that helps with your issue?

[Robbie-sys]

Hey @rjmholt - after installing the Powershell preview and disabling the Powershell extension the problem persists.

StartEditorServices.log
vscode-powershell.log

[rjmholt]

@Robbie-sys Can you set the log level to diagnostic in your configuration and grab the logs again? That will help me work out if the reason Serilog is getting the MissingMethodException is that it’s coming from somewhere else

[Robbie-sys]

@rjmholt - Oops, please find the new logs attached.

StartEditorServices.log
vscode-powershell.log

[rjmholt]

Thanks for that!

There it is:

[DBG]: Loaded 'Serilog.Sinks.File, Version=2.0.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10' from 'C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\Serilog.Sinks.File\v4.0_2.0.0.0__24c2f752a8e58a10\Serilog.Sinks.File.dll'

Compare that to the same line in my log:

DEBUG: Loaded 'Serilog.Sinks.File, Version=2.0.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10' from 'C:\Users\Robert 
Holt\Documents\Dev\Microsoft\PowerShellEditorServices\module\PowerShellEditorServices\bin\Common\Serilog.Sinks.File.dll'

Here's the method we depend on being there and here's where we call it.

It doesn't yet make sense to me though why an assembly with the same name, version and public token is failing like this, but it does seem somehow that the GAC assembly is missing that method.

I can tell you that this isn't an issue in PS 6 and 7, since they have much better mechanisms for dependency resolution.

[rjmholt]

Ok our csproj specified Serilog.Sinkgs.File version 4.1.0, so something seems amiss here

[rjmholt]

serilog/serilog#1319 (comment)

The 2.0.0 assembly version seems to be very much by design...

[TylerLeonhardt]

by design between 2.7 and 2.8... but we're on 4.1 now. Surely that should use an assembly version update

[mmascolino]

over on #2526 @rjmholt asked to repo with the preview extension so here it is:
1583874501-afcdef50-8118-4dc4-8e85-97bc2d5ea4661583874498632.zip

[TylerLeonhardt]

Can you all give the PowerShell Preview extension a try? We just did a release of it.

Don't forget to disable the regular PowerShell extension for VS Code when you enable the PowerShell Preview extension for VS Code

[clouditgirl]

@TylerLeonhardt
I installed PowerShell Preview extension and it didn't fix the issue with the error "ConsoleFeature>: Unable to instantiate; language client undefined."

vscode\extensions\ms-vscode.powershell-preview-2020.5.0\modules' -EnableConsoleRepl -StartupBanner "=====> PowerShell Preview Integrated Console v2020.5.0 <=====
" -LogLevel 'Normal' -LogPath 'c:\Users\Claudia.vscode\extensions\ms-vscode.powershell-preview-2020.5.0\logs\1589818401-0bc709be-f0e3-4621-82d1-203b9eaacb021589818395793\EditorServices.log' -SessionDetailsPath 'c:\Users\Claudia.vscode\extensions\ms-vscode.powershell-preview-2020.5.0\sessions\PSES-VSCode-2192-922253' -FeatureFlags @()
5/18/2020 12:13:21 PM [NORMAL] - pwsh.exe started.
5/18/2020 12:13:21 PM [NORMAL] - Waiting for session file
5/18/2020 12:13:28 PM [ERROR] - : Unable to instantiate; language client undefined.

[TylerLeonhardt]

What were you doing that caused ConsoleFeature>: Unable to instantiate; language client undefined.? Usually this is because the extension hasn't finished starting up.

[andyleejordan]

The extension has gone through a major rewrite since this was originally reported and I've not seen the same bug report crop back up, so going ahead and marking this resolved. Thanks!

[github-actions]

This issue has been labeled as resolved, please verify the provided fix (or other reason).

[github-actions]

This issue has been labeled as needing fix verification and has not had any activity a week. It has been closed for housekeeping purposes.

[andyleejordan]

The extension has gone through a major rewrite since this was originally reported and I've not seen the same bug report crop back up, so going ahead and marking this resolved. Thanks!

Joke's on me, this problem is still very much around and cropped up again after we updated Serilog.

[github-actions]

This issue has been labeled as resolved, please verify the provided fix (or other reason).

[andyleejordan]

The fix for this is merged, it will be in the next pre-release (coming out today). PowerShell/PowerShellEditorServices#2197