Ability for Tasks (such as NuGet) to display progress, have fine-grained cursor position control

[zivkan]

As some of you know, I work on NuGet client. For Microsoft's annual hackathon, I was investigating this NuGet issue: NuGet/Home#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 the Log* methods, the method returns before the message is written to the console. Therefore, trying to use Console.SetCursorPosition(0, Console.CursorTop), calling Log.LogMessage(...), and then Console.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.

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<bool> 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.

[zivkan]

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]

Perhaps this could interoperate with the Windows Terminal progress bar feature microsoft/terminal#3004.

[rainersigwald]

Perhaps this could interoperate with the Windows Terminal progress bar feature microsoft/terminal#3004.

We're gonna do this for the new -terminalLogger: #8878.

[rainersigwald]

Prior art on semi-general progress reporting: https://microsoft.github.io/language-server-protocol/specifications/lsp/3.17/specification/#workDoneProgress

[xoofx]

We are also looking forward to this as we are seeing some dotnet commands like dotnet restore that can take several dozens of minutes on a slow connection and we are not able to get a progress on what is happening (as per NuGet/Home#4346 issue)

If this can help, I can write a proposal and make a PR for this?

[rainersigwald]

For bookkeeping: we've split this up into

1. API to report fine-grained progress from a task (this issue)
2. API to support more sophisticated console output (Terminal Logger: Rewritable Logger API spec #9378).

@xoofx we'll get back to you by ~tomorrow about whether anyone on our team has planned to work on this in the short term.

[rainersigwald]

@xoofx Nobody is already working on it, please feel free to work up a design!

To be super clear about expectations, it's probably a 17.10 timeline thing, and we'll have to coordinate with NuGet to get them to adopt the API after it exists, so this'll be the first step--but a necessary one!

[baronfel]

If we want another test case I'd love for Container Layer upload in SDK Containers to prove out the API and Implementation.

[rainersigwald]

Something that recently came up in a discussion: we'll need to think about throttling the progress messages, because the easiest use of the API will be something like "update progress every time there's something new in the active state" (e.g. "running test Test1", "running test Test2, 1 failed test", "running test Test3, 1 failed test") . . . but we don't need all of that in the TL output or in the binlog.

[baronfel]

One thought I had for that was that the binlog (and even the current console logger) would just display whatever the 'final' result was, some kind of summary event that says that "operation X completed in Y time with Z final summary". More thoughts to come later today.

[baronfel]

A bit delayed, made a tiny spec here to serve as the basis of discussion: https://gist.github.com/baronfel/c41cf19737532af0c1c07f8bff08a646

[baronfel]

Another use case - the DownloadFile Task from Arcade - this downloads hundred+ MB files and can take a while for those of us not near to Redmond.