Skip to content

Commit

Permalink
Log when a property is being assigned a new value. (#1841)
Browse files Browse the repository at this point in the history 
Log a low priority message during evaluation when a property that was previously assigned is being assigned a new and different value. This is useful to determine when your property might be stomped over later.

Also adding Evaluation started and Evaluation finished messages for each project evaluation to logically isolated messages coming from the evaluation phase.

Sample log output:

Evaluation started ("C:\CodeCleanupTools\SortProjectItems\SortProjectItems.csproj")
Property reassignment: $(ProcessorArchitecture)="msil" (previous value: "AnyCPU") at C:\MSBuild\bin\Bootstrap\15.0\Bin\Microsoft.Common.CurrentVersion.targets (457,5)
Evaluation finished ("C:\CodeCleanupTools\SortProjectItems\SortProjectItems.csproj")
  • Loading branch information
@KirillOsenkov
KirillOsenkov authored Mar 10, 2017
1 parent 5cd702f commit 21eeb45
Show file tree
Hide file tree
Showing 3 changed files with 91 additions and 6 deletions.
49 changes: 49 additions & 0 deletions src/Build.UnitTests/Evaluation/Evaluator_Tests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -661,6 +661,55 @@ public void UsePropertyBeforeSet()
}
}

/// <summary>
/// Log when a property is being assigned a new value.
/// </summary>
[Fact]
public void LogPropertyAssignments()
{
string testtargets = ObjectModelHelpers.CleanupFileContents(@"
<Project xmlns='msbuildnamespace'>
<PropertyGroup>
<Prop>OldValue</Prop>
<Prop>NewValue</Prop>
</PropertyGroup>
<Target Name=""Test""/>
</Project>");

string tempPath = Path.GetTempPath();
string targetDirectory = Path.Combine(tempPath, "LogPropertyAssignments");
string testTargetPath = Path.Combine(targetDirectory, "test.proj");

bool originalValue = BuildParameters.WarnOnUninitializedProperty;
try
{
BuildParameters.WarnOnUninitializedProperty = true;
Directory.CreateDirectory(targetDirectory);
File.WriteAllText(testTargetPath, testtargets);

MockLogger logger = new MockLogger();
logger.Verbosity = LoggerVerbosity.Diagnostic;
ProjectCollection pc = new ProjectCollection();
pc.RegisterLogger(logger);
Project project = pc.LoadProject(testTargetPath);

bool result = project.Build();
Assert.Equal(true, result);
logger.AssertLogContains("Evaluation started");
logger.AssertLogContains("Property reassignment");
logger.AssertLogContains("Evaluation finished");
logger.AssertLogContains("Prop");
logger.AssertLogContains("OldValue");
logger.AssertLogContains("NewValue");
}
finally
{
BuildParameters.WarnOnUninitializedProperty = originalValue;
FileUtilities.DeleteWithoutTrailingBackslash(targetDirectory, true);
}
}

/// <summary>
/// If we use a property twice make sure we warn and dont crash due to the dictionary which is holding the used but uninitialized variables..
/// </summary>
Expand Down
39 changes: 33 additions & 6 deletions src/Build/Evaluation/Evaluator.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -777,6 +777,8 @@ private IDictionary<string, object> Evaluate()
#endif
string projectFile = String.IsNullOrEmpty(_projectRootElement.ProjectFileLocation.File) ? "(null)" : _projectRootElement.ProjectFileLocation.File;

_loggingService.LogComment(_buildEventContext, MessageImportance.Low, "EvaluationStarted", projectFile);

#if MSBUILDENABLEVSPROFILING
string endPass0 = String.Format(CultureInfo.CurrentCulture, "Evaluate Project {0} - End Pass 0 (Initial properties)", projectFile);
DataCollection.CommentMarkProfile(8816, endPass0);
Expand Down Expand Up @@ -929,6 +931,8 @@ private IDictionary<string, object> Evaluate()

_data.FinishEvaluation();

_loggingService.LogComment(_buildEventContext, MessageImportance.Low, "EvaluationFinished", projectFile);

#if FEATURE_MSBUILD_DEBUGGER
return _projectLevelLocalsForBuild;
#else
Expand Down Expand Up @@ -1013,7 +1017,7 @@ element is ProjectOtherwiseElement
}

implicitImports.Add(ProjectImportElement.CreateImplicit("Sdk.props", currentProjectOrImport, ImplicitImportLocation.Top, sdkName));

implicitImports.Add(ProjectImportElement.CreateImplicit("Sdk.targets", currentProjectOrImport, ImplicitImportLocation.Bottom, sdkName));
}
}
Expand Down Expand Up @@ -1627,7 +1631,7 @@ private void EvaluatePropertyElement(ProjectPropertyElement propertyElement)

string evaluatedValue = _expander.ExpandIntoStringLeaveEscaped(propertyElement.Value, ExpanderOptions.ExpandProperties, propertyElement.Location);

// If we are goign to set a property to a value other than null or empty we need to check to see if it has been used
// If we are going to set a property to a value other than null or empty we need to check to see if it has been used
// during evaluation.
if (evaluatedValue.Length > 0 && _expander.WarnForUninitializedProperties)
{
Expand All @@ -1649,6 +1653,11 @@ private void EvaluatePropertyElement(ProjectPropertyElement propertyElement)

P property = _data.SetProperty(propertyElement, evaluatedValue, predecessor);

if (predecessor != null)
{
LogPropertyReassignment(predecessor, property, propertyElement.Location.LocationString);
}

#if FEATURE_MSBUILD_DEBUGGER
if (DebuggerManager.DebuggingEnabled)
{
Expand All @@ -1657,6 +1666,24 @@ private void EvaluatePropertyElement(ProjectPropertyElement propertyElement)
#endif
}

private void LogPropertyReassignment(P predecessor, P property, string location)
{
string newValue = property.EvaluatedValue;
string oldValue = predecessor.EvaluatedValue;

if (newValue != oldValue)
{
_loggingService.LogComment(
_buildEventContext,
MessageImportance.Low,
"PropertyReassignment",
property.Name,
newValue,
oldValue,
location);
}
}

private void EvaluateItemElement(bool itemGroupConditionResult, ProjectItemElement itemElement, LazyItemEvaluator<P, I, M, D> lazyEvaluator)
{
#if FEATURE_MSBUILD_DEBUGGER
Expand Down Expand Up @@ -2290,7 +2317,7 @@ private List<ProjectRootElement> ExpandAndLoadImports(string directoryOfImportin
{
project = Path.Combine(BuildEnvironmentHelper.Instance.MSBuildSDKsPath, importElement.Sdk, "Sdk", project);
}


var newExpandedImportPath = project.Replace(extensionPropertyRefAsString, extensionPathExpanded);
_loggingService.LogComment(_buildEventContext, MessageImportance.Low, "TryingExtensionsPath", newExpandedImportPath, extensionPathExpanded);
Expand Down Expand Up @@ -2351,7 +2378,7 @@ private List<ProjectRootElement> ExpandAndLoadImports(string directoryOfImportin
/// requests can be satisfied without re-parsing it.
/// </summary>
private LoadImportsResult ExpandAndLoadImportsFromUnescapedImportExpressionConditioned(string directoryOfImportingFile, ProjectImportElement importElement, string unescapedExpression,
out List<ProjectRootElement> projects, bool throwOnFileNotExistsError=true)
out List<ProjectRootElement> projects, bool throwOnFileNotExistsError = true)
{
if (!EvaluateConditionCollectingConditionedProperties(importElement, ExpanderOptions.ExpandProperties, ParserOptions.AllowProperties, _projectRootElementCache))
{
Expand Down Expand Up @@ -2490,7 +2517,7 @@ private LoadImportsResult ExpandAndLoadImportsFromUnescapedImportExpression(stri
importFileUnescaped,
new ReadOnlyConvertingDictionary<string, ProjectPropertyInstance, string>(
_data.GlobalPropertiesDictionary,
instance => ((IProperty) instance).EvaluatedValueEscaped),
instance => ((IProperty)instance).EvaluatedValueEscaped),
_data.ExplicitToolsVersion,
_loggingService,
_projectRootElementCache,
Expand Down Expand Up @@ -2768,7 +2795,7 @@ private void ThrowForImportedProjectWithSearchPathsNotFound(ProjectImportPathMat
private static string StringifyList(IList<string> strings)
{
var sb = new StringBuilder();
for (int i = 0; i < strings.Count - 1; i ++)
for (int i = 0; i < strings.Count - 1; i++)
{
if (i > 0)
{
Expand Down
9 changes: 9 additions & 0 deletions src/Build/Resources/Strings.resx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -339,6 +339,12 @@
<data name="ErrorWarningMessageNotSupported" UESanitized="false" Visibility="Public">
<value>The &lt;{0}&gt; tag is no longer supported as a child of the &lt;Project&gt; element. Place this tag within a target, and add the name of the target to the "InitialTargets" attribute of the &lt;Project&gt; element.</value>
</data>
<data name="EvaluationStarted" UESanitized="false" Visibility="Public">
<value>Evaluation started ("{0}")</value>
</data>
<data name="EvaluationFinished" UESanitized="false" Visibility="Public">
<value>Evaluation finished ("{0}")</value>
</data>
<data name="ExecutingTaskInTaskHost">
<value>Launching task "{0}" from assembly "{1}" in an external task host with a runtime of "{2}" and a process architecture of "{3}".</value>
</data>
Expand Down Expand Up @@ -740,6 +746,9 @@
<value>MSB4148: The name of a property stored under the registry key "{0}" has zero length.</value>
<comment>{StrBegin="MSB4148: "}</comment>
</data>
<data name="PropertyReassignment" UESanitized="false" Visibility="Public">
<value>Property reassignment: $({0})="{1}" (previous value: "{2}") at {3}</value>
</data>
<data name="QualifiedMetadataInTransformNotAllowed" UESanitized="false" Visibility="Public">
<value>MSB4043: The item metadata reference "{0}" is invalid because it is qualified with an item name. Item metadata referenced in transforms do not need to be qualified, because the item name is automatically deduced from the items being transformed. Change "{0}" to "%({1})".</value>
<comment>{StrBegin="MSB4043: "}UE: This message is shown when the user does something like this: @(foo->'%(foo.metadata)'). There is no need to specify
Expand Down

0 comments on commit 21eeb45

Please sign in to comment.