Use MSBuild Logging APIs for Task output instead of StdOut

[baronfel]

Fixes #712
Fixes #616

This is a refresh of #730 that I've gotten the tests to green up on. Along the way I think I've also addressed #616, which was a consequence of way the dependencies of the task were initialized in the .NET task.

Since the majority of the tool uses Serilog, the strategy here is to integrate MSBuild's logging APIs into Serilog's logging configuration where possible. This means, broadly, two things:

• creating and using an MSBuild Logger that converts Serilog's messages to calls to the TaskLoggingHelper's logging methods
• ensuring that the Verbosity selected in the Task is used when configuring Serilog

Along the way, I've made it easier to test the post-conditions of the Task on both net472 and .NET.

[baronfel]

One big note - I'm using .NET SDK 9.0.200, where some of the Roslyn analyzers have been tweaked/fixed and so are reporting things that I had to fix in order to get the repo to compile.

[baronfel]

I've attached a zipped binlog of the tool working with these changes. The detailed logs are in the binlog as expected.

sbom-pack.zip

To the end user, it looks like this:

> dotnet pack -bl
Restore complete (0.3s)
  sbom-tests succeeded with 1 warning(s) (5.6s) → bin\Release\net9.0\sbom-tests.dll
    E:\code\nuget-packages\microsoft.sbom.targets\3.1.1-preview.0.6\build\Microsoft.Sbom.Targets.targets(57,5): warning : Deleting pre-existing folder E:\Code\Scratch\sbom-tests\bin\Release\sbom-tests.1.0.0.4b5fcd2f.temp\_manifest as DeleteManifestDirIfPresent is 'true'.

Build succeeded with 1 warning(s) in 6.2s

I'd like to dig in a bit more about the spurious warning, I expect that's a mismatched warning regex or something on MSbuild's side.

This warning is coming from the SBOM targets - specifically from

sbom-tool/src/Microsoft.Sbom.Api/Workflows/SBOMGenerationWorkflow.cs

Lines 240 to 242 in 3d1a59f

	log.Warning(
	$"Deleting pre-existing folder {rootManifestFolderPath} as {Constants.DeleteManifestDirBoolVariableName}" +
	$" is 'true'.");

. Is this really a warning? A user asked to delete a manifest if it was already there, and we're doing what they asked? This feels more like a debug/diagnostic to me. The big problem here is twofold:

• many users run MSBuild with TreatWarningsAsErrors enabled
• this particular warning, because it's coming from deep in the Serilog stack and not from direct use of MSBuild Logging APIs, doesn't have a Code associated with it, so users can't use MSbuild's knobs to disable/hide this warning when it does appear

[sfoslund]

/azp run

[DaveTryon]

sbom-tool/src/Microsoft.Sbom.Api/Workflows/SBOMGenerationWorkflow.cs

Lines 240 to 242 in 3d1a59f

	log.Warning(
	$"Deleting pre-existing folder {rootManifestFolderPath} as {Constants.DeleteManifestDirBoolVariableName}" +
	$" is 'true'.");

. Is this really a warning? A user asked to delete a manifest if it was already there, and we're doing what they asked? This feels more like a debug/diagnostic to me. The big problem here is twofold:

• many users run MSBuild with TreatWarningsAsErrors enabled
• this particular warning, because it's coming from deep in the Serilog stack and not from direct use of MSBuild Logging APIs, doesn't have a Code associated with it, so users can't use MSbuild's knobs to disable/hide this warning when it does appear

Please feel free to change this log.Warning to log.Info

[baronfel]

I've taken another pass at this, addressing the feedback (thanks folks!) and I'm much happier with how this integration looks now. There's only one actually functional gap, and I need a bit of direction on where I should go with that.

[sfoslund]

Generally looks good to me, other than the 2 comments I added + those that others have already added

[baronfel]

I've just rebased against main - the major conflict was that there's now SPDX3.0 configurations in the DI registration.

I've addressed all outstanding feedback I think - the last thing is to check out some hangs that @sfoslund reported to me today in the CLI tool itself.

[baronfel]

@sfoslund the loop is coming from a circular dependency in the DI configuration. ILogger requires knowing the verbosity (from InputConfiguration) in order to initialize, but reading the InputConfiguration requires IConfigurationBuilder<T>, which requires ConfigFileParser, which requires IFileSystemUtils, all implementations of which require ILogger.

[baronfel]

Alright, fixed the loop by using the strategy from main - the FileSystemUtils get a default logger with an expected verbosity.
Also fixed more warnings coming from component detection, but in a way that remaps all of them cleanly to MSBuild Information without impacting the tool experience.

I am now completely satisfied with this PR. whew!

[sfoslund]

/azp run

[sfoslund]

My understanding is that this will create a breaking change for API users, as they will now have to inject a logger similarly to how we are now doing it in Program.cs, is that right? This is okay with me as our next release will be a breaking change anyways, but tagging @DaveTryon for visibility

[baronfel]

Oof, good call - I didn't realize that the dependency injection project was public API surface area. Let me noodle on how that could be fixed.

[baronfel]

I've pushed a commit that minimizes the API surface area changes, and adds a ton of xmldoc that instructs users on the new requirement of registering their own ILogger. That won't stop someone that just updates and then runs tests from failing, but maybe that will help mitigate somewhat.

[sfoslund]

Looks like we're seeing some CI unit test failures with this change: https://dev.azure.com/mseng/1ES/_build/results?buildId=29662326&view=logs&j=aeb7b77f-2f5c-5c5e-fb92-f326324a83fb&t=947a9a91-a289-5b68-4a98-262ba6071be8

[sfoslund]

Also @DaveTryon do you know why the 'Check for API changes' commentor check is failing?

[baronfel]

The last failures I think are real - I've seen them when packing my own projects using the newly-built nuget package manually. I'll test with a package from main to compare. The failures are a double-access to the manifest.spdx.json - I've only seen them happen for the spdx_3.0 pathway, but it's possible the 2.2 pathway could also be impacted? The stack looks like this:

System.IO.IOException: The process cannot access the file 'E:\Code\sbom-tool\test\Microsoft.Sbom.Tool.Tests\bin\Debug\net8.0\TestResults\Deploy_chusk 20250301T213843_15624\E2E_GenerateManifest_GeneratesManifest_ReturnsZeroExitCode\_manifest\spdx_3.0\manifest.spdx.json' 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.FileInfo.OpenRead()
   at Microsoft.ComponentDetection.Common.LazyComponentStream.SafeOpenFile()

EDIT: I've confirmed this happens with a nuget package built from main too (version 3.1.1-preview.0.8 as of this comment). I believe there's a bug in the tool itself independent of my PR.

dotnet pack -bl
Restore complete (0.8s)
  sbom-tests                                                                                  GenerateSbomTarget (7.1s)
information]Finding components...                                                                                (7.3s)
##[information]No instructions received to scan docker images.                                                   (7.4s)
##[information]Starting enumeration of "E:\\Code\\Scratch\\sbom-tests"
##[information]Enumerated 50 files and 23 directories in 00:00:00.0149485
##[warning]Unhandled exception caught when trying to open "E:\\Code\\Scratch\\sbom-tests\\bin\\Release\\sbom-tests.1.0.0.98080a7c.temp\\_manifest\\spdx_3.0\\manifest.spdx.json"
System.IO.IOException: The process cannot access the file 'E:\Code\Scratch\sbom-tests\bin\Release\sbom-tests.1.0.0.98080a7c.temp\_manifest\spdx_3.0\manifest.spdx.json' 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.FileInfo.OpenRead()
   at Microsoft.ComponentDetection.Common.LazyComponentStream.SafeOpenFile()