Msbuild: Logging through an out-of-date `TaskLoggingHelper` causes MSB0001

[rainersigwald]

MSB0001: Internal MSBuild Error: ContextID 10 should have been in the ID-to-project file mapping but wasn't!

---

at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
    at Microsoft.Build.BackEnd.Logging.LoggingService.GetAndVerifyProjectFileFromContext(BuildEventContext context)
    at Microsoft.Build.BackEnd.Logging.LoggingService.LogBuildEvent(BuildEventArgs buildEvent)
    at Microsoft.Build.BackEnd.TaskHost.LogMessageEvent(BuildMessageEventArgs e)
    at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(MessageImportance importance, String message, Object[] messageArgs)
    at NuGet.Build.MSBuildLogger.LogMessage(INuGetLogMessage logMessage, MessageImportance importance, LogMessageWithDetails logWithDetails, LogMessageAsString logAsString)
    at NuGet.Build.MSBuildLogger.LogForNonMono(INuGetLogMessage message)
    at NuGet.Build.MSBuildLogger.Log(ILogMessage message)
    at NuGet.Common.LoggerBase.Log(LogLevel level, String data)
    at NuGet.Common.LoggerBase.LogVerbose(String data)
    at NuGet.Protocol.Plugins.LogRequestHandler.Log(LogRequest request)
    at NuGet.Protocol.Plugins.LogRequestHandler.HandleResponseAsync(IConnection connection, Message request, IResponseHandler responseHandler, CancellationToken cancellationToken)

[rainersigwald]

Rough notes on what I've figured out debugging the repro I got offline so far:

• RestoreTask is called twice; the second one is the one that crashes.
• it uses async/await and does a bunch of work in the background, but AFAIK waits for it all to complete before returning (doesn't even yield the node).
• The internal error is thrown here:
  https://github.com/microsoft/msbuild/blob/25f141655da25aace8fd2ee1776f43210b124e92/src/Build/BackEnd/Components/Logging/LoggingService.cs#L1548-L1553
• that _projectFileMap is added to on project start
  https://github.com/microsoft/msbuild/blob/25f141655da25aace8fd2ee1776f43210b124e92/src/Build/BackEnd/Components/Logging/LoggingServiceLogMethods.cs#L567
• and removed from on project finish
  https://github.com/microsoft/msbuild/blob/25f141655da25aace8fd2ee1776f43210b124e92/src/Build/BackEnd/Components/Logging/LoggingServiceLogMethods.cs#L640
• The repro always fails with the map containing

4: C:\Users\azdofeeds\Workdir\dotnet-core-setup\.packages\microsoft.dotnet.arcade.sdk\1.0.0-beta.19461.7\tools\Build.proj
124: C:\Users\azdofeeds\Workdir\dotnet-core-setup\.dotnet\sdk\3.0.100-preview6-012264\NuGet.targets

• NuGet.targets being a project is weird but expected because of https://github.com/dotnet/arcade/blob/8cd48078f550fbcbd4f684b897b14db207397b52/src/Microsoft.DotNet.Arcade.Sdk/tools/Build.proj#L150-L162
• It fails because it's looking for

7: C:\Users\azdofeeds\Workdir\dotnet-core-setup\.packages\microsoft.dotnet.arcade.sdk\1.0.0-beta.19461.7\tools\Tools.proj

• But I think the second time the task is run, it should be from build.proj

[rainersigwald]

1. The first call to RestoreTask gets a TaskLoggingHelper (which I made object ID $1)
2. The second call to RestoreTask gets a TaskLoggingHelper (which I made object ID $2)
3. At the point of failure inside the second task, it tries to log through $1:

[rainersigwald]

The root cause here is NuGet/Home#8688; NuGet preserves a reference to a TaskLoggingHelper object in a static field beyond the lifetime of its associated Task invocation. When NuGet tries to log to it later, it results in this assertion failure.

MSBuild may be able to provide a more helpful error in this case. It'd be nice to be able to know what task created the logging context in the error, for instance.

[livarcocc]

Closing this issue as this has been root caused to be an issue in NuGet.

[livarcocc]

@rainersigwald if you want to add better error messages here, let's use a separate issue for that.

[danmoseley]

Since it's easy for task authors to get this wrong, perhaps TaskLoggingHelper should implement IDisposable, and the Dispose would zombify it to block all calls to it.