ProjectImportedEventArgs missing from most projects

[KirillOsenkov]

@tmat has sent me a binlog from "17.9.0-preview-23570-02+bf9d6d46d"
D:\Program Files\Microsoft Visual Studio\2022\Preview\MSBuild\Current\Bin\amd64\MSBuild.exe

It's missing ProjectImported events for all but a handful of projects:

Build.proj id:51
Microsoft.CodeAnalysis.CSharp.Features.UnitTests.csproj net472 id:10601
Microsoft.CodeAnalysis.ExternalAccess.Copilot.csproj net472;net6.0 id:10501
Microsoft.CodeAnalysis.ExternalAccess.Copilot.csproj net472 id:10551
Roslyn.sln.metaproj v4.0 id:101
Roslyn.VisualStudio.Setup.csproj net472 id:2501

Ping me on teams and I can share the binlog internally.

[KirillOsenkov]

The binlog contains only about 1,200 import events, only for those 6 projects:

Could it be that the ProjectImportedEventArgs are no longer sent across other node processes? Could this have regressed recently?

[JanKrivanek]

Might the MSBUILDLOGIMPORTS env var be fiddled with in your env @tmat?

[KirillOsenkov]

The binlog should contain it if so?

[KirillOsenkov]

and some imports were logged

[tmat]

Might the MSBUILDLOGIMPORTS env var be fiddled with in your env @tmat?

Not that I am aware of.

[JanKrivanek]

It was just a wild quick quess.

For some reason calls emiting ProjectImportedEventArgs are conddition via few various conditions - just about half of those check the trait that wraps that env var - so flipping it would filter only some. But unless the env var would be accessed as a property by the msbuild script it would not be dumped into binlog (the whole env is not dumped any more intentionally).

Anyways - Alina is currently having few leads for next investigation steps, so please ignore my intervention here :-)

Unless any of those turns promissing - then I suggest to quickly try to investigate if setting/unsetting repores the issue - as the env var is explicitly set by BinaryLogger - but just for current process - so that might answer why only the imports from inproc nodes are logged.

[KirillOsenkov]

No problem! I think we always log environment variables that start with MSBUILD, DOTNET and a third prefix that I don't remember.

Good idea, if the other nodes don't set the env then it might not happen there! I think it's a regression but I might be wrong (if it's always been broken then I'll be very surprised about how come we've missed this all this time)

[JanKrivanek]

Ah - didn't know about the logging of MSBUILD*,DOTNET* env vars - thanks for learning me something new today! :-)

Building with /m:1 leads to all project imports being logged.
Building with $env:MSBUILDNOINPROCNODE=1 leads to no project imports being logged
Ordinary cases of building are somewhere in between (depending if/how much evaluations occured on extra nodes)

vs

So I believe the Trait is the culprit here.

Regression or not - it's still worth fixing. I'd just like us to invest slightly more and introduce general way of communicating state (env, subscriptions, etc.) from main node to others - this way we wouldn't need to transmit (and ideally not even emit) events if there are no subscriber.

As a workaround - setting the trait globally (SETX MSBUILDLOGIMPORTS "1") should do the trick (FYI @tmat)

[KirillOsenkov]

I'm not seeing ProjectImportedEventArgs in this list:
https://github.com/dotnet/msbuild/pull/8917/files#diff-49f60fe36c5743a0285e9d27ce7c6e981d8dc73de8bfa23405a9fdbd2cf69eddR75

Could it be that removing binary formatter impacted serialization of ProjectImportedEventArgs in node packet translator?

@rokonec

[KirillOsenkov]

As part of this issue let's verify that all node types mentioned here are being serialized properly:
https://github.com/dotnet/msbuild/blob/abc2f4620f6749289cafeed7c9a9a80eaeb38e28/src/Build/Logging/BinaryLogger/BuildEventArgsWriter.cs#L152C21-L152C21

[JanKrivanek]

As part of this issue let's verify that all node types mentioned here are being serialized properly: https://github.com/dotnet/msbuild/blob/abc2f4620f6749289cafeed7c9a9a80eaeb38e28/src/Build/Logging/BinaryLogger/BuildEventArgsWriter.cs#L152C21-L152C21

Btw. to make sure there are no BuildEventArgs left of off the roundtrip test (even in future) - we can easily enumerate all BuildEventArgs inheritors from the Microsoft.Build assembly. Similarly as we test the BuildException types serialization here: https://github.com/dotnet/msbuild/blob/main/src/Build.UnitTests/BackEnd/BinaryTranslator_Tests.cs#L247-L258

[KirillOsenkov]

Hey folks, any progress on this issue? A bit worried that we have incomplete information in the binlogs and it could be misleading and make investigations harder.

[JanKrivanek]

@AR-May is on it - just currently OOF this week

[KirillOsenkov]

ah ok, no rush

[AR-May]

Back to work, on it!

[AR-May]

Ah - didn't know about the logging of MSBUILD*,DOTNET* env vars - thanks for learning me something new today! :-)

Building with /m:1 leads to all project imports being logged. Building with $env:MSBUILDNOINPROCNODE=1 leads to no project imports being logged Ordinary cases of building are somewhere in between (depending if/how much evaluations occured on extra nodes)

vs So I believe the [`Trait`](https://github.com/dotnet/msbuild/blob/abc2f4620f6749289cafeed7c9a9a80eaeb38e28/src/Framework/Traits.cs#L211) is the culprit here.

Regression or not - it's still worth fixing. I'd just like us to invest slightly more and introduce general way of communicating state (env, subscriptions, etc.) from main node to others - this way we wouldn't need to transmit (and ideally not even emit) events if there are no subscriber.

As a workaround - setting the trait globally (SETX MSBUILDLOGIMPORTS "1") should do the trick (FYI @tmat)

I agree, I managed to reproduce and debug the issue and I also believe the Traits class poses a problem, moreover, there should be a problem with any behavior that is controlled via environment variable that goes to Traits class (which is a lot). What happens is that the msbuild nodes get the Traits class created during the msbuild node creation and it is filled according to the env. variables on the initial build. So, when the new build reuses the old nodes, the main node sends the new configuration, including the environment variables, the old msbuild node sets these variables, but the values in the Traits class are not updated accordingly.

In the case of this issue, the MSBUILDLOGIMPORTS variable gets the new value that is not propagated to Traits.