Log environment-derived properties

src/Build.UnitTests/BinaryLogger_Tests.cs

@@ -1,12 +1,13 @@
 using System;
 using System.Collections.Generic;
+using System.IO;
 using System.Text;
 
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.Execution;
 using Microsoft.Build.Framework;
 using Microsoft.Build.Logging;
-
+using Microsoft.Build.UnitTests.Shared;
 using Shouldly;
 using Xunit;
 using Xunit.Abstractions;
@@ -138,6 +139,45 @@ public void BinaryLoggerShouldSupportFilePathExplicitParameter()
             ObjectModelHelpers.BuildProjectExpectSuccess(s_testProject, binaryLogger);
         }
 
+        [Fact]
+        public void UnusedEnvironmentVariablesDoNotAppearInBinaryLog()
+        {
+            using (TestEnvironment env = TestEnvironment.Create())
+            {
+                env.SetEnvironmentVariable("EnvVar1", "itsValue");
+                env.SetEnvironmentVariable("EnvVar2", "value2");
+                env.SetEnvironmentVariable("EnvVar3", "value3");
+                string contents = @"
+<Project DefaultTargets=""PrintEnvVar"">
+
+<PropertyGroup>
+<MyProp1>value</MyProp1>
+<MyProp2>$(EnvVar2)</MyProp2>
+</PropertyGroup>
+
+<Target Name=""PrintEnvVar"">
+<Message Text=""Environment variable EnvVar3 has value $(EnvVar3)"" Importance=""High"" />
+</Target>
+
+</Project>";
+                TransientTestFolder logFolder = env.CreateFolder(createFolder: true);
+                TransientTestFile projectFile = env.CreateFile(logFolder, "myProj.proj", contents);
+                BinaryLogger logger = new();
+                logger.Parameters = _logFile;
+                RunnerUtilities.ExecMSBuild($"{projectFile.Path} -bl:{logger.Parameters}", out bool success);
+                success.ShouldBeTrue();
+                RunnerUtilities.ExecMSBuild($"{logger.Parameters} -flp:logfile={Path.Combine(logFolder.Path, "logFile.log")};verbosity=diagnostic", out success);
+                success.ShouldBeTrue();
+                string text = File.ReadAllText(Path.Combine(logFolder.Path, "logFile.log"));
+                text.ShouldContain("EnvVar2");
+                text.ShouldContain("value2");
+                text.ShouldContain("EnvVar3");
+                text.ShouldContain("value3");
+                text.ShouldNotContain("EnvVar1");
+                text.ShouldNotContain("itsValue");
+            }
+        }
+
         [Fact]
         public void BinaryLoggerShouldNotThrowWhenMetadataCannotBeExpanded()
         {

src/Build.UnitTests/BuildEventArgsSerialization_Tests.cs

@@ -24,30 +24,36 @@ public BuildEventArgsSerializationTests()
             _ = ItemGroupLoggingHelper.ItemGroupIncludeLogMessagePrefix;
         }
 
-        [Fact]
-        public void RoundtripBuildStartedEventArgs()
+        [Theory]
+        [InlineData(true)]
+        [InlineData(false)]
+        public void RoundtripBuildStartedEventArgs(bool serializeAllEnvironmentVariables)
         {
-            var args = new BuildStartedEventArgs(
-                "Message",
-                "HelpKeyword",
-                DateTime.Parse("3/1/2017 11:11:56 AM"));
-            Roundtrip(args,
-                e => e.Message,
-                e => e.HelpKeyword,
-                e => e.Timestamp.ToString());
-
-            args = new BuildStartedEventArgs(
-                "M",
-                null,
-                new Dictionary<string, string>
-                {
+            using (TestEnvironment env = TestEnvironment.Create())
+            {
+                env.SetEnvironmentVariable("MSBUILDLOGALLENVIRONMENTVARIABLES", serializeAllEnvironmentVariables ? "1" : null);
+                var args = new BuildStartedEventArgs(
+                    "Message",
+                    "HelpKeyword",
+                    DateTime.Parse("3/1/2017 11:11:56 AM"));
+                Roundtrip(args,
+                    e => e.Message,
+                    e => e.HelpKeyword,
+                    e => e.Timestamp.ToString());
+
+                args = new BuildStartedEventArgs(
+                    "M",
+                    null,
+                    new Dictionary<string, string>
+                    {
                     { "SampleName", "SampleValue" }
-                });
-            Roundtrip(args,
-                e => TranslationHelpers.ToString(e.BuildEnvironment),
-                e => e.HelpKeyword,
-                e => e.ThreadId.ToString(),
-                e => e.SenderName);
+                    });
+                Roundtrip(args,
+                    e => serializeAllEnvironmentVariables ? TranslationHelpers.ToString(e.BuildEnvironment) : null,
+                    e => e.HelpKeyword,
+                    e => e.ThreadId.ToString(),
+                    e => e.SenderName);
+            }
         }
 
         [Fact]
@@ -173,6 +179,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

@@ -4518,7 +4518,7 @@ public void VerifyMSBuildLogsAMessageWhenLocalPropertyCannotOverrideValueOfGloba
         [Fact]
         public void VerifyPropertyTrackingLoggingDefault()
         {
-            // Having nothing defined should default to nothing being logged.
+            // Having just environment variables defined should default to nothing being logged except one environment variable read.
             this.VerifyPropertyTrackingLoggingScenario(
                 null,
                 logger =>
@@ -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,55 +81,41 @@ public UtilitiesTestReadOnlyLoad()
         [Fact]
         public void CommentsInPreprocessing()
         {
-            Microsoft.Build.Construction.XmlDocumentWithLocation.ClearReadOnlyFlags_UnitTestsOnly();
+            using TestEnvironment env = TestEnvironment.Create();
+            XmlDocumentWithLocation.ClearReadOnlyFlags_UnitTestsOnly();
 
-            string input = FileUtilities.GetTemporaryFile();
-            string output = FileUtilities.GetTemporaryFile();
+            TransientTestFile inputFile = env.CreateFile("tempInput.tmp", ObjectModelHelpers.CleanupFileContents(@"
+<Project DefaultTargets='Build'>
+<Import Project='$(MSBuildToolsPath)\Microsoft.CSharp.targets'/>
+</Project>"));
+            TransientTestFile outputFile = env.CreateFile("tempOutput.tmp");
 
-            string _initialLoadFilesWriteable = Environment.GetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE");
-            try
-            {
-                Environment.SetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE", "1");
-
-                string content = ObjectModelHelpers.CleanupFileContents(@"
-<Project DefaultTargets='Build' ToolsVersion='msbuilddefaulttoolsversion' xmlns='msbuildnamespace'>
-  <Import Project='$(MSBuildToolsPath)\Microsoft.CSharp.targets'/>
-</Project>");
-                File.WriteAllText(input, content);
+            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 + '"'}));
+            Assert.Equal(
+                MSBuildApp.ExitType.Success,
+                MSBuildApp.Execute(
+                    new[] { @"c:\bin\msbuild.exe", '"' + inputFile.Path + '"',
+                '"' + (NativeMethodsShared.IsUnixLike ? "-pp:" : "/pp:") + outputFile.Path + '"'}));
 #endif
 
-                bool foundDoNotModify = false;
-                foreach (string line in File.ReadLines(output))
+            bool foundDoNotModify = false;
+            foreach (string line in File.ReadLines(outputFile.Path))
+            {
+                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
                 {
-                    if (line.Contains("<!---->")) // This is what it will look like if we're loading read/only
-                    {
-                        Assert.True(false);
-                    }
-
-                    if (line.Contains("DO NOT MODIFY")) // this is in a comment in our targets
-                    {
-                        foundDoNotModify = true;
-                    }
+                    foundDoNotModify = true;
                 }
-
-                Assert.True(foundDoNotModify);
-            }
-            finally
-            {
-                File.Delete(input);
-                File.Delete(output);
-                Environment.SetEnvironmentVariable("MSBUILDLOADALLFILESASWRITEABLE", _initialLoadFilesWriteable);
             }
+
+            foundDoNotModify.ShouldBeTrue();
         }
 
         [Fact]

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

@@ -1432,20 +1432,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)
             {
@@ -1489,14 +1477,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);
@@ -1541,7 +1527,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.
@@ -1562,7 +1548,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/BackEnd/Components/Logging/LoggingServiceLogMethods.cs

@@ -388,14 +388,11 @@ public void LogBuildStarted()
                 message = ResourceUtilities.GetResourceString("BuildStarted");
             }
 
-            IDictionary<string, string> environmentProperties = null;
+            IDictionary<string, string> environmentProperties = _componentHost?.BuildParameters != null && Traits.Instance.LogAllEnvironmentVariables ?
+                _componentHost.BuildParameters.BuildProcessEnvironment
+                : null;
 
-            if (_componentHost?.BuildParameters != null)
-            {
-                environmentProperties = _componentHost.BuildParameters.BuildProcessEnvironment;
-            }
-
-            BuildStartedEventArgs buildEvent = new BuildStartedEventArgs(message, null /* no help keyword */, environmentProperties);
+            BuildStartedEventArgs buildEvent = new(message, helpKeyword: null, environmentProperties);
 
             // Raise the event with the filters
             ProcessLoggingEvent(buildEvent);