ConsoleLogger Queue optimization can lead to missed log entries

[JanKrivanek]

Description

CompleteAdding and TryDequeue try to compete for same lock. Once CompleteAdding wins, no more entries are being logged despite there might still be some in the queue.

More details: #70186 (comment)

Reproduction Steps

Just manual code analysis for now (after one of our integration test broke with runtime upgrade).
We can work on repro if needed.

FYI @vlada-shubina - as she started to dig into our broken test and pointed the focus to the recent console logger queue behavior change

Expected behavior

All logged items, that are logged prior calling Dispose are being flushed after calling Dispose. No items are skipped.

Actual behavior

Some already logged items can be skipped (and not flushed) after calling Dispose

Regression?

Yes

Known Workarounds

No response

Configuration

No response

Other information

No response

[ghost]

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

Issue Details

---

Description

CompleteAdding and TryDequeue try to compete for same lock. Once CompleteAdding wins, no more entries are being logged despite there might still be some in the queue.

More details: #70186 (comment)

Reproduction Steps

Just manual code analysis for now (after one of our integration test broke with runtime upgrade).
We can work on repro if needed.

FYI @vlada-shubina - as she started to dig into our broken test and pointed the focus to the recent console logger queue behavior change

Expected behavior

All logged items, that are logged prior calling Dispose are being flushed after calling Dispose. No items are skipped.

Actual behavior

Some already logged items can be skipped (and not flushed) after calling Dispose

Regression?

Yes

Known Workarounds

No response

Configuration

No response

Other information

No response

Author:	JanKrivanek
Assignees:	-
Labels:	area-Extensions-Logging
Milestone:	-

[JanKrivanek]

repro: https://github.com/JanKrivanek/ConsoleLogging

[eerhardt]

IMHO, I don't think that Microsoft.Extensions.Logging.Console should be used outside of long running server applications (i.e. ASP.NET, Microsoft.Extensions.Hosting, etc.). At least not in its current form. For simple console apps, starting a background thread to serialize the writing to the console just doesn't make sense.

[JanKrivanek]

It would be nice if Microsoft.Extensions.Logging.Console would be a go-to solution (as compared to non-MSFT loggers) without the need for user to answer the questions:

• Is my application long running? How do I differentiate?
• If my application is long running - am I fine with immediately drop of all messages on dispose?

I can imagine there can be many important messages on shutdown of a long running service ("was the state preserved?", "Was the shutdown acknowledged by other services?" etc.), that user might want to see (e.g. when deploying containerized apps and redirecting container output to persistnet cloud logs).

We are anyway already waiting with timeout for the flushing thread in the Dispose call, so the fix can be as easy as:

https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Logging.Console/src/ConsoleLoggerProcessor.cs#L168

if (_messageQueue.Count > 0 && !_isAddingCompleted)

--->

if (_messageQueue.Count > 0)

That would at least spare the need for the question 2 above.

[eerhardt]

so the fix can be as easy as

would you be willing to send a PR with the fix and some tests?