Adding logging causes exception and failure

[michael-hawker]

Added the following logging parameters:

-bl:slngen.binlog --consolelogger:ShowEventId,Summary,Verbosity=Detailed --filelogger:LogFile=slngen.log,Append,Verbosity=Diagnostic,Encoding=UTF-8 

Without them, slngen worked, but with them, it causes this error:

SlnGen : error : System.AggregateException: One or more errors occurred. ---> System.InvalidOperationException: Stack empty.
SlnGen : error :    at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
SlnGen : error :    at System.Collections.Generic.Stack`1.Pop()
SlnGen : error :    at Microsoft.Build.BackEnd.Logging.SerialConsoleLogger.WriteProjectStarted()
SlnGen : error :    at Microsoft.Build.BackEnd.Logging.SerialConsoleLogger.ShowDeferredMessages()
SlnGen : error :    at Microsoft.Build.BackEnd.Logging.SerialConsoleLogger.ProjectStartedHandler(Object sender, ProjectStartedEventArgs e)
SlnGen : error :    at Microsoft.Build.Logging.EventArgsDispatcher.Dispatch(BuildEventArgs buildEvent)
SlnGen : error :    at Microsoft.VisualStudio.SlnGen.ProjectLoading.ProjectGraphProjectLoader.CreateProjectInstance(String projectFullPath, IDictionary`2 globalProperties, ProjectCollection projectCollection)
SlnGen : error :    at Microsoft.Build.Graph.GraphBuilder.ParseProject(ConfigurationMetadata configurationMetadata)
SlnGen : error :    at System.Lazy`1.CreateValue()
SlnGen : error :    at System.Lazy`1.LazyInitValue()
SlnGen : error :    at Microsoft.Build.Graph.ParallelWorkSet`2.ExecuteWorkItem()
SlnGen : error :    --- End of inner exception stack trace ---
SlnGen : error :    at Microsoft.Build.Graph.ParallelWorkSet`2.WaitForAllWorkAndComplete()
SlnGen : error :    at Microsoft.Build.Graph.GraphBuilder.FindGraphNodes()
SlnGen : error :    at Microsoft.Build.Graph.GraphBuilder.BuildGraph()
SlnGen : error :    at Microsoft.Build.Graph.ProjectGraph..ctor(IEnumerable`1 entryPoints, ProjectCollection projectCollection, ProjectInstanceFactoryFunc projectInstanceFactory, Int32 degreeOfParallelism, CancellationToken cancellationToken)
SlnGen : error :    at Microsoft.VisualStudio.SlnGen.ProjectLoading.ProjectGraphProjectLoader.LoadProjects(IEnumerable`1 projectPaths, ProjectCollection projectCollection, IDictionary`2 globalProperties)
SlnGen : error :    at Microsoft.VisualStudio.SlnGen.ProjectLoading.ProjectLoader.LoadProjects(FileInfo msbuildExeFileInfo, ProjectCollection projectCollection, IEnumerable`1 entryProjects, IDictionary`2 globalProperties, ISlnGenLogger logger)
SlnGen : error : ---> (Inner Exception #0) System.InvalidOperationException: Stack empty.
SlnGen : error :    at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
SlnGen : error :    at System.Collections.Generic.Stack`1.Pop()
SlnGen : error :    at Microsoft.Build.BackEnd.Logging.SerialConsoleLogger.WriteProjectStarted()
SlnGen : error :    at Microsoft.Build.BackEnd.Logging.SerialConsoleLogger.ShowDeferredMessages()
SlnGen : error :    at Microsoft.Build.BackEnd.Logging.SerialConsoleLogger.ProjectStartedHandler(Object sender, ProjectStartedEventArgs e)
SlnGen : error :    at Microsoft.Build.Logging.EventArgsDispatcher.Dispatch(BuildEventArgs buildEvent)
SlnGen : error :    at Microsoft.VisualStudio.SlnGen.ProjectLoading.ProjectGraphProjectLoader.CreateProjectInstance(String projectFullPath, IDictionary`2 globalProperties, ProjectCollection projectCollection)
SlnGen : error :    at Microsoft.Build.Graph.GraphBuilder.ParseProject(ConfigurationMetadata configurationMetadata)
SlnGen : error :    at System.Lazy`1.CreateValue()
SlnGen : error :    at System.Lazy`1.LazyInitValue()
SlnGen : error :    at Microsoft.Build.Graph.ParallelWorkSet`2.ExecuteWorkItem()<---
SlnGen : error :
    7 Warning(s)
    1 Error(s)

(realized I had commas above as was confused by #450; so that may have been part of the issue for this one, but had another stack below)

[michael-hawker]

Found another:

Microsoft.Build.Exceptions.InternalLoggerException: The build stopped unexpectedly because the "ReusableLogger" logger failed unexpectedly during shutdown. ---> System.ObjectDisposedException: Cannot write to a closed TextWriter.
   at System.IO.__Error.WriterClosed()
   at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
   at Microsoft.Build.Framework.BuildFinishedEventHandler.Invoke(Object sender, BuildFinishedEventArgs e)
   at Microsoft.Build.Logging.EventArgsDispatcher.Dispatch(BuildEventArgs buildEvent)
   at Microsoft.VisualStudio.SlnGen.ForwardingLogger.Shutdown()
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
   --- End of inner exception stack trace ---
   at Microsoft.Build.Exceptions.InternalLoggerException.Throw(Exception innerException, BuildEventArgs e, String messageResourceName, Boolean initializationException, String[] messageArgs)
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownComponent()
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()
   at Microsoft.Build.Evaluation.ProjectCollection.Dispose(Boolean disposing)
   at Microsoft.Build.Evaluation.ProjectCollection.Dispose()
   at Microsoft.VisualStudio.SlnGen.Program.Execute(ProgramArguments arguments, IConsole console)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at McMaster.Extensions.CommandLineUtils.Conventions.ExecuteMethodConvention.Invoke(MethodInfo method, Object instance, Object[] arguments)
   at McMaster.Extensions.CommandLineUtils.Conventions.ExecuteMethodConvention.<OnExecute>d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
[slngen-logs.zip](https://github.com/microsoft/slngen/files/10572819/slngen-logs.zip)

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at McMaster.Extensions.CommandLineUtils.Conventions.ExecuteMethodConvention.<>c__DisplayClass0_0.<<Apply>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at McMaster.Extensions.CommandLineUtils.CommandLineApplication.<ExecuteAsync>d__154.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at McMaster.Extensions.CommandLineUtils.CommandLineApplication.<ExecuteAsync>d__183`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at McMaster.Extensions.CommandLineUtils.CommandLineApplication.Execute[TApp](CommandLineContext context)
   at Microsoft.VisualStudio.SlnGen.Program.Execute(String[] args, IConsole console)

Can see this in our CI run here: https://github.com/CommunityToolkit/Labs-Windows/actions/runs/4077929697/jobs/7027560709#step:8:1138

Logs from our CI as well:
slngen-logs.zip

[michael-hawker]

Interestingly, on a linux environment on Codespaces things seem to work, so these may be issues with the loggers on Windows only? (Saw them locally and in our CI, so Win10 and Server 2022.)

Logs from linux environment in codespaces attached here.

slngen-linux.zip

[jeffkl]

SlnGen is faking a project started event so that the binary log shows SUCCESS vs FAILURE. It would appear that the SerialConsoleLogger doesn't like this...

[michael-hawker]

See this with 11.2.3 and 11.2.6 still.

[Arlodotexe]

Looks like the issue is coming up with ReusableLogger/TextWriter as well: https://github.com/CommunityToolkit/Tooling-Windows-Submodule/actions/runs/11509384515/job/32039385206#step:12:3084

Importing project "C:\Program Files\dotnet\sdk\8.0.403\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.GenerateGlobalUsings.targets" into project "C:\Program Files\dotnet\sdk\8.0.403\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets" at (1299,3).
Microsoft.Build.Exceptions.InternalLoggerException: The build stopped unexpectedly because the "ReusableLogger" logger failed unexpectedly during shutdown. ---> System.ObjectDisposedException: Cannot write to a closed TextWriter.
   at System.IO.__Error.WriterClosed()
   at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
   at Microsoft.Build.Framework.BuildFinishedEventHandler.Invoke(Object sender, BuildFinishedEventArgs e)
   at Microsoft.Build.Logging.EventArgsDispatcher.Dispatch(BuildEventArgs buildEvent)
   at Microsoft.VisualStudio.SlnGen.ForwardingLogger.Shutdown()

[michael-hawker]

@jeffkl any suggestions on how this could be resolved or worked around? We're encountering issues with slngen failing in particular circumstances now, but not sure why. It's just a not implemented exception, so getting logs from slngen itself would be useful to understand what's going on.

[jeffkl]

I haven't been able to reproduce the problem. SlnGen is using the logging infrastructure in MSBuild so I would expect the issue to be in those APIs. Can you find a way to reproduce the problem so I can debug it?