Embed source file from CodeTaskFactory and RoslynCodeTaskFactory in binlog

[surayya-MS]

Fixes #9686

Context

See more details in the issue description.

There is no way to embed the source file inside the CodeTaskFactory.cs / RoslynCodeTaskFactory.cs because there is no logging context or logging service, only IBuildEngine. But it is possible to do that after the factory is intialized because there is logging context available there https://github.com/dotnet/msbuild/blob/b783f61ef6fcadef68c54daac21e18c1c20fc071/src/Build/Instance/TaskRegistry.cs#L1479 I needed the factory to have SourceFilePath (ITaskFactory seemed not the right place for that). So, I introduced new interface IHasSourceFilePath

Changes Made

Introduced new interface IHasSourceFilePath

namespace Microsoft.Build.Framework
{
    public interface IHasSourceFilePath
    {
        string? SourceFilePath { get; }
    }
}

CodeTaskFactory and RoslynCodeTaskFactory implement that interface.

Embedded the source file via logging context and specifying SourceFilePath from the factory.

Testing

Added unit tests and tested manually.

Notes

[surayya-MS]

Question: this is doing what the bug asked for, which is logging the .cs file if it was separate. Looking at it, I wonder if we should try to do one better and embed the generated source file too, regardless of where the C# came from--that is, log the file we tried to compile instead of the source.

@rainersigwald , I agree that logging the generated file would improve debuggability. However, on the second thought wouldn't that be redundant because the code is already in the .csproj file? And what about Type "Fragment" and "Method"? Example:

<Task>
	<Code Type="Class" Language="cs">
		using Microsoft.Build.Framework;
		using Microsoft.Build.Utilities;

		public class MyTask : Microsoft.Build.Utilities.Task
		{
		public override bool Execute()
		{
		Log.LogMessage(MessageImportance.High, "MyTask has been executed. The value of StringComparison is: " + StringComparison);
		return true;
		}
		}
	</Code>
</Task>

[rainersigwald]

I think logging the generated file for Fragment and Method types would be the most helpful thing, since the interaction of the code we generate and the code from the project file could be going wrong and seeing it all in one place could help explain why.

Agreed that if you have 100% of the code in the project there's no need to log it redundantly.

[surayya-MS]

There are some strange fails on Windows Full and Windows Core (Now it is only Windows Full and I didn't change the code). The error message is:

Child node "1" exited prematurely. Shutting down. Diagnostic information may be found in files in "C:\Users\VssAdministrator\AppData\Local\Temp\MSBuildTemp\" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.Microsoft.Build.Exceptions.InternalLoggerException: The build stopped unexpectedly because of an unexpected logger failure. ---> System.ArgumentNullException: Parameter "BuildEventContext" cannot be null.
   at Microsoft.Build.Shared.ErrorUtilities.ThrowArgumentNull(String parameterName, String resourceName) in /_/src/Shared/ErrorUtilities.cs:line 575
   at Microsoft.Build.Shared.ErrorUtilities.VerifyThrowArgumentNull(Object parameter, String parameterName, String resourceName) in /_/src/Shared/ErrorUtilities.cs:line 568
   at Microsoft.Build.Shared.ErrorUtilities.VerifyThrowArgumentNull(Object parameter, String parameterName) in /_/src/Shared/ErrorUtilities.cs:line 557
   at Microsoft.Build.BackEnd.Logging.ParallelConsoleLogger.MessageHandler(Object sender, BuildMessageEventArgs e) in /_/src/Build/Logging/ParallelLogger/ParallelConsoleLogger.cs:line 1132
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseMessageEvent(Object sender, BuildMessageEventArgs buildEvent) in /_/src/Build/BackEnd/Components/Logging/EventSourceSink.cs:line 323
   --- End of inner exception stack trace ---
   at Microsoft.Build.Exceptions.InternalLoggerException.Throw(Exception innerException, BuildEventArgs e, String messageResourceName, Boolean initializationException, String[] messageArgs) in /_/src/Build/Errors/InternalLoggerException.cs:line 253
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseMessageEvent(Object sender, BuildMessageEventArgs buildEvent) in /_/src/Build/BackEnd/Components/Logging/EventSourceSink.cs:line 344
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent) in /_/src/Build/BackEnd/Components/Logging/EventSourceSink.cs:line 223
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent, Int32 sinkId) in /_/src/Build/BackEnd/Components/Logging/EventSourceSink.cs:line 211
   at Microsoft.Build.BackEnd.Logging.LoggingService.RouteBuildEvent(KeyValuePair`2 nodeEvent) in /_/src/Build/BackEnd/Components/Logging/LoggingService.cs:line 1630
   at Microsoft.Build.BackEnd.Logging.LoggingService.RouteBuildEvent(Object loggingEvent) in /_/src/Build/BackEnd/Components/Logging/LoggingService.cs:line 1614
   at Microsoft.Build.BackEnd.Logging.LoggingService.LoggingEventProcessor(Object loggingEvent) in /_/src/Build/BackEnd/Components/Logging/LoggingService.cs:line 1454

Given the error message, my guess was that the unexpected error could be thrown while the execution of the new tests. So, I removed the tests to see if Windows Full and Windows Core will fail again, and they failed again. When reverting the changes back now Windows Core passes and Windows Full not.

@rainersigwald , @ladipro what do you think might be the problem?

[surayya-MS]

I think logging the generated file for Fragment and Method types would be the most helpful thing, since the interaction of the code we generate and the code from the project file could be going wrong and seeing it all in one place could help explain why.

Agreed that if you have 100% of the code in the project there's no need to log it redundantly.

Thanks! I agree. In that case, it makes sense to log the generated file not only for Fragment and Method but for Class also. I will change the code and add tests.

[rainersigwald]

That type of error generally indicates a hard crash in a worker node. In this case it's happening in the post-bootstrap portion of our build, when we build the MSBuild codebase with the MSBuild engine you just built (to catch just this kind of problem!).

Is your new code setting a BuildEventContext to null anywhere? That seems like a legit error. You should be able to repro on your machine by running build.cmd to get a bootstrap build, and then using artifacts\bin\bootstrap\net472\MSBuild\Current\Bin\amd64\MSBuild.exe to build a project (with a CodeTaskFactory, I guess).

[surayya-MS]

That type of error generally indicates a hard crash in a worker node. In this case it's happening in the post-bootstrap portion of our build, when we build the MSBuild codebase with the MSBuild engine you just built (to catch just this kind of problem!).

Is your new code setting a BuildEventContext to null anywhere? That seems like a legit error. You should be able to repro on your machine by running build.cmd to get a bootstrap build, and then using artifacts\bin\bootstrap\net472\MSBuild\Current\Bin\amd64\MSBuild.exe to build a project (with a CodeTaskFactory, I guess).

I tried to build with artifacts\bin\bootstrap\net472\MSBuild\Current\Bin\amd64\MSBuild.exe and it works on my machine. I will investigate further.

[ladipro]

@surayya-MS have you been able to reproduce? For what it's worth, running eng\cibuild_bootstrapped_msbuild.cmd reproduces the crash on my machine. Should the new LogIncludeFile call be executed only if initialized is true?

[surayya-MS]

@surayya-MS have you been able to reproduce? For what it's worth, running eng\cibuild_bootstrapped_msbuild.cmd reproduces the crash on my machine. Should the new LogIncludeFile call be executed only if initialized is true?

Thanks @ladipro for pointing out the script! I was able to repro the error on my machine.

The reason for not checking for initialized is because we want to log the file in case when initialization failed (for example file does not compile, I added tests for this case)

It looks like the problem arises because of incorrect serializing/deserializing ResponseFileUsedEventArgs as BuildMessageEventArgs in ParallelConsoleLogger. In BuildMessageEventArgs nullable is disabled and something goes wrong because of MessageImportance. Specifying MessageImportance.Low in ResponseFileUsedEventArgs seems to fix the issue.

[rainersigwald]

It looks like the problem arises because of incorrect serializing/deserializing ResponseFileUsedEventArgs as BuildMessageEventArgs in ParallelConsoleLogger. In BuildMessageEventArgs nullable is disabled and something goes wrong because of MessageImportance. Specifying MessageImportance.Low in ResponseFileUsedEventArgs seems to fix the issue.

The changes you made there look fine to me, but what about this PR is triggering the problem?

[surayya-MS]

The changes you made there look fine to me, but what about this PR is triggering the problem?

The LogIncludeFile call in TaskRegistry.cs triggers it. I tried removing this call and run the script and it didn't fail. My understanding is that when eng\cibuild_bootstrapped_msbuild.cmd is executed some test is running and fails unexpectedly because of ParallelConsoleLogger

[surayya-MS]

The PR is not ready for review yet. I will apply changes so that the generated file would be included in the binlog.

[surayya-MS]

The current logic for RoslynCodeTaskFactory is to create a .tmp file for compiling regardless of whether the code is coming from a source file or the code inside <Code> in csproj: https://github.com/dotnet/msbuild/blob/cdcfc3501d6c086407703194f742ab65d5a80525/src/Tasks/RoslynCodeTaskFactory/RoslynCodeTaskFactory.cs#L689 @rainersigwald should we just embed this compilation file in the binlog instead of embedding the source file if it exists or generated file (the compilation file)?

[rainersigwald]

Yeah that sounds pretty reasonable to me. My only concern would be: are we creating a race between embedding that file and deleting it?

[surayya-MS]

Yeah that sounds pretty reasonable to me. My only concern would be: are we creating a race between embedding that file and deleting it?

Yeah, there is a race condition, and in most cases in tests the file is deleted before being embedded. I missed it when debugging.

I came up with a different solution of logging the generated file from the given content that should be in the file. I updated the PR description.

[surayya-MS]

Question after reading the comment from the linked PR.

The current logic is to create a file when this MSBUILDLOGCODETASKFACTORYOUTPUT is set and the compilation failed. @rainersigwald , should I remove the current behavior now when the files are embedded in the binlog after my changes? And if yes, should I apply change wave for the removal of this behavior?

[rainersigwald]

I'd leave the env car opt in. I wouldn't add it now but putting "respect env var opt in" behind "changewave env var opt in" feels like a dark path to go down.

[surayya-MS]

The PR is ready for review.

[surayya-MS]

Thanks @ladipro! I investigated if it is possible to get the full path of the file relative to the current project inside of BinnaryLogger and it turns out it is. Removed the interface.