diff --git a/src/VisualStudio/LanguageService/XSharpLanguagePackage.cs b/src/VisualStudio/LanguageService/XSharpLanguagePackage.cs index ed203be557..b0b0171115 100644 --- a/src/VisualStudio/LanguageService/XSharpLanguagePackage.cs +++ b/src/VisualStudio/LanguageService/XSharpLanguagePackage.cs @@ -236,7 +236,7 @@ public void GetIntellisenseSettings(bool load) protected override async System.Threading.Tasks.Task InitializeAsync(CancellationToken cancellationToken, IProgress progress) { instance = this; - Logger.Initialize(); + await Logger.InitializeAsync(); await base.InitializeAsync(cancellationToken, progress); _txtManager = await GetServiceAsync(typeof(SVsTextManager)) as IVsTextManager4; Assumes.Present(_txtManager); diff --git a/src/VisualStudio/ProjectPackage/XSharpProjectPackage.cs b/src/VisualStudio/ProjectPackage/XSharpProjectPackage.cs index da020b38e7..9a77d9ec9b 100644 --- a/src/VisualStudio/ProjectPackage/XSharpProjectPackage.cs +++ b/src/VisualStudio/ProjectPackage/XSharpProjectPackage.cs @@ -174,9 +174,14 @@ public XSharpProjectPackage() : base() /// protected override async Task InitializeAsync(CancellationToken cancellationToken, IProgress progress) { - // Give the codemodel a way to talk to the VS Shell + // Give the codemodel a way to talk to the VS Shell. + // Everything on this path is awaited and must stay that way: when a solution is opened + // while VS is starting, the shell loads this package synchronously from + // Solution.OpenAsync() -> CanOpenProject() and waits for it on the UI thread. Blocking + // here while waiting for that same UI thread deadlocks the IDE. _shellEvents = new XSharpShellEvents(); - XSharp.Support.Logger.Initialize(); + await _shellEvents.InitializeAsync(); + await XSharp.Support.Logger.InitializeAsync(); this.RegisterToolWindows(); await base.InitializeAsync(cancellationToken, progress); diff --git a/src/VisualStudio/ProjectPackage/XSharpShellEvents.cs b/src/VisualStudio/ProjectPackage/XSharpShellEvents.cs index 5783cfcd53..1530436562 100644 --- a/src/VisualStudio/ProjectPackage/XSharpShellEvents.cs +++ b/src/VisualStudio/ProjectPackage/XSharpShellEvents.cs @@ -28,34 +28,22 @@ internal class XSharpShellEvents bool isInitialized = false; static XSharpShellEvents() { + // Only read the environment here. Showing the warning is UI work and would block while + // waiting for the UI thread, which deadlocks when we are constructed during a package + // load that the shell is waiting for. It is reported from InitializeAsync() instead. hasEnvironmentvariable = !string.IsNullOrEmpty(System.Environment.GetEnvironmentVariable("XSharpMsBuildDir")); - if (!hasEnvironmentvariable) - { - VS.MessageBox.ShowWarning("The environment variable 'XSharpMsBuildDir' is missing. \rSome projects may have problems loading. \rPlease run the XSharp setup program again."); - } } - internal XSharpShellEvents() - { - if (ThreadHelper.CheckAccess()) - { - // Already on UI thread - Initialize(); - } - else - { - ThreadHelper.JoinableTaskFactory.Run(async delegate - { - await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); - Initialize(); - }); - } - } - internal void Initialize() + /// + /// Subscribe to the shell events. Must be awaited and never waited on: we are called from + /// XSharpProjectPackage.InitializeAsync(), where blocking while waiting for the UI thread + /// deadlocks the IDE. See the remarks on Logger.InitializeAsync(). + /// + internal async Task InitializeAsync() { if (isInitialized) return; - ThreadHelper.ThrowIfNotOnUIThread(); + await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); #if DEV17 VS.Events.SolutionEvents.OnAfterOpenSolution += SolutionEvents_OnAfterOpenSolution; #endif @@ -65,20 +53,22 @@ internal void Initialize() VS.Events.SolutionEvents.OnBeforeOpenProject += SolutionEvents_OnBeforeOpenProject; VS.Events.DocumentEvents.Closed += DocumentEvents_Closed; - ThreadHelper.JoinableTaskFactory.Run(async delegate - { - _ = await VS.Commands.InterceptAsync(KnownCommands.File_CloseSolution, CloseDesignerWindows); - _ = await VS.Commands.InterceptAsync(KnownCommands.File_Exit, CloseDesignerWindows); - var sol = await VS.Solutions.GetCurrentSolutionAsync(); + _ = await VS.Commands.InterceptAsync(KnownCommands.File_CloseSolution, CloseDesignerWindows); + _ = await VS.Commands.InterceptAsync(KnownCommands.File_Exit, CloseDesignerWindows); + var sol = await VS.Solutions.GetCurrentSolutionAsync(); #if DEV17 - if (sol is Solution) - { - SolutionEvents_OnAfterOpenSolution(sol); - } + if (sol is Solution) + { + await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); + SolutionEvents_OnAfterOpenSolution(sol); + } #endif - }); isInitialized = true; + if (!hasEnvironmentvariable) + { + VS.MessageBox.ShowWarningAsync("The environment variable 'XSharpMsBuildDir' is missing. \rSome projects may have problems loading. \rPlease run the XSharp setup program again.").FireAndForget(); + } } diff --git a/src/VisualStudio/Support/Logger.cs b/src/VisualStudio/Support/Logger.cs index 5cf755769c..856699b54f 100644 --- a/src/VisualStudio/Support/Logger.cs +++ b/src/VisualStudio/Support/Logger.cs @@ -24,13 +24,23 @@ public static class Logger static object gate = new object (); static bool initialized = false; - public static bool Initialize() + /// + /// Initialize the logger and the link to the VS shell. + /// + /// + /// Nothing on this path may block the calling thread, because this is called from the + /// InitializeAsync() of our packages. The shell can load those packages synchronously from + /// Solution.OpenAsync() -> CanOpenProject() when a solution is opened while VS is starting + /// (a pinned solution or a solution on the commandline). The UI thread then waits for the + /// package load to complete, so anything here that blocks while waiting for the UI thread - + /// a JoinableTaskFactory.Run() or one of the synchronous Community Toolkit wrappers - + /// deadlocks the IDE. The work that needs the UI thread is therefore awaited and never + /// waited on: see StartAsync(), LogEnvironmentAsync() and XSharpShellLink.InitializeAsync(). + /// Flags are still set inside the lock and everything else happens after it is released, + /// so we also never hold the lock while waiting for another thread. + /// + public static async System.Threading.Tasks.Task InitializeAsync() { - // Flags set inside the lock; all JoinableTaskFactory.Run work happens outside it. - // Holding a lock while calling JoinableTaskFactory.Run risks a deadlock: the background - // thread blocks waiting for the UI thread, but the UI thread may be waiting to acquire - // the same lock. XSharpShellLink's constructor and Logger.Start/Stop all call - // JoinableTaskFactory.Run, so they must be invoked after the lock is released. bool needsShellLink = false; bool shouldStart = false; bool alreadyActive; @@ -57,13 +67,17 @@ public static bool Initialize() } } if (needsShellLink) - XSettings.ShellLink = new XSharpShellLink(); + { + var shellLink = new XSharpShellLink(); + XSettings.ShellLink = shellLink; + await shellLink.InitializeAsync(); + } if (alreadyActive) return active; if (shouldStart) - Logger.Start(); - else - Logger.Stop(); + await Logger.StartAsync(); + else + Logger.Stop(); return shouldStart; } @@ -73,127 +87,177 @@ public static bool Initialize() static bool active = false; internal static bool Active => active; + /// + /// Start logging. The environment is logged in the background, because that part needs the + /// UI thread. Callers that can await should use StartAsync(). + /// public static void Start() { try { - if (!active || - log2debugger != XSettings.EnableDebugLogging || - log2file != XSettings.EnableFileLogging) + if (ConfigureSerilog()) { - if (active) - { - Stop(); - } - var config = new LoggerConfiguration() - .MinimumLevel.Debug(); - log2debugger = false; - log2file = false; - if (XSettings.EnableDebugLogging) - { - config = config.WriteTo.Debug(); - log2debugger = true; - } - if (XSettings.EnableFileLogging) - { - var temp = Path.GetTempPath(); - temp = Path.Combine(temp, "XSharp.Intellisense"); - if (!Directory.Exists(temp)) - { - Directory.CreateDirectory(temp); - } - int threadid = Process.GetCurrentProcess().Id; - string strId = threadid.ToString("X"); - var log = Path.Combine(temp, "Project_" + strId + "_.log"); - config = config.WriteTo.File(log, - rollingInterval: RollingInterval.Day, - rollOnFileSizeLimit: true, - flushToDiskInterval: TimeSpan.FromSeconds(15), - retainedFileCountLimit: 5); - log2file = true; - } + active = true; + LogEnvironmentAsync().FireAndForget(); + } + // Force all Logging options to be enabled + XSettings.EnableAll(); + } + catch (Exception e) + { + System.Diagnostics.Debug.WriteLine(e.Message); + } + } + /// + /// Start logging without ever blocking the calling thread. Use this from package + /// initialization. See the remarks on InitializeAsync(). + /// + public static async System.Threading.Tasks.Task StartAsync() + { + try + { + if (ConfigureSerilog()) + { + active = true; + await LogEnvironmentAsync(); + } + // Force all Logging options to be enabled + XSettings.EnableAll(); + } + catch (Exception e) + { + System.Diagnostics.Debug.WriteLine(e.Message); + } + } - Log.Logger = config.CreateLogger(); + /// + /// (Re)create the Serilog logger. This is pure configuration: no VS services, no UI thread. + /// + /// TRUE when the logger was (re)created, so the environment must be logged again + private static bool ConfigureSerilog() + { + if (active && + log2debugger == XSettings.EnableDebugLogging && + log2file == XSettings.EnableFileLogging) + { + return false; + } + if (active) + { + Stop(); + } + var config = new LoggerConfiguration() + .MinimumLevel.Debug(); + log2debugger = false; + log2file = false; + if (XSettings.EnableDebugLogging) + { + config = config.WriteTo.Debug(); + log2debugger = true; + } + if (XSettings.EnableFileLogging) + { + var temp = Path.GetTempPath(); + temp = Path.Combine(temp, "XSharp.Intellisense"); + if (!Directory.Exists(temp)) + { + Directory.CreateDirectory(temp); + } + int threadid = Process.GetCurrentProcess().Id; + string strId = threadid.ToString("X"); + var log = Path.Combine(temp, "Project_" + strId + "_.log"); + config = config.WriteTo.File(log, + rollingInterval: RollingInterval.Day, + rollOnFileSizeLimit: true, + flushToDiskInterval: TimeSpan.FromSeconds(15), + retainedFileCountLimit: 5); + log2file = true; + } + + + Log.Logger = config.CreateLogger(); - Log.Information(doubleline); - Log.Information("Started Logging"); - string version = ""; - bool isOpening = false; // This is TRUE when we are opening VS with a solution from the commandline - ThreadHelper.JoinableTaskFactory.Run(async delegate + Log.Information(doubleline); + Log.Information("Started Logging"); + return true; + } + + /// + /// Log the environment and register the current solution with the code model. + /// This needs the UI thread, so it must be awaited and never waited on. + /// + internal static async System.Threading.Tasks.Task LogEnvironmentAsync() + { + try + { + var ver = await VS.Shell.GetVsVersionAsync(); + // This is TRUE when we are opening VS with a solution from the commandline, + // which is also what happens for a solution pinned to the start window or the jumplist + bool isOpening = await VS.Solutions.IsOpeningAsync(); + Log.Information("Visual Studio Exe : " + Process.GetCurrentProcess().MainModule.FileName); + Log.Information("Visual Studio version : " + ver?.ToString()); + Log.Information("XSharp Project System : " + Constants.FileVersion); + Log.Information("Commandline : " + Environment.CommandLine.ToString()); + + + Log.Information(doubleline); + var sol = await VS.Solutions.GetCurrentSolutionAsync(); + if (sol == null) + { + return; + } + Log.Information(singleline); + Log.Information("Current solution: " + sol.FullPath); + if (!XSolution.IsOpen) + XSolution.Open(sol.FullPath); + // we only want to enum projects when the solution explorer window is already visible + bool enumProjects = !isOpening; + if (enumProjects) + { + try { - var ver = await VS.Shell.GetVsVersionAsync(); - isOpening = await VS.Solutions.IsOpeningAsync(); - version = ver.ToString(); - }); - Log.Information("Visual Studio Exe : " + Process.GetCurrentProcess().MainModule.FileName); - Log.Information("Visual Studio version : " + version); - Log.Information("XSharp Project System : " + Constants.FileVersion); - Log.Information("Commandline : " + Environment.CommandLine.ToString()); - - - Log.Information(doubleline); - var sol = VS.Solutions.GetCurrentSolution(); - if (sol != null) + var solwin = await VS.Windows.GetSolutionExplorerWindowAsync(); + enumProjects = solwin != null; + } + catch (Exception) { - Log.Information(singleline); - Log.Information("Current solution: " + sol.FullPath); - if (!XSolution.IsOpen) - XSolution.Open(sol.FullPath); - // we only want to enum projects when the solution explorer window is already visible - bool enumProjects = !isOpening; - if (enumProjects) - { - ThreadHelper.JoinableTaskFactory.Run(async delegate - { - try - { - var solwin = await VS.Windows.GetSolutionExplorerWindowAsync(); - enumProjects = solwin != null; - } - catch (Exception) - { - // This happens when the solution explorer is not visible yet - // do not enum the projects then - enumProjects = false; - } - - }); - } - if (enumProjects) + // This happens when the solution explorer is not visible yet + // do not enum the projects then + enumProjects = false; + } + } + if (enumProjects) + { + // walking the solution items is COM work, so we need the UI thread for that + await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); + try + { + var children = EnumChildren(sol, SolutionItemType.Project); + if (children != null) { - var children = EnumChildren(sol, SolutionItemType.Project); - try + foreach (var child in children) { - if (children != null) + if (child.Type == SolutionItemType.Project) { - foreach (var child in children) - { - if (child.Type == SolutionItemType.Project) - { - Log.Information("Project " + child.FullPath); - } - } + Log.Information("Project " + child.FullPath); } } - catch (Exception e) - { - Log.Error(e.Message); - } - } - else - { - Log.Information("No projects opened yet"); } - Log.Information(singleline); - - AppDomain.CurrentDomain.UnhandledException += CurrentDomain_UnhandledException; - //AppDomain.CurrentDomain.FirstChanceException += CurrentDomain_FirstChanceException; } - active = true; + catch (Exception e) + { + Log.Error(e.Message); + } } - // Force all Logging options to be enabled - XSettings.EnableAll(); + else + { + Log.Information("No projects opened yet"); + } + Log.Information(singleline); + + AppDomain.CurrentDomain.UnhandledException += CurrentDomain_UnhandledException; + //AppDomain.CurrentDomain.FirstChanceException += CurrentDomain_FirstChanceException; } catch (Exception e) { diff --git a/src/VisualStudio/Support/XSharpShellLink.cs b/src/VisualStudio/Support/XSharpShellLink.cs index cbcdb3b7d1..9d7974517b 100644 --- a/src/VisualStudio/Support/XSharpShellLink.cs +++ b/src/VisualStudio/Support/XSharpShellLink.cs @@ -33,13 +33,16 @@ internal class XSharpShellLink : IXVsShellLink { static ILogger Logger => XSettings.Logger; - internal XSharpShellLink() + /// + /// Subscribe to the shell events. Must be awaited and never waited on: we are called from + /// the InitializeAsync() of our packages, where blocking while waiting for the UI thread + /// deadlocks the IDE. See the remarks on Logger.InitializeAsync(). + /// + internal async System.Threading.Tasks.Task InitializeAsync() { - ThreadHelper.JoinableTaskFactory.Run(async delegate - { - await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); - // Logger may not be fully initialized yet, so guard against null - Logger?.Information("Initialize XSharpShellLink"); + await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync(); + // Logger may not be fully initialized yet, so guard against null + Logger?.Information("Initialize XSharpShellLink"); @@ -88,9 +91,6 @@ internal XSharpShellLink() Logger?.Information("Initialized XSharpShellLink"); - }); - - } private List GetProjects(SolutionItem parent)