Wrong output order when mixing ConsoleLogger with System.Console

[BalassaMarton]

When using the console logger, but also writing to the console using System.Console.WriteLine, the output doesn't match the order of calls:

        private static ILogger<Program> _logger;

        public static async Task Main(string[] args)
        {
            Console.WriteLine("Hello World!");
            _logger = new LoggerFactory().AddConsole().CreateLogger<Program>();
            _logger.LogInformation("Doing stuff");
            await DoSomethingAsync();
            Console.WriteLine("Press any key to exit");
            Console.ReadKey();
        }

        static async Task DoSomethingAsync()
        {
            for (var i = 1; i <= 100; i++)
            {
                await Task.Delay(1);
                _logger.LogInformation(i.ToString());
            }
        }

Output order at the end is non-deterministic, but after a few runs you will get something like this:

info: ConsoleApp2.Program[0]
      98
info: ConsoleApp2.Program[0]
      99
Press any key to exit
info: ConsoleApp2.Program[0]
      100

Using scopes does not solve the problem.
In my actual project, where the async methods do more stuff, and I have a few nested scopes, 100+ lines are shifted after the System.Console.WriteLine output.
Tested with .NET Core 2.0 and 2.1.

[muratg]

Your loop waits in each iteration of the loop, and hence is not parallel. Was that what you were aiming at?

[BalassaMarton]

Yes, that is intentional.

[ajcvickers]

@muratg Just FYI--I frequently run into this issue as well.

[muratg]

@pakrym any thoughts on this?

[pakrym]

It's the side effect of background logging in console logger that is done for performance reasons.

We can add a flag to disable background logging, it would also solve the related issue with a requirement to dispose logger factory to get all console messages out.

But mixing Console.Write and logging is not a great pattern in general and we shouldn't be getting into a business of trying to synchronize them.

[muratg]

But mixing Console.Write and logging is not a great pattern in general and we shouldn't be getting into a business of trying to synchronize them

This is an important point IMHO.

[ajcvickers]

@muratg @pakrym Agreed. However, while it was clear to me what was going on when I hit this the first time, I think it is something that will catch people out who aren't aware that the logging is asynchronous, so if that could be documented/communicated it would be good.

[BalassaMarton]

If the logger can flush all remaining messages synchronously, then this is an acceptable solution. The mixing comes from hosting inside a console application. The program itself doesn't know anything about logging or services, just creates an object and calls an entry point. Before and after, it writes some messages like "Press Ctrl+C to cancel" or "Press any key to exit".

[aspnet-hello]

We periodically close 'discussion' issues that have not been updated in a long period of time.

We apologize if this causes any inconvenience. We ask that if you are still encountering an issue, please log a new issue with updated information and we will investigate.