Log how properties are initially assigned

[KirillOsenkov]

See request here:
KirillOsenkov/MSBuildStructuredLog#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. - this chuck of work is tracked separately ! #10103

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