Introduce a ConsoleLogger option - or expose a synchronization primitive - so ConsoleLogger plays nice with interactive Console applications

[daiplusplus]

Background and Motivation

The Microsoft.Extensions.Logging.Console's ConsoleLoggerProcessor class iterates over BlockingCollection and writes formatted messages to the console in a new, separate, and private thread. There are 3 problems with the current design when used in a console application program:

• Writing formatted messages with ANSI control codes (e.g. coloring) - or sequences of separate writes - to the console is not atomic nor thread-safe.
  • For example, when an application program writes to Console directly while also calling-into services that log messages then colored message text will clash with the application's writes.
  • While I understand that concurrent calls to Console.WriteLine(String) will not be intermingled (i.e. they'll appear as two separate uncorrupted lines), if one thread needs to render multiple lines together then that cannot be guaranteed as the ConsoleLoggerProcessor thread may have its Console.Write calls run in-between the other thread's calls.
• There is no way to temporarily pause and buffer console messages while the console application program needs uninterrupted access to System.Console.
• In simpler console applications logged messages will never be displayed if/when returning from Main without disposing of the DI container.

Proposed API

(Unrealistic) Solution: Make IConsole a public DI service and add methods to allow consumers to temporarily borrow exclusive access:

As much as we'd all like System.Console to go-away and be replaced with an injectable IConsole interface, that's too much to ask for - and even if we kept System.Console and merely added IConsole as an improved way for working with the console/terminal/stdout it would be subject to too much bikeshedding so I won't go into detail on this option.

...but if we did, I'd want it to have something like this:

public interface IConsole
{
    void WriteLine();
    // Write(), WriteLine(), etc

   /// <summary>Returns an object that has exclusive access to the console for the specified period of time. All other IConsole users will buffer their messages until either the returned IBorrowedConsole is disposed or the maxExclusiveUseTime time expires, whichever is sooner.</summary>
    IBorrowedConsole Borrow( TimeSpan maxExclusiveUseTime ); // `maxExclusiveUseTime` defaults to 1000ms
}

public interface IBorrowedConsole : IConsole, IDisposable
{
    // Or perhaps name it `IExclusiveConsole`?
}

(Realistic) Solution 2: Allow a lock()-able object to be specified in ConsoleLoggerOptions which is respected by ConsoleLoggerProcessor.

namespace Microsoft.Extensions.Logging.Console
{
    public class ConsoleLoggerOptions
    {
+      public Object? ConsoleLockObject { get; set; }
+      public TimeSpan ConsoleLockTimeout { get; set; } = TimeSpan.FromSeconds(1);
    }
}

• When ConsoleLoggerOptions.ConsoleLockObject is not-null, then ConsoleLoggerProcessor.WriteMessage method would lock on ConsoleLoggerOptions.ConsoleLockObject (if specified) so that each message can be written atomically and not when application code is locked on the same object to gain exclusive use of Console for an uninterruptable sequence of writes.
  • ...but ideally I'd like ProcessLogQueue() to lock on ConsoleLockObject for the entire batch of pending messages, so all pending messages are written without any interleaving writes from application code (assuming that application code is also locking on the same ConsoleLockObject of course).
    • I'm not too familiar with BlockingCollection<T> - while I see that ConsoleLoggerProcessor uses a single foreach with GetConsumingEnumerable, I assume it's possible to detect when there's a batch of pending messages and to use a single lock for all of them, instead of individually.

Note that while consuming applications would be free to use lock() to synchronize their own Console use-sites, the ConsoleLoggerProcessor would always use Monitor.TryEnter with the ConsoleLockTimeout to prevent deadlocks.

An example of its usage:

public static class ConsoleProgram
{
    public static readonly Object MyConsoleLock = new Object();

    private static IHost CreateHost( String[] args )
    {
         IHostBuilder hb = Host.CreateDefaultBuilder( args );
         _ = hb.ConfigureLogging( lb => {
            lb.AddConsole( consoleLoggerOptions => {
                consoleLoggerOptions.ConsoleLockObject = ConsoleProgram.MyConsoleLock;
            } );
        } );

        _ = hb.ConfigureServices( /* Add IHttpClientFactory, etc */ );
    }

    public static async Task Main( String[] args )
    {
        IHost host = CreateHost( args );

        IHttpClientFactory hcf = host.Services.RequireService<IHttpClientFactory>();
        HttpClient hc = hcf.CreateClient();

        String foo = await ( await hc.GetAsync( "https://contoso.com/etc" ) ).Content.ReadAsStringAsync();
        lock( MyConsoleLock )
        {
            Console.WriteLine( "Got response" );
            Console.WriteLine( "Length: {0:N0} chars", foo.Length );
            Console.WriteLine();
            Console.WriteLine( foo );
        }
    }
}

Solution addendum for pending console log messages at the end of Main: Add a code-analysis checker

A simple solution for the problem of trivial Main methods returning (and causing an entire application shutdown) before ConsoleLoggerProcessor has finished writing all pending messages to the console would be the introduction of a Roslyn code-analyzer that warns the user if an IHost is created inside Main but not disposed before Main returns.

So the code above (and the linked example) would trigger an analysis warning that Main does not dispose of IHost and/or call StopAsync before returning.

Triggering code example:

    public static void Main( String[] args )
    {
        IHost host = CreateHost( args );

        MainInner( host );

        Console.WriteLine( "Now exiting, but any pending logged messages won't be printed." );
    } // <-- Code analysis warning that `host` is not disposed.

Code-fix result example:

The code-analysis code-fix would be to wrap the IHost in an explicit using block - but exclude any trailing use of Console:

    public static void Main( String[] args )
    {
        using( IHost host = CreateHost( args ) )
        {
            MainInner( host );
        }

        Console.WriteLine( "Now exiting. Any pending logged messages will have been printed before this message." );
    }

Risks

As with any use of lock, the opportunity for deadlocks is present, however because only the user's application code would ever use lock() and the library code will only ever use Monitor.TryEnter there shouldn't be any issues there.

Because C# already disallows the use of await inside a lock I don't forsee there being any major issues.

Contribution / PR

As per the Contribution guidelines and API review process, because this is a public API addition, I won't submit my PR with my changes (and tests) until this suggestion is accepted.

[ghost]

Tagging subscribers to this area: @carlossanlop
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Background and Motivation

The Microsoft.Extensions.Logging.Console's ConsoleLoggerProcessor class iterates over BlockingCollection and writes formatted messages to the console in a new, separate, and private thread. There are 3 problems with the current design when used in a console application program:

• Writing formatted messages with ANSI control codes (e.g. coloring) - or sequences of separate writes - to the console is not atomic nor thread-safe.
  • For example, when an application program writes to Console directly while also calling-into services that log messages then colored message text will clash with the application's writes.
  • While I understand that concurrent calls to Console.WriteLine(String) will not be intermingled (i.e. they'll appear as two separate uncorrupted lines), if one thread needs to render multiple lines together then that cannot be guaranteed as the ConsoleLoggerProcessor thread may have its Console.Write calls run in-between the other thread's calls.
• There is no way to temporarily pause and buffer console messages while the console application program needs uninterrupted access to System.Console.
• In simpler console applications logged messages will never be displayed if/when returning from Main without disposing of the DI container.

Proposed API

(Unrealistic) Solution: Make IConsole a public DI service and add methods to allow consumers to temporarily borrow exclusive access:

As much as we'd all like System.Console to go-away and be replaced with an injectable IConsole interface, that's too much to ask for - and even if we kept System.Console and merely added IConsole as an improved way for working with the console/terminal/stdout it would be subject to too much bikeshedding so I won't go into detail on this option.

...but if we did, I'd want it to have something like this:

public interface IConsole
{
    void WriteLine();
    // Write(), WriteLine(), etc

   /// <summary>Returns an object that has exclusive access to the console for the specified period of time. All other IConsole users will buffer their messages until either the returned IBorrowedConsole is disposed or the maxExclusiveUseTime time expires, whichever is sooner.</summary>
    IBorrowedConsole Borrow( TimeSpan maxExclusiveUseTime ); // `maxExclusiveUseTime` defaults to 1000ms
}

public interface IExclusiveConsole : IConsole, IDisposable
{
}

(Realistic) Solution 2: Allow a lock()-able object to be specified in ConsoleLoggerOptions which is respected by ConsoleLoggerProcessor.

namespace Microsoft.Extensions.Logging.Console
{
    public class ConsoleLoggerOptions
    {
+      public Object? ConsoleLockObject { get; set; }
+      public TimeSpan ConsoleLockTimeout { get; set; } = TimeSpan.FromSeconds(1);
    }
}

At the very minimum, the ConsoleLoggerProcessor.WriteMessage method would lock on ConsoleLoggerOptions.ConsoleLockObject (if specified) so that each message can be written atomically - but ideally I'd like ProcessLogQueue() to lock on ConsoleLockObject for the entire batch of pending messages, so all messages are written without any interleaving writes from application code (assuming that application code is also locking on the same ConsoleLockObject of course).

Note that while consuming applications would be free to use lock() to synchronize their own Console use-sites, the ConsoleLoggerProcessor would always use Monitor.TryEnter with the ConsoleLockTimeout to prevent deadlocks.

An example of its usage:

public static class ConsoleProgram
{
    public static readonly Object MyConsoleLock = new Object();

    private static IHost CreateHost( String[] args )
    {
         IHostBuilder hb = Host.CreateDefaultBuilder( args );
         _ = hb.ConfigureLogging( lb => {
            lb.AddConsole( consoleLoggerOptions => {
                consoleLoggerOptions.ConsoleLockObject = ConsoleProgram.MyConsoleLock;
            } );
        } );

        _ = hb.ConfigureServices( /* Add IHttpClientFactory, etc */ );
    }

    public static async Task Main( String[] args )
    {
        IHost host = CreateHost( args );

        IHttpClientFactory hcf = host.Services.RequireService<IHttpClientFactory>();
        HttpClient hc = hcf.CreateClient();

        String foo = await ( await hc.GetAsync( "https://contoso.com/etc" ) ).Content.ReadAsStringAsync();
       lock( ConsoleLockObject )
       {
           Console.WriteLine( "Got response" );
           Console.WriteLine( "Length: {0:N0} chars", foo.Length );
           Console.WriteLine();
           Console.WriteLine( foo );
       }
    }
}

Solution addendum for pending console log messages at the end of Main: Add a code-analysis checker

A simple solution for the problem of trivial Main methods returning (and causing an entire application shutdown) before ConsoleLoggerProcessor has finished writing all pending messages to the console would be the introduction of a Roslyn code-analyzer that warns the user if an IHost is created inside Main but not disposed before Main returns.

So the code above (and the linked example) would trigger an analysis warning that Main does not dispose of IHost and/or call StopAsync before returning.

Risks

As with any use of lock, the opportunity for deadlocks is present, however because only the user's application code would ever use lock() and the library code will only ever use Monitor.TryEnter there shouldn't be any issues there.

Because C# already disallows the use of await inside a lock I don't forsee there being any major issues.

Author:	Jehoel
Assignees:	-
Labels:	api-suggestion, area-System.Console, untriaged
Milestone:	-

[ghost]

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Background and Motivation

The Microsoft.Extensions.Logging.Console's ConsoleLoggerProcessor class iterates over BlockingCollection and writes formatted messages to the console in a new, separate, and private thread. There are 3 problems with the current design when used in a console application program:

• Writing formatted messages with ANSI control codes (e.g. coloring) - or sequences of separate writes - to the console is not atomic nor thread-safe.
  • For example, when an application program writes to Console directly while also calling-into services that log messages then colored message text will clash with the application's writes.
  • While I understand that concurrent calls to Console.WriteLine(String) will not be intermingled (i.e. they'll appear as two separate uncorrupted lines), if one thread needs to render multiple lines together then that cannot be guaranteed as the ConsoleLoggerProcessor thread may have its Console.Write calls run in-between the other thread's calls.
• There is no way to temporarily pause and buffer console messages while the console application program needs uninterrupted access to System.Console.
• In simpler console applications logged messages will never be displayed if/when returning from Main without disposing of the DI container.

Proposed API

(Unrealistic) Solution: Make IConsole a public DI service and add methods to allow consumers to temporarily borrow exclusive access:

As much as we'd all like System.Console to go-away and be replaced with an injectable IConsole interface, that's too much to ask for - and even if we kept System.Console and merely added IConsole as an improved way for working with the console/terminal/stdout it would be subject to too much bikeshedding so I won't go into detail on this option.

...but if we did, I'd want it to have something like this:

public interface IConsole
{
    void WriteLine();
    // Write(), WriteLine(), etc

   /// <summary>Returns an object that has exclusive access to the console for the specified period of time. All other IConsole users will buffer their messages until either the returned IBorrowedConsole is disposed or the maxExclusiveUseTime time expires, whichever is sooner.</summary>
    IBorrowedConsole Borrow( TimeSpan maxExclusiveUseTime ); // `maxExclusiveUseTime` defaults to 1000ms
}

public interface IBorrowedConsole : IConsole, IDisposable
{
    // Or perhaps name it `IExclusiveConsole`?
}

(Realistic) Solution 2: Allow a lock()-able object to be specified in ConsoleLoggerOptions which is respected by ConsoleLoggerProcessor.

namespace Microsoft.Extensions.Logging.Console
{
    public class ConsoleLoggerOptions
    {
+      public Object? ConsoleLockObject { get; set; }
+      public TimeSpan ConsoleLockTimeout { get; set; } = TimeSpan.FromSeconds(1);
    }
}

• When ConsoleLoggerOptions.ConsoleLockObject is not-null, then ConsoleLoggerProcessor.WriteMessage method would lock on ConsoleLoggerOptions.ConsoleLockObject (if specified) so that each message can be written atomically and not when application code is locked on the same object to gain exclusive use of Console for an uninterruptable sequence of writes.
  • ...but ideally I'd like ProcessLogQueue() to lock on ConsoleLockObject for the entire batch of pending messages, so all pending messages are written without any interleaving writes from application code (assuming that application code is also locking on the same ConsoleLockObject of course).
    • I'm not too familiar with BlockingCollection<T> - while I see that ConsoleLoggerProcessor uses a single foreach with GetConsumingEnumerable, I assume it's possible to detect when there's a batch of pending messages and to use a single lock for all of them, instead of individually.

Note that while consuming applications would be free to use lock() to synchronize their own Console use-sites, the ConsoleLoggerProcessor would always use Monitor.TryEnter with the ConsoleLockTimeout to prevent deadlocks.

An example of its usage:

public static class ConsoleProgram
{
    public static readonly Object MyConsoleLock = new Object();

    private static IHost CreateHost( String[] args )
    {
         IHostBuilder hb = Host.CreateDefaultBuilder( args );
         _ = hb.ConfigureLogging( lb => {
            lb.AddConsole( consoleLoggerOptions => {
                consoleLoggerOptions.ConsoleLockObject = ConsoleProgram.MyConsoleLock;
            } );
        } );

        _ = hb.ConfigureServices( /* Add IHttpClientFactory, etc */ );
    }

    public static async Task Main( String[] args )
    {
        IHost host = CreateHost( args );

        IHttpClientFactory hcf = host.Services.RequireService<IHttpClientFactory>();
        HttpClient hc = hcf.CreateClient();

        String foo = await ( await hc.GetAsync( "https://contoso.com/etc" ) ).Content.ReadAsStringAsync();
        lock( MyConsoleLock )
        {
            Console.WriteLine( "Got response" );
            Console.WriteLine( "Length: {0:N0} chars", foo.Length );
            Console.WriteLine();
            Console.WriteLine( foo );
        }
    }
}

Solution addendum for pending console log messages at the end of Main: Add a code-analysis checker

A simple solution for the problem of trivial Main methods returning (and causing an entire application shutdown) before ConsoleLoggerProcessor has finished writing all pending messages to the console would be the introduction of a Roslyn code-analyzer that warns the user if an IHost is created inside Main but not disposed before Main returns.

So the code above (and the linked example) would trigger an analysis warning that Main does not dispose of IHost and/or call StopAsync before returning.

Triggering code example:

    public static void Main( String[] args )
    {
        IHost host = CreateHost( args );

        MainInner( host );

        Console.WriteLine( "Now exiting, but any pending logged messages won't be printed." );
    } // <-- Code analysis warning that `host` is not disposed.

Code-fix result example:

The code-analysis code-fix would be to wrap the IHost in an explicit using block - but exclude any trailing use of Console:

    public static void Main( String[] args )
    {
        using( IHost host = CreateHost( args ) )
        {
            MainInner( host );
        }

        Console.WriteLine( "Now exiting. Any pending logged messages will have been printed before this message." );
    }

Risks

As with any use of lock, the opportunity for deadlocks is present, however because only the user's application code would ever use lock() and the library code will only ever use Monitor.TryEnter there shouldn't be any issues there.

Because C# already disallows the use of await inside a lock I don't forsee there being any major issues.

Contribution / PR

As per the Contribution guidelines and API review process, because this is a public API addition, I won't submit my PR with my changes (and tests) until this suggestion is accepted.

Author:	daiplusplus
Assignees:	-
Labels:	api-suggestion, area-Extensions-Logging
Milestone:	Future