Reduced MsBuild log output and consistent use of [Reqnroll] prefix (#381

) * Reduced MsBuild log output and consistent use of [Reqnroll] prefix * log dumping error with low importance * Add more logging for code behind file generation * rename LogMessageWithLowImportance to LogDiagnosticMessage --------- Co-authored-by: Gáspár Nagy <[email protected]>
reqnroll · Jan 10, 2025 · e133a57 · e133a57
1 parent dc1c3e4
commit e133a57
Show file tree

Hide file tree

Showing 17 changed files with 73 additions and 40 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -5,6 +5,7 @@
 * Enhance BoDi error handling to provide the name of the interface being registered when that interface has already been resolved (#324)
 * Improve code-behind feature file compilation speed (#336)
 * Improve parameter type naming for generic types (#343)
+* Reduced MsBuild log output and consistent use of [Reqnroll] prefix (#381)
 
 ## Bug fixes:
 

diff --git a/Reqnroll.Tools.MsBuild.Generation/AssemblyResolveLogger.cs b/Reqnroll.Tools.MsBuild.Generation/AssemblyResolveLogger.cs
@@ -25,7 +25,7 @@ public AssemblyResolveLogger(ITaskLoggingWrapper taskLoggingWrapper)
 
         public Assembly CurrentDomain_AssemblyResolve(object sender, ResolveEventArgs args)
         {
-            _taskLoggingWrapper.LogMessage($"Resolving {args.Name}");
+            _taskLoggingWrapper.LogDiagnosticMessage($"Resolving {args.Name}");
 
             try
             {
@@ -34,7 +34,7 @@ public Assembly CurrentDomain_AssemblyResolve(object sender, ResolveEventArgs ar
                 var loadedAssembly = AppDomain.CurrentDomain.GetAssemblies().FirstOrDefault(a => a.GetName().Name == requestedAssemblyName.Name);
                 if (loadedAssembly != null)
                 {
-                    _taskLoggingWrapper.LogMessage($"  Loading {args.Name} from loaded assembly ('{loadedAssembly.FullName}')");
+                    _taskLoggingWrapper.LogDiagnosticMessage($"  Loading {args.Name} from loaded assembly ('{loadedAssembly.FullName}')");
                     return loadedAssembly;
                 }
 
@@ -43,12 +43,12 @@ public Assembly CurrentDomain_AssemblyResolve(object sender, ResolveEventArgs ar
                     var assemblyPath = Path.Combine(_taskFolder, requestedAssemblyName.Name + ".dll");
                     if (File.Exists(assemblyPath))
                     {
-                        _taskLoggingWrapper.LogMessage($"  Loading {args.Name} from {assemblyPath}");
+                        _taskLoggingWrapper.LogDiagnosticMessage($"  Loading {args.Name} from {assemblyPath}");
                         return Assembly.LoadFrom(assemblyPath);
                     }
                 }
 
-                _taskLoggingWrapper.LogMessage($"  {args.Name} is not in folder {_taskFolder}");
+                _taskLoggingWrapper.LogDiagnosticMessage($"  {args.Name} is not in folder {_taskFolder}");
             }
             catch (Exception ex)
             {

diff --git a/Reqnroll.Tools.MsBuild.Generation/GenerateFeatureFileCodeBehindTaskExecutor.cs b/Reqnroll.Tools.MsBuild.Generation/GenerateFeatureFileCodeBehindTaskExecutor.cs
@@ -68,8 +68,13 @@ public IResult<IReadOnlyCollection<ITaskItem>> Execute()
             catch (Exception e)
             {
                 _exceptionTaskLogger.LogException(e);
+                _processInfoDumper.DumpLoadedAssemblies();
                 return Result<IReadOnlyCollection<ITaskItem>>.Failure(e);
             }
+            finally
+            {
+                _processInfoDumper.DumpLoadedAssemblies();
+            }
         }
     }
 }
diff --git a/Reqnroll.Tools.MsBuild.Generation/IProcessInfoDumper.cs b/Reqnroll.Tools.MsBuild.Generation/IProcessInfoDumper.cs
@@ -3,5 +3,6 @@ namespace Reqnroll.Tools.MsBuild.Generation
     public interface IProcessInfoDumper
     {
         void DumpProcessInfo();
+        void DumpLoadedAssemblies();
     }
 }
diff --git a/Reqnroll.Tools.MsBuild.Generation/ITaskLoggingWrapper.cs b/Reqnroll.Tools.MsBuild.Generation/ITaskLoggingWrapper.cs
@@ -4,7 +4,7 @@ public interface ITaskLoggingWrapper
     {
         void LogMessage(string message);
 
-        void LogMessageWithLowImportance(string message);
+        void LogDiagnosticMessage(string message);
 
         void LogError(string message);
 

diff --git a/Reqnroll.Tools.MsBuild.Generation/MSBuildTaskAnalyticsTransmitter.cs b/Reqnroll.Tools.MsBuild.Generation/MSBuildTaskAnalyticsTransmitter.cs
@@ -35,14 +35,14 @@ public async Task TryTransmitProjectCompilingEventAsync()
 
                 if (transmissionResult is IFailure failure)
                 {
-                    _taskLoggingWrapper.LogMessageWithLowImportance($"Could not transmit analytics: {failure}");
+                    _taskLoggingWrapper.LogDiagnosticMessage($"Could not transmit analytics: {failure}");
                 }
             }
             catch (Exception exc)
             {
                 // catch all exceptions since we do not want to break the build simply because event creation failed
                 // but still return an error containing the exception to at least log it
-                _taskLoggingWrapper.LogMessageWithLowImportance($"Could not transmit analytics: {exc}");
+                _taskLoggingWrapper.LogDiagnosticMessage($"Could not transmit analytics: {exc}");
             }
         }
 

diff --git a/Reqnroll.Tools.MsBuild.Generation/MSBuildTraceListener.cs b/Reqnroll.Tools.MsBuild.Generation/MSBuildTraceListener.cs
@@ -6,20 +6,20 @@ namespace Reqnroll.Tools.MsBuild.Generation;
 
 public class MSBuildTraceListener : ITraceListener
 {
-    private readonly TaskLoggingHelper _taskLoggingHelper;
+    private readonly ITaskLoggingWrapper _taskLoggingHelper;
 
-    public MSBuildTraceListener(TaskLoggingHelper taskLoggingHelper) 
+    public MSBuildTraceListener(ITaskLoggingWrapper taskLoggingHelper) 
     {
         _taskLoggingHelper = taskLoggingHelper;
     }
 
     public void WriteTestOutput(string message)
     {
-        _taskLoggingHelper.LogMessage(MessageImportance.High, message);
+        _taskLoggingHelper.LogMessage(message);
     }
 
     public void WriteToolOutput(string message)
     {
-        _taskLoggingHelper.LogMessage(MessageImportance.High, "-> " + message);
+        _taskLoggingHelper.LogMessage("-> " + message);
     }
 }
diff --git a/Reqnroll.Tools.MsBuild.Generation/ProcessInfoDumper.cs b/Reqnroll.Tools.MsBuild.Generation/ProcessInfoDumper.cs
@@ -1,5 +1,7 @@
 using System;
 using System.Diagnostics;
+using System.Linq;
+using System.Runtime.InteropServices;
 
 namespace Reqnroll.Tools.MsBuild.Generation
 {
@@ -17,17 +19,30 @@ public void DumpProcessInfo()
             try
             {
                 var currentProcess = Process.GetCurrentProcess();
+                _taskLoggingWrapper.LogDiagnosticMessage($"process: {currentProcess.ProcessName}, .NET: {RuntimeInformation.FrameworkDescription}, pid: {currentProcess.Id}, CD: {Environment.CurrentDirectory}");
+            }
+            catch (Exception e)
+            {
+                _taskLoggingWrapper.LogDiagnosticMessage($"Error when dumping process info: {e}");
+            }
+            DumpLoadedAssemblies();
+        }
 
-                _taskLoggingWrapper.LogMessage($"process: {currentProcess.ProcessName}, pid: {currentProcess.Id}, CD: {Environment.CurrentDirectory}");
+        public void DumpLoadedAssemblies()
+        {
+            try
+            {
+                _taskLoggingWrapper.LogDiagnosticMessage("Loaded assemblies:");
 
-                foreach (var assembly in AppDomain.CurrentDomain.GetAssemblies())
+                foreach (var assembly in AppDomain.CurrentDomain.GetAssemblies().OrderBy(a => a.FullName))
                 {
-                    _taskLoggingWrapper.LogMessage($"  {assembly.FullName}");
+                    var location = assembly.IsDynamic ? "<dyn>" : assembly.Location;
+                    _taskLoggingWrapper.LogDiagnosticMessage($"  {assembly.FullName};{location}");
                 }
             }
             catch (Exception e)
             {
-                _taskLoggingWrapper.LogMessage($"Error when dumping process info: {e}");
+                _taskLoggingWrapper.LogDiagnosticMessage($"Error when dumping loaded assemblies: {e}");
             }
         }
     }

diff --git a/Reqnroll.Tools.MsBuild.Generation/TaskLoggingHelperWithNameTagWrapper.cs b/Reqnroll.Tools.MsBuild.Generation/TaskLoggingHelperWithNameTagWrapper.cs
@@ -18,7 +18,7 @@ public void LogMessage(string message)
             _taskLoggingHelper.LogMessage(messageWithNameTag);
         }
 
-        public void LogMessageWithLowImportance(string message)
+        public void LogDiagnosticMessage(string message)
         {
             string messageWithNameTag = GetMessageWithNameTag(message);
             _taskLoggingHelper.LogMessage(MessageImportance.Low, messageWithNameTag);

diff --git a/Reqnroll.Tools.MsBuild.Generation/build/Reqnroll.Tools.MsBuild.Generation.props b/Reqnroll.Tools.MsBuild.Generation/build/Reqnroll.Tools.MsBuild.Generation.props
@@ -17,8 +17,6 @@
     <OverwriteReadOnlyFiles Condition="'$(OverwriteReadOnlyFiles)'==''">false</OverwriteReadOnlyFiles>
     <ForceGeneration Condition="'$(ForceGeneration)'==''">false</ForceGeneration>
 
-    <ShowTrace Condition="'$(ShowTrace)'==''">false</ShowTrace>
-    <VerboseOutput Condition="'$(VerboseOutput)'==''">true</VerboseOutput>
     <Reqnroll_DebugMSBuildTask Condition="'$(Reqnroll_DebugMSBuildTask)' == ''">false</Reqnroll_DebugMSBuildTask>
 
     <_ReqnrollPropsImported Condition="'$(_ReqnrollPropsImported)'==''">true</_ReqnrollPropsImported>

diff --git a/Reqnroll.Tools.MsBuild.Generation/build/Reqnroll.Tools.MsBuild.Generation.targets b/Reqnroll.Tools.MsBuild.Generation/build/Reqnroll.Tools.MsBuild.Generation.targets
@@ -68,7 +68,7 @@
   <Target Name="UpdateFeatureFilesInProject"
           DependsOnTargets="BeforeUpdateFeatureFilesInProject">
 
-    <Message Text="ReqnrollFeatureFiles: @(ReqnrollFeatureFiles)" Importance="high" Condition="'$(VerboseOutput)' == 'true'" />
+    <Message Text="[Reqnroll] FeatureFiles: @(ReqnrollFeatureFiles)" Importance="normal" />
 
     <Error
       Text="Reqnroll designer codebehind generation is not compatible with MSBuild codebehind generation. The custom tool must be removed from the file. See https://www.reqnroll.net/documentation/Generate-Tests-from-MsBuild"
@@ -107,8 +107,7 @@
       <Output TaskParameter="GeneratedFiles" ItemName="ReqnrollGeneratedFiles" />
     </GenerateFeatureFileCodeBehindTask>
 
-    <Message Text="ReqnrollGeneratedFiles: %(ReqnrollGeneratedFiles.Identity)" Importance="high" Condition="'$(VerboseOutput)' == 'true'" />
-
+    <Message Text="[Reqnroll] GeneratedFile: %(ReqnrollGeneratedFiles.Identity)" Importance="normal" />
 
     <!--
       net.sdk support: globbing does not support including files which are dynamically generated inside targets, we have to manually update compile items

diff --git a/Tests/Reqnroll.Specs/Features/Execution/Configuration.feature b/Tests/Reqnroll.Specs/Features/Execution/Configuration.feature
@@ -14,11 +14,13 @@ Background:
 
 Scenario: Generation configuration in reqnroll.json
 	Given Reqnroll is configured in the reqnroll.json
-	When I execute the tests
-	Then the reqnroll.json is used for configuration	
+	When the solution is built with log level normal
+	And I execute the tests
+	Then the reqnroll.json is used for configuration
 
 Scenario: Runtime configuration in reqnroll.json
 	Given Reqnroll is configured in the reqnroll.json
-	When I execute the tests
-	Then the reqnroll.json is used for configuration	
+	When the solution is built with log level normal
+	And I execute the tests
+	Then the reqnroll.json is used for configuration
 
diff --git a/Tests/Reqnroll.Specs/StepDefinitions/ExecutionSteps.cs b/Tests/Reqnroll.Specs/StepDefinitions/ExecutionSteps.cs
@@ -51,5 +51,11 @@ public void WhenTheSolutionIsBuiltTwice(uint times)
         {
             _compilationDriver.CompileSolutionTimes(times);
         }
+
+        [When(@"^the solution is built with log level (minimal|normal|detailed)$")]
+        public void WhenTheSolutionIsBuiltWithLogLevel(string logLevel)
+        {
+            _compilationDriver.CompileSolution(logLevel: logLevel);
+        }
     }
 }
diff --git a/Tests/TestProjectGenerator/Reqnroll.TestProjectGenerator/Compiler.cs b/Tests/TestProjectGenerator/Reqnroll.TestProjectGenerator/Compiler.cs
@@ -17,29 +17,29 @@ public Compiler(MSBuildFinder msBuildFinder, TestProjectFolders testProjectFolde
             _outputWriter = outputWriter;
         }
 
-        public CompileResult Run(BuildTool buildTool, bool? treatWarningsAsErrors)
+        public CompileResult Run(BuildTool buildTool, bool? treatWarningsAsErrors, string logLevel)
         {
             switch (buildTool)
             {
                 case BuildTool.MSBuild:
-                    return CompileWithMSBuild(treatWarningsAsErrors);
+                    return CompileWithMSBuild(treatWarningsAsErrors, logLevel);
                 case BuildTool.DotnetBuild:
-                    return CompileWithDotnetBuild(treatWarningsAsErrors);
+                    return CompileWithDotnetBuild(treatWarningsAsErrors, logLevel);
                 case BuildTool.DotnetMSBuild:
-                    return CompileWithDotnetMSBuild(treatWarningsAsErrors);
+                    return CompileWithDotnetMSBuild(treatWarningsAsErrors, logLevel);
                 default:
                     throw new ArgumentOutOfRangeException(nameof(buildTool), buildTool, null);
             }
         }
 
-        private CompileResult CompileWithMSBuild(bool? treatWarningsAsErrors)
+        private CompileResult CompileWithMSBuild(bool? treatWarningsAsErrors, string logLevel)
         {
             var msBuildPath = _msBuildFinder.FindMSBuild();
 
             _outputWriter.WriteLine($"Invoke MsBuild from {msBuildPath}");
 
             var processHelper = new ProcessHelper();
-            string argumentsFormat = $"{GetWarningAsErrorParameter(treatWarningsAsErrors)} -restore -binaryLogger:;ProjectImports=None -nodeReuse:false -v:m \"{_testProjectFolders.PathToSolutionFile}\"";
+            string argumentsFormat = $"{GetWarningAsErrorParameter(treatWarningsAsErrors)} -restore -binaryLogger:;ProjectImports=None -nodeReuse:false -v:{logLevel ?? "m"} \"{_testProjectFolders.PathToSolutionFile}\"";
 
             var msBuildProcess = processHelper.RunProcess(_outputWriter, _testProjectFolders.PathToSolutionDirectory, msBuildPath, argumentsFormat);
 
@@ -51,19 +51,19 @@ private string GetWarningAsErrorParameter(bool? treatWarningsAsErrors)
             return treatWarningsAsErrors is true ? "-warnaserror" : "";
         }
 
-        private CompileResult CompileWithDotnetBuild(bool? treatWarningsAsErrors)
+        private CompileResult CompileWithDotnetBuild(bool? treatWarningsAsErrors, string logLevel)
         {
             _outputWriter.WriteLine("Invoking dotnet build");
 
             var processHelper = new ProcessHelper();
 
-            string argumentsFormat = $"build {GetWarningAsErrorParameter(treatWarningsAsErrors)} -nologo -v:m \"{_testProjectFolders.PathToSolutionFile}\"";
+            string argumentsFormat = $"build {GetWarningAsErrorParameter(treatWarningsAsErrors)} -nologo -v:{logLevel ?? "m"} \"{_testProjectFolders.PathToSolutionFile}\"";
             var dotnetBuildProcessResult = processHelper.RunProcess(_outputWriter, _testProjectFolders.PathToSolutionDirectory, "dotnet", argumentsFormat);
 
             return new CompileResult(dotnetBuildProcessResult.ExitCode, dotnetBuildProcessResult.CombinedOutput);
         }
 
-        private CompileResult CompileWithDotnetMSBuild(bool? treatWarningsAsErrors)
+        private CompileResult CompileWithDotnetMSBuild(bool? treatWarningsAsErrors, string logLevel)
         {
             _outputWriter.WriteLine($"Invoking dotnet msbuild");
 
@@ -72,7 +72,7 @@ private CompileResult CompileWithDotnetMSBuild(bool? treatWarningsAsErrors)
             // execute dotnet restore
             processHelper.RunProcess(_outputWriter, _testProjectFolders.PathToSolutionDirectory, "dotnet", "restore -binaryLogger:;ProjectImports=None -nodeReuse:false -nologo");
 
-            string argumentsFormat = $@"msbuild {GetWarningAsErrorParameter(treatWarningsAsErrors)} -binaryLogger:;ProjectImports=None -nodeReuse:false -nologo -v:m ""{_testProjectFolders.PathToSolutionFile}""";
+            string argumentsFormat = $@"msbuild {GetWarningAsErrorParameter(treatWarningsAsErrors)} -binaryLogger:;ProjectImports=None -nodeReuse:false -nologo -v:{logLevel ?? "m"} ""{_testProjectFolders.PathToSolutionFile}""";
             var msBuildProcess = processHelper.RunProcess(_outputWriter, _testProjectFolders.PathToSolutionDirectory, "dotnet", argumentsFormat);
 
             return new CompileResult(msBuildProcess.ExitCode, msBuildProcess.CombinedOutput);

diff --git a/Tests/TestProjectGenerator/Reqnroll.TestProjectGenerator/Driver/CompilationDriver.cs b/Tests/TestProjectGenerator/Reqnroll.TestProjectGenerator/Driver/CompilationDriver.cs
@@ -22,12 +22,12 @@ public CompilationDriver(Compiler compiler, SolutionWriteToDiskDriver solutionWr
 
         public bool HasTriedToCompile { get; private set; }
 
-        public void CompileSolution(BuildTool buildTool = DefaultBuildTool, bool? treatWarningsAsErrors = null, bool failOnError = true)
+        public void CompileSolution(BuildTool buildTool = DefaultBuildTool, bool? treatWarningsAsErrors = null, bool failOnError = true, string logLevel = null)
         {
-            CompileSolutionTimes(1, buildTool, treatWarningsAsErrors, failOnError);
+            CompileSolutionTimes(1, buildTool, treatWarningsAsErrors, failOnError, logLevel);
         }
 
-        public void CompileSolutionTimes(uint times, BuildTool buildTool = DefaultBuildTool, bool? treatWarningsAsErrors = null, bool failOnError = true)
+        public void CompileSolutionTimes(uint times, BuildTool buildTool = DefaultBuildTool, bool? treatWarningsAsErrors = null, bool failOnError = true, string logLevel = null)
         {
             HasTriedToCompile = true;
             _solutionWriteToDiskDriver.WriteSolutionToDisk(treatWarningsAsErrors);
@@ -36,7 +36,7 @@ public void CompileSolutionTimes(uint times, BuildTool buildTool = DefaultBuildT
 
             for (uint time = 0; time < times; time++)
             {
-                _compilationResultDriver.CompileResult = _compiler.Run(usedBuildTool, treatWarningsAsErrors);
+                _compilationResultDriver.CompileResult = _compiler.Run(usedBuildTool, treatWarningsAsErrors, logLevel);
                 if (failOnError && !_compilationResultDriver.CompileResult.IsSuccessful)
                 {
                     var missingSdk = Regex.Match(_compilationResultDriver.CompileResult.Output, @"(MSB3644: .* not found\.)");

diff --git a/...ProjectGenerator/Reqnroll.TestProjectGenerator/FilesystemWriter/OldFormatProjectWriter.cs b/...ProjectGenerator/Reqnroll.TestProjectGenerator/FilesystemWriter/OldFormatProjectWriter.cs
@@ -147,7 +147,6 @@ private void WriteProjectProperties(XmlWriter xw, Project project)
                 xw.WriteElementString("SchemaVersion", "2.0");
                 xw.WriteElementString("ProductVersion", null);
                 xw.WriteElementString("ProjectTypeGuids", "{3AC096D0-A1C2-E12C-1390-A8335801FDAB};{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}");
-                xw.WriteElementString("ShowTrace", "true");
                 xw.WriteElementString("ErrorReport", "prompt");
                 xw.WriteElementString("WarningLevel", "4");
             }

diff --git a/docs/help/troubleshooting.md b/docs/help/troubleshooting.md
@@ -6,3 +6,10 @@ You can enable traces for Reqnroll. Once tracing is enabled, a new `Reqnroll` pa
 
 To enable tracing, select **Tools | Options | Reqnroll** from the menu in Visual Studio and set **Enable Tracing** to 'True'. 
 
+## Additional MSBuild logs
+
+You can enable additional Reqnroll-specific MSBuild logs. Enable a higher [level of detail in MSBuild](https://learn.microsoft.com/en-us/visualstudio/msbuild/obtaining-build-logs-with-msbuild#set-the-level-of-detail).
+
+The most important logs are already displayed with `detailed' output.
+
+All Reqnroll log entries have a `[Reqnroll]` prefix.