Basic support for colorized logging by yoav-steinberg · Pull Request #10650 · redis/redis

yoav-steinberg · 2022-04-27T08:15:31Z

This colorizes the "level char" at the beginning of each log line when outputting to a TTY.

And on a bright background:

I'd be happy to hear any suggestions for improvements, since this is pretty minimal. But even coloring this single char makes reading the log from a console output much easier in my opinion.

oranagra

i wonder how this would play with someone who configured his terminal to have a white background?
info type will not be visible?

@yossigo can you think of any other concerns?

src/server.c

yoav-steinberg · 2022-04-28T06:09:56Z

i wonder how this would play with someone who configured his terminal to have a white background? info type will not be visible?

gnome-terminal "White on black" scheme:

gnome-terminal "Solarized light" scheme:

oranagra · 2022-04-28T06:57:24Z

so the verbose is barely visible. i.e. if we would have colored the entire line, or just the timestamp, that text will be unreadable.

yoav-steinberg · 2022-04-28T12:08:04Z

Updated coloring:

yoav-steinberg · 2022-04-28T14:30:46Z

An issue that came up while working on this is related to the current use of log levels and how effective they currently are in detecting issues. Once we got the colors we started noticing that some log lines might actually benefit from a different level so not to be mixed up visually with other more/less important lines. Specifically:

We have cases where we print information (might be important but by no means an error indicator) with the LL_WARNING level. Maybe we should demote these to LL_NOTICE:
- oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
- User requested shutdown...
This is also true for cases that we encounter a rare but normal situation. Maybe here we should too demote to LL_NOTICE. Examples:
- AOF was enabled but there is already another background operation. An AOF background was scheduled to start when possible.
- Connection with master lost.
There are cases where we encounter a critical issue, leading to closing the server or hinting we're in a degraded mode of operation or possibly a bug which are logged as LL_WARNING but we might want to elevate them to some LL_ERROR or LL_CRITICAL so they'll stick out in the log:
- CRITICAL ERROR: User ACLs don't match final bitmap: '%s'
- Failed restoring failed CONFIG SET command. Error setting %s to '%s': %s
- "WARNING overcommit_memory is set to 0!

This PR might be an opportunity to address issues and then update the coloring scheme appropriately.

yossigo

I'm not a huge fan of coloring logs at the source, but as long as we do that only on TTYs and maybe after validating the TERM environment variable is sane, I'm OK with that.

Discussed quickly with @oranagra the idea of creating a new "error" log level. I think it's going to be a lot of work because it seems like a big portion of the current warnings are really errors. Also, there would be more backwards compatibility issues, module support, etc.

The alternative of demoting some of the non-warning messages to notice makes sense to me, and should have minimal impact on users who use default config (loglevel notice). That said, I think it's still technically a breaking change - as a user I'd hate to spend a long time troubleshooting an issue only to discover the newly upgraded versions hides warnings I'm used to see.

oranagra · 2022-05-10T13:27:51Z

ok, so we need someone with some spare time, to go over all the LL_WARNING usages and evaluate which ones should be demoted. any volunteers?

enjoy-binbin · 2022-05-11T12:41:39Z

go over all the LL_WARNING usages and evaluate which ones should be demoted

I have indeed seen some strange warning messages in the past, I can try to collect them

enjoy-binbin · 2022-05-11T15:07:45Z

here is what i got, base on my understanding, did not go through the module part (not familiar with it)
2cb9af3

oranagra · 2022-05-12T06:04:42Z

thank you @enjoy-binbin , i took a look. most of them seem ok with that plan, i commented on a few i wasn't sure about.
let's make a PR and i'll transfer my comments to it so that it'll easier to collaborate on it.

oranagra · 2022-05-12T06:38:47Z

I went over all the LL_WARNING usages in module.c, they all seem valid (don't need any change IMHO)

src/server.c

oranagra · 2022-05-12T10:44:11Z

src/server.c

        }
-        fprintf(fp,"%d:%c %s %c %s\n",
-            (int)getpid(),role_char, buf,c[level],msg);
+        if (isatty(fileno(fp))) {


let's check if there's any performance implication to calling isatty, and consider caching it or at the very least doing it only when log_to_stdout is set?

isatty() performs a system call (on Linux) which has a noticeable performance impact. I'll cache it (but just for stdout) since the current code doesn't assume an immutable log file name and calls open() per log, so it doesn't feel right to cache it between open()s.

could it even be that we use open() on a file name and it's a TTY?
i don't think so, so there's no need to call it at all in that case.
look like that's what you did, but your comment indicated otherwise so asking..

In theory someone could do redis-server --logfile /dev/stdout or even redis-server --logfile /dev/tty. I can't think of a good reason to do that, though.

ohh, right..
well, so they'll get what they deserve (no colors)
unless there's a good reason to do that (in which case they don't deserve it)

+1 to keeping the optimization at the expense of not detecting a TTY logfile name.

oranagra · 2022-05-12T14:45:44Z

since this is not a bug fix or an important improvement, and it could in theory cause some unexpected issues, we decided to push this back to 7.2

madolson · 2022-05-15T04:08:17Z

I don't feel all that strongly, but I want to +1 to I don't see a lot of value in trying to color the output outside of a config option. I really just don't want it on by default.

oranagra · 2022-05-15T07:16:59Z

@madolson you mean it should be an opt-in feature that should be explicitly enabled?
chances are that no one will bother so we don't gain anything by this "feature".
why don't you want it by default? is it harmful in your opinion?

madolson · 2022-05-16T04:30:55Z

I personally just find coloring annoying unless I am the one configuring it. When I'm interactively running redis I'm usually greping the log for something specific, this isn't going to show up in the logs so it doesn't matter there. It might draw attention if you do something wrong to a specific line for a warning, but outside of that I would rather just keep it clean and simple.

We have cases where we print information (might be important but by no means an error indicator) with the LL_WARNING level. Demoting these to LL_NOTICE: - oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo - User requested shutdown... This is also true for cases that we encounter a rare but normal situation. Demoting to LL_NOTICE. Examples: - AOF was enabled but there is already another background operation. An AOF background was scheduled to start when possible. - Connection with master lost. base on yoav-steinberg's #10650 (comment) and yossigo's #10650 (review)

We have cases where we print information (might be important but by no means an error indicator) with the LL_WARNING level. Demoting these to LL_NOTICE: - oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo - User requested shutdown... This is also true for cases that we encounter a rare but normal situation. Demoting to LL_NOTICE. Examples: - AOF was enabled but there is already another background operation. An AOF background was scheduled to start when possible. - Connection with master lost. base on yoav-steinberg's redis#10650 (comment) and yossigo's redis#10650 (review)

CLAassistant · 2024-03-24T23:13:52Z

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

basic support for colorized logging

cf71082

oranagra reviewed Apr 27, 2022

View reviewed changes

src/server.c Outdated Show resolved Hide resolved

some more colorization

54cb22a

zeekling approved these changes May 2, 2022

View reviewed changes

yossigo reviewed May 10, 2022

View reviewed changes

enjoy-binbin mentioned this pull request May 12, 2022

Demoting some of the non-warning messages to notice #10715

Merged

oranagra reviewed May 12, 2022

View reviewed changes

yoav-steinberg added 2 commits May 12, 2022 14:51

cache isatty() (performance)

53eb967

remove unused ANSI colors

b4aa8a3

oranagra mentioned this pull request Dec 15, 2022

In cluster-mode enabled, override the databases config at startup to 1 #11555

Merged

Conversation

yoav-steinberg commented Apr 27, 2022 • edited by oranagra Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

oranagra left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

yoav-steinberg commented Apr 28, 2022

Uh oh!

oranagra commented Apr 28, 2022

Uh oh!

yoav-steinberg commented Apr 28, 2022

Uh oh!

yoav-steinberg commented Apr 28, 2022

Uh oh!

yossigo left a comment

Choose a reason for hiding this comment

Uh oh!

oranagra commented May 10, 2022

Uh oh!

enjoy-binbin commented May 11, 2022

Uh oh!

enjoy-binbin commented May 11, 2022

Uh oh!

oranagra commented May 12, 2022

Uh oh!

oranagra commented May 12, 2022

Uh oh!

Uh oh!

oranagra May 12, 2022

Choose a reason for hiding this comment

Uh oh!

yoav-steinberg May 12, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

oranagra May 12, 2022

Choose a reason for hiding this comment

Uh oh!

yossigo May 12, 2022

Choose a reason for hiding this comment

Uh oh!

oranagra May 12, 2022

Choose a reason for hiding this comment

Uh oh!

yoav-steinberg May 12, 2022

Choose a reason for hiding this comment

Uh oh!

oranagra commented May 12, 2022

Uh oh!

madolson commented May 15, 2022

Uh oh!

oranagra commented May 15, 2022

Uh oh!

madolson commented May 16, 2022

Uh oh!

CLAassistant commented Mar 24, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

yoav-steinberg commented Apr 27, 2022 •

edited by oranagra

Loading

yoav-steinberg May 12, 2022 •

edited

Loading