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

[Bug]: PropertyReassignment logged as plain messages #9385

Closed
KirillOsenkov opened this issue Nov 2, 2023 · 4 comments · Fixed by #9494
Closed

[Bug]: PropertyReassignment logged as plain messages #9385

KirillOsenkov opened this issue Nov 2, 2023 · 4 comments · Fixed by #9494
Assignees

Comments

@KirillOsenkov
Copy link
Member

KirillOsenkov commented Nov 2, 2023

Issue Description

I just discovered that Property reassignment events are logged as plain messages, and not as PropertyReassignmentEventArgs:

_evaluationLoggingContext.LogComment(
MessageImportance.Low,
"PropertyReassignment",
property.Name,
newValue,
oldValue,
location);

I don't know how I've missed this previously. If we log the structured event, we don't need to materialize the long string message at all.

Here's where we log the real event args, but I suspect this code is not currently enabled:

var args = new PropertyReassignmentEventArgs(
property.Name,
oldValue,
newValue,
location,
message: null);
args.BuildEventContext = _evaluationLoggingContext.BuildEventContext;

@KirillOsenkov KirillOsenkov added bug needs-triage Have yet to determine what bucket this goes in. Area: Logging labels Nov 2, 2023
@KirillOsenkov
Copy link
Member Author

KirillOsenkov commented Nov 2, 2023

Oh wow, this is where it started:
21eeb45

A detective who is also the murderer.

@YuliiaKovalova YuliiaKovalova added Priority:2 Work that is important, but not critical for the release Iteration:2023December internal-team-onboarding and removed needs-triage Have yet to determine what bucket this goes in. labels Nov 7, 2023
@YuliiaKovalova YuliiaKovalova self-assigned this Nov 30, 2023
@baronfel
Copy link
Member

baronfel commented Nov 30, 2023

Fixing this should make it much easier to track the property assignments in the UI - @KirillOsenkov would it be possible to link a property change to the position that the change occurred (meaning both in the specific file that caused the change as well as in the overall build graph)? Or a helper to search for a specific property name being changed?

@KirillOsenkov
Copy link
Member Author

We already do all of the above - the viewer uses Regex to recognize the property reassignment messages and manufactures synthetic PropertyReassignmentBuildEventArgs when reading binlogs:

https://github.com/KirillOsenkov/MSBuildStructuredLog/blob/45ba130c7f3a1c311a7ece980b2a5d3f3ada0bc1/src/StructuredLogger/BinaryLogger/BuildEventArgsReader.cs#L895-L899

In the viewer you can search for Property reassignment: $( and the property name and it will find the places where a property is reassigned:

image

Pressing Space on the message will jump to the source code where it happens (because we parse the location information out of the message).

Also all property reassignments are grouped under folders under Evaluation:
image

And you can search for a property name in the Properties and Items tab while a project is selected in the tree and you'll see reassignments of that property:

image

Logging a more strongly typed message on the MSBuild side will hopefully reduce allocations (if we don't need to realize the full text of the string) and generally provide a better experience for log readers.

@YuliiaKovalova I'm happy to help review this when ready, ping me with any questions! Thanks!

@KirillOsenkov
Copy link
Member Author

Note that the viewer also deduplicates the messages because they are long strings and they repeat with the same text for every project being evaluated:
https://github.com/KirillOsenkov/MSBuildStructuredLog/blob/45ba130c7f3a1c311a7ece980b2a5d3f3ada0bc1/src/StructuredLogger/BinaryLogger/BuildEventArgsReader.Viewer.cs#L64-L99

So for a binlog with a thousand projects you get a thousand copies of each of these strings unless you deduplicate. But this is on the reader side, the writer (MSBuild) doesn't need to worry about that.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants