Enable logging from .NET / MSBuild-engine discovery logic during lang…

…uage-server startup

#28

.appveyor.yml

@@ -1,4 +1,4 @@
-version: 0.4.6.{build}
+version: 0.4.7.{build}
 image: Visual Studio 2022
 build_script:
 - ps: >-

CHANGELOG.md

@@ -1,5 +1,9 @@
 # Change Log
 
+# v0.4.7
+
+* Enable logging from .NET / MSBuild-engine discovery logic during language-server startup (tintoy/msbuild-project-tools-server#28).
+
 # v0.4.6
 
 * Simplify logic for detecting .NET SDK/host/runtime versions (tintoy/msbuild-project-tools-vscode#99).

src/LanguageServer.Common/Utilities/DotNetRuntimeInfo.cs

@@ -67,11 +67,14 @@ public static DotNetRuntimeInfo GetCurrent(string baseDirectory = null, ILogger
             using (TextReader dotnetVersionOutput = InvokeDotNetHost("--version", baseDirectory, logger))
             {
                 sdkVersion = ParseDotNetVersionOutput(dotnetVersionOutput);
+
+                logger.Verbose("Discovered .NET SDK v{SdkVersion:l}.", sdkVersion);
             }
 
             if (sdkVersion >= Sdk60Version)
             {
                 // From .NET 6.x onwards, we can rely on "dotnet --list-sdks" and "dotnet --list-runtimes" to give us the information we need.
+                logger.Verbose("Using new SDK discovery logic because .NET SDK v{SdkVersion:l} is greater than or equal to the minimum required v6 SDK version (v{MinSdkVersion:l}).", sdkVersion, Sdk60Version);
 
                 DotnetSdkInfo targetSdk;
 
@@ -80,10 +83,10 @@ public static DotNetRuntimeInfo GetCurrent(string baseDirectory = null, ILogger
                     List<DotnetSdkInfo> discoveredSdks = ParseDotNetListSdksOutput(dotnetListSdksOutput);
 
                     targetSdk = discoveredSdks.Find(sdk => sdk.Version == sdkVersion);
-                    if (targetSdk == null)
-                    {
+                    if (targetSdk != null)
+                        logger.Verbose("Target .NET SDK is v{SdkVersion:l} in {SdkBaseDirectory}.", targetSdk.Version, targetSdk.BaseDirectory); 
+                    else
                         logger.Error("Cannot find SDK v{SdkVersion} via 'dotnet --list-sdks'.", sdkVersion);
-                    }
                 }
 
                 DotnetRuntimeInfo hostRuntime = null;
@@ -99,7 +102,9 @@ public static DotNetRuntimeInfo GetCurrent(string baseDirectory = null, ILogger
                         .OrderByDescending(runtime => runtime.Version)
                         .FirstOrDefault();
 
-                    if (hostRuntime == null)
+                    if (hostRuntime != null)
+                        logger.Verbose(".NET host runtime is v{RuntimeVersion:l} ({RuntimeName}).", hostRuntime.Version, hostRuntime.Name);
+                    else
                         logger.Error("Failed to discover any runtimes via 'dotnet --list-runtimes'.");
                 }
 
@@ -113,6 +118,7 @@ public static DotNetRuntimeInfo GetCurrent(string baseDirectory = null, ILogger
             else
             {
                 // Fall back to legacy parser.
+                logger.Verbose("Using legacy (pre-v6) SDK discovery logic because .NET SDK v{SdkVersion:l} is less than the minimum required v6 SDK version (v{MinSdkVersion:l}).", sdkVersion, Sdk60Version);
 
                 using (TextReader dotnetInfoOutput = InvokeDotNetHost("--info", baseDirectory, logger))
                 {

src/LanguageServer/LanguageServer.csproj

@@ -33,6 +33,7 @@
     <PackageReference Include="Serilog.Enrichers.Demystify" Version="0.1.0-dev-00016" />
     <PackageReference Include="Serilog.Extensions.Logging" Version="2.0.2" />
     <PackageReference Include="Serilog.Sinks.Seq" Version="3.3.3" />
+    <PackageReference Include="Serilog.Sinks.TextWriter" Version="2.1.0" />
     <PackageReference Include="System.Reactive" Version="3.1.1" />
     <PackageReference Include="System.Security.Principal" Version="4.3.0" />
   </ItemGroup>

src/LanguageServer/LoggingModule.cs

@@ -65,67 +65,82 @@ static ILogger CreateLogger(IComponentContext componentContext)
             if (componentContext == null)
                 throw new ArgumentNullException(nameof(componentContext));
 
-            Configuration configuration = componentContext.Resolve<Configuration>();
-            ConfigureSeq(configuration.Logging.Seq);
+            ILanguageServer languageServer = componentContext.Resolve<ILanguageServer>();
+
+            Configuration languageServerConfiguration = componentContext.Resolve<Configuration>();
+
+            LoggerConfiguration loggerConfiguration = CreateDefaultLoggerConfiguration(languageServerConfiguration)
+                .WriteTo.LanguageServer(languageServer, languageServerConfiguration.Logging.LevelSwitch);
+
+            ILogger logger = loggerConfiguration.CreateLogger();
+            Log.Logger = logger;
+
+            logger.Verbose("Logger initialised.");
 
-            // Override default log level.
-            if (Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING") == "1")
+            return logger;
+        }
+
+        /// <summary>
+        ///     Create the default <see cref="LoggerConfiguration"/>, optionally based on language-server configuration.
+        /// </summary>
+        /// <param name="languageServerConfiguration">
+        ///     An optional <see cref="Configuration"/> representing the language-server configuration.
+        /// </param>
+        /// <returns>
+        ///     The new <see cref="LoggerConfiguration"/>.
+        /// </returns>
+        public static LoggerConfiguration CreateDefaultLoggerConfiguration(Configuration languageServerConfiguration = null)
+        {
+            languageServerConfiguration ??= new Configuration();
+
+            // Override defaults from environment.
+            // We have to use environment variables here since at configuration time there's no LSP connection yet.
+            string loggingVerbosityOverride = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING");
+            if (loggingVerbosityOverride == "1")
             {
-                configuration.Logging.LevelSwitch.MinimumLevel = LogEventLevel.Verbose;
-                configuration.Logging.Seq.LevelSwitch.MinimumLevel = LogEventLevel.Verbose;
+                languageServerConfiguration.Logging.LevelSwitch.MinimumLevel = LogEventLevel.Verbose;
+                languageServerConfiguration.Logging.Seq.LevelSwitch.MinimumLevel = LogEventLevel.Verbose;
             }
+            string loggingFilePathOverride = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_LOG_FILE");
+            if (!String.IsNullOrWhiteSpace(loggingFilePathOverride))
+                languageServerConfiguration.Logging.LogFile = loggingFilePathOverride;
 
-            ILanguageServer languageServer = componentContext.Resolve<ILanguageServer>();
+            languageServerConfiguration.Logging.Seq.Url = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_SEQ_URL");
+            languageServerConfiguration.Logging.Seq.ApiKey = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_SEQ_API_KEY");
 
             var loggerConfiguration = new LoggerConfiguration()
                 .MinimumLevel.Verbose()
                 .Enrich.WithCurrentActivityId()
                 .Enrich.WithDemystifiedStackTraces()
                 .Enrich.FromLogContext();
 
-            if (!String.IsNullOrWhiteSpace(configuration.Logging.Seq.Url))
+            if (!String.IsNullOrWhiteSpace(languageServerConfiguration.Logging.Seq.Url))
             {
-                loggerConfiguration = loggerConfiguration.WriteTo.Seq(configuration.Logging.Seq.Url,
-                    apiKey: configuration.Logging.Seq.ApiKey,
-                    controlLevelSwitch: configuration.Logging.Seq.LevelSwitch
+                loggerConfiguration = loggerConfiguration.WriteTo.Seq(languageServerConfiguration.Logging.Seq.Url,
+                    apiKey: languageServerConfiguration.Logging.Seq.ApiKey,
+                    controlLevelSwitch: languageServerConfiguration.Logging.Seq.LevelSwitch
                 );
             }
 
-            string logFilePath = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_LOG_FILE");
-            if (!String.IsNullOrWhiteSpace(logFilePath))
+            if (!String.IsNullOrWhiteSpace(languageServerConfiguration.Logging.LogFile))
             {
                 loggerConfiguration = loggerConfiguration.WriteTo.File(
-                    path: logFilePath,
-                    levelSwitch: configuration.Logging.LevelSwitch,
+                    path: languageServerConfiguration.Logging.LogFile,
+                    levelSwitch: languageServerConfiguration.Logging.LevelSwitch,
                     outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level}/{Operation}] {Message}{NewLine}{Exception}",
                     flushToDiskInterval: TimeSpan.FromSeconds(1)
                 );
             }
 
-            loggerConfiguration = loggerConfiguration.WriteTo.LanguageServer(languageServer, configuration.Logging.LevelSwitch);
-
-            ILogger logger = loggerConfiguration.CreateLogger();
-            Log.Logger = logger;
-
-            logger.Verbose("Logger initialised.");
-
-            return logger;
-        }
+            if (Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_LOGGING_TO_STDERR") == "1")
+            {
+                loggerConfiguration = loggerConfiguration.WriteTo.TextWriter(Console.Error,
+                    levelSwitch: languageServerConfiguration.Logging.LevelSwitch,
+                    outputTemplate: "[{Level}/{Operation}] {Message}{NewLine}{Exception}"
+                );
+            }
 
-        /// <summary>
-        ///     Configure SEQ logging from environment variables.
-        /// </summary>
-        /// <param name="configuration">
-        ///     The language server's Seq logging configuration.
-        /// </param>
-        static void ConfigureSeq(SeqLoggingConfiguration configuration)
-        {
-            if (configuration == null)
-                throw new ArgumentNullException(nameof(configuration));
-
-            // We have to use environment variables here since at configuration time there's no LSP connection yet.
-            configuration.Url = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_SEQ_URL");
-            configuration.ApiKey = Environment.GetEnvironmentVariable("MSBUILD_PROJECT_TOOLS_SEQ_API_KEY");
+            return loggerConfiguration;
         }
     }
 }

src/LanguageServer/Program.cs

@@ -36,7 +36,16 @@ static int Main()
             {
                 AutoDetectExtensionDirectory();
 
-                MSBuildHelper.DiscoverMSBuildEngine();
+                // Ensure the initial MSBuild discovery process has a logger to work with.
+                ILogger msbuildDiscoveryLogger = LoggingModule.CreateDefaultLoggerConfiguration()
+                    .CreateLogger()
+                    .ForContext("Operation", "MSBuildDiscovery");
+
+                using (msbuildDiscoveryLogger as IDisposable)
+                {
+                    MSBuildHelper.DiscoverMSBuildEngine(logger: msbuildDiscoveryLogger);
+                }
+
                 ConfigureNuGetCredentialProviders();
 
                 return AsyncMain().GetAwaiter().GetResult();