Don't forward along binlog arguments to runnable applications #43430

baronfel · 2024-09-13T14:31:13Z

In #42240 I introduced a regression in behavior for applications in dotnet run. The -bl argument would get forwarded along as application arguments, not arguments to the implicit build/restore that dotnet run performs.

A 'proper' way of handling this would be to model the -bl argument syntax in S.CL, but this is currently impossible due to design differences between MSBuild's CLI syntax and S.CL.

So instead we filter out the -bl argument from the application arguments if it exists (along with any of its arguments) and apply it to the restore arguments. We have to do special handling of the binlog file name because binlogs are not appendable and we're actually doing two 'build' operations here - one managed entirely by MSBuild, and one managed by the CLI. As a result, we need to provide different names to the binlogs used in each case.

One odd case that I found is that for some reason I cannot use the same binaryLogger for the evaluation phase and the execution phase of the dotnet run protocol - I split this into two binlogs to illustrate the problem. Would love some feedback from @JanKrivanek / @rainersigwald et al about how I'm holding it wrong here.

baronfel · 2024-09-13T14:34:52Z

src/Cli/dotnet/commands/dotnet-run/RunCommand.cs

+            ILogger? binaryLogger = DetermineBinlogger(RestoreArgs, true);
+            var project = EvaluateProject(ProjectFileFullPath, RestoreArgs, binaryLogger);
+            binaryLogger?.Shutdown();
            ValidatePreconditions(project);
-            InvokeRunArgumentsTarget(project, RestoreArgs, Verbosity);
+            binaryLogger = DetermineBinlogger(RestoreArgs, false);
+            InvokeRunArgumentsTarget(project, RestoreArgs, Verbosity, binaryLogger);
+            binaryLogger?.Shutdown();


Here's the split I'm talking about. When I use the same binaryLogger the 'execution' phase seems to overwrite the evaluation-phase binlog data. Here's what I have from the current state:

msbuild-dotnet-run-build.zip

In this zip,

msbuild.binlog is the -bl passed to MSbuild to actually build the project

msbuild-dotnet-run-restore.binlog is the binlog generated from line 230 (evaluating the project to get a ProjectInstance)

msbuild-dotnet-run-build.binlog is the binlog generated from line 234 (executing the Target)

I can imagine the Initialize is being called in those methods - so the stream is thrown away and file overwritten (regardless of it was flushed or not with Shutdown call):

https://github.com/dotnet/msbuild/blob/e4797f3f007419ed0bc46182a13d953ace47a308/src/Build/Logging/BinaryLogger/BinaryLogger.cs#L194

Yeah - this is where I ended up after trying for an hour or so to get evaluation and execution to use the same binlog.

Let me get an example of that - what I had hoped was that if I used the same binaryLogger instance in the Projectcollection's logger collection and the ProjectInstance's Build logger collection, it would all just work. Let me get an example of what that looks like pushed up.

I believe the MuxLogger can come to the rescue here. Though I never used it myself

Here's the result:

> dotnet run -bl Using launch settings from E:\Code\sdk-container-demo\src\sdk-container-demo\Properties\launchSettings.json... Building... E:\Code\dotnet-sdk\artifacts\bin\redist\Debug\dotnet\sdk\9.0.100-dev\Sdks\Microsoft.NET.Sdk\Sdk\Sdk.targets(65,3): warning MSB4011: "C:\Users\chusk\.nuget\packages\microsoft.net.build.containers\8.0.403\build\Microsoft.NET.Build.Containers.targets" cannot be imported again. It was already imported at "E:\Code\sdk-container-demo\artifacts\obj\sdk-container-demo\sdk-container-demo.csproj.nuget.g.targets (4,5)". This is most likely a build authoring error. This subsequent import will be ignored. [E:\Code\sdk-container-demo\src\sdk-container-demo\sdk-container-demo.csproj] Unhandled exception: Microsoft.Build.Framework.LoggerException: Failed to write to log file "E:\Code\sdk-container-demo\src\sdk-container-demo\msbuild-dotnet-run-restore.binlog". The process cannot access the file 'E:\Code\sdk-container-demo\src\sdk-container-demo\msbuild-dotnet-run-restore.binlog' because it is being used by another process. ---> System.IO.IOException: The process cannot access the file 'E:\Code\sdk-container-demo\src\sdk-container-demo\msbuild-dotnet-run-restore.binlog' because it is being used by another process. at Microsoft.Win32.SafeHandles.SafeFileHandle.CreateFile(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options) at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode) at System.IO.Strategies.OSFileStreamStrategy..ctor(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode) at System.IO.Strategies.FileStreamHelpers.ChooseStrategyCore(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode) at System.IO.FileStream..ctor(String path, FileMode mode) at Microsoft.Build.Logging.BinaryLogger.Initialize(IEventSource eventSource) --- End of inner exception stack trace --- at Microsoft.Build.Logging.BinaryLogger.Initialize(IEventSource eventSource) at Microsoft.Build.BackEnd.Logging.LoggingService.InitializeLogger(ILogger logger, IEventSource sourceForLogger) at Microsoft.Build.BackEnd.Logging.LoggingService.RegisterLogger(ILogger logger) at Microsoft.Build.Execution.BuildManager.CreateLoggingService(IEnumerable`1 loggers, IEnumerable`1 forwardingLoggers, ISet`1 warningsAsErrors, ISet`1 warningsNotAsErrors, ISet`1 warningsAsMessages) at Microsoft.Build.Execution.BuildManager.<BeginBuild>g__InitializeLoggingService|63_0() at Microsoft.Build.Execution.BuildManager.BeginBuild(BuildParameters parameters) at Microsoft.Build.Execution.BuildManager.Build[TRequestData,TResultData](BuildParameters parameters, TRequestData requestData) at Microsoft.Build.Execution.BuildManager.Build(BuildParameters parameters, BuildRequestData requestData) at Microsoft.Build.Execution.ProjectInstance.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers, ILoggingService loggingService, Int32 maxNodeCount, IDictionary`2& targetOutputs) at Microsoft.Build.Execution.ProjectInstance.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers, ILoggingService loggingService, IDictionary`2& targetOutputs) at Microsoft.Build.Execution.ProjectInstance.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers, IDictionary`2& targetOutputs) at Microsoft.DotNet.Tools.Run.RunCommand.<GetTargetCommand>g__InvokeRunArgumentsTarget|50_5(ProjectInstance project, String[] restoreArgs, Nullable`1 verbosity, ILogger binaryLogger) in E:\Code\dotnet-sdk\src\Cli\dotnet\commands\dotnet-run\RunCommand.cs:line 345 at Microsoft.DotNet.Tools.Run.RunCommand.GetTargetCommand() in E:\Code\dotnet-sdk\src\Cli\dotnet\commands\dotnet-run\RunCommand.cs:line 232 at Microsoft.DotNet.Tools.Run.RunCommand.Execute() in E:\Code\dotnet-sdk\src\Cli\dotnet\commands\dotnet-run\RunCommand.cs:line 78 at Microsoft.DotNet.Tools.Run.RunCommand.Run(ParseResult parseResult) in E:\Code\dotnet-sdk\src\Cli\dotnet\commands\dotnet-run\Program.cs:line 69 at System.CommandLine.Invocation.AnonymousSynchronousCliAction.Invoke(ParseResult parseResult) at System.CommandLine.Invocation.InvocationPipeline.Invoke(ParseResult parseResult) at System.CommandLine.ParseResult.Invoke() at Microsoft.DotNet.Cli.Program.ProcessArgs(String[] args, TimeSpan startupTime, ITelemetry telemetryClient) in E:\Code\dotnet-sdk\src\Cli\dotnet\Program.cs:line 233

In this case, executing the Target tries to write to the binlog file that's still open from the evaluation phase. This is why I thought I needed to Shutdown the previous logger to flush the outputs, but then you hit the 'overwrite' problem.

Looking at XMake.cs, it seems like it uses the ProjectCollection to initialize BuildParameters, then passes that to the default BuildManager.BeginBuild; perhaps that would work?

Yeah without looking at any details attaching to the ProjectCollection seems right

Pushed up a better implementation based on @JanKrivanek's feedback.

Basically we need to make sure that the BinaryLogger only initializes once, so we need some buffer between the loggers that are used in the eval/exec phases and the actual binlogger.

The problem is the IEventSource - in MSBuild the IEventSource between the evaluation and the build is all the same. When using the MSBuild APIs it seems to be impossible to achieve the same without the kind of code I have here.

src/Cli/dotnet/commands/dotnet-run/Program.cs

Forgind · 2024-09-13T15:35:41Z

src/Cli/dotnet/commands/dotnet-run/RunCommand.cs

+            ILogger? binaryLogger = DetermineBinlogger(RestoreArgs, true);
+            var project = EvaluateProject(ProjectFileFullPath, RestoreArgs, binaryLogger);
+            binaryLogger?.Shutdown();
            ValidatePreconditions(project);
-            InvokeRunArgumentsTarget(project, RestoreArgs, Verbosity);
+            binaryLogger = DetermineBinlogger(RestoreArgs, false);
+            InvokeRunArgumentsTarget(project, RestoreArgs, Verbosity, binaryLogger);
+            binaryLogger?.Shutdown();


Looking at XMake.cs, it seems like it uses the ProjectCollection to initialize BuildParameters, then passes that to the default BuildManager.BeginBuild; perhaps that would work?

baronfel · 2024-09-13T15:56:24Z

Looking at XMake.cs, it seems like it uses the ProjectCollection to initialize BuildParameters, then passes that to the default BuildManager.BeginBuild; perhaps that would work?

It's actually way worse than that. @JanKrivanek gave me some pointers, I'll push something later today with what we have to do here.

joeloff · 2024-09-16T17:55:38Z

src/Cli/dotnet/commands/dotnet-run/Program.cs

+            foreach (var arg in applicationArguments)
+            {
+
+                if (arg.StartsWith("/bl:") || arg.Equals("/bl")


if you just did arg.Contains("/bl" and ignored the : variant` would that still work and simplify the check a bit?

it would potentially capture user-application arguments that started with bl but were otherwise distinct from MSBuild's /bl arg.

nagilson

The change looks good to me. The code is well done, so thank you.

Having more tests would be ideal, but time is limited.
Note that there is a 'bug' where if you pass -bl -bl it will fail with an uhandled exception. dotnet run -bl -bl --project .\newconsole.csproj will fail because Unhandled exception: Microsoft.Build.Framework.LoggerException: Failed to write to log file, used by another process.

Given that it did not work in the first place and anybody who would be impacted by this would also have been impacted by the other break, I still think it can be merged.

baronfel · 2024-09-16T20:38:46Z

good call-out @nagilson - though that would fail in MSBuild for other reasons I think. You can specify any number of BL instances you want as long as they are differently-named, and the default name for /bl is msbuild.binlog, which would clobber in this case.

nagilson · 2024-09-16T20:39:32Z

dotnet build -bl -bl works for me, but I am a bit surprised by that

don't forward -bl arguments along to running applications

be321e7

dotnet-issue-labeler bot added Area-CLI untriaged Request triage from a team member labels Sep 13, 2024

baronfel requested a review from a team September 13, 2024 14:31

baronfel commented Sep 13, 2024

View reviewed changes

Forgind reviewed Sep 13, 2024

View reviewed changes

baronfel added 2 commits September 13, 2024 11:57

Use an event forwarder to allow for one unified binary log

ac1738e

handle multiple binlog args

14b014e

baronfel requested a review from a team September 13, 2024 18:13

joeloff reviewed Sep 16, 2024

View reviewed changes

nagilson approved these changes Sep 16, 2024

View reviewed changes

baronfel merged commit 92b8b5e into dotnet:release/9.0.1xx Sep 16, 2024
31 checks passed

baronfel deleted the bl-in-dotnet-run branch September 16, 2024 22:07

eerhardt mentioned this pull request Dec 5, 2024

Add annotation to manually specify project command line arguments. (Needed for AWS Lambda support) dotnet/aspire#6120

Open

1 task

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Don't forward along binlog arguments to runnable applications #43430

Don't forward along binlog arguments to runnable applications #43430

baronfel commented Sep 13, 2024 •

edited

Loading

baronfel Sep 13, 2024 •

edited

Loading

JanKrivanek Sep 13, 2024

baronfel Sep 13, 2024

JanKrivanek Sep 13, 2024

baronfel Sep 13, 2024

Forgind Sep 13, 2024

rainersigwald Sep 13, 2024

baronfel Sep 13, 2024

baronfel Sep 13, 2024

Forgind Sep 13, 2024

baronfel commented Sep 13, 2024

joeloff Sep 16, 2024 •

edited

Loading

baronfel Sep 16, 2024

nagilson left a comment •

edited

Loading

baronfel commented Sep 16, 2024

nagilson commented Sep 16, 2024

Don't forward along binlog arguments to runnable applications #43430

Don't forward along binlog arguments to runnable applications #43430

Conversation

baronfel commented Sep 13, 2024 • edited Loading

baronfel Sep 13, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

baronfel commented Sep 13, 2024

joeloff Sep 16, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nagilson left a comment • edited Loading

Choose a reason for hiding this comment

baronfel commented Sep 16, 2024

nagilson commented Sep 16, 2024

baronfel commented Sep 13, 2024 •

edited

Loading

baronfel Sep 13, 2024 •

edited

Loading

joeloff Sep 16, 2024 •

edited

Loading

nagilson left a comment •

edited

Loading