[Bug]: Enabling msbuild engine logging can cause EndBuild to fail

[adrianvmsft]

Issue Description

This was encountered while investigating an issue where design time builds were very slow. It turns out, EndBuild failed, leaving the DTBB service in an invalid state, causing CPS based projects to fallback to the slower, legacy build pipeline.

The DTBB service is being improved to better handle EndBuild throwing exceptions. However, this exception may still be thrown. Also, repeated opening and closing of the file may be less performant than keeping the file opened, and could be locked by the antivirus.

For more details, please refer to the internal devdiv item AB#2235125

Exception object: 000002225a4a7658
Exception type:   System.IO.IOException
Message:          The process cannot access the file 'C:\Temp\msbuild\SchedulerState_57780.txt' because it is being used by another process.
InnerException:   <none>
StackTrace (generated):
    SP               IP               Function
    000000B2140BE830 00007FFABC760917 mscorlib_ni!System.IO.__Error.WinIOError(Int32, System.String)+0x3a7
    000000B2140BE880 00007FFABC7B165F mscorlib_ni!System.IO.FileStream.Init(System.String, System.IO.FileMode, System.IO.FileAccess, Int32, Boolean, System.IO.FileShare, Int32, System.IO.FileOptions, SECURITY_ATTRIBUTES, System.String, Boolean, Boolean, Boolean)+0x42f
    000000B2140BE950 00007FFABC7FFCB4 mscorlib_ni!System.IO.FileStream..ctor(System.String, System.IO.FileMode, System.IO.FileAccess, System.IO.FileShare, Int32, System.IO.FileOptions)+0x84
    000000B2140BEA00 00007FFA099393C8 Microsoft_Build_ni!Microsoft.Build.Shared.FileUtilities.OpenWrite(System.String, Boolean, System.Text.Encoding)+0x58
    000000B2140BEA60 00007FFA099730D2 Microsoft_Build_ni!Microsoft.Build.BackEnd.Scheduler.DumpSchedulerState()+0xe2
    000000B2140BEB60 00007FFA09972324 Microsoft_Build_ni!Microsoft.Build.BackEnd.Scheduler.ScheduleUnassignedRequests(System.Collections.Generic.List`1<Microsoft.Build.BackEnd.ScheduleResponse>)+0x434
    000000B2140BEBE0 00007FFA09976295 Microsoft_Build_ni!Microsoft.Build.BackEnd.Scheduler.ReportResult(Int32, Microsoft.Build.Execution.BuildResult)+0x255
    000000B2140BEC80 00007FFA099693AC Microsoft_Build_ni!Microsoft.Build.Execution.BuildManager.HandleResult(Int32, Microsoft.Build.Execution.BuildResult)+0xfc
    000000B2140BED10 00007FFA09968890 Microsoft_Build_ni!Microsoft.Build.Execution.BuildManager.ProcessPacket(Int32, Microsoft.Build.BackEnd.INodePacket)+0xf0
    000000B2140BED80 00007FFA09965F9E Microsoft_Build_ni!Microsoft.Build.Execution.BuildManager.ProcessWorkQueue(System.Action)+0x9e
    000000B2135BE310 00007FFABD145040 mscorlib_ni!System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()+0x20
    000000B2135BE340 00007FFA09967E31 Microsoft_Build_ni!Microsoft.Build.Execution.BuildManager.EndBuild()+0x4b1
    000000B2135BE4C0 00007FFA233237F1 Microsoft_VisualStudio_ProjectServices_ni!Microsoft.VisualStudio.ProjectServices.BuildManagerAdapter.Microsoft.VisualStudio.ProjectServices.IBuildManager.EndBuildAsync()+0x11
    000000B2135BE4F0 00007FFA2334C258 Microsoft_VisualStudio_ProjectServices_ni!Microsoft.VisualStudio.ProjectServices.DesignTimeBuildScheduler+<EndBuildAsync>d__40.MoveNext()+0x48
    000000B2135BE600 00007FFABD145040 mscorlib_ni!System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()+0x20
    000000B2135BE630 00007FFABC80D66E mscorlib_ni!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)+0x3e
    000000B2135BE660 00007FFA2334CBF0 Microsoft_VisualStudio_ProjectServices_ni!Microsoft.VisualStudio.ProjectServices.DesignTimeBuildScheduler+<SubmitNextAsync>d__59.MoveNext()+0x140
    000000B2135BE820 00007FFABD145040 mscorlib_ni!System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()+0x20
    000000B2135BE850 00007FFA2334C49C Microsoft_VisualStudio_ProjectServices_ni!Microsoft.VisualStudio.ProjectServices.DesignTimeBuildScheduler+<FeedMSBuildAsync>d__58.MoveNext()+0xfc
    000000B2135BE960 00007FFABD145040 mscorlib_ni!System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()+0x20
    000000B2135BE990 00007FFABC80D66E mscorlib_ni!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)+0x3e
    000000B2135BE9C0 00007FFA2334B60F Microsoft_VisualStudio_ProjectServices_ni!Microsoft.VisualStudio.ProjectServices.DesignTimeBuildScheduler+<CompleteOneAsync>d__53.MoveNext()+0x19f

Steps to Reproduce

No repro, for dump please refer to internal devdiv item 2235125

Expected Behavior

This method should not cause EndBuild to fail.

Actual Behavior

EndBuild fails, leading to DTBB Service in invalid state (that issue is being fixed on the DTBB side)

Analysis

No response

Versions & Configurations

No response

[rainersigwald]

Also, repeated opening and closing of the file may be less performant than keeping the file opened

It is more robust to crashing, though, which I think is why this was decided long ago.

I agree that this logging should be best-effort and not cause a crash.

[baronfel]

Is this logging to the file logger? Why not a binlog instead?

[rainersigwald]

This is engine/scheduler-state logging that is also enabled with MSBUILDDEBUGENGINE. Which we should maybe reconsider, it is rarely useful even to us.

[rainersigwald]

This is engine/scheduler-state logging that is also enabled with MSBUILDDEBUGENGINE. Which we should maybe reconsider, it is rarely useful even to us.

10639

[rainersigwald]

Fixed with #10642.