Revisit console coloring in tooling commands #26249
Comments
|
Tagging subscribers to this area: @dotnet/area-system-console Issue DetailsThis issue has been moved from a ticket on Developer Community. I have written a simple logger, that outputs to the console. See attached screen. Original CommentsFeedback 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, Why do we ask for more info? Brian Bergh on 10/2/2021, 09:54 AM:Sure
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. Original Solutions(no solutions)
|
|
What OS is this on- Windows, Mac or Linux? |
|
As it was originally from VS Feedback - I believe it's on Windows |
|
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. |
|
@BrianBergh thanks for the pointer. In a quick scan, that seems unrelated. That was pointing out that in .NET Framework, 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. 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: dotnet/runtime#39746 (in there it points out it's racy) Linking here another issue that I didn't look into further and may be unrelated: dotnet/runtime#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... |
|
Meanwhile shall I close this? |
|
Hi @danmoseley , sure go ahead.
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 |
|
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. 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 Line 22 in 29e2c15 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
changed the title
|
Moved to EF. |
|
@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 |
|
Hi @ajcvickers If NoColor is false, when Reporter is asked to eg write an error, it wraps the text in escape sequences representing colors Line 22 in 29e2c15 It passes these to AnsiConsole.WriteLine Line 13 in 29e2c15 AnsiConsole wraps Console.Out in an AnsiTextWriter Line 10 in 29e2c15 AnsiTextWriter then unpacks these into colors efcore/src/ef/AnsiTextWriter.cs Line 31 in 29e2c15 sets Background/ForegroundColor eg efcore/src/ef/AnsiTextWriter.cs Line 108 in 29e2c15 then writes efcore/src/ef/AnsiTextWriter.cs Line 26 in 29e2c15 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 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 efcore/src/ef/AnsiTextWriter.cs Line 108 in 29e2c15 read, write, read, write efcore/src/ef/AnsiTextWriter.cs Lines 115 to 121 in 29e2c15 Console.WriteLine() read, ResetColor(), read, write efcore/src/ef/AnsiTextWriter.cs Lines 127 to 133 in 29e2c15 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 |
|
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. 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. 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 |
|
@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. |
ajcvickers
changed the title
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 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)
The text was updated successfully, but these errors were encountered: