Only log properties and items on evaluation if ALL loggers support it #6514

KirillOsenkov · 2021-06-03T03:14:27Z

Opt in serial and parallel console loggers to the new behavior.

This should fix an inadvertent regression when a legacy logger is present that relies on either Properties or Items on ProjectStartedEventArgs to be not null, together with the binary logger that switches on the new behavior.

Fixes #6498

KirillOsenkov · 2021-06-03T04:34:33Z

I've hit a complication with this logic:
https://source.dot.net/#Microsoft.Build/Logging/ParallelLogger/ParallelConsoleLogger.cs,c8331049011579b8

The failing test is https://source.dot.net/#Microsoft.Build.Engine.UnitTests/ConsoleLogger_Tests.cs,033182bb824cc88e

This logic relies on properties being logged on each ProjectStarted as it uses the ProjectContextId as the key in the dictionary, such that later error events can look up the property by their ProjectContextId.

Since we now log properties at evaluation, there isn't any ProjectContextId to speak of during ProjectEvaluationFinished.

This is a great exercise for me to do what I tell others to do: "just update your loggers to use ProjectEvaluationFinished instead". It appears to be not as trivial and will require some thinking.

I'll continue on this tomorrow.

Perhaps the best thing would be to change the Any to All as a high-pri change and ship that to servicing first, and then "enlighten" the console loggers in a separate change.

rainersigwald · 2021-06-03T16:57:27Z

Perhaps the best thing would be to change the Any to All as a high-pri change and ship that to servicing first, and then "enlighten" the console loggers in a separate change.

This is a reasonable plan, I think.

One note: the failing test that's trying to disambiguate TFs of the same project is not actually turned on in the SDK at the moment (dotnet/sdk#12030). But we'd like to get that in at some point. However, maybe we should take from this that the change is more impactful than we hoped :(

KirillOsenkov · 2021-06-03T20:15:16Z

Yes, I agree we had a hole where the console loggers didn't properly look up items from ProjectEvaluationFinished.

I've found a relatively simple way to plug that hole. Now we're going to store the results for an evaluation if we find them, and copy them to each project (since the project now points back to its evaluation).

We could still ship this one PR, or I could split it into just the All change and make a separate PR to enlighten the console loggers.

KirillOsenkov · 2021-06-04T03:40:20Z

Someone please revoke my coding license.

Changing Any to All is not so straightforward:

        var a = Array.Empty<DictionaryEntry>().Any(d => d.Value != null); // false
        var b = Array.Empty<DictionaryEntry>().All(d => d.Value != null); // true

KirillOsenkov · 2021-06-04T05:56:06Z

Ugh, this suddenly spiraled way out of control. I'll continue on this tomorrow.

KirillOsenkov · 2021-06-04T05:58:55Z

Filed #6518 to look closer into

msbuild/src/Build.UnitTests/ConsoleLogger_Tests.cs

Line 324 in 46b723b

public void TestItemsWithUnexpandableMetadata()

KirillOsenkov · 2021-06-04T06:00:38Z

src/Shared/UnitTests/ObjectModelHelpers.cs

@@ -725,7 +746,7 @@ internal static void BuildProjectExpectSuccess
            params ILogger[] loggers
            )
        {
-            Project project = CreateInMemoryProject(projectContents, logger: null); // logger is null so we take care of loggers ourselves


Since we were explicitly nulling out the logger here, we were dropping all evaluation events.

KirillOsenkov · 2021-06-04T06:03:51Z

src/Build/Logging/BaseConsoleLogger.cs

            setColor(ConsoleColor.DarkGray);
-            foreach (ITaskItem item in itemTypeList)


Earlier we only used to get items of type ITaskItem (from ProjectStartedEventArgs). Now we can also get instances of ProjectItem (from ProjectEvaluationFinishedEventArgs), which don't implement either ITaskItem or IMetadataContainer. Hence some ugly pattern-matching and special-casing. Made me wonder whether ProjectItem should implement ITaskItem and/or IMetadataContainer.

Also this behavior seems to break the test TestItemsWithUnexpandableMetadata (#6518)

KirillOsenkov · 2021-06-04T06:04:31Z

src/Build/BackEnd/Components/Logging/LoggingService.cs

+                {
+                    var sinks = _eventSinkDictionary.Values.OfType<EventSourceSink>();
+                    // .All() on an empty list defaults to true, we want to default to false
+                    _includeEvaluationPropertiesAndItems = sinks.Any() && sinks.All(sink => sink.IncludeEvaluationPropertiesAndItems);


Can't just switch Any to All without inverting the default for empty dictionaries.

KirillOsenkov · 2021-06-04T06:27:35Z

Ugh, more issues in

Microsoft.Build.UnitTests.BinaryLoggerTests.BinaryLoggerShouldNotThrowWhenMetadataCannotBeExpanded
Microsoft.Build.Framework.LoggerException : Failed to write to log file \"C:\\Users\\VssAdministrator\\AppData\\Local\\Temp\\haxozl1r.ymr\\tmpd948805cb14d45c99c0aa53b084afda2.binlog\". The process cannot access the file 'C:\\Users\\VssAdministrator\\AppData\\Local\\Temp\\haxozl1r.ymr\\tmpd948805cb14d45c99c0aa53b084afda2.binlog' because it is being used by another process.\r\n---- System.IO.IOException : The process cannot access the file 'C:\\Users\\VssAdministrator\\AppData\\Local\\Temp\\haxozl1r.ymr\\tmpd948805cb14d45c99c0aa53b084afda2.binlog' because it is being used by another process.
   at Microsoft.Build.Logging.BinaryLogger.Initialize(IEventSource eventSource) in /_/src/Build/Logging/BinaryLogger/BinaryLogger.cs:line 158
   at Microsoft.Build.BackEnd.Logging.LoggingService.InitializeLogger(ILogger logger, IEventSource sourceForLogger) in /_/src/Build/BackEnd/Components/Logging/LoggingService.cs:line 1544
   at Microsoft.Build.BackEnd.Logging.LoggingService.RegisterDistributedLogger(ILogger centralLogger, LoggerDescription forwardingLogger) in /_/src/Build/BackEnd/Components/Logging/LoggingService.cs:line 982
   at Microsoft.Build.BackEnd.Logging.LoggingService.RegisterLogger(ILogger logger) in /_/src/Build/BackEnd/Components/Logging/LoggingService.cs:line 896
   at Microsoft.Build.Execution.BuildManager.CreateLoggingService(IEnumerable`1 loggers, IEnumerable`1 forwardingLoggers, ISet`1 warningsAsErrors, ISet`1 warningsAsMessages) in /_/src/Build/BackEnd/BuildManager/BuildManager.cs:line 2877
   at Microsoft.Build.Execution.BuildManager.<BeginBuild>g__InitializeLoggingService|64_0() in /_/src/Build/BackEnd/BuildManager/BuildManager.cs:line 488
   at Microsoft.Build.Execution.BuildManager.BeginBuild(BuildParameters parameters) in /_/src/Build/BackEnd/BuildManager/BuildManager.cs:line 445
   at Microsoft.Build.Execution.BuildManager.Build(BuildParameters parameters, BuildRequestData requestData) in /_/src/Build/BackEnd/BuildManager/BuildManager.cs:line 938
   at Microsoft.Build.Execution.ProjectInstance.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers, ILoggingService loggingService, Int32 maxNodeCount, IDictionary`2& targetOutputs) in /_/src/Build/Instance/ProjectInstance.cs:line 2326
   at Microsoft.Build.Evaluation.Project.ProjectImpl.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers, EvaluationContext evaluationContext) in /_/src/Build/Definition/Project.cs:line 3270
   at Microsoft.Build.Evaluation.Project.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers, EvaluationContext evaluationContext) in /_/src/Build/Definition/Project.cs:line 1597
   at Microsoft.Build.Evaluation.Project.Build(String[] targets, IEnumerable`1 loggers, IEnumerable`1 remoteLoggers) in /_/src/Build/Definition/Project.cs:line 1584
   at Microsoft.Build.Evaluation.Project.Build(IEnumerable`1 loggers) in /_/src/Build/Definition/Project.cs:line 1474
   at Microsoft.Build.UnitTests.ObjectModelHelpers.BuildProjectExpectSuccess(String projectContents, ILogger[] loggers) in D:\a\1\s\src\Shared\UnitTests\ObjectModelHelpers.cs:line 750
   at Microsoft.Build.UnitTests.BinaryLoggerTests.BinaryLoggerShouldNotThrowWhenMetadataCannotBeExpanded() in D:\a\1\s\src\Build.UnitTests\BinaryLogger_Tests.cs:line 160

rainersigwald · 2021-06-04T14:24:31Z

Someone please revoke my coding license.

That's bad news for the rest of us!

Since this is pretty complicated, should we change the direction of the escape hatch for 16.10 and revert it to prior behavior in (almost all) cases? Then we can take some time to figure out a path forward.

KirillOsenkov · 2021-06-04T18:39:09Z

I've created a more targeted fix in a separate PR here:
#6520

I'll continue using this PR to properly enlighten the console loggers and the test infrastructure.

KirillOsenkov · 2021-06-04T18:53:00Z

I'm now wading through the test infrastructure and noticing systemic issues with how loggers are passed to the build.

Filed #6521 to clean all of that debt up.

KirillOsenkov · 2021-06-05T00:22:24Z

The more I peel off the more I discover:
#6521 (comment)

KirillOsenkov · 2021-06-05T00:53:59Z

Well, I think I got the tests to pass.

But this PR is a mess. I'll be cleaning it up next week.

KirillOsenkov · 2021-06-05T00:55:00Z

src/Build/Logging/BinaryLogger/BuildEventArgsWriter.cs

+                    Write(new TaskItemData(
+                        iitem.EvaluatedInclude,
+                        iitem.Metadata.ToDictionary(m => m.Name, m => m.EvaluatedValue)), writeMetadata);
+                }


I still don't understand why this suddenly became necessary.

KirillOsenkov · 2021-06-05T00:55:39Z

src/Shared/UnitTests/ObjectModelHelpers.cs

-            project.Build(loggers).ShouldBeTrue();
+            Project project = CreateInMemoryProjectWithLoggers(projectContents, loggers);
+            project.Build().ShouldBeTrue();
+            project.ProjectCollection.Dispose();


Ugh, I'm really not sure this is how it's supposed to be.

Opt in serial and parallel console loggers to the new behavior. This should fix an inadvertent regression when a legacy logger is present that relies on either Properties or Items on ProjectStartedEventArgs to be not null, together with the binary logger that switches on the new behavior.

Using the .All() predicate on an empty sequence returns true, which is a breaking change from .Any() (which returns false). I think we should default to the old (legacy) behavior if no sinks are present in the list.

Now that OutputItems can be called for items provided by ProjectEvaluationFinished, add proper support for iterating these items and printing including all metadata.

This ensures we don't lose evaluation messages in some unit-tests.

…ectStarted. Enable the old behavior of passing properties on ProjectStartedEventArgs instead of ProjectEvaluationFinishedEventArgs (since the latter always passes all properties, so the test is not applicable).

Filed #6518 to clarify the expected behavior.

Under some conditions (in tests) we see ProjectItem instances in ProjectEvaluationFinished. Support writing those too.

…the base method instead.

Since the loggers are on the ProjectCollection already, no need to pass them again. But now we have to dispose of the ProjectCollection() to clean up the loggers.

KirillOsenkov · 2021-06-08T02:36:37Z

This PR is a mess, so I'm closing it and starting over at #6535

KirillOsenkov mentioned this pull request Jun 3, 2021

Azure Devops pipelines crashing in MSBuild logger, as of 5/25 VS2019 image #6498

Closed

KirillOsenkov added the WIP Work in Progress Pull Request--do not merge yet. label Jun 3, 2021

KirillOsenkov commented Jun 4, 2021

View reviewed changes

KirillOsenkov commented Jun 5, 2021

View reviewed changes

KirillOsenkov self-assigned this Jun 7, 2021

KirillOsenkov added 10 commits June 7, 2021 18:03

Support reading items from ProjectEvaluationFinished for console logger.

864913b

Change the default behavior of IncludeEvaluationPropertiesAndItems

11cc60c

Using the .All() predicate on an empty sequence returns true, which is a breaking change from .Any() (which returns false). I think we should default to the old (legacy) behavior if no sinks are present in the list.

Support iterating over evaluation items in BaseConsoleLogger

d2507e1

Now that OutputItems can be called for items provided by ProjectEvaluationFinished, add proper support for iterating these items and printing including all metadata.

Properly pass loggers to evaluation in tests

abafd06

This ensures we don't lose evaluation messages in some unit-tests.

Ensure OutOfProcNodeForwardCertainproperties tests Properties on Proj…

7dfd82a

…ectStarted. Enable the old behavior of passing properties on ProjectStartedEventArgs instead of ProjectEvaluationFinishedEventArgs (since the latter always passes all properties, so the test is not applicable).

Skip TestItemsWithUnexpandableMetadata

dcca1c7

Filed #6518 to clarify the expected behavior.

Support writing ProjectItem items to the binlog.

db87e6e

Under some conditions (in tests) we see ProjectItem instances in ProjectEvaluationFinished. Support writing those too.

Remove duplicated OutputItems() from ParallelConsoleLogger and reuse …

72dcfb9

…the base method instead.

Don't pass loggers to project.Build() in BuildProjectExpectSuccess

6ff063b

Since the loggers are on the ProjectCollection already, no need to pass them again. But now we have to dispose of the ProjectCollection() to clean up the loggers.

Skip NullMetadataOnLegacyOutputItems_InlineTask

751a67f

KirillOsenkov force-pushed the dev/kirillo/evalOptIn branch from f6adaa2 to 751a67f Compare June 8, 2021 01:04

KirillOsenkov mentioned this pull request Jun 8, 2021

Console logger support for IncludeEvaluationPropertiesAndItems #6535

Merged

KirillOsenkov closed this Jun 8, 2021

KirillOsenkov deleted the dev/kirillo/evalOptIn branch January 2, 2022 04:03

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Only log properties and items on evaluation if ALL loggers support it #6514

Only log properties and items on evaluation if ALL loggers support it #6514

KirillOsenkov commented Jun 3, 2021

KirillOsenkov commented Jun 3, 2021

rainersigwald commented Jun 3, 2021

KirillOsenkov commented Jun 3, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov Jun 4, 2021

KirillOsenkov Jun 4, 2021

KirillOsenkov Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

rainersigwald commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 5, 2021

KirillOsenkov commented Jun 5, 2021

KirillOsenkov Jun 5, 2021

KirillOsenkov Jun 5, 2021

KirillOsenkov commented Jun 8, 2021

		setColor(ConsoleColor.DarkGray);
		foreach (ITaskItem item in itemTypeList)

Only log properties and items on evaluation if ALL loggers support it #6514

Only log properties and items on evaluation if ALL loggers support it #6514

Conversation

KirillOsenkov commented Jun 3, 2021

KirillOsenkov commented Jun 3, 2021

rainersigwald commented Jun 3, 2021

KirillOsenkov commented Jun 3, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov Jun 4, 2021

Choose a reason for hiding this comment

KirillOsenkov Jun 4, 2021

Choose a reason for hiding this comment

KirillOsenkov Jun 4, 2021

Choose a reason for hiding this comment

KirillOsenkov commented Jun 4, 2021

rainersigwald commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 4, 2021

KirillOsenkov commented Jun 5, 2021

KirillOsenkov commented Jun 5, 2021

KirillOsenkov Jun 5, 2021

Choose a reason for hiding this comment

KirillOsenkov Jun 5, 2021

Choose a reason for hiding this comment

KirillOsenkov commented Jun 8, 2021