dotnet
Revisit console coloring in tooling commands
This issue has been moved from a ticket on Developer Community.
I have written a simple logger, that outputs to the console. The entire color+write statement is inside a SemaphoreSlim set to (1), howver. Sometimes (1 / 500) setting Console.Foreground doesn't actually change the Console.Foreground.
See attached screen.
Original Comments
Feedback Bot on 9/27/2021, 07:07 AM:
We have directed your feedback to the appropriate engineering team for further evaluation. The team will review the feedback and notify you about the next steps.
Natalia Kondratyeva [MSFT] on 10/1/2021, 02:45 PM:
Hello Brian,
Could you please let us know, which version of .NET is your code running on?
Could that be that some other thread has changed the ForegroundColor in the meantime?
Will you be able to provide a minimal repro please?
Why do we ask for more info?
We try to reproduce all issues reported with the information provided in the description and comments. When we can’t reproduce the issue, we ask you for more information so we can resolve the issue as quickly and efficiently as possible.
In our guidelines, you can get tips on how to provide clear and simple reproducible steps.
Brian Bergh on 10/2/2021, 09:54 AM:
Sure
- I’m running .NET 5
- No, that cannot be the case ,as the statement is wrapped in lock.
I have tried wrapping it in Lock(Console.Out) {…} as well, i’ve tried Mutex and Semaphore, and no matter what i do, i get this random issue.
I have found an “old” git thread on the internet (can’t remember where now) where MS developer actually discussed this as an issue you needed to address. However, it was old and “closed”.
Just wanted you to know that the issue is still there.
Natalia Kondratyeva on 10/4/2021, 01:15 PM:
Thanks.
Since the issue is about .NET 5, I’ll transfer it to the dotnet/runtime GitHub repo.
If you by chance will find again this thread you were speaking about, it would be helpful if you could link it there.
Original Solutions
(no solutions)
Tagging subscribers to this area: @dotnet/area-system-console See info in area-owners.md if you want to be subscribed.
Issue Details
This issue has been moved from a ticket on Developer Community.
I have written a simple logger, that outputs to the console. The entire color+write statement is inside a SemaphoreSlim set to (1), howver. Sometimes (1 / 500) setting Console.Foreground doesn't actually change the Console.Foreground.
See attached screen.
Original Comments
Feedback Bot on 9/27/2021, 07:07 AM:
We have directed your feedback to the appropriate engineering team for further evaluation. The team will review the feedback and notify you about the next steps.
Natalia Kondratyeva [MSFT] on 10/1/2021, 02:45 PM:
Hello Brian,
Could you please let us know, which version of .NET is your code running on?
Could that be that some other thread has changed the ForegroundColor in the meantime?
Will you be able to provide a minimal repro please?
Why do we ask for more info?
We try to reproduce all issues reported with the information provided in the description and comments. When we can’t reproduce the issue, we ask you for more information so we can resolve the issue as quickly and efficiently as possible.
In our guidelines, you can get tips on how to provide clear and simple reproducible steps.
Brian Bergh on 10/2/2021, 09:54 AM:
Sure
- I’m running .NET 5
- No, that cannot be the case ,as the statement is wrapped in lock.
I have tried wrapping it in Lock(Console.Out) {…} as well, i’ve tried Mutex and Semaphore, and no matter what i do, i get this random issue.
I have found an “old” git thread on the internet (can’t remember where now) where MS developer actually discussed this as an issue you needed to address. However, it was old and “closed”.
Just wanted you to know that the issue is still there.
Natalia Kondratyeva on 10/4/2021, 01:15 PM:
Thanks.
Since the issue is about .NET 5, I’ll transfer it to the dotnet/runtime GitHub repo.
If you by chance will find again this thread you were speaking about, it would be helpful if you could link it there.
Original Solutions
(no solutions)
| Author: | vsfeedback |
|---|---|
| Assignees: | - |
| Labels: |
|
| Milestone: | - |
What OS is this on- Windows, Mac or Linux? Is it possible to reduce to a simple repro that we can try?
This is on Windows, and i've only tested it with .NET 5.
This old thread is about the exact same issue with .net core vs desktop several years ago.
https://github.com/dotnet/runtime/issues/15037
@BrianBergh thanks for the pointer. In a quick scan, that seems unrelated. That was pointing out that in .NET Framework, lock { Console.Out } should exclude any other threads writing through Console.Out. This was fixed by changing Console.Out back to a SyncTextWriter.
However in neither .NET Core nor .NET Framework does there seem to be any lock of Console.Out around setting colors. I would expect this to repro on .NET Framework as well. https://referencesource.microsoft.com/#mscorlib/system/console.cs,801
Do you own the other threads setting the color? If so can you have them lock Console.Out directly?
If you don't own the other threads, I do not see a mechanism to set console and write atomically. that would require we implement this: https://github.com/dotnet/runtime/issues/39746 (in there it points out it's racy)
Linking here another issue that I didn't look into further and may be unrelated: https://github.com/dotnet/runtime/issues/53751
BTW, we'd welcome your input into dotnet/runtime#39746 if you want to help move it along. The API is not controversial, but there are some implementation difficulties eg with Unix...
Hi @danmoseley , sure go ahead.
- Yes, you are right about the relation to the link.
- Yes, I do own the other threats, but the case is that piping a lot of data (logging) to a static method in a static class, that is supposed to handle "ALL" console writing (and coloring), and in this method I've tried to lock(Console.Out)...Semaphore, etc etc. No matter what I do, I get random "gray" texts :(
And nowhere in the entire solution are we writing to the console in gray (in fact, we aren't writing to the console anywhere else in the solution)
However, I have just setup a simple .NET 5 console application, created 100 tasks that randomly writes in different colors to the console, and guess what........I can't reproduce.....
This is either some very weird bug in out code (which I simple don't understand as we currently only have one pipe to the Console.Foreground -> out -> Foreground back to old.) or it has to do with the fact that the other project is a .NET 5 WebApp - which sounds unlikely to be the cause.
But please close this, I will continue to see if I can trigger the issue somehow.
After reading the source behind setting the console foreground color in the Windows implementation
(internal static class ConsolePal) - I can see some notice about possible issues in Windows? But I might be wrong (I'm not expert in Windows Interop for Kernel32 console interactions :) - See attached screen.
I believe by default ASP.NET Core Web App would have some logging turned on... could that interfere?
When I look in the console window right when I get the issue, there is NO foreign text (nor in gray)
As stated, all the code is surrounded in lock(Console.Out) { ... } - and still I get this :
Okay, finally I got something. This issue seems to be related to the LogTo function in EF Core. If I remove that, it all goes away.
I'm not the one to figure out if this issue is then related to the runtime or to EF Core
It is most likely here. Although colors seem to be constructed as escape sequences (eg here https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/Reporter.cs#L22) they are later unpacked into explicitly setting Console.ForegroundColor:
https://github.com/dotnet/efcore/blob/release/6.0/src/ef/AnsiTextWriter.cs
To fix this, EF should consider following the "convention" of locking Console.Out to write color + text atomically. Note that this scope should be small or it could impact the perf of the app if it's writing often to the console.
@danmoseley I think you are spot on, thank you very much for helping out with this.
@BrianBergh my pleasure. perhaps we'll see you again in this repo? we are always glad for our community to grow. there are up for grabs issues, API proposals etc... 😄
@danmoseley Can you explain more how you think the code in Reporter.cs is relevant here? Likewise for AnsiTextWriter.cs? When using LogTo, EF does not do any manipulation of the strings or the console. LogTo simply sends strings directly to the delegate supplied. EF does not even know if it is connected to a console or not.
Hi @ajcvickers
If NoColor is false, when Reporter is asked to eg write an error, it wraps the text in escape sequences representing colors https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/Reporter.cs#L22
It passes these to AnsiConsole.WriteLine https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiConsole.cs#L13
AnsiConsole wraps Console.Out in an AnsiTextWriter https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiConsole.cs#L10
AnsiTextWriter then unpacks these into colors https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiTextWriter.cs#L31
sets Background/ForegroundColor eg https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiTextWriter.cs#L108
then writes https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiTextWriter.cs#L26
The net result is that it sets fore/background color and writes assuming that they are atomic wrt other threads doing the same. Until Console offers a way to do this atomically (dotnet/runtime#39746) the convention is to lock on Console.Out during this process. This can be done in AnsiTextWriter.
I guess there is also a non-convention (non-respected here!) that one sets the color back.
BTW, AnsiTextWriter does a lot of reading and writing of the color. Writing a single message that is bolded:
read, write https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiTextWriter.cs#L108
read, write, read, write https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiTextWriter.cs#L115-L121
Console.WriteLine()
read, ResetColor(), read, write https://github.com/dotnet/efcore/blob/29e2c156c412118be2859511529c5fb541b36832/src/ef/AnsiTextWriter.cs#L127-L133
for a total of 9 reads and writes, and a reset. If the code assumes nothing about the color at the start, and does not reset it at the end, which are both conventions in multithreaded console access, it should do no reads and just one write. I know these color sets/reads have shown up in hot paths elsewhere.
@danmoseley Yes, but none of that code is used for LogTo, so I'm not sure how it is relevant to this issue.
Ah, I see. I couldn't see all @BrianBergh code so I didn't attempt to connect. @BrianBergh can you shed light? is it possible to share code of SimpleDebugLogger?
Hi @danmoseley , unfortunately I can't share the code of SimpleDebugLogger as I am not the owner of it (it belongs to my company, and it contains secrets) However, I can share the primary logic of it, and explain what I have discovered so far. This method is whats used in .LogTo :
private static readonly Regex _regexFindExecuteCommandTables = new("(?:[\\b|\\s|\\n|\\r]+from[\\b|\\s|\\n|\\r]+)(?:\\[)*(?<table>[\\w\\d\\b]*)(?:\\])*", RegexOptions.Multiline | RegexOptions.IgnoreCase | RegexOptions.Compiled, TimeSpan.FromMilliseconds(250));
private static readonly Regex _regexFindExecuteCommandTiming = new("\\w*\\(\\s*(?<exeTime>(?:\\d+)).*ms\\s*\\)", RegexOptions.Multiline | RegexOptions.Compiled, TimeSpan.FromMilliseconds(250));
public static void EFLogTo(string data)
{
if (!LogDBQueries)
return;
try
{
if (!LogDBQueriesDetailed)
{
// just fetch the table names and the execution time
string time = null;
string table = null;
try
{
// find time
var timeResult = _regexFindExecuteCommandTiming.Match(data);
// find the table
var tableResult = _regexFindExecuteCommandTables.Matches(data); // only get the first (otherwise its confusing)
if (timeResult.Success && tableResult.Any(a=>a.Success))
{
time = timeResult.Groups["exeTime"].Value;
table = tableResult.Select(a => a.Groups["table"].Value).Where(a=>!string.IsNullOrWhiteSpace(a)).Aggregate((a, b) => a + "," + b);
}
else
{
return;
}
}
catch { /* regex timed out, tough luck */ }
if (!string.IsNullOrWhiteSpace(time))
{
if (int.TryParse(time, out int ms))
WriteLine(LogTypes.SqlTrace, $"[EF][{table}] ", ms);
else
WriteLine(LogTypes.SqlTrace, $"[EF][{table}] {time}");
}
}
else
{
// Trace logging detailed, throw it all out to console
WriteLine(LogTypes.SqlTrace, data);
}
}
catch { }
}
EFLogTo is then calling this:
public static void WriteLine(LogTypes logType, string message, double elapsedMilliseconds = -1d)
{
if (!LogToConsole && !Debugger.IsAttached)
return;
_= Task.Run(() =>
{
lock (Console.Out)
{
try
{
StringBuilder sb = new StringBuilder();
sb.Append($"[{DateTime.Now:yyyy-MM-dd HH:mm:ss}");
ConsoleColor fg = ConsoleColor.White;
ConsoleColor fgTime = ConsoleColor.Green;
if (logType == LogTypes.Measurement && elapsedMilliseconds >= 500)
fgTime = ConsoleColor.Red;
else if (logType == LogTypes.Measurement && elapsedMilliseconds >= 50)
fgTime = ConsoleColor.Yellow;
switch (logType)
{
case LogTypes.Error:
{
fg = ConsoleColor.Red;
sb.Append(" ERROR]");
}
break;
case LogTypes.Info:
{
fg = ConsoleColor.White;
sb.Append(" INFO]");
}
break;
case LogTypes.Statement:
{
fg = ConsoleColor.Green;
sb.Append(" STATE]");
}
break;
case LogTypes.Warning:
{
fg = ConsoleColor.DarkYellow;
sb.Append(" WARNING]");
}
break;
case LogTypes.Measurement:
{
fg = ConsoleColor.Cyan;
sb.Append(" MEASURE]");
}
break;
case LogTypes.SqlTrace:
{
fg = ConsoleColor.DarkCyan;
sb.Append(" SQL TRACE]");
}
break;
}
string lead = sb.ToString();
if (LogToConsole)
{
Console.ForegroundColor = fg;
if (elapsedMilliseconds > -1)
{
Console.Write($"{lead}:{message}");
Console.ForegroundColor = fgTime;
Console.WriteLine($" {elapsedMilliseconds:#,0} ms.");
}
else
{
Console.WriteLine($"{lead}:{message}");
}
Console.ResetColor();
}
else
{
if (logType == LogTypes.Measurement && elapsedMilliseconds > 0)
System.Diagnostics.Debug.WriteLine($"{lead}:{message} {elapsedMilliseconds:#,0} ms.");
else
System.Diagnostics.Debug.WriteLine($"{lead}:{message}");
}
}
catch { }
}
});
}
This is an example of how we setup LogTo:
var builder = new DbContextOptionsBuilder<ApplicationDbContext>();
if (SimpleDebugLogger.LogDBQueries)
{
builder.UseSqlServer(_connectionString)
.LogTo(SimpleDebugLogger.EFLogTo, LogLevel.Information);
}
else
{
builder.UseSqlServer(_connectionString);
}
The issue (dark-gray texts random appearing) goes completely away, if I remove all the LogTo statements. (sets SimpleDebugLogger.LogDBQueries to false)
And I can't figure out why.
)
Hope it helps :-
@BrianBergh If you make any async calls with EF, then your LogTo delegate will likely be called by different threads. Could this be causing your issues?
@ajcvickers Thats why the entire statement (color and out) is wrapped in a lock(Console.Out) { .... } - So no?
@BrianBergh I notice that if an exception is thrown, then Console.ResetColor(); will not be called.
@ajcvickers Thats correct thanks, that should be fixed. But that will not cause the console to not respond to setting foreground, and nor will it set the foregroundcolor do darkgray. Unfortunately that's not the issue.
Perhaps add some logging with Debug.WriteLine around the various console calls, including the thread ID? That should be low enough overhead the problem will still occur. I use the free sysinternals dbgview to monitor them.
@danmoseley Thanks for the tip. There is not one single console call outside the SimpleDebugLogger in the whole solution. That is the point of it, we wanted to consolidate all output to it, to easily be able to control where the output goes (Debug or Console) because the application normally runs in Azure (as a service). - And as im 100% sure that this is the only place in the entire solution that we do any console write/color etc. and since its all wrapped in lock(Console.out) I am 100% sure it isn't our solution that causes the odd color shifting. - What i can't say for sure is what other frameworks we use do with the console, but its strange that it only ever occurs when LogTo is set. - But then again, the issue can be in the runtime it self - Anyway, this is not a big deal to us, i just thought i'd mention it.
OK. My next step would be breaking on WriteConsole etc with a native debugger.
Anyway, we found a place that could be tweaked in EF so perhaps this issue can be for that.