[Bug]: MSBuild target with multiple projects, Console.Out suppressed from second project

[jzabroski]

Issue Description

1. Custom task which uses Console.Out output colors.
2. Multiple projects are invoked from MSBuild task, which invokes the custom task per project
3. The output gets lost for the second project onward 🫨

This is something I noticed at least six months ago, but it's not bad enough to report a bug typically. It's also very possible the way we are doing this is simpler incorrect, and instead of relying on Console.Out, we should be using the ILogger in the MSBuild framework - which I have started prototyping.

This problem happens on both net48 MSBuild (Visual Studio latest) and dotnet.exe (net8.0 latest sdk), but has been happening for awhile, so something likely changed over the last 1-2 years to break this.

Steps to Reproduce

I have a target in a custom .targets file like this:

<?xml version="1.0" encoding="utf-8" ?>
<Project ToolsVersion="15.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003" DefaultTargets="Build">

  <UsingTask TaskName="FluentMigrator.MSBuild.Migrate" AssemblyFile="$(FluentMigratorMSBuildAssemblyPath)" Condition="$(FluentMigratorMSBuildAssemblyPath) != ''" />

  <!-- Target: DbMigrateCore -->
  <Target Name="DbMigrateCore">
    <Error Text="Server property is required!" Condition="$(Server) == ''" />
    <Error Text="Catalog property is required!" Condition="$(Catalog) == ''" />
    <Error Text="Assembly property is required!" Condition="$(Assembly) == ''" />
    <Error Text="TrustServerCertificate property is required!" Condition="$(TrustServerCertificate) == ''" />
    <Error Text="Encrypt property is required!" Condition="$(Encrypt) == ''" />
    <Error Text="Task property is required!" Condition="$(Task) == ''" />
    <Error Text="FluentMigratorMSBuildAssemblyPath property is required!" Condition="$(FluentMigratorMSBuildAssemblyPath) == ''" />

    <PropertyGroup>
      <ConnectionString Condition="$(Username) == ''">Data Source=$(Server)%3BInitial Catalog=$(Catalog)%3BIntegrated Security=SSPI;TrustServerCertificate=$(TrustServerCertificate);Encrypt=$(Encrypt)</ConnectionString>
      <ConnectionString Condition="$(Username) != ''">Data Source=$(Server)%3BInitial Catalog=$(Catalog)%3BUser ID=$(Username)%3BPassword=$(Password);TrustServerCertificate=$(TrustServerCertificate);Encrypt=$(Encrypt)</ConnectionString>
      <Processor>SqlServer2014</Processor>
      <Timeout>6000</Timeout>
      <Verbose>True</Verbose>
      <StripComments>False</StripComments>
    </PropertyGroup>

    <Message Importance="High" Text="Running FluentMigrator task [$(Task)] against [$(ConnectionString)] with assembly [$(Assembly)].  Profile=[$(Profile)] Tags=[$(Tags)]" />

    <Migrate Database="$(Processor)"
             Connection="$(ConnectionString)"
             Target="$(Assembly)"
             Profile="$(Profile)"
             Tags="$(Tags)"
             Timeout="$(Timeout)"
             StripComments="$(StripComments)"
             Verbose="$(Verbose)"
             Task="$(Task)"/>
  </Target>
</Project>

I then have Directory.Package.props like this:

<?xml version="1.0"?>
<Project>
    <ItemGroup>
        <PackageReference Include="FluentMigrator.MSBuild" Version="6.1.4" GeneratePathProperty="true" />
    </ItemGroup>
    <PropertyGroup>
        <FluentMigratorMSBuildAssemblyPath>$(PKGFluentMigrator_MSBuild)\tasks\net48\FluentMigrator.MSBuild.dll</FluentMigratorMSBuildAssemblyPath>
    </PropertyGroup>
</Project>

and then a build.targets like this:

<?xml version="1.0" encoding="utf-8" ?>
<Project ToolsVersion="15.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003" DefaultTargets="Build">
  <Import Project="$(MSBuildProjectDirectory)\custom.targets"
          Condition="Exists('$(MSBuildProjectDirectory)\custom.targets')" />
  <!-- Database Property Groups -->
  <ItemGroup>
    <DatabaseConnection Include="Logging">
      <Environment>UnitTest</Environment>
      <DatabaseToolsDirectory>$(SourceDirectory)\$(LoggingDatabaseAssembly)\Tools</DatabaseToolsDirectory>
      <RunDbMigrations>true</RunDbMigrations>
      <RunScriptDatabaseSchema>false</RunScriptDatabaseSchema>
      <OnBeforeScriptDatabaseSchemaScript></OnBeforeScriptDatabaseSchemaScript>
      <Assembly>$(LoggingDatabaseAssembly)</Assembly>
      <Server>(local)</Server>
      <Catalog>Logging_UnitTest</Catalog>
      <Tags>UnitTest</Tags>
    </DatabaseConnection>
    <DatabaseConnection Include="Stats">
      <Environment>UnitTest</Environment>
      <DatabaseToolsDirectory>$(SourceDirectory)\$(LoggingDatabaseAssembly)\Tools</DatabaseToolsDirectory>
      <RunDbMigrations>true</RunDbMigrations>
      <RunScriptDatabaseSchema>false</RunScriptDatabaseSchema>
      <OnBeforeScriptDatabaseSchemaScript></OnBeforeScriptDatabaseSchemaScript>
      <Assembly>$(LoggingDatabaseAssembly)</Assembly>
      <Server>(local)</Server>
      <Catalog>Stats_UnitTest</Catalog>
      <Tags>UnitTest</Tags>
    </DatabaseConnection>
  </ItemGroup>

  <!-- Target: DbMigrateTest -->
  <Target Name="DbMigrateTest">
    <PropertyGroup Condition="$(Environment) == ''">
      <Environment>Test</Environment>
    </PropertyGroup>
    <ItemGroup>
      <Arguments Include="@(DatabaseConnection)" Condition="%(Environment) == $(Environment) And %(RunDbMigrations) == True">
        <AssemblyPath>$(SourceDirectory)\%(DatabaseConnection.Assembly)\bin\release\%(DatabaseConnection.Assembly).dll</AssemblyPath>
        <Tags>%(DatabaseConnection.Tags)</Tags>
		<Encrypt>True</Encrypt>
		<TrustServerCertificate>True</TrustServerCertificate>
      </Arguments>
    </ItemGroup>

    <Message Importance="High" Text="Running migrations against the following databases:" />
    <Message Importance="High" Text="Environment:$(Environment) Server:%(Arguments.Server) Catalog:%(Arguments.Catalog) Tags:%(Arguments.Tags)" />

    <MSBuild Projects="$(MSBuildProjectFile)"
             Targets="DbMigrateCore"
             Properties="
             Server=%(Arguments.Server);
             Catalog=%(Arguments.Catalog);
             Username=%(Arguments.Username);
             Password=%(Arguments.Password);
             Assembly=%(Arguments.AssemblyPath);
             TrustServerCertificate=%(Arguments.TrustServerCertificate);
             Encrypt=%(Arguments.Encrypt);
             Task=migrate:up;
             Tags=%(Arguments.Tags);" />
  </Target>
</Project>

Expected Behavior

Output per project

Actual Behavior

Output for the first project, but not the second project

Analysis

No clue. It is possible it is a bug in my custom task, but I am not sure how to figure that out. Are custom tasks thread safe / isolated in the context of MSBuild task?

Versions & Configurations

msbuild -version

MSBuild version 17.11.9+a69bbaaf5 for .NET Framework
17.11.9.46202

dotnet.exe --list-sdks

6.0.321 [C:\Program Files\dotnet\sdk]
8.0.400 [C:\Program Files\dotnet\sdk]

dotnet.exe --version

8.0.400

dotnet.exe --list-runtimes

Microsoft.AspNetCore.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 6.0.33 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 8.0.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 6.0.33 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 8.0.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.WindowsDesktop.App 6.0.26 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 6.0.33 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 8.0.8 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

[baronfel]

You should 100% be using ILogger - I think what you're seeing is the fact that MSBuild is a multi-process architecture, and only one build process actually has a StdOut that can be written to (without doing gymnastics). The purpose of the ILogger mechanism is to provide a safe way for nodes without a StdOut to communicate with the node that does (in addition to all output that goes over the ILogger interface being included in diagnostic tooling like binlogs, etc). This is not a bug, and is the intended design of MSBuild - it would even be the case if MSBuild was a single-process, multi-threaded process.

[jzabroski]

Ok, thanks - that makes sense. Crazy that this was working for so long. Not sure what broke it, but clear I was depending on something I should not.

Separately, there is basically no bridge to Microsoft DI, which makes writing MSBuild tasks that reference transitive projects difficult - so it's hard to modularize MSBuild. It turns out Coverlet uses Serilog MSBuildSink, but nothing exists for Microsoft.Extensions.Logging. I wrote a dumb one here : https://github.com/fluentmigrator/fluentmigrator/blob/main/src/FluentMigrator.MSBuild/MicrosoftBuildLogger.cs

[baronfel]

We have one in the SDK as well. I agree that this is a thing that would be useful to ship, at some point - @rainersigwald do you think a contribution to MSBuild Utils would be appropriate, or would we need a new package to not drag in the Microsoft.Extensions.Logging.Abstractions dependency?

[baronfel]

@jzabroski there's also a longer-term discussion here because the MEL logging might lack some of the abilities of the MSBuild logging (specifically knowledge of MSBuild Codes (which are used to toggle warning levels, etc) and knowledge of file/line/range markers) - we haven't spec'd out what those interactions should be so we haven't codified them in an MSBuild-shipped MEL.ILogger.

[rainersigwald]

Let's open an issue to flesh that out @baronfel. Put it in #10733 :)

[baronfel]

Added #10757 to #10733 to track this.