zivkan
commented
3 years ago FWIW, here's a video/gif of my sample running at different verbosity. You can see how I don't have control to remove the progress message before the log messages are written, so only the -v:q run works as intended. Also one of the lines in the -v:m run has "corrupted" output, because moving the cursor position and writing output wasn't synchronised, so the line wasn't cleared when a short message was written.
edit: in fact, in the -v:m run, the output is just wrong, because it's supposed to show all 10 of the finished messages. The inability to syncronise cursor movement and output messages has this weird timing bug.
KalleOlaviNiemitalo
rainersigwald
xoofx
baronfel
As some of you know, I work on NuGet client. For Microsoft's annual hackathon, I was investigating this NuGet issue: https://github.com/NuGet/Home/issues/4346. It's about adding progress indicators, similar to what docker, npm, and others have.
I think in order to provide a "good" progress bar, or spinner, I need to be able to control the cursor position, including synchronous "blocking" when a log message is being output in order to allow me to clear any existing progress message (in case the progress message is longer than the log message being written), and then re-write the progress message, so the progress message is always on the last line.
However, in my testing, when I have a task using
TaskLoggingHelper, when I call theLog*methods, the method returns before the message is written to the console. Therefore, trying to useConsole.SetCursorPosition(0, Console.CursorTop), callingLog.LogMessage(...), and thenConsole.Write(...)to write my progress status doesn't work, as MSBuild's console logger usually (but not always) writes the console log after my progress status.See code sample
Here's a code sample for a Task that can be run to demonstrate the issue. Try running it with different verbosities (`-v:q`, `-v:n`). Sorry that the code is quite convoluted for a sample. I was trying to be "kind of" realistic for production code, while still being relatively minimalistic for a sample. ```csharp using Microsoft.Build.Framework; using Microsoft.Build.Utilities; using System; using System.ComponentModel; using System.Threading.Tasks; using Task = System.Threading.Tasks.Task; namespace LoggingTest { public class CustomTask : Microsoft.Build.Utilities.Task { public override bool Execute() { return ExecuteAsync().Result; } public async Task ExecuteAsync()
{
IMyLogger logger = new MSBuildLogger(Log);
ConsoleProgressLogger? progressLogger = null;
if (!Console.IsOutputRedirected)
{
progressLogger = new ConsoleProgressLogger(logger);
logger = progressLogger;
}
var worker = new Worker(10, logger);
if (progressLogger != null)
{
progressLogger.SetWorker(worker);
progressLogger.WriteMessage();
}
await worker.Run();
return !Log.HasLoggedErrors;
}
private class Worker : INotifyPropertyChanged
{
private readonly IMyLogger _logger;
public int TotalWork { get; }
private int _finishedWork;
public event PropertyChangedEventHandler PropertyChanged;
public int FinishedWork
{
get => _finishedWork;
private set
{
if (_finishedWork != value)
{
_finishedWork = value;
PropertyChanged?.Invoke(this, new PropertyChangedEventArgs(nameof(FinishedWork)));
}
}
}
public Worker(int totalWork, IMyLogger logger)
{
TotalWork = totalWork;
_logger = logger;
}
public async Task Run()
{
for (int i = 1; i <= 10; i++)
{
_logger.Log(LoggerVerbosity.Normal, "Starting thing " + i);
await Task.Delay(500);
_logger.Log(LoggerVerbosity.Minimal, "Finished thing " + i);
FinishedWork++;
}
}
}
private interface IMyLogger
{
void Log(LoggerVerbosity verbosity, string message);
}
private class MSBuildLogger : IMyLogger
{
TaskLoggingHelper _logger;
public MSBuildLogger(TaskLoggingHelper logger)
{
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
}
public void Log(LoggerVerbosity verbosity, string message)
{
switch (verbosity)
{
case LoggerVerbosity.Normal:
_logger.LogMessage(MessageImportance.Normal, message);
break;
case LoggerVerbosity.Minimal:
_logger.LogMessage(MessageImportance.High, message);
break;
default:
throw new NotImplementedException();
}
}
}
private class ConsoleProgressLogger : IMyLogger
{
private readonly IMyLogger _inner;
private Worker _worker;
private string _message;
public ConsoleProgressLogger(IMyLogger inner)
{
_inner = inner ?? throw new ArgumentNullException(nameof(inner));
}
public void SetWorker(Worker worker)
{
if (_worker != null)
{
throw new InvalidOperationException();
}
_worker = worker ?? throw new ArgumentNullException(nameof(worker));
_worker.PropertyChanged += OnPropertyChanged;
}
public void WriteMessage()
{
_message = $"Finished {_worker.FinishedWork}/{_worker.TotalWork}";
// Set cursor to start of line, and write message without new line, so we can update it if it changes.
// We know the new message will be the same, or longer length as the old message, so no need to clear it.
Console.SetCursorPosition(0, Console.CursorTop);
Console.Write(_message);
}
private void OnPropertyChanged(object sender, PropertyChangedEventArgs eventArgs)
{
WriteMessage();
}
public void Log(LoggerVerbosity verbosity, string message)
{
// Cursor is currently at the end of the progress message line, so set it to the beginning of the line
Console.SetCursorPosition(0, Console.CursorTop);
// If the logged message is shorter than the current progress message, we need to clear the progress message, so it doesn't pollute the line
if (message.Length < _message.Length)
{
Console.Write(new string(' ', _message.Length));
Console.SetCursorPosition(0, Console.CursorTop);
}
// Let MSBuild log the line, which will include the new line
_inner.Log(verbosity, message);
// Write back the progress message, so it's always on the last line.
Console.Write(_message);
}
}
}
}
```
I can't think of any way to use existing APIs to improve NuGet's restore task to have similar progress feedback that customers of similar tools from other ecosysems are used to.