Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log how properties are initially assigned #2711

Open
KirillOsenkov opened this issue Nov 9, 2017 · 17 comments · May be fixed by #11106
Open

Log how properties are initially assigned #2711

KirillOsenkov opened this issue Nov 9, 2017 · 17 comments · May be fixed by #11106
Assignees
Labels
Area: BuildCheck Area: Debuggability Issues impacting the diagnosability of builds, including logging and clearer error messages. Area: Logging Feature Request Feature: Warning Waves Warnings to enable in opt-in waves. Formerly "strict mode". help wanted Issues that the core team doesn't plan to work on, but would accept a PR for. Comment to claim.

Comments

@KirillOsenkov
Copy link
Member

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
Copy link
Contributor

kkm000 commented Dec 10, 2017

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 rainersigwald added help wanted Issues that the core team doesn't plan to work on, but would accept a PR for. Comment to claim. Area: Debuggability Issues impacting the diagnosability of builds, including logging and clearer error messages. Feature Request labels Feb 15, 2018
@rainersigwald
Copy link
Member

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
Copy link

iii-i commented Jul 6, 2022

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

@KirillOsenkov
Copy link
Member Author

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
Copy link
Member Author

KirillOsenkov commented Jan 18, 2024

@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
Copy link
Member

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").

@rainersigwald rainersigwald added the Feature: Warning Waves Warnings to enable in opt-in waves. Formerly "strict mode". label Jan 18, 2024
@JanKrivanek
Copy link
Member

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
Copy link
Member Author

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

@YuliiaKovalova YuliiaKovalova self-assigned this Feb 19, 2024
@YuliiaKovalova
Copy link
Member

@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
Copy link
Member Author

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
Copy link
Member

+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
Copy link
Member

ladipro commented Feb 21, 2024

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
Copy link
Member Author

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
Copy link
Member

YuliiaKovalova commented Feb 21, 2024

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
Copy link
Member

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

@ivanpovazan
Copy link
Member

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
Copy link
Member

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

@YuliiaKovalova YuliiaKovalova linked a pull request Dec 6, 2024 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: BuildCheck Area: Debuggability Issues impacting the diagnosability of builds, including logging and clearer error messages. Area: Logging Feature Request Feature: Warning Waves Warnings to enable in opt-in waves. Formerly "strict mode". help wanted Issues that the core team doesn't plan to work on, but would accept a PR for. Comment to claim.
Projects
None yet
10 participants