Log environment-derived properties

src/Build.UnitTests/BinaryLogger_Tests.cs

@@ -124,6 +124,10 @@ public void TestBinaryLoggerRoundtrip(string projectText)
             var serialActual = serialFromPlaybackText.ToString();
             var parallelExpected = parallelFromBuildText.ToString();
             var parallelActual = parallelFromPlaybackText.ToString();
+            serialExpected = serialExpected.Substring(serialExpected.IndexOf("Project"));
+            serialActual = serialActual.Substring(serialActual.IndexOf("Project"));
+            parallelExpected = parallelExpected.Substring(parallelExpected.IndexOf("Project"));
+            parallelActual = parallelActual.Substring(parallelActual.IndexOf("Project"));
 
             serialActual.ShouldContainWithoutWhitespace(serialExpected);
             parallelActual.ShouldContainWithoutWhitespace(parallelExpected);

src/Build.UnitTests/BuildEventArgsSerialization_Tests.cs

@@ -38,13 +38,8 @@ public void RoundtripBuildStartedEventArgs()
 
             args = new BuildStartedEventArgs(
                 "M",
-                null,
-                new Dictionary<string, string>
-                {
-                    { "SampleName", "SampleValue" }
-                });
+                null);
             Roundtrip(args,
-                e => TranslationHelpers.ToString(e.BuildEnvironment),
                 e => e.HelpKeyword,
                 e => e.ThreadId.ToString(),
                 e => e.SenderName);
@@ -173,6 +168,17 @@ public void RoundtripTaskStartedEventArgs()
                 e => e.ColumnNumber.ToString());
         }
 
+        [Fact]
+        public void RoundtripEnvironmentVariableReadEventArgs()
+        {
+            EnvironmentVariableReadEventArgs args = new("VarName", "VarValue");
+            args.BuildEventContext = new BuildEventContext(4, 5, 6, 7);
+            Roundtrip(args,
+                e => e.Message,
+                e => e.EnvironmentVariableName,
+                e => e.BuildEventContext.ToString());
+        }
+
         [Fact]
         public void RoundtripTaskFinishedEventArgs()
         {

src/Build.UnitTests/Evaluation/Evaluator_Tests.cs

@@ -4531,7 +4531,9 @@ public void VerifyPropertyTrackingLoggingDefault()
                     logger
                         .AllBuildEvents
                         .OfType<EnvironmentVariableReadEventArgs>()
-                        .ShouldBeEmpty();
+                        .ShouldHaveSingleItem()
+                        .EnvironmentVariableName
+                        .ShouldBe("DEFINED_ENVIRONMENT_VARIABLE2");
 
                     logger
                         .AllBuildEvents
@@ -4560,7 +4562,9 @@ public void VerifyPropertyTrackingLoggingPropertyReassignment()
                     logger
                         .AllBuildEvents
                         .OfType<EnvironmentVariableReadEventArgs>()
-                        .ShouldBeEmpty();
+                        .ShouldHaveSingleItem()
+                        .EnvironmentVariableName
+                        .ShouldBe("DEFINED_ENVIRONMENT_VARIABLE2");
 
                     logger
                         .AllBuildEvents
@@ -4589,7 +4593,9 @@ public void VerifyPropertyTrackingLoggingNone()
                     logger
                         .AllBuildEvents
                         .OfType<EnvironmentVariableReadEventArgs>()
-                        .ShouldBeEmpty();
+                        .ShouldHaveSingleItem()
+                        .EnvironmentVariableName
+                        .ShouldBe("DEFINED_ENVIRONMENT_VARIABLE2");
 
                     logger
                         .AllBuildEvents
@@ -4618,7 +4624,9 @@ public void VerifyPropertyTrackingLoggingPropertyInitialValue()
                     logger
                         .AllBuildEvents
                         .OfType<EnvironmentVariableReadEventArgs>()
-                        .ShouldBeEmpty();
+                        .ShouldHaveSingleItem()
+                        .EnvironmentVariableName
+                        .ShouldBe("DEFINED_ENVIRONMENT_VARIABLE2");
 
                     logger
                         .AllBuildEvents
@@ -4702,7 +4710,9 @@ public void VerifyPropertyTrackingLoggingUninitializedPropertyRead()
                     logger
                         .AllBuildEvents
                         .OfType<EnvironmentVariableReadEventArgs>()
-                        .ShouldBeEmpty();
+                        .ShouldHaveSingleItem()
+                        .EnvironmentVariableName
+                        .ShouldBe("DEFINED_ENVIRONMENT_VARIABLE2");
 
                     logger
                         .AllBuildEvents

src/Build.UnitTests/Utilities_Tests.cs

@@ -22,6 +22,7 @@
 using System.Collections.Generic;
 using System.IO;
 using Xunit.Abstractions;
+using Shouldly;
 
 #nullable disable
 
@@ -80,54 +81,42 @@ public UtilitiesTestReadOnlyLoad()
         [Fact]
         public void CommentsInPreprocessing()
         {
-            Microsoft.Build.Construction.XmlDocumentWithLocation.ClearReadOnlyFlags_UnitTestsOnly();
-
-            string input = FileUtilities.GetTemporaryFile();
-            string output = FileUtilities.GetTemporaryFile();
-
-            string _initialLoadFilesWriteable = Environment.GetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE");
-            try
+            using (TestEnvironment env = TestEnvironment.Create())
             {
-                Environment.SetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE", "1");
+                XmlDocumentWithLocation.ClearReadOnlyFlags_UnitTestsOnly();
 
-                string content = ObjectModelHelpers.CleanupFileContents(@"
-<Project DefaultTargets='Build' ToolsVersion='msbuilddefaulttoolsversion' xmlns='msbuildnamespace'>
+                TransientTestFile inputFile = env.CreateFile("tempInput.tmp", ObjectModelHelpers.CleanupFileContents(@"
+<Project DefaultTargets='Build'>
   <Import Project='$(MSBuildToolsPath)\Microsoft.CSharp.targets'/>
-</Project>");
-                File.WriteAllText(input, content);
+</Project>"));
+                TransientTestFile outputFile = env.CreateFile("tempOutput.tmp");
+
+                env.SetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE", "1");
 
 #if FEATURE_GET_COMMANDLINE
-                Assert.Equal(MSBuildApp.ExitType.Success, MSBuildApp.Execute(@"c:\bin\msbuild.exe """ + input +
-                    (NativeMethodsShared.IsUnixLike ? @""" -pp:""" : @""" /pp:""") + output + @""""));
+                MSBuildApp.Execute(@"c:\bin\msbuild.exe """ + inputFile.Path +
+                    (NativeMethodsShared.IsUnixLike ? @""" -pp:""" : @""" /pp:""") + outputFile.Path + @"""")
+                    .ShouldBe(MSBuildApp.ExitType.Success);
 #else
                 Assert.Equal(
                     MSBuildApp.ExitType.Success,
                     MSBuildApp.Execute(
-                        new[] { @"c:\bin\msbuild.exe", '"' + input + '"',
-                    '"' + (NativeMethodsShared.IsUnixLike ? "-pp:" : "/pp:") + output + '"'}));
+                        new[] { @"c:\bin\msbuild.exe", '"' + inputFile.Path + '"',
+                    '"' + (NativeMethodsShared.IsUnixLike ? "-pp:" : "/pp:") + outputFile.Path + '"'}));
 #endif
 
                 bool foundDoNotModify = false;
-                foreach (string line in File.ReadLines(output))
+                foreach (string line in File.ReadLines(outputFile.Path))
                 {
-                    if (line.Contains("<!---->")) // This is what it will look like if we're loading read/only
-                    {
-                        Assert.True(false);
-                    }
+                    line.ShouldNotContain("<!---->", "This is what it will look like if we're loading read/only");
 
                     if (line.Contains("DO NOT MODIFY")) // this is in a comment in our targets
                     {
                         foundDoNotModify = true;
                     }
                 }
 
-                Assert.True(foundDoNotModify);
-            }
-            finally
-            {
-                File.Delete(input);
-                File.Delete(output);
-                Environment.SetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE", _initialLoadFilesWriteable);
+                foundDoNotModify.ShouldBeTrue();
             }
         }
 

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

@@ -1154,19 +1154,15 @@ public void LogBuildEvent(BuildEventArgs buildEvent)
             {
                 ErrorUtilities.VerifyThrow(buildEvent != null, "buildEvent is null");
 
-                BuildWarningEventArgs warningEvent = null;
-                BuildErrorEventArgs errorEvent = null;
-                BuildMessageEventArgs messageEvent = null;
-
-                if ((warningEvent = buildEvent as BuildWarningEventArgs) != null && warningEvent.BuildEventContext != null && warningEvent.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId)
+                if (buildEvent is BuildWarningEventArgs warningEvent && warningEvent.BuildEventContext != null && warningEvent.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId)
                 {
                     warningEvent.ProjectFile = GetAndVerifyProjectFileFromContext(warningEvent.BuildEventContext);
                 }
-                else if ((errorEvent = buildEvent as BuildErrorEventArgs) != null && errorEvent.BuildEventContext != null && errorEvent.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId)
+                else if (buildEvent is BuildErrorEventArgs errorEvent && errorEvent.BuildEventContext != null && errorEvent.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId)
                 {
                     errorEvent.ProjectFile = GetAndVerifyProjectFileFromContext(errorEvent.BuildEventContext);
                 }
-                else if ((messageEvent = buildEvent as BuildMessageEventArgs) != null && messageEvent.BuildEventContext != null && messageEvent.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId)
+                else if (buildEvent is BuildMessageEventArgs messageEvent && messageEvent.BuildEventContext != null && messageEvent.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId)
                 {
                     messageEvent.ProjectFile = GetAndVerifyProjectFileFromContext(messageEvent.BuildEventContext);
                 }
@@ -1175,10 +1171,10 @@ public void LogBuildEvent(BuildEventArgs buildEvent)
                 {
                     // Only log certain events if OnlyLogCriticalEvents is true
                     if (
-                        (warningEvent != null)
-                        || (errorEvent != null)
-                        || (buildEvent is CustomBuildEventArgs)
-                        || (buildEvent is CriticalBuildMessageEventArgs)
+                        buildEvent is BuildWarningEventArgs
+                        || buildEvent is BuildErrorEventArgs
+                        || buildEvent is CustomBuildEventArgs
+                        || buildEvent is CriticalBuildMessageEventArgs
                        )
                     {
                         ProcessLoggingEvent(buildEvent);
@@ -1451,20 +1447,8 @@ private void LoggingEventProcessor(object loggingEvent)
         /// </summary>
         private void RouteBuildEvent(object loggingEvent)
         {
-            BuildEventArgs buildEventArgs = null;
-
-            if (loggingEvent is BuildEventArgs bea)
-            {
-                buildEventArgs = bea;
-            }
-            else if (loggingEvent is KeyValuePair<int, BuildEventArgs> kvp)
-            {
-                buildEventArgs = kvp.Value;
-            }
-            else
-            {
-                ErrorUtilities.ThrowInternalError("Unknown logging item in queue:" + loggingEvent.GetType().FullName);
-            }
+            BuildEventArgs buildEventArgs = loggingEvent as BuildEventArgs ?? (loggingEvent as KeyValuePair<int, BuildEventArgs>?)?.Value;
+            ErrorUtilities.VerifyThrow(buildEventArgs is not null, "Unknown logging item in queue:" + loggingEvent.GetType().FullName);
 
             if (buildEventArgs is BuildWarningEventArgs warningEvent)
             {
@@ -1508,14 +1492,12 @@ private void RouteBuildEvent(object loggingEvent)
                     };
                 }
             }
-
-            if (loggingEvent is BuildErrorEventArgs errorEvent)
+            else if (loggingEvent is BuildErrorEventArgs errorEvent)
             {
                 // Keep track of build submissions that have logged errors.  If there is no build context, add BuildEventContext.InvalidSubmissionId.
                 _buildSubmissionIdsThatHaveLoggedErrors.Add(errorEvent.BuildEventContext?.SubmissionId ?? BuildEventContext.InvalidSubmissionId);
             }
-
-            if (loggingEvent is ProjectFinishedEventArgs projectFinishedEvent && projectFinishedEvent.BuildEventContext != null)
+            else if (loggingEvent is ProjectFinishedEventArgs projectFinishedEvent && projectFinishedEvent.BuildEventContext != null)
             {
                 int key = GetWarningsAsErrorOrMessageKey(projectFinishedEvent);
                 _warningsAsErrorsByProject?.Remove(key);
@@ -1560,7 +1542,7 @@ private void RouteBuildEvent(BuildEventArgs eventArg)
             TryRaiseProjectStartedEvent(eventArg);
 
             // The event has not been through a filter yet. All events must go through a filter before they make it to a logger
-            if (_filterEventSource != null)   // Loggers may not be registered
+            if (_filterEventSource != null) // Loggers may not be registered
             {
                 // Send the event to the filter, the Consume will not return until all of the loggers which have registered to the event have process
                 // them.
@@ -1581,7 +1563,7 @@ private void RouteBuildEvent(BuildEventArgs eventArg)
                         {
                             if (!sink.HaveLoggedBuildStartedEvent)
                             {
-                                sink.Consume(eventArg, (int)pair.Key);
+                                sink.Consume(eventArg, pair.Key);
                             }
 
                             // Reset the HaveLoggedBuildStarted event because no one else will be sending a build started event to any loggers at this time.

src/Build/Definition/Project.cs

@@ -2923,7 +2923,7 @@ public override bool SetGlobalProperty(string name, string escapedValue)
                     string originalValue = (existing == null) ? String.Empty : ((IProperty)existing).EvaluatedValueEscaped;
 
                     _data.GlobalPropertiesDictionary.Set(ProjectPropertyInstance.Create(name, escapedValue));
-                    _data.Properties.Set(ProjectProperty.Create(Owner, name, escapedValue, true /* is global */, false /* may not be reserved name */));
+                    _data.Properties.Set(ProjectProperty.Create(Owner, name, escapedValue, true /* is global */, false /* may not be reserved name */, null));
 
                     ProjectCollection.AfterUpdateLoadedProjectGlobalProperties(Owner);
                     MarkDirty();
@@ -4389,9 +4389,9 @@ public IItemDefinition<ProjectMetadata> GetItemDefinition(string itemType)
             /// <summary>
             /// Sets a property which is not derived from Xml.
             /// </summary>
-            public ProjectProperty SetProperty(string name, string evaluatedValueEscaped, bool isGlobalProperty, bool mayBeReserved, bool isEnvironmentVariable = false)
+            public ProjectProperty SetProperty(string name, string evaluatedValueEscaped, bool isGlobalProperty, bool mayBeReserved, bool isEnvironmentVariable = false, BackEnd.Logging.LoggingContext loggingContext = null)
             {
-                ProjectProperty property = ProjectProperty.Create(Project, name, evaluatedValueEscaped, isGlobalProperty, mayBeReserved);
+                ProjectProperty property = ProjectProperty.Create(Project, name, evaluatedValueEscaped, isGlobalProperty, mayBeReserved, loggingContext);
                 Properties.Set(property);
 
                 AddToAllEvaluatedPropertiesList(property);

src/Build/Definition/ProjectProperty.cs

@@ -3,8 +3,10 @@
 
 using System;
 using System.Diagnostics;
+using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.Collections;
 using Microsoft.Build.Construction;
+using Microsoft.Build.Framework;
 using Microsoft.Build.Shared;
 
 using ReservedPropertyNames = Microsoft.Build.Internal.ReservedPropertyNames;
@@ -94,9 +96,22 @@ public string EvaluatedValue
         string IProperty.EvaluatedValueEscaped
         {
             [DebuggerStepThrough]
-            get => EvaluatedValueEscapedInternal;
+            get
+            {
+                if ((this as IProperty).IsEnvironmentProperty && this is ProjectPropertyNotXmlBacked notXmlBacked && notXmlBacked.loggingContext?.IsValid == true && !_loggedEnvProperty)
+                {
+                    EnvironmentVariableReadEventArgs args = new(Name, EvaluatedValueEscapedInternal);
+                    args.BuildEventContext = notXmlBacked.loggingContext.BuildEventContext;
+                    notXmlBacked.loggingContext.LogBuildEvent(args);
+                    _loggedEnvProperty = true;
+                }
+
+                return EvaluatedValueEscapedInternal;
+            }
         }
 
+        private bool _loggedEnvProperty = false;
+
         /// <summary>
         /// Gets or sets the unevaluated property value.
         /// Updates the evaluated value in the project, although this is not sure to be correct until re-evaluation.
@@ -204,6 +219,8 @@ string IValued.EscapedValue
             get => EvaluatedValueEscapedInternal;
         }
 
+        bool IProperty.IsEnvironmentProperty { get => IsEnvironmentProperty; set => throw new NotImplementedException(); }
+
         #region IEquatable<ProjectProperty> Members
 
         /// <summary>
@@ -237,9 +254,9 @@ bool IEquatable<ProjectProperty>.Equals(ProjectProperty other)
         /// This is ONLY to be used by the Evaluator (and Project.SetGlobalProperty) and ONLY for Global, Environment, and Built-in properties.
         /// All other properties originate in XML, and should have a backing XML object.
         /// </summary>
-        internal static ProjectProperty Create(Project project, string name, string evaluatedValueEscaped, bool isGlobalProperty, bool mayBeReserved)
+        internal static ProjectProperty Create(Project project, string name, string evaluatedValueEscaped, bool isGlobalProperty, bool mayBeReserved, LoggingContext loggingContext = null)
         {
-            return new ProjectPropertyNotXmlBacked(project, name, evaluatedValueEscaped, isGlobalProperty, mayBeReserved);
+            return new ProjectPropertyNotXmlBacked(project, name, evaluatedValueEscaped, isGlobalProperty, mayBeReserved, loggingContext);
         }
 
         /// <summary>
@@ -494,14 +511,15 @@ private class ProjectPropertyNotXmlBacked : ProjectProperty
             /// Name of the property.
             /// </summary>
             private readonly string _name;
+            internal LoggingContext loggingContext;
 
             /// <summary>
             /// Creates a property without backing XML.
             /// Property MAY BE global, and property MAY HAVE a reserved name (such as "MSBuildProjectDirectory") if indicated.
             /// This is ONLY to be used by the Evaluator (and Project.SetGlobalProperty) and ONLY for Global, Environment, and Built-in properties.
             /// All other properties originate in XML, and should have a backing XML object.
             /// </summary>
-            internal ProjectPropertyNotXmlBacked(Project project, string name, string evaluatedValueEscaped, bool isGlobalProperty, bool mayBeReserved)
+            internal ProjectPropertyNotXmlBacked(Project project, string name, string evaluatedValueEscaped, bool isGlobalProperty, bool mayBeReserved, LoggingContext loggingContext)
                 : base(project, evaluatedValueEscaped)
             {
                 ErrorUtilities.VerifyThrowArgumentLength(name, nameof(name));
@@ -510,6 +528,7 @@ internal ProjectPropertyNotXmlBacked(Project project, string name, string evalua
                 ErrorUtilities.VerifyThrowArgument(mayBeReserved || !ReservedPropertyNames.IsReservedProperty(name), "OM_ReservedName", name);
 
                 _name = name;
+                this.loggingContext = loggingContext;
             }
 
             /// <summary>