|
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
using System;
using System.Collections;
using System.Collections.Generic;
using System.Globalization;
using System.Linq;
using Microsoft.Build.Evaluation;
using Microsoft.Build.Framework;
using Microsoft.Build.Shared;
using ColorResetter = Microsoft.Build.Logging.ColorResetter;
using ColorSetter = Microsoft.Build.Logging.ColorSetter;
using WriteHandler = Microsoft.Build.Logging.WriteHandler;
#nullable disable
namespace Microsoft.Build.BackEnd.Logging
{
/// <summary>
/// This class implements the default logger that outputs event data
/// to the console (stdout).
/// </summary>
/// <remarks>This class is not thread safe.</remarks>
internal class ParallelConsoleLogger : BaseConsoleLogger
{
/// <summary>
/// Associate a (nodeID and project_context_id) to a target framework.
/// </summary>
internal Dictionary<(int nodeId, int contextId), string> propertyOutputMap = new Dictionary<(int nodeId, int contextId), string>();
#region Constructors
/// <summary>
/// Default constructor.
/// </summary>
public ParallelConsoleLogger()
: this(LoggerVerbosity.Normal)
{
// do nothing
}
/// <summary>
/// Create a logger instance with a specific verbosity. This logs to
/// the default console.
/// </summary>
public ParallelConsoleLogger(LoggerVerbosity verbosity)
:
this
(
verbosity,
new WriteHandler(Console.Out.Write),
new ColorSetter(SetColor),
new ColorResetter(ResetColor))
{
// do nothing
}
/// <summary>
/// Initializes the logger, with alternate output handlers.
/// </summary>
public ParallelConsoleLogger(
LoggerVerbosity verbosity,
WriteHandler write,
ColorSetter colorSet,
ColorResetter colorReset)
{
InitializeConsoleMethods(verbosity, write, colorSet, colorReset);
_deferredMessages = new Dictionary<BuildEventContext, List<BuildMessageEventArgs>>(s_compareContextNodeId);
_buildEventManager = new BuildEventManager();
}
/// <summary>
/// Check to see if the console is going to a char output such as a console,printer or com port, or if it going to a file
/// </summary>
private void CheckIfOutputSupportsAlignment()
{
_alignMessages = false;
_bufferWidth = -1;
// If forceNoAlign is set there is no point getting the console width as there will be no aligning of the text
if (!_forceNoAlign)
{
if (runningWithCharacterFileType)
{
// Get the size of the console buffer so messages can be formatted to the console width
try
{
_bufferWidth = ConsoleConfiguration.BufferWidth;
_alignMessages = true;
}
catch (Exception)
{
// on Win8 machines while in IDE Console.BufferWidth will throw (while it talks to native console it gets "operation aborted" native error)
// this is probably temporary workaround till we understand what is the reason for that exception
_alignMessages = false;
}
}
else
{
_alignMessages = false;
}
}
_consoleOutputAligner = new ConsoleOutputAligner(_bufferWidth, _alignMessages, (IStringBuilderProvider)this);
}
#endregion
#region Methods
/// <summary>
/// Allows the logger to take action based on a parameter passed on when initializing the logger
/// </summary>
internal override bool ApplyParameter(string parameterName, string parameterValue)
{
if (base.ApplyParameter(parameterName, parameterValue))
{
return true;
}
if (String.Equals(parameterName, "SHOWCOMMANDLINE", StringComparison.OrdinalIgnoreCase))
{
if (String.IsNullOrEmpty(parameterValue))
{
_showCommandLine = true;
}
else
{
try
{
_showCommandLine = ConversionUtilities.ConvertStringToBool(parameterValue);
}
catch (ArgumentException)
{
// For compatibility, if the string is not a boolean, just ignore it
_showCommandLine = false;
}
}
return true;
}
else if (String.Equals(parameterName, "SHOWTIMESTAMP", StringComparison.OrdinalIgnoreCase))
{
_showTimeStamp = true;
return true;
}
else if (String.Equals(parameterName, "SHOWEVENTID", StringComparison.OrdinalIgnoreCase))
{
_showEventId = true;
return true;
}
else if (String.Equals(parameterName, "FORCENOALIGN", StringComparison.OrdinalIgnoreCase))
{
_forceNoAlign = true;
_alignMessages = false;
return true;
}
return false;
}
public override void Initialize(IEventSource eventSource)
{
// If the logger is being used in singleproc do not show EventId after each message unless it is set as part of a console parameter
if (NumberOfProcessors == 1)
{
_showEventId = false;
}
// Parameters are parsed in Initialize
base.Initialize(eventSource);
CheckIfOutputSupportsAlignment();
}
/// <summary>
/// Keep track of the last event displayed so target names can be displayed at the correct time
/// </summary>
private void ShownBuildEventContext(BuildEventContext e)
{
_lastDisplayedBuildEventContext = e;
}
/// <summary>
/// Reset the states of per-build member variables
/// VSW#516376
/// </summary>
internal override void ResetConsoleLoggerState()
{
if (ShowSummary == true)
{
errorList = new List<BuildErrorEventArgs>();
warningList = new List<BuildWarningEventArgs>();
}
else
{
errorList = null;
warningList = null;
}
errorCount = 0;
warningCount = 0;
projectPerformanceCounters = null;
targetPerformanceCounters = null;
taskPerformanceCounters = null;
_hasBuildStarted = false;
// Reset the data structures created when the logger was created
propertyOutputMap = new Dictionary<(int, int), string>();
_buildEventManager = new BuildEventManager();
_deferredMessages = new Dictionary<BuildEventContext, List<BuildMessageEventArgs>>(s_compareContextNodeId);
_prefixWidth = 0;
_lastDisplayedBuildEventContext = null;
}
/// <summary>
/// Handler for build started events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void BuildStartedHandler(object sender, BuildStartedEventArgs e)
{
buildStarted = e.Timestamp;
_hasBuildStarted = true;
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
WriteLinePrettyFromResource("BuildStartedWithTime", e.Timestamp);
}
if (Traits.LogAllEnvironmentVariables)
{
WriteEnvironment(e.BuildEnvironment);
}
else
{
WriteEnvironment(e.BuildEnvironment?.Where(kvp => EnvironmentUtilities.IsWellKnownEnvironmentDerivedProperty(kvp.Key)).ToDictionary(kvp => kvp.Key, kvp => kvp.Value));
}
}
/// <summary>
/// Handler for build finished events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void BuildFinishedHandler(object sender, BuildFinishedEventArgs e)
{
// If for some reason we have deferred messages at the end of the build they should be displayed
// so that the reason why they are still buffered can be determined.
if (!showOnlyErrors && !showOnlyWarnings && _deferredMessages.Count > 0)
{
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
// Print out all of the deferred messages
WriteLinePrettyFromResource("DeferredMessages");
foreach (List<BuildMessageEventArgs> messageList in _deferredMessages.Values)
{
foreach (BuildMessageEventArgs message in messageList)
{
PrintMessage(message, false);
}
}
}
}
// Show the performance summary if the verbosity is diagnostic or the user specifically asked for it
// with a logger parameter.
if (this.showPerfSummary)
{
ShowPerfSummary();
}
// Write the "Build Finished" event if verbosity is normal, detailed or diagnostic or the user
// specified to show the summary.
if (ShowSummary == true)
{
if (e.Succeeded)
{
setColor(ConsoleColor.Green);
}
// Write the "Build Finished" event.
WriteNewLine();
WriteLinePretty(e.Message);
resetColor();
}
// The decision whether or not to show a summary at this verbosity
// was made during initialization. We just do what we're told.
if (ShowSummary == true)
{
// We can't display a nice nested summary unless we're at Normal or above,
// since we need to have gotten TargetStarted events, which aren't forwarded otherwise.
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
ShowNestedErrorWarningSummary();
}
else
{
ShowFlatErrorWarningSummary();
}
// Emit text like:
// 1 Warning(s)
// 0 Error(s)
// Don't color the line if it's zero. (Per Whidbey behavior.)
if (warningCount > 0)
{
setColor(ConsoleColor.Yellow);
}
WriteLinePrettyFromResource(2, "WarningCount", warningCount);
resetColor();
if (errorCount > 0)
{
setColor(ConsoleColor.Red);
}
WriteLinePrettyFromResource(2, "ErrorCount", errorCount);
resetColor();
}
// Show build time if verbosity is normal, detailed or diagnostic or the user specified to
// show the summary.
if (ShowSummary == true)
{
// The time elapsed is the difference between when the BuildStartedEventArg
// was created and when the BuildFinishedEventArg was created
string timeElapsed = LogFormatter.FormatTimeSpan(e.Timestamp - buildStarted);
WriteNewLine();
WriteLinePrettyFromResource("TimeElapsed", timeElapsed);
}
ResetConsoleLoggerState();
CheckIfOutputSupportsAlignment();
}
/// <summary>
/// At the end of the build, repeats the errors and warnings that occurred
/// during the build, and displays the error count and warning count.
/// Does this in a "flat" style, without context.
/// </summary>
private void ShowFlatErrorWarningSummary()
{
if (warningList.Count == 0 && errorList.Count == 0)
{
return;
}
// If we're showing only warnings and/or errors, don't summarize.
// This is the buildc.err case. There's no point summarizing since we'd just
// repeat the entire log content again.
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
// Make some effort to distinguish this summary from the output above, since otherwise
// it's not clear in lower verbosities
WriteNewLine();
if (warningList.Count > 0)
{
setColor(ConsoleColor.Yellow);
foreach (BuildWarningEventArgs warning in warningList)
{
WriteMessageAligned(EventArgsFormatting.FormatEventMessage(warning, showProjectFile, FindLogOutputProperties(warning)), true);
}
}
if (errorList.Count > 0)
{
setColor(ConsoleColor.Red);
foreach (BuildErrorEventArgs error in errorList)
{
WriteMessageAligned(EventArgsFormatting.FormatEventMessage(error, showProjectFile, FindLogOutputProperties(error)), true);
}
}
resetColor();
}
/// <summary>
/// At the end of the build, repeats the errors and warnings that occurred
/// during the build, and displays the error count and warning count.
/// Does this in a "nested" style.
/// </summary>
private void ShowNestedErrorWarningSummary()
{
if (warningList.Count == 0 && errorList.Count == 0)
{
return;
}
// If we're showing only warnings and/or errors, don't summarize.
// This is the buildc.err case. There's no point summarizing since we'd just
// repeat the entire log content again.
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
if (warningCount > 0)
{
setColor(ConsoleColor.Yellow);
ShowErrorWarningSummary(warningList);
}
if (errorCount > 0)
{
setColor(ConsoleColor.Red);
ShowErrorWarningSummary(errorList);
}
resetColor();
}
private void ShowErrorWarningSummary(IEnumerable<BuildEventArgs> listToProcess)
{
// Group the build warning event args based on the entry point and the target in which the warning occurred
var groupByProjectEntryPoint = new Dictionary<ErrorWarningSummaryDictionaryKey, List<BuildEventArgs>>();
// Loop through each of the warnings and put them into the correct buckets
foreach (BuildEventArgs errorWarningEventArgs in listToProcess)
{
// Target event may be null for a couple of reasons:
// 1) If the event was from a project load, or engine
// 2) If the flushing of the event queue for each request and result is turned off
// as this could cause errors and warnings to be seen by the logger after the target finished event
// which would cause the error or warning to have no matching target started event as they are removed
// when a target finished event is logged.
// 3) On NORMAL verbosity if the error or warning occurs in a project load then the error or warning and the target started event will be forwarded to
// different forwarding loggers which cannot communicate to each other, meaning there will be no matching target started event logged
// as the forwarding logger did not know to forward the target started event
string targetName = null;
TargetStartedEventMinimumFields targetEvent = _buildEventManager.GetTargetStartedEvent(errorWarningEventArgs.BuildEventContext);
if (targetEvent != null)
{
targetName = targetEvent.TargetName;
}
// Create a new key from the error event context and the target where the error happened
ErrorWarningSummaryDictionaryKey key = new ErrorWarningSummaryDictionaryKey(errorWarningEventArgs.BuildEventContext, targetName);
// Check to see if there is a bucket for the warning
// If there is no bucket create a new one which contains a list of all the errors which
// happened for a given buildEventContext / target
if (!groupByProjectEntryPoint.TryGetValue(key, out var errorWarningEventListByTarget))
{
// happened for a given buildEventContext / target
errorWarningEventListByTarget = new List<BuildEventArgs>();
groupByProjectEntryPoint.Add(key, errorWarningEventListByTarget);
}
// Add the error event to the correct bucket
errorWarningEventListByTarget.Add(errorWarningEventArgs);
}
BuildEventContext previousEntryPoint = null;
string previousTarget = null;
// Loop through each of the bucket and print out the stack trace information for the errors
foreach (KeyValuePair<ErrorWarningSummaryDictionaryKey, List<BuildEventArgs>> valuePair in groupByProjectEntryPoint)
{
// If the project entry point where the error occurred is the same as the previous message do not print the
// stack trace again
if (previousEntryPoint != valuePair.Key.EntryPointContext)
{
WriteNewLine();
foreach (string s in _buildEventManager.ProjectCallStackFromProject(valuePair.Key.EntryPointContext))
{
WriteMessageAligned(s, false);
}
previousEntryPoint = valuePair.Key.EntryPointContext;
}
// If the target where the error occurred is the same as the previous message do not print the location
// where the error occurred again
if (!String.Equals(previousTarget, valuePair.Key.TargetName, StringComparison.OrdinalIgnoreCase))
{
// If no targetName was specified then do not show the target where the error occurred
if (!string.IsNullOrEmpty(valuePair.Key.TargetName))
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ErrorWarningInTarget", valuePair.Key.TargetName), false);
}
previousTarget = valuePair.Key.TargetName;
}
// Print out all of the errors under the ProjectEntryPoint / target
foreach (BuildEventArgs errorWarningEvent in valuePair.Value)
{
if (errorWarningEvent is BuildErrorEventArgs buildErrorEventArgs)
{
WriteMessageAligned(" " + EventArgsFormatting.FormatEventMessage(buildErrorEventArgs, showProjectFile, FindLogOutputProperties(errorWarningEvent)), false);
}
else if (errorWarningEvent is BuildWarningEventArgs buildWarningEventArgs)
{
WriteMessageAligned(" " + EventArgsFormatting.FormatEventMessage(buildWarningEventArgs, showProjectFile, FindLogOutputProperties(errorWarningEvent)), false);
}
}
WriteNewLine();
}
}
/// <summary>
/// Handler for project started events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void ProjectStartedHandler(object sender, ProjectStartedEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
ErrorUtilities.VerifyThrowArgumentNull(e.ParentProjectBuildEventContext, "ParentProjectBuildEventContext");
// Add the project to the BuildManager so we can use the start information later in the build process
_buildEventManager.AddProjectStartedEvent(e, _showTimeStamp || IsVerbosityAtLeast(LoggerVerbosity.Detailed));
if (this.showPerfSummary)
{
// Create a new project performance counter for this project
MPPerformanceCounter counter = GetPerformanceCounter(e.ProjectFile, ref projectPerformanceCounters);
counter.AddEventStarted(e.TargetNames, e.BuildEventContext, e.Timestamp, s_compareContextNodeId);
}
// If there were deferred messages then we should show them now, this will cause the project started event to be shown properly
if (_deferredMessages.TryGetValue(e.BuildEventContext, out var deferredMessages))
{
if (!showOnlyErrors && !showOnlyWarnings)
{
foreach (BuildMessageEventArgs message in deferredMessages)
{
// This will display the project started event before the messages is shown
this.MessageHandler(sender, message);
}
}
_deferredMessages.Remove(e.BuildEventContext);
}
// If we are in diagnostic and are going to show items, show the project started event
// along with the items. The project started event will only be shown if it has not been shown before
if (Verbosity == LoggerVerbosity.Diagnostic && showItemAndPropertyList)
{
// Show the deferredProjectStartedEvent
if (!showOnlyErrors && !showOnlyWarnings)
{
DisplayDeferredProjectStartedEvent(e.BuildEventContext);
}
if (e.Properties != null)
{
WriteProperties(e, e.Properties);
}
if (e.Items != null)
{
WriteItems(e, e.Items);
}
}
var projectKey = (e.BuildEventContext.NodeId, e.BuildEventContext.ProjectContextId);
// If the value is available at all, it will be either in the items
// from ProjectStarted (old behavior), or the items from ProjectEvaluationFinished (new behavior).
// First try the old behavior, and fallback to the new behavior.
var result = ReadProjectConfigurationDescription(e.Items);
if (result != null)
{
// Found the items directly on ProjectStarted
propertyOutputMap[projectKey] = result;
}
else
{
// Try to see if we saw the items on the corresponding ProjectEvaluationFinished
var evaluationKey = GetEvaluationKey(e.BuildEventContext);
// if the value was set from ProjectEvaluationFinished, copy it into the entry
// for this project
if (propertyOutputMap.TryGetValue(evaluationKey, out string value))
{
propertyOutputMap[projectKey] = value;
}
}
}
private string ReadProjectConfigurationDescription(IEnumerable items)
{
if (items == null)
{
return null;
}
ReuseableStringBuilder projectConfigurationDescription = null;
bool descriptionEmpty = true;
Internal.Utilities.EnumerateItems(items, item =>
{
// Determine if the LogOutputProperties item has been used.
if (string.Equals((string)item.Key, ItemMetadataNames.ProjectConfigurationDescription, StringComparison.OrdinalIgnoreCase))
{
if (projectConfigurationDescription == null)
{
projectConfigurationDescription = new ReuseableStringBuilder();
}
string itemSpec = item.Value switch
{
IItem iitem => iitem.EvaluatedInclude, // ProjectItem
ITaskItem taskItem => taskItem.ItemSpec, // ProjectItemInstance
_ => throw new NotSupportedException(Convert.ToString(item.Value))
};
// Add the item value to the string to be printed in error/warning messages.
if (!descriptionEmpty)
{
projectConfigurationDescription.Append(" ");
}
projectConfigurationDescription.Append(itemSpec);
descriptionEmpty = false;
}
});
if (projectConfigurationDescription != null)
{
var result = projectConfigurationDescription.ToString();
(projectConfigurationDescription as IDisposable)?.Dispose();
return result;
}
return null;
}
/// <summary>
/// In case the items are stored on ProjectEvaluationFinishedEventArgs
/// (new behavior), we first store the value per evaluation, and then
/// in ProjectStarted, find the value from the project's evaluation
/// and use that.
/// </summary>
private (int, int) GetEvaluationKey(BuildEventContext buildEventContext)
// note that we use a negative number for evaluations so that we don't conflict
// with project context ids.
=> (buildEventContext.NodeId, -buildEventContext.EvaluationId);
/// <summary>
/// Handler for project finished events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void ProjectFinishedHandler(object sender, ProjectFinishedEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
// Get the project started event so we can use its information to properly display a project finished event
ProjectStartedEventMinimumFields startedEvent = _buildEventManager.GetProjectStartedEvent(e.BuildEventContext);
ErrorUtilities.VerifyThrow(startedEvent != null, "Project finished event for {0} received without matching start event", e.ProjectFile);
if (this.showPerfSummary)
{
// Stop the performance counter which was created in the project started event handler
MPPerformanceCounter counter = GetPerformanceCounter(e.ProjectFile, ref projectPerformanceCounters);
counter.AddEventFinished(startedEvent.TargetNames, e.BuildEventContext, e.Timestamp);
}
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
// Only want to show the project finished event if a project started event has been shown
if (startedEvent.ShowProjectFinishedEvent)
{
_lastProjectFullKey = GetFullProjectKey(e.BuildEventContext);
if (!showOnlyErrors && !showOnlyWarnings)
{
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
setColor(ConsoleColor.Cyan);
// In the project finished message the targets which were built and the project which was built
// should be shown
string targets = startedEvent.TargetNames;
string projectName = startedEvent.ProjectFile ?? string.Empty;
// Show which targets were built as part of this project
if (string.IsNullOrEmpty(targets))
{
if (e.Succeeded)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectFinishedPrefixWithDefaultTargetsMultiProc", projectName), true);
}
else
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectFinishedPrefixWithDefaultTargetsMultiProcFailed", projectName), true);
}
}
else
{
if (e.Succeeded)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectFinishedPrefixWithTargetNamesMultiProc", projectName, targets), true);
}
else
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectFinishedPrefixWithTargetNamesMultiProcFailed", projectName, targets), true);
}
}
// In single proc only make a space between the project done event and the next line, this
// is to increase the readability on the single proc log when there are a number of done events
// or a mix of done events and project started events. Also only do this on the console and not any log file.
if (NumberOfProcessors == 1 && runningWithCharacterFileType)
{
WriteNewLine();
}
}
ShownBuildEventContext(e.BuildEventContext);
resetColor();
}
}
// We are done with the project started event if the project has finished building, remove its reference
_buildEventManager.RemoveProjectStartedEvent(e.BuildEventContext);
}
/// <summary>
/// Writes out the list of property names and their values.
/// This could be done at any time during the build to show the latest
/// property values, using the cached reference to the list from the
/// appropriate ProjectStarted event.
/// </summary>
/// <param name="e">A <see cref="BuildEventArgs"/> object containing information about the build event.</param>
/// <param name="properties">List of properties</param>
internal void WriteProperties(BuildEventArgs e, IEnumerable properties)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
var propertyList = ExtractPropertyList(properties);
// if there are no properties to display return out of the method and dont print out anything related to displaying
// the properties, this includes the multiproc prefix information or the Initial properties header
if (propertyList.Count == 0)
{
return;
}
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
WriteProperties(propertyList);
ShownBuildEventContext(e.BuildEventContext);
}
internal override void OutputProperties(List<DictionaryEntry> list)
{
// Write the banner
setColor(ConsoleColor.Green);
WriteMessageAligned(ResourceUtilities.GetResourceString("PropertyListHeader"), true);
// Write each property name and its value, one per line
foreach (DictionaryEntry prop in list)
{
setColor(ConsoleColor.Gray);
string propertyString = String.Format(CultureInfo.CurrentCulture, "{0} = {1}", prop.Key, EscapingUtilities.UnescapeAll((string)(prop.Value)));
WriteMessageAligned(propertyString, false);
}
resetColor();
}
/// <summary>
/// Write the environment strings to the console.
/// </summary>
internal override void OutputEnvironment(IDictionary<string, string> environment)
{
// Write the banner
setColor(ConsoleColor.Green);
WriteMessageAligned(ResourceUtilities.GetResourceString("EnvironmentHeader"), true);
if (environment != null)
{
// Write each property name and its value, one per line
foreach (KeyValuePair<string, string> entry in environment)
{
setColor(ConsoleColor.Gray);
string environmentMessage = String.Format(CultureInfo.CurrentCulture, "{0} = {1}", entry.Key, entry.Value);
WriteMessageAligned(environmentMessage, false);
}
}
resetColor();
}
/// <summary>
/// Writes out the list of item specs and their metadata.
/// This could be done at any time during the build to show the latest
/// items, using the cached reference to the list from the
/// appropriate ProjectStarted event.
/// </summary>
/// <param name="e">A <see cref="BuildEventArgs"/> object containing information about the build event.</param>
/// <param name="items">List of items</param>
internal void WriteItems(BuildEventArgs e, IEnumerable items)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
SortedList itemList = ExtractItemList(items);
// If there are no Items to display return out of the method and don't print out anything related to displaying
// the items, this includes the multiproc prefix information or the Initial items header
if (itemList.Count == 0)
{
return;
}
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
WriteItems(itemList);
ShownBuildEventContext(e.BuildEventContext);
}
protected override void WriteItemType(string itemType)
{
setColor(ConsoleColor.DarkGray);
WriteMessageAligned(itemType, prefixAlreadyWritten: false);
setColor(ConsoleColor.Gray);
}
protected override void WriteItemSpec(string itemSpec)
{
WriteMessageAligned(new string(' ', 2 * tabWidth) + itemSpec, prefixAlreadyWritten: false);
}
protected override void WriteMetadata(string name, string value)
{
WriteMessageAligned($"{new string(' ', 4 * tabWidth)}{name} = {value}", prefixAlreadyWritten: false);
}
/// <summary>
/// Handler for target started events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void TargetStartedHandler(object sender, TargetStartedEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
// Add the target started information to the buildEventManager so its information can be used
// later in the build
_buildEventManager.AddTargetStartedEvent(e, _showTimeStamp || IsVerbosityAtLeast(LoggerVerbosity.Detailed));
if (this.showPerfSummary)
{
// Create a new performance counter for this target
MPPerformanceCounter counter = GetPerformanceCounter(e.TargetName, ref targetPerformanceCounters);
counter.AddEventStarted(null, e.BuildEventContext, e.Timestamp, s_compareContextNodeIdTargetId);
}
}
/// <summary>
/// Handler for target finished events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void TargetFinishedHandler(object sender, TargetFinishedEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
if (this.showPerfSummary)
{
// Stop the performance counter started in the targetStartedEventHandler
MPPerformanceCounter counter = GetPerformanceCounter(e.TargetName, ref targetPerformanceCounters);
counter.AddEventFinished(null, e.BuildEventContext, e.Timestamp);
}
if (IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
// Display the target started event arg if we have got to the target finished but have not displayed it yet.
DisplayDeferredTargetStartedEvent(e.BuildEventContext);
// Get the target started event so we can determine whether or not to show the targetFinishedEvent
// as we only want to show target finished events if a target started event has been shown
TargetStartedEventMinimumFields startedEvent = _buildEventManager.GetTargetStartedEvent(e.BuildEventContext);
ErrorUtilities.VerifyThrow(startedEvent != null, "Started event should not be null in the finished event handler");
if (startedEvent.ShowTargetFinishedEvent)
{
if (showTargetOutputs)
{
IEnumerable targetOutputs = e.TargetOutputs;
if (targetOutputs != null)
{
WriteMessageAligned(ResourceUtilities.GetResourceString("TargetOutputItemsHeader"), false);
foreach (ITaskItem item in targetOutputs)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetOutputItem", item.ItemSpec), false);
IDictionary metadata = item.CloneCustomMetadata();
foreach (DictionaryEntry metadatum in metadata)
{
WriteMessageAligned(new String(' ', 4 * tabWidth) + metadatum.Key + " = " + item.GetMetadata(metadatum.Key as string), false);
}
}
}
}
if (!showOnlyErrors && !showOnlyWarnings)
{
_lastProjectFullKey = GetFullProjectKey(e.BuildEventContext);
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
setColor(ConsoleColor.Cyan);
if (IsVerbosityAtLeast(LoggerVerbosity.Diagnostic) || _showEventId)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetMessageWithId", e.Message, e.BuildEventContext.TargetId), true);
}
else
{
WriteMessageAligned(e.Message, true);
}
resetColor();
}
ShownBuildEventContext(e.BuildEventContext);
}
}
// We no longer need this target started event, it can be removed
_buildEventManager.RemoveTargetStartedEvent(e.BuildEventContext);
}
/// <summary>
/// Handler for task started events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void TaskStartedHandler(object sender, TaskStartedEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
// if verbosity is detailed or diagnostic
if (IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
DisplayDeferredStartedEvents(e.BuildEventContext);
if (!showOnlyErrors && !showOnlyWarnings)
{
bool prefixAlreadyWritten = WriteTargetMessagePrefix(e, e.BuildEventContext, e.Timestamp);
setColor(ConsoleColor.DarkCyan);
if (IsVerbosityAtLeast(LoggerVerbosity.Diagnostic) || _showEventId)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TaskMessageWithId", e.Message, e.BuildEventContext.TaskId), prefixAlreadyWritten);
}
else
{
WriteMessageAligned(e.Message, prefixAlreadyWritten);
}
resetColor();
}
ShownBuildEventContext(e.BuildEventContext);
}
if (this.showPerfSummary)
{
// Create a new performance counter for this task
MPPerformanceCounter counter = GetPerformanceCounter(e.TaskName, ref taskPerformanceCounters);
counter.AddEventStarted(null, e.BuildEventContext, e.Timestamp, null);
}
}
/// <summary>
/// Handler for task finished events
/// </summary>
/// <param name="sender">sender (should be null)</param>
/// <param name="e">event arguments</param>
public override void TaskFinishedHandler(object sender, TaskFinishedEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
if (this.showPerfSummary)
{
// Stop the task performance counter which was started in the task started event
MPPerformanceCounter counter = GetPerformanceCounter(e.TaskName, ref taskPerformanceCounters);
counter.AddEventFinished(null, e.BuildEventContext, e.Timestamp);
}
// if verbosity is detailed or diagnostic
if (IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
if (!showOnlyErrors && !showOnlyWarnings)
{
bool prefixAlreadyWritten = WriteTargetMessagePrefix(e, e.BuildEventContext, e.Timestamp);
setColor(ConsoleColor.DarkCyan);
if (IsVerbosityAtLeast(LoggerVerbosity.Diagnostic) || _showEventId)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TaskMessageWithId", e.Message, e.BuildEventContext.TaskId), prefixAlreadyWritten);
}
else
{
WriteMessageAligned(e.Message, prefixAlreadyWritten);
}
resetColor();
}
ShownBuildEventContext(e.BuildEventContext);
}
}
/// <summary>
/// Finds the LogOutProperty string to be printed in messages.
/// </summary>
/// <param name="e">Build event to extract context information from.</param>
internal string FindLogOutputProperties(BuildEventArgs e)
{
string projectConfigurationDescription = String.Empty;
if (e.BuildEventContext != null)
{
var key = (e.BuildEventContext.NodeId, e.BuildEventContext.ProjectContextId);
propertyOutputMap.TryGetValue(key, out projectConfigurationDescription);
}
return projectConfigurationDescription;
}
/// <summary>
/// Prints an error event
/// </summary>
public override void ErrorHandler(object sender, BuildErrorEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
// Keep track of the number of error events raised
errorCount++;
// If there is an error we need to walk up the call stack and make sure that
// the project started events back to the root project know an error has occurred
// and are not removed when they finish
_buildEventManager.SetErrorWarningFlagOnCallStack(e.BuildEventContext);
TargetStartedEventMinimumFields targetStartedEvent = _buildEventManager.GetTargetStartedEvent(e.BuildEventContext);
// Can be null if the error occurred outside of a target, or the error occurred before the targetStartedEvent
if (targetStartedEvent != null)
{
targetStartedEvent.ErrorInTarget = true;
}
DisplayDeferredStartedEvents(e.BuildEventContext);
// Display only if showOnlyWarnings is false;
// unless showOnlyErrors is true, which trumps it.
if (!showOnlyWarnings || showOnlyErrors)
{
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
}
setColor(ConsoleColor.Red);
WriteMessageAligned(EventArgsFormatting.FormatEventMessage(e, showProjectFile, FindLogOutputProperties(e)), true);
ShownBuildEventContext(e.BuildEventContext);
if (ShowSummary == true)
{
if (!errorList.Contains(e))
{
errorList.Add(e);
}
}
resetColor();
}
}
/// <summary>
/// Prints a warning event
/// </summary>
public override void WarningHandler(object sender, BuildWarningEventArgs e)
{
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
// Keep track of the number of warning events raised during the build
warningCount++;
// If there is a warning we need to walk up the call stack and make sure that
// the project started events back to the root project know a warning has occurred
// and are not removed when they finish
_buildEventManager.SetErrorWarningFlagOnCallStack(e.BuildEventContext);
TargetStartedEventMinimumFields targetStartedEvent = _buildEventManager.GetTargetStartedEvent(e.BuildEventContext);
// Can be null if the error occurred outside of a target, or the error occurs before the targetStartedEvent
if (targetStartedEvent != null)
{
targetStartedEvent.ErrorInTarget = true;
}
DisplayDeferredStartedEvents(e.BuildEventContext);
// Display only if showOnlyErrors is false;
// unless showOnlyWarnings is true, which trumps it.
if (!showOnlyErrors || showOnlyWarnings)
{
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
}
setColor(ConsoleColor.Yellow);
WriteMessageAligned(EventArgsFormatting.FormatEventMessage(e, showProjectFile, FindLogOutputProperties(e)), true);
}
ShownBuildEventContext(e.BuildEventContext);
if (ShowSummary == true)
{
if (!warningList.Contains(e))
{
warningList.Add(e);
}
}
resetColor();
}
/// <summary>
/// Prints a message event
/// </summary>
public override void MessageHandler(object sender, BuildMessageEventArgs e)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
if (e.BuildEventContext == null && e is AssemblyLoadBuildEventArgs)
{
return;
}
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
bool print = false;
bool lightenText = false;
if (e is TaskCommandLineEventArgs)
{
if ((_showCommandLine.HasValue && !_showCommandLine.Value) || (!_showCommandLine.HasValue && !IsVerbosityAtLeast(LoggerVerbosity.Normal)))
{
return;
}
print = true;
}
else
{
LoggerVerbosity minimumVerbosity = ImportanceToMinimumVerbosity(e.Importance, out lightenText);
print = IsVerbosityAtLeast(minimumVerbosity);
}
if (print)
{
// If the event has a valid Project contextId but the project started event has not been fired, the message needs to be
// buffered until the project started event is fired
if (
_hasBuildStarted
&& e.BuildEventContext.ProjectContextId != BuildEventContext.InvalidProjectContextId
&& _buildEventManager.GetProjectStartedEvent(e.BuildEventContext) == null
&& IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
if (!_deferredMessages.TryGetValue(e.BuildEventContext, out List<BuildMessageEventArgs> messageList))
{
messageList = new List<BuildMessageEventArgs>();
_deferredMessages.Add(e.BuildEventContext, messageList);
}
messageList.Add(e);
return;
}
DisplayDeferredStartedEvents(e.BuildEventContext);
// Print the message event out to the console
PrintMessage(e, lightenText);
ShownBuildEventContext(e.BuildEventContext);
}
}
public override void StatusEventHandler(object sender, BuildStatusEventArgs e)
{
if (e is ProjectEvaluationStartedEventArgs projectEvaluationStarted)
{
if (showPerfSummary)
{
MPPerformanceCounter counter = GetPerformanceCounter(projectEvaluationStarted.ProjectFile, ref projectEvaluationPerformanceCounters);
counter.AddEventStarted(null, e.BuildEventContext, e.Timestamp, s_compareContextNodeId);
}
}
else if (e is ProjectEvaluationFinishedEventArgs projectEvaluationFinished)
{
if (showPerfSummary)
{
MPPerformanceCounter counter = GetPerformanceCounter(projectEvaluationFinished.ProjectFile, ref projectEvaluationPerformanceCounters);
counter.AddEventFinished(null, e.BuildEventContext, e.Timestamp);
}
if (Verbosity == LoggerVerbosity.Diagnostic && showItemAndPropertyList)
{
if (projectEvaluationFinished.Properties != null)
{
WriteProperties(projectEvaluationFinished, projectEvaluationFinished.Properties);
}
if (projectEvaluationFinished.Items != null)
{
WriteItems(projectEvaluationFinished, projectEvaluationFinished.Items);
}
}
var value = ReadProjectConfigurationDescription(projectEvaluationFinished.Items);
if (value != null)
{
var evaluationKey = GetEvaluationKey(e.BuildEventContext);
propertyOutputMap[evaluationKey] = value;
}
}
else if (e is BuildCanceledEventArgs buildCanceled)
{
Console.WriteLine(e.Message);
}
}
private void DisplayDeferredStartedEvents(BuildEventContext e)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
// Display any project started events which were deferred until a visible
// message from their project is displayed
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
DisplayDeferredProjectStartedEvent(e);
}
// Display any target started events which were deferred until a visible
// message from their target is displayed
if (IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
DisplayDeferredTargetStartedEvent(e);
}
}
/// <summary>
/// Prints out a message event to the console
/// </summary>
private void PrintMessage(BuildMessageEventArgs e, bool lightenText)
{
string nonNullMessage = null;
if (e is EnvironmentVariableReadEventArgs environmentPropertyReadEventArgs)
{
nonNullMessage = ResourceUtilities.FormatResourceStringIgnoreCodeAndKeyword("EnvironmentDerivedPropertyRead", environmentPropertyReadEventArgs.EnvironmentVariableName, e.Message);
}
// Include file information if present.
if (e.File != null)
{
nonNullMessage = EventArgsFormatting.FormatEventMessage(e, showProjectFile, FindLogOutputProperties(e), nonNullMessage);
}
else
{
nonNullMessage ??= e.Message ?? string.Empty;
}
int prefixAdjustment = 0;
// Do not include prefixAdjustment if TaskId is invalid or file information is present.
// We want messages with file information to appear aligned with warning and error messages.
if (e.BuildEventContext.TaskId != BuildEventContext.InvalidTaskId && e.File == null)
{
prefixAdjustment = 2;
}
if (lightenText)
{
setColor(ConsoleColor.DarkGray);
}
PrintTargetNamePerMessage(e, lightenText);
// On diagnostic or if showEventId is set the task message should also display the taskId to assist debugging
if ((IsVerbosityAtLeast(LoggerVerbosity.Diagnostic) || _showEventId) && e.BuildEventContext.TaskId != BuildEventContext.InvalidTaskId)
{
bool prefixAlreadyWritten = WriteTargetMessagePrefix(e, e.BuildEventContext, e.Timestamp);
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TaskMessageWithId", nonNullMessage, e.BuildEventContext.TaskId), prefixAlreadyWritten, prefixAdjustment);
}
else
{
// A time stamp may be shown on verbosities lower than diagnostic
if (_showTimeStamp || IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
bool prefixAlreadyWritten = WriteTargetMessagePrefix(e, e.BuildEventContext, e.Timestamp);
WriteMessageAligned(nonNullMessage, prefixAlreadyWritten, prefixAdjustment);
}
else
{
WriteMessageAligned(nonNullMessage, false, prefixAdjustment);
}
}
if (lightenText)
{
resetColor();
}
}
private void PrintTargetNamePerMessage(BuildMessageEventArgs e, bool lightenText)
{
if (IsVerbosityAtLeast(LoggerVerbosity.Normal))
{
// Event Context of the current message
BuildEventContext currentBuildEventContext = e.BuildEventContext;
// Should the target name be written before the message
bool writeTargetName = false;
string targetName = string.Empty;
// Does the context (Project, Node, Context, Target, NOT task) of the previous event match the current message
bool contextAreEqual = s_compareContextNodeIdTargetId.Equals(currentBuildEventContext, _lastDisplayedBuildEventContext);
TargetStartedEventMinimumFields targetStartedEvent = null;
// If the previous event does not have the same target context information, the target name needs to be printed to the console
// to give the message some more contextual information
if (!contextAreEqual)
{
targetStartedEvent = _buildEventManager.GetTargetStartedEvent(currentBuildEventContext);
// Some messages such as engine messages will not have a target started event, in their case, dont print the targetName
if (targetStartedEvent != null)
{
targetName = targetStartedEvent.TargetName;
writeTargetName = true;
}
}
if (writeTargetName)
{
bool prefixAlreadyWritten = WriteTargetMessagePrefix(e, targetStartedEvent.ProjectBuildEventContext, targetStartedEvent.TimeStamp);
setColor(ConsoleColor.Cyan);
if (IsVerbosityAtLeast(LoggerVerbosity.Diagnostic) || _showEventId)
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetMessageWithId", targetName, e.BuildEventContext.TargetId), prefixAlreadyWritten);
}
else
{
WriteMessageAligned(targetName + ":", prefixAlreadyWritten);
}
if (lightenText)
{
setColor(ConsoleColor.DarkGray);
}
else
{
resetColor();
}
}
}
}
private bool WriteTargetMessagePrefix(BuildEventArgs e, BuildEventContext context, DateTime timeStamp)
{
bool prefixAlreadyWritten = true;
ProjectFullKey currentProjectFullKey = GetFullProjectKey(e.BuildEventContext);
if (!_lastProjectFullKey.Equals(currentProjectFullKey))
{
// Write the prefix information about the target for the message
WriteLinePrefix(context, timeStamp, false);
_lastProjectFullKey = currentProjectFullKey;
}
else
{
prefixAlreadyWritten = false;
}
return prefixAlreadyWritten;
}
/// <summary>
/// Writes a message to the console, aligned and formatted to fit within the console width
/// </summary>
/// <param name="message">Message to be formatted to fit on the console</param>
/// <param name="prefixAlreadyWritten">Has the prefix(timestamp or key been written)</param>
private void WriteMessageAligned(string message, bool prefixAlreadyWritten)
{
WriteMessageAligned(message, prefixAlreadyWritten, 0);
}
/// <summary>
/// Writes a message to the console, aligned and formatted to fit within the console width
/// </summary>
/// <param name="message">Message to be formatted to fit on the console</param>
/// <param name="prefixAlreadyWritten">Has the prefix(timestamp or key been written)</param>
/// <param name="prefixAdjustment">An amount to adjust the prefix by.</param>
private void WriteMessageAligned(string message, bool prefixAlreadyWritten, int prefixAdjustment)
{
// This method may require the splitting of lines in order to format them to the console; this must be an atomic operation
lock (_lockObject)
{
int adjustedPrefixWidth = _prefixWidth + prefixAdjustment;
WriteHandler(_consoleOutputAligner.AlignConsoleOutput(message, prefixAlreadyWritten, adjustedPrefixWidth));
}
}
/// <summary>
/// Write message taking into account whether or not the prefix (timestamp and key) have already been written on the line
/// </summary>
private void WriteBasedOnPrefix(string nonNullMessage, bool prefixAlreadyWritten, int adjustedPrefixWidth)
{
if (prefixAlreadyWritten)
{
WriteHandler(nonNullMessage + Environment.NewLine);
}
else
{
// No prefix info has been written, indent the line to the proper location
WriteHandler(IndentString(nonNullMessage, adjustedPrefixWidth));
}
}
/// <summary>
/// Will display the target started event which was deferred until the first visible message for the target is ready to be displayed
/// </summary>
private void DisplayDeferredTargetStartedEvent(BuildEventContext e)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
// Get the deferred target started event
TargetStartedEventMinimumFields targetStartedEvent = _buildEventManager.GetTargetStartedEvent(e);
// Make sure we have not shown the event before
if (targetStartedEvent?.ShowTargetFinishedEvent == false)
{
// Since the target started event has been shows, the target finished event should also be shown
targetStartedEvent.ShowTargetFinishedEvent = true;
// If there are any other started events waiting and we are the first message, show them
DisplayDeferredStartedEvents(targetStartedEvent.ProjectBuildEventContext);
WriteLinePrefix(targetStartedEvent.ProjectBuildEventContext, targetStartedEvent.TimeStamp, false);
setColor(ConsoleColor.Cyan);
ProjectStartedEventMinimumFields startedEvent = _buildEventManager.GetProjectStartedEvent(e);
ErrorUtilities.VerifyThrow(startedEvent != null, "Project Started should not be null in deferred target started");
string currentProjectFile = startedEvent.ProjectFile ?? string.Empty;
string targetName;
if (IsVerbosityAtLeast(LoggerVerbosity.Diagnostic) || _showEventId)
{
targetName = ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetMessageWithId", targetStartedEvent.TargetName, targetStartedEvent.ProjectBuildEventContext.TargetId);
}
else
{
targetName = targetStartedEvent.TargetName;
}
if (IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
if (String.Equals(currentProjectFile, targetStartedEvent.TargetFile, StringComparison.OrdinalIgnoreCase))
{
if (!String.IsNullOrEmpty(targetStartedEvent.ParentTarget))
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetStartedProjectDepends", targetName, currentProjectFile, targetStartedEvent.ParentTarget), true);
}
else
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetStartedProjectEntry", targetName, currentProjectFile), true);
}
}
else
{
if (!String.IsNullOrEmpty(targetStartedEvent.ParentTarget))
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetStartedFileProjectDepends", targetName, targetStartedEvent.TargetFile, currentProjectFile, targetStartedEvent.ParentTarget), true);
}
else
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetStartedFileProjectEntry", targetName, targetStartedEvent.TargetFile, currentProjectFile), true);
}
}
}
else
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("TargetStartedFileProjectEntry", targetName, targetStartedEvent.TargetFile, currentProjectFile), true);
}
resetColor();
ShownBuildEventContext(e);
}
}
/// <summary>
/// Will display the project started event which was deferred until the first visible message for the project is ready to be displayed
/// </summary>
private void DisplayDeferredProjectStartedEvent(BuildEventContext e)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
if (!SkipProjectStartedText)
{
// Get the project started event which matched the passed in event context
ProjectStartedEventMinimumFields projectStartedEvent = _buildEventManager.GetProjectStartedEvent(e);
// Make sure the project started event has not been show yet
if (projectStartedEvent?.ShowProjectFinishedEvent == false)
{
projectStartedEvent.ShowProjectFinishedEvent = true;
ProjectStartedEventMinimumFields parentStartedEvent = projectStartedEvent.ParentProjectStartedEvent;
if (parentStartedEvent != null)
{
// Make sure that if there are any events deferred on this event to show them first
DisplayDeferredStartedEvents(parentStartedEvent.ProjectBuildEventContext);
}
string current = projectStartedEvent.ProjectFile ?? string.Empty;
string previous = parentStartedEvent?.ProjectFile;
string targetNames = projectStartedEvent.TargetNames;
// Log 0-based node id's, where 0 is the parent. This is a little unnatural for the reader,
// but avoids confusion by being consistent with the Engine and any error messages it may produce.
int currentProjectNodeId = (projectStartedEvent.ProjectBuildEventContext.NodeId);
if (previous == null)
{
WriteLinePrefix(projectStartedEvent.FullProjectKey, projectStartedEvent.TimeStamp, false);
setColor(ConsoleColor.Cyan);
string message;
if (string.IsNullOrEmpty(targetNames))
{
message = ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectStartedTopLevelProjectWithDefaultTargets", current, currentProjectNodeId);
}
else
{
message = ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectStartedTopLevelProjectWithTargetNames", current, currentProjectNodeId, targetNames);
}
WriteMessageAligned(message, true);
resetColor();
}
else
{
WriteLinePrefix(parentStartedEvent.FullProjectKey, parentStartedEvent.TimeStamp, false);
setColor(ConsoleColor.Cyan);
if (string.IsNullOrEmpty(targetNames))
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectStartedWithDefaultTargetsMultiProc", previous, parentStartedEvent.FullProjectKey, current, projectStartedEvent.FullProjectKey, currentProjectNodeId), true);
}
else
{
WriteMessageAligned(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("ProjectStartedWithTargetsMultiProc", previous, parentStartedEvent.FullProjectKey, current, projectStartedEvent.FullProjectKey, currentProjectNodeId, targetNames), true);
}
resetColor();
}
// Make the last shown build event context to be null so that the next message will always print out the target name. If this is not null
// then the first message after the project started event will not have the target name printed out which was causing some confusion.
ShownBuildEventContext(null);
}
}
}
/// <summary>
/// Prints a custom event
/// </summary>
public override void CustomEventHandler(object sender, CustomBuildEventArgs e)
{
if (showOnlyErrors || showOnlyWarnings)
{
return;
}
ErrorUtilities.VerifyThrowArgumentNull(e.BuildEventContext, "BuildEventContext");
if (IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
// ignore custom events with null messages -- some other
// logger will handle them appropriately
if (e.Message != null)
{
DisplayDeferredStartedEvents(e.BuildEventContext);
WriteLinePrefix(e.BuildEventContext, e.Timestamp, false);
WriteMessageAligned(e.Message, true);
ShownBuildEventContext(e.BuildEventContext);
}
}
}
/// <summary>
/// Writes message contextual information for each message displayed on the console
/// </summary>
private void WriteLinePrefix(BuildEventContext e, DateTime eventTimeStamp, bool isMessagePrefix)
{
WriteLinePrefix(GetFullProjectKey(e).ToString(Verbosity), eventTimeStamp, isMessagePrefix);
}
private void WriteLinePrefix(string key, DateTime eventTimeStamp, bool isMessagePrefix)
{
// Don't want any prefix for single proc
if (NumberOfProcessors == 1)
{
return;
}
setColor(ConsoleColor.Cyan);
string context = string.Empty;
if (_showTimeStamp || IsVerbosityAtLeast(LoggerVerbosity.Diagnostic))
{
context = LogFormatter.FormatLogTimeStamp(eventTimeStamp);
}
string prefixString;
if (!isMessagePrefix || IsVerbosityAtLeast(LoggerVerbosity.Detailed))
{
prefixString = ResourceUtilities.FormatResourceStringStripCodeAndKeyword("BuildEventContext", context, key) + ">";
}
else
{
prefixString = ResourceUtilities.FormatResourceStringStripCodeAndKeyword("BuildEventContext", context, string.Empty) + " ";
}
WritePretty(prefixString);
resetColor();
if (_prefixWidth == 0)
{
_prefixWidth = prefixString.Length;
}
}
/// <summary>
/// Extract the full project key from the BuildEventContext
/// </summary>
private ProjectFullKey GetFullProjectKey(BuildEventContext e)
{
ProjectStartedEventMinimumFields startedEvent = null;
if (e != null)
{
startedEvent = _buildEventManager.GetProjectStartedEvent(e);
}
// Project started event can be null, if the message has come before the project started event
// or the message is not part of a project such as if the message came from the engine
return startedEvent == null
? new ProjectFullKey(0, 0)
: new ProjectFullKey(startedEvent.ProjectKey, startedEvent.EntryPointKey);
}
/// <summary>
/// Returns a performance counter for a given scope (either task name or target name)
/// from the given table.
/// </summary>
/// <param name="scopeName">Task name or target name.</param>
/// <param name="table">Table that has tasks or targets.</param>
internal static new MPPerformanceCounter GetPerformanceCounter(string scopeName, ref Dictionary<string, PerformanceCounter> table)
{
// Lazily construct the performance counter table.
if (table == null)
{
table = new Dictionary<string, PerformanceCounter>(StringComparer.OrdinalIgnoreCase);
}
// And lazily construct the performance counter itself.
PerformanceCounter counter;
if (!table.TryGetValue(scopeName, out counter))
{
counter = new MPPerformanceCounter(scopeName);
table[scopeName] = counter;
}
return (MPPerformanceCounter)counter;
}
#endregion
#region InternalClass
/// <summary>
/// Stores and calculates the performance numbers for the different events
/// </summary>
internal class MPPerformanceCounter : PerformanceCounter
{
// Set of performance counters for a project
private Dictionary<string, PerformanceCounter> _internalPerformanceCounters;
// Dictionary mapping event context to the start number of ticks, this will be used to calculate the amount
// of time between the start of the performance counter and the end
// An object is being used to box the start time long value to prevent jitting when this code path is executed.
private Dictionary<BuildEventContext, object> _startedEvent;
internal int MessageIndentLevel { get; set; } = 2;
internal MPPerformanceCounter(string scopeName)
: base(scopeName)
{
// Do Nothing
}
/// <summary>
/// Add a started event to the performance counter, by adding the event this sets the start time of the performance counter
/// </summary>
internal void AddEventStarted(string projectTargetNames, BuildEventContext buildEventContext, DateTime eventTimeStamp, IEqualityComparer<BuildEventContext> comparer)
{
// If the projectTargetNames are set then we should be a project started event
if (!string.IsNullOrEmpty(projectTargetNames))
{
// Create a new performance counter for the project entry point to calculate how much time and how many calls
// were made to the entry point
MPPerformanceCounter entryPoint = GetPerformanceCounter(projectTargetNames, ref _internalPerformanceCounters);
entryPoint.AddEventStarted(null, buildEventContext, eventTimeStamp, s_compareContextNodeIdTargetId);
// Indent the output so it is indented with respect to its parent project
entryPoint.MessageIndentLevel = 7;
}
_startedEvent ??= comparer == null
? new Dictionary<BuildEventContext, object>()
: new Dictionary<BuildEventContext, object>(comparer);
if (!_startedEvent.ContainsKey(buildEventContext))
{
_startedEvent.Add(buildEventContext, eventTimeStamp.Ticks);
++calls;
}
}
/// <summary>
/// Add a finished event to the performance counter, so perf numbers can be calculated
/// </summary>
internal void AddEventFinished(string projectTargetNames, BuildEventContext buildEventContext, DateTime eventTimeStamp)
{
if (!string.IsNullOrEmpty(projectTargetNames))
{
MPPerformanceCounter entryPoint = GetPerformanceCounter(projectTargetNames, ref _internalPerformanceCounters);
entryPoint.AddEventFinished(null, buildEventContext, eventTimeStamp);
}
ErrorUtilities.VerifyThrow(_startedEvent != null, "Cannot have finished counter without started counter. ");
if (_startedEvent.TryGetValue(buildEventContext, out object time))
{
// Calculate the amount of time spent in the event based on the time stamp of when
// the started event was created and when the finished event was created
elapsedTime += (TimeSpan.FromTicks(eventTimeStamp.Ticks - (long)time));
_startedEvent.Remove(buildEventContext);
}
}
/// <summary>
/// Print out the performance counter message
/// </summary>
internal override void PrintCounterMessage(WriteLinePrettyFromResourceDelegate WriteLinePrettyFromResource, ColorSetter setColor, ColorResetter resetColor)
{
// round: sub-millisecond values are not meaningful
string time = String.Format(CultureInfo.CurrentCulture,
"{0,5}", Math.Round(elapsedTime.TotalMilliseconds, 0));
WriteLinePrettyFromResource(
MessageIndentLevel,
"PerformanceLine",
time,
String.Format(CultureInfo.CurrentCulture, "{0,-40}" /* pad to 40 align left */, scopeName),
String.Format(CultureInfo.CurrentCulture, "{0,3}", calls));
if (_internalPerformanceCounters?.Count > 0)
{
// For each of the entry points in the project print out the performance numbers for them
foreach (var counter in _internalPerformanceCounters.Values)
{
setColor(ConsoleColor.White);
counter.PrintCounterMessage(WriteLinePrettyFromResource, setColor, resetColor);
resetColor();
}
}
}
}
#endregion
#region internal MemberData
private static readonly ComparerContextNodeId<BuildEventContext> s_compareContextNodeId = new ComparerContextNodeId<BuildEventContext>();
private static readonly ComparerContextNodeIdTargetId<BuildEventContext> s_compareContextNodeIdTargetId = new ComparerContextNodeIdTargetId<BuildEventContext>();
private BuildEventContext _lastDisplayedBuildEventContext;
private int _bufferWidth = -1;
private readonly object _lockObject = new Object();
private int _prefixWidth = 0;
private ProjectFullKey _lastProjectFullKey = new ProjectFullKey(-1, -1);
private bool _alignMessages;
private bool _forceNoAlign;
private bool _showEventId;
// According to the documentation for ENABLE_PROCESSED_OUTPUT tab width for the console is 8 characters
#endregion
#region Per-build Members
// Holds messages that were going to be shown before the project started event, buffer them until the project started event is shown
private Dictionary<BuildEventContext, List<BuildMessageEventArgs>> _deferredMessages;
private BuildEventManager _buildEventManager;
// Has the build started
private bool _hasBuildStarted;
private bool? _showCommandLine;
private bool _showTimeStamp;
private ConsoleOutputAligner _consoleOutputAligner;
#endregion
}
}
|