Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce status bar spam, log only minimal message to the status bar #4366

Merged
merged 6 commits into from
Dec 10, 2021
Merged
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@ internal sealed class NuGetFileLogger : IDisposable

public bool IsEnabled { get; }

public bool ShouldFormatWithTime { get; }
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that this logger is a testing utility that's only built under debug, so changes here don't affect the product.


// The DateTimeOffset and Stopwatch ticks are not equivalent. 1/10000000 is 1 DateTime tick.
public DateTimeOffset Now => _startTime.AddTicks(_stopwatch.ElapsedTicks * 10000000 / Stopwatch.Frequency);

Expand All @@ -34,13 +36,22 @@ internal NuGetFileLogger(IEnvironmentVariableReader environmentVariableReader)
throw new ArgumentNullException(nameof(environmentVariableReader));
}

_logDirectoryPath = environmentVariableReader.GetEnvironmentVariable("NUGET_SOLUTION_LOAD_LOGGING_PATH");
_logDirectoryPath = environmentVariableReader.GetEnvironmentVariable("NUGET_VS_RESTORE_LOGGING_PATH");

if (!string.IsNullOrWhiteSpace(_logDirectoryPath))
{
IsEnabled = true;
}

var formatWithTime = environmentVariableReader.GetEnvironmentVariable("NUGET_VS_RESTORE_FORMAT_WITH_TIME");

if (!string.IsNullOrWhiteSpace(formatWithTime))
{
_ = bool.TryParse(formatWithTime, out bool formatWithTimeOverride);

ShouldFormatWithTime = formatWithTimeOverride;
}

_startTime = DateTimeOffset.UtcNow;
_stopwatch = Stopwatch.StartNew();

Expand Down Expand Up @@ -84,7 +95,13 @@ public void Write(string logMessage)

lock (_streamWriterLock)
{
_streamWriter.Value.WriteLine(FormatWithTime(logMessage));
string message = logMessage;
if (ShouldFormatWithTime)
{
message = FormatWithTime(logMessage);
}
_streamWriter.Value.WriteLine(message);

}
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -213,13 +213,18 @@ private void HandleErrorsAndWarnings(ILogMessage logMessage)

private static bool ShouldReportProgress(ILogMessage logMessage)
{
// Only show messages with VerbosityLevel.Normal. That is, info messages only.
// Only show messages with VerbosityLevel.Minimal.
// Do not show errors, warnings, verbose or debug messages on the progress dialog
// Avoid showing indented messages, these are typically not useful for the progress dialog since
// they are missing the context of the parent text above it
return RestoreOperationProgressUI.Current != null
&& GetMSBuildLevel(logMessage.Level) == MSBuildVerbosityLevel.Normal
&& logMessage.Message.Length == logMessage.Message.TrimStart().Length;
&& GetMSBuildLevel(logMessage.Level) == MSBuildVerbosityLevel.Minimal
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the "big" change.

&& !IsStringIndented(logMessage);

static bool IsStringIndented(ILogMessage logMessage)
{
return logMessage.Message.Length > 0 && char.IsWhiteSpace(logMessage.Message[0]);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 Waaaaay better!

}
}

/// <summary>
Expand Down Expand Up @@ -468,71 +473,6 @@ private static LogLevel GetLogLevel(MSBuildVerbosityLevel level)
}
}

internal class WaitDialogProgress : RestoreOperationProgressUI
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unused class, just kept creating extra refs to some methods.

{
private readonly ThreadedWaitDialogHelper.Session _session;
private readonly JoinableTaskFactory _taskFactory;

private WaitDialogProgress(
ThreadedWaitDialogHelper.Session session,
JoinableTaskFactory taskFactory)
{
_session = session;
_taskFactory = taskFactory;
UserCancellationToken = _session.UserCancellationToken;
}

public static async Task<RestoreOperationProgressUI> StartAsync(
IAsyncServiceProvider asyncServiceProvider,
JoinableTaskFactory jtf,
CancellationToken token)
{
token.ThrowIfCancellationRequested();

await jtf.SwitchToMainThreadAsync(token);

var waitDialogFactory = await asyncServiceProvider.GetServiceAsync<
SVsThreadedWaitDialogFactory, IVsThreadedWaitDialogFactory>();

var session = waitDialogFactory.StartWaitDialog(
waitCaption: Resources.DialogTitle,
initialProgress: new ThreadedWaitDialogProgressData(
Resources.RestoringPackages,
progressText: string.Empty,
statusBarText: string.Empty,
isCancelable: true,
currentStep: 0,
totalSteps: 0));

return new WaitDialogProgress(session, jtf);
}

public async override ValueTask DisposeAsync()
{
await _taskFactory.SwitchToMainThreadAsync();
_session.Dispose();
}

public override async Task ReportProgressAsync(
string progressMessage,
uint currentStep,
uint totalSteps)
{
await _taskFactory.SwitchToMainThreadAsync();

// When both currentStep and totalSteps are 0, we get a marquee on the dialog
var progressData = new ThreadedWaitDialogProgressData(
progressMessage,
progressText: string.Empty,
statusBarText: string.Empty,
isCancelable: true,
currentStep: (int)currentStep,
totalSteps: (int)totalSteps);

_session.Progress.Report(progressData);
}
}

internal class StatusBarProgress : RestoreOperationProgressUI
{
private static object Icon = (short)Constants.SBAI_General;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -259,7 +259,7 @@ public static async Task<RestoreSummary> CommitAsync(RestoreResultPair restoreRe
var log = summaryRequest.Request.Log;

// Commit the result
log.LogInformation(Strings.Log_Committing);
jeffkl marked this conversation as resolved.
Show resolved Hide resolved
log.LogVerbose(Strings.Log_Committing);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I seriously considered removing this.

It literally just says "Comitting restore" which is not extremely helpful but it is a progress indicator.

For now, I just moved it verbose, but we can totally change it if others strongly lean one way or another.

await result.CommitAsync(log, token);

if (result.Success)
Expand Down