Log how properties are initially assigned

[KirillOsenkov]

See request here: https://github.com/KirillOsenkov/MSBuildStructuredLog/issues/133

We log when properties are reassigned when they already had a value, but it would be useful to specify how a property was initially assigned - from an environment variable, from /p:, from evaluation (and which location exactly) or from building (which target, task etc).

PropertyAssignmentSource or something.

[kkm000]

Yes pretty please! Your log viewer is just an indispensable tool, thank you very much for it! But I lamented not once being unable to figure out where the initial value of a property is coming from.

[rainersigwald]

Sounds reasonable. Until this is implemented, I usually use a preprocessed project, searching from the top for <PropertyName to see where it could have gotten assigned.

[iii-i]

This seems to be working now: export MsBuildLogPropertyTracking=3.

[KirillOsenkov]

Implementing this is likely to cause a huge perf overhead (but needs to be measured to confirm). Like Rainer says, the workaround is to preprocess the project and search for the <PropertyName in the preprocessed text. Binlog viewer supports the Preprocess command on any project.

However I think we could implement logging cheaply for some special cases (where we don't have it already):

1. property coming from a command-line argument (e.g. /p:)
2. property coming from environment (another PR already in progress that should solve this)
3. as an output of a target
4. as an output of a task
5. from a PropertyGroup inside a target

basically everything but evaluation. I'm worried that logging every property initial assignment for every evaluation will result in way too much new logging args and allocations and create a lot of noise too. I think preprocessor gives a reasonable alternative for those.

[KirillOsenkov]

@JanKrivanek @AR-May @rokonec @rainersigwald not logging initial assignment for properties and items during evaluation continues to be a huge pain point. Normally binlogs are great, but not having this information often leaves us in the dark and guessing.

I think there's some disabled code from at least two past attempts, as well as event args ready to use such as PropertyInitialValueSetEventArgs. I think it would be nice to build a prototype and see how much it slows the build down as well as how does this impact the binlog size. Maybe our fears are unfounded and the overhead will be negligible?

Checklist for what would be nice:

• [ ] PropertyInitialValueSetEventArgs for properties assigned during evaluation, contain location in the XML where the assignment happened (inside a <PropertyGroup> presumably)
• [ ] TaskParameterEventArgs of type TaskParameterMessageKind.AddItem/RemoveItem - has the item list as well as metadata and the location in XML where it happened during initial evaluation.

Both of these would be logged during evaluation.

[rainersigwald]

I suspect we'll also want these events for analyzers (rules like "don't set property X in context Y" or "never set property Q to value Z").

[JanKrivanek]

Let's use some structured info (not a textual info in BuildMessageEventArgs etc.). We possibly might reuse PropertyReassignmentEventArgs (where previous value is null) - but probably not a good idea as Viewer and other things might already have some assumptions

[KirillOsenkov]

we do have the (unused) structured events already, see my comment above

[YuliiaKovalova]

@KirillOsenkov , @rainersigwald , @JanKrivanek could you clarify these points? Before reusing the unused structured events, should I measure the perf impact? Or are we ready to have it at any price? Should these events be an opt-in thing or emitted always?

[KirillOsenkov]

I'd say let's build a prototype and gather some data on the impact to build perf and binlog size, for small and large builds

[JanKrivanek]

+1 on prototyping and then measuring on a reasonably sized project (OrchardCore e.g.)

If there is a measurable difference in overall build time and binlog size, then we can think about couple possible optimizations (e.g. the info can be probably be groupped into single message for a single project evaluation, it can possibly be opt-in only similar to requiring MSBUILDLOGPROPERTIESANDITEMSAFTEREVALUATION for props/items values in ProjectEvaluationFinishedEventArgs - though this particular one has very minimum impact when opted in)

[ladipro]

As noted in one of the older messages above, this feature already exists and can be enabled by setting MsBuildLogPropertyTracking. Just wanted to point it out so it doesn't get lost. It looks like it just needs location info added to PropertyInitialValueSetEventArgs.

[KirillOsenkov]

Right; there have been at least two attempts to do this, and both were either backed out or disabled. We need to do some archeology to understand what happened and dig through the old PRs.

[YuliiaKovalova]

Right; there have been at least two attempts to do this, and both were either backed out or disabled. We need to do some archeology to understand what happened and dig through the old PRs.

Sounds good! I will approach it at the beginning of March . Thank you for the details.

[ivanpovazan]

I use export MsBuildLogPropertyTracking=3 quite often in my daily work on dotnet/runtime, +1 on having this feature :)

[ivanpovazan]

Not sure if this is the right place to report it, but when I create a log and enable tracking of initial property values (e.g., export MsBuildLogPropertyTracking=15) the log does not include the full source information in case the value comes from .xml. The example output:

...
Read uninitialized property "DirectorySolutionTargetsPath"
Read uninitialized property "_DirectorySolutionTargetsFile"
Property initial value: $(_DirectorySolutionTargetsFile)="Directory.Solution.targets" Source: Xml
...

It is good that the log includes the information that the value comes from an .xml ie Source: Xml but it would be great if it could include the full path to the source. This would be particularly useful when debugging the order of imports where various .props and .targets files from our SDKs contribute to setting the initial value of the same property.

[MarcoRossignoli]

I think this is really useful to speedup the investigations on binlogs!