Configuration option to output logs in logfmt #12934

azuredream · 2024-01-11T04:34:59Z

Add ability to configure Redis to output logs in logfmt (See https://brandur.org/logfmt) as well as configure timestamp format options to more standard ISO 8601 or unix timestamp.

This change is implemented by two configs:
log-format: Either default or logfmt.
log-timestamp-format: default, iso8601, or unix.

iso8601 includes time zone.
Closes #12918
Closes #12932

LOG_FORMAT_DEFAULT + LOG_TIMESTAMP_DEFAULT
42888:M 12 Jan 2024 18:26:34.377 * Server initialized
42888:M 12 Jan 2024 18:26:34.377 * Ready to accept connections tcp

LOG_FORMAT_LOGFMT + LOG_TIMESTAMP_DEFAULT
pid=43765 role=master   timestamp="12 Jan 2024 18:29:14.441" level=notice  message="Server initialized"
pid=43765 role=master   timestamp="12 Jan 2024 18:29:14.441" level=notice  message="Ready to accept connections tcp"

LOG_FORMAT_LOGFMT + LOG_TIMESTAMP_ISO8601
pid=44325 role=master   timestamp="2024-01-12T18:31:24.697+05:00" level=notice  message="Server initialized"
pid=44325 role=master   timestamp="2024-01-12T18:31:24.697+05:00" level=notice  message="Ready to accept connections tcp"

LOG_FORMAT_LOGFMT + LOG_TIMESTAMP_UNIX
pid=44790 role=master   timestamp="1705102366" level=notice  message="Server initialized"
pid=44790 role=master   timestamp="1705102366" level=notice  message="Ready to accept connections tcp"

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

zuiderkwast

@azuredream Thanks, it's a good start. Let's see if the core team will accept this.

@madolson do you like the idea of a configurable logging format?

src/config.c

zuiderkwast · 2024-01-11T10:50:05Z

src/server.c

+        if(server.logfmt) {
+            fprintf(fp,"pid=%d role_char=%c timestamp=\"%s\" level=%c message=\"%s\"\n",
+                (int)getpid(),role_char, buf,c[level],msg);


I suggest role=%c (instead of role_char=%c). Is one char clear enough? If not, we can consider using role=master, role=sentinel, etc. but it makes the log longer. Maybe one char is clear enough?

For the level, maybe it would be more normal to use the words warning, notice, info, debug instead of the symbols?

Do we need to check if msg contains double quotes and linebreaks and escape those?

One more thing: I think the timestamp should be in ISO format, like 2024-01-11T10:34:38.000Z (always in UTC or with another timezone, i'm not sure what's best...)

Thanks for your review!
I suppose the questions are for @madolson. I'll wait for his reply.

@azuredream The questions are for you. :) What do you think?

I actually have a slightly different opinion, which is that I think the strftime format for timestamps should be configurable. It's easiest to test and validate, and I've seen various asks for it to be in a slight different format over time.

@madolson the log in debug.c you linked prints the argv, which can be a key name.

Correct, it's on my list of stuff I would like to remove. It was vaguely on my radar as one of the things to fix with https://github.com/redis/redis/pulls?q=is%3Apr+is%3Aopen+redact.

@madolson Ah, so do we need to get #11747 merged before we can proceed with this and avoid escaping stuff in message? (I don't like that PRs are blocked by other PRs. Maybe we can just change " to ' in that log entry for now?)

For modules logging, can we simply replace " with ' in-place in moduleLogRaw?

@madolson Ah, so do we need to get #11747 merged before we can proceed with this and avoid escaping stuff in message? (I don't like that PRs are blocked by other PRs. Maybe we can just change " to ' in that log entry for now?)

Let's do as you suggested for the moment. Let's also make a debug assertion so we never add the " for any logs.

For modules logging, can we simply replace " with ' in-place in moduleLogRaw?

Like at runtime? I suppose that works, but is also a bit of a breaking change.

Yes at runtime. Or replace with \". What else can we do?

Yes at runtime. Or replace with ". What else can we do?

I suppose we probably need to do that now.

madolson · 2024-01-11T18:31:40Z

Also just wanted to mention #12932 for reference.

CharlesChen888 · 2024-01-12T02:51:08Z

Does this mean we will have two new configs, one for enabling json logfmt, another one for selecting timestamp format?

madolson · 2024-01-12T05:08:17Z

Does this mean we will have two new configs, one for enabling json logfmt, another one for selecting timestamp format?

I don't have a great alternative suggestion without making a complex configuration argument.

ecerulm · 2024-01-12T07:48:46Z

Regarding timestamps #12932, I guess most of the time user would like to see millisecond or microseconds resolution, a configurable strftime() format specification won't cut it because there is no way to specify milliseconds / microseconds in linux's strftime(). Linux strftime() does not have it, and I think BSD's strftime does not have it either.

Even today redis source code adds the milliseconds outside the strftime() as show on

redis/src/server.c

Lines 138 to 139 in 9d0158b

    
           off = strftime(buf,sizeof(buf),"%d %b %Y %H:%M:%S.",&tm); 
        
           snprintf(buf+off,sizeof(buf)-off,"%03d",(int)tv.tv_usec/1000);

So then you would need to create your own extended "format specification" supporting "%f" for microseconds (like python does) and to hide differences between strftime format specification across operating system.

Summarizing the issues with strftime() are in my opinion

strftime format specification differences between operating systems
strftime usually does not allow fractional seconds/ milliseconds / microseconds

To me it seems simpler to enforce a ISO 8601 with microsecond resolution and utc offset:

2024-01-11T12:45:30.123456+02:00

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream · 2024-01-12T22:23:30Z

Added timestamp_format enum.
Use reader friendly role and verbose_level string in logfmt ouput.

azuredream · 2024-01-12T22:37:55Z

DEFAULT
42888:M 12 Jan 2024 18:26:34.377 * Server initialized
42888:M 12 Jan 2024 18:26:34.377 * Ready to accept connections tcp

LOG_FORMAT_LOGFMT + LOG_TIMESTAMP_DEFAULT
pid=43765 role=master   timestamp="12 Jan 2024 18:29:14.441" level=notice  message="Server initialized"
pid=43765 role=master   timestamp="12 Jan 2024 18:29:14.441" level=notice  message="Ready to accept connections tcp"

LOG_FORMAT_LOGFMT + LOG_TIMESTAMP_ISO8601
pid=44325 role=master   timestamp="2024-01-12T18:31:24.697+0000" level=notice  message="Server initialized"
pid=44325 role=master   timestamp="2024-01-12T18:31:24.697+0000" level=notice  message="Ready to accept connections tcp"


LOG_FORMAT_LOGFMT + LOG_TIMESTAMP_UNIX
pid=44790 role=master   timestamp="1705102366" level=notice  message="Server initialized"
pid=44790 role=master   timestamp="1705102366" level=notice  message="Ready to accept connections tcp"

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream · 2024-01-19T00:17:56Z

Hi @zuiderkwast. Any comment on this PR?

zuiderkwast

I'm OK with the config, but it is marked with major-decision which means the core team will need to decide about the config in a meeting. (I'm not in the core team.)

Maybe it's better to wait until the config has been decided before changing the details of the code.

src/server.c

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream · 2024-01-21T14:52:29Z

Thanks for your review. Updated.

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream · 2024-01-21T15:37:48Z

src/server.c

+                break;
+        }
+
+        switch (server.log_format) {


There are 6 combinations of log_format X role. Could be more moving forward. This is another way to code the logic, but I'm not sure if it's the "better" way...
It does keep the minimum memory usage for role print though.

I think this approach is sensible enough.

We could do like we do for verbosity level. For the legacy format we pick a char from "XCSM" and for logfmt a string from an array, same index.

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

src/server.c

src/server.h

madolson · 2024-01-23T00:33:52Z

@azuredream Thanks for all your involvement, we'll discuss it tomorrow and give directional input if this is the best format for it to be accepted. Thanks for all your help so far.

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream · 2024-01-26T02:48:41Z

Hi @madolson. Thanks for review. I just updated my PR based on your suggestions.

madolson · 2024-01-30T05:05:13Z

@redis/core-team Please review the two configurations at the top for a high level approval. There is one pending question, which is what to do about module logging that might inject ", which would break the logfmt structure.

oranagra · 2024-01-30T09:31:43Z

can someone edit the top comment to provide some overview of the differences (examples), as well as justification for this feature?

src/server.c

azuredream · 2024-01-31T02:23:54Z

can someone edit the top comment to provide some overview of the differences (examples), as well as justification for this feature?

Thanks to @zuiderkwast for updating the top comment.
I added some examples.

azuredream · 2024-01-31T02:25:42Z

PR updated.
Fixed an issue in nolocks_localtime(). The timezone field was not set.

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream · 2024-01-31T03:25:46Z

Not sure how to make tm_gmtoff work on every the platform. Maybe that's why it was not set before.
Any advice on this?

oranagra · 2024-01-31T08:07:32Z

i still don't see the top comment mentions the justification.
specifically, why do we want to change the log format, and specifically why is logmft the right one.

our log file isn't an API, and for the most part we feel free to add / remove rephrase messages, or change their log level, so i wonder why would someone want to parse by software.

zuiderkwast · 2024-01-31T08:26:14Z

src/server.c

+                snprintf(buf+off,sizeof(buf)-off,"%03d",(int)tv.tv_usec/1000);
+                char tzbuf[6];
+                strftime(tzbuf, sizeof(tzbuf), "%z", &tm);
+                char tz_formatted[7];
+                snprintf(tz_formatted, sizeof(tz_formatted), "%c%c%c:%c%c", tzbuf[0], tzbuf[1], tzbuf[2], tzbuf[3], tzbuf[4]);
+                strncat(buf, tz_formatted, sizeof(buf) - strlen(buf) - 1);


Good, but maybe we can do it with only one snprintf for milliseconds and time zone?

Suggested change

snprintf(buf+off,sizeof(buf)-off,"%03d",(int)tv.tv_usec/1000);

char tzbuf[6];

strftime(tzbuf, sizeof(tzbuf), "%z", &tm);

char tz_formatted[7];

snprintf(tz_formatted, sizeof(tz_formatted), "%c%c%c:%c%c", tzbuf[0], tzbuf[1], tzbuf[2], tzbuf[3], tzbuf[4]);

strncat(buf, tz_formatted, sizeof(buf) - strlen(buf) - 1);

char tzbuf[6];

strftime(tzbuf, sizeof(tzbuf), "%z", &tm);

snprintf(buf + off, sizeof(buf) - off, "%03d%c%c%c:%c%c",

(int)tv.tv_usec/1000,

tzbuf[0], tzbuf[1], tzbuf[2], tzbuf[3], tzbuf[4]);

Thanks. Updated as your suggestion.

zuiderkwast · 2024-01-31T08:37:05Z

@oranagra The motivation is in the linked issue #12918. I thought it was linked before but it wasn't so I linked it now.

@azuredream Hint for another time: Include Fixes #12918 or Closes #12918 in the PR description to automatically link it to the issue.

azuredream · 2024-01-31T13:20:32Z

@oranagra The motivation is in the linked issue #12918. I thought it was linked before but it wasn't so I linked it now.

@azuredream Hint for another time: Include Fixes #12918 or Closes #12918 in the PR description to automatically link it to the issue.

Thanks! I linked two issues that may be closed by this PR

soloestoy · 2024-02-01T06:53:24Z

I have no opinion to logfmt (neither supporting nor opposing), but I do believe that time zone information is useful. It helps to determine the actual time when deploying globally. Another PR #12939 has been submitted separately to add time zone information.

zuiderkwast · 2024-02-01T11:47:50Z

@redis/core-team There are three more or less orthogonal things to take decisions about here:

Add time zone info in timestamps. This is new info that we don't have today.
Timestamp format. Presumably a more standard format is easier to consume by tools.
Log format that can be more easily aggregated by generic tools ("slurped", "grokkable by telemetry collection systems"). JSON or logfmt or some other format would do. (Logfmt seemed simpler than JSON. I assume we don't want to add a JSON lib to Redis.)

You may want to decide about each of these separately.

azuredream · 2024-02-04T15:31:59Z

Implemented a function to populate timezone string since gmtoff + strftime is not always available.

The tm_gmtoff field is derived from BSD and is a GNU library extension; it is not visible in a strict ISO C environment.

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

CLAassistant · 2024-03-24T23:04:03Z

All committers have signed the CLA.

Configuration option to output logs in logfmt

22937cf

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

zuiderkwast reviewed Jan 11, 2024

View reviewed changes

madolson added the state:major-decision Requires core team consensus label Jan 11, 2024

ecerulm mentioned this pull request Jan 12, 2024

[NEW] Add timezone to redis logs #12932

Open

CharlesChen888 mentioned this pull request Jan 12, 2024

Print time zone in server log. #12939

Closed

Configuration option to output logs in logfmt

22276d4

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream added 3 commits January 12, 2024 17:39

Configuration option to output logs in logfmt

cee0b01

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

Configuration option to output logs in logfmt

34a7453

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

Configuration option to output logs in logfmt

f1ab440

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream mentioned this pull request Jan 12, 2024

[NEW] Configuration option to output logs in JSON format or logfmt #12918

Open

zuiderkwast reviewed Jan 19, 2024

View reviewed changes

src/server.c Outdated Show resolved Hide resolved

src/server.c Outdated Show resolved Hide resolved

src/server.c Outdated Show resolved Hide resolved

Configuration option to output logs in logfmt

7266874

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

Configuration option to output logs in logfmt

68580e7

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

azuredream commented Jan 21, 2024

View reviewed changes

Configuration option to output logs in logfmt

30c2314

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

madolson reviewed Jan 23, 2024

View reviewed changes

src/server.c Outdated Show resolved Hide resolved

madolson reviewed Jan 23, 2024

View reviewed changes

src/server.h Outdated Show resolved Hide resolved

azuredream added 2 commits January 25, 2024 21:35

Merge branch 'redis:unstable' into log-in-logfmt-style

4f518b5

Configuration option to output logs in logfmt

aa1370f

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

zuiderkwast reviewed Jan 30, 2024

View reviewed changes

src/server.c Outdated Show resolved Hide resolved

Configuration option to output logs in logfmt

c457d44

azuredream added 2 commits January 30, 2024 21:36

Configuration option to output logs in logfmt

7ed5616

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

Configuration option to output logs in logfmt

69d36e6

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

zuiderkwast reviewed Jan 31, 2024

View reviewed changes

zuiderkwast linked an issue Jan 31, 2024 that may be closed by this pull request

[NEW] Configuration option to output logs in JSON format or logfmt #12918

Open

Configuration option to output logs in logfmt

b7d1327

azuredream added 3 commits February 4, 2024 10:35

Configuration option to output logs in logfmt

92e2bf2

Configuration option to output logs in logfmt

11c6bd5

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

Configuration option to output logs in logfmt

c755a32

Signed-off-by: azuredream <zhaozixuan67@gmail.com>

Configuration option to output logs in logfmt #12934

Are you sure you want to change the base?

Configuration option to output logs in logfmt #12934

Conversation

azuredream commented Jan 11, 2024 • edited

zuiderkwast left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zuiderkwast Jan 11, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

madolson Jan 11, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

madolson commented Jan 11, 2024

CharlesChen888 commented Jan 12, 2024 • edited

madolson commented Jan 12, 2024

ecerulm commented Jan 12, 2024 • edited

azuredream commented Jan 12, 2024

azuredream commented Jan 12, 2024 • edited

azuredream commented Jan 19, 2024

zuiderkwast left a comment

Choose a reason for hiding this comment

azuredream commented Jan 21, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

madolson commented Jan 23, 2024

azuredream commented Jan 26, 2024

madolson commented Jan 30, 2024

oranagra commented Jan 30, 2024

azuredream commented Jan 31, 2024

azuredream commented Jan 31, 2024

azuredream commented Jan 31, 2024

oranagra commented Jan 31, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zuiderkwast commented Jan 31, 2024

azuredream commented Jan 31, 2024

soloestoy commented Feb 1, 2024

zuiderkwast commented Feb 1, 2024 • edited

azuredream commented Feb 4, 2024 • edited

CLAassistant commented Mar 24, 2024 • edited

azuredream commented Jan 11, 2024 •

edited

zuiderkwast Jan 11, 2024 •

edited

madolson Jan 11, 2024 •

edited

CharlesChen888 commented Jan 12, 2024 •

edited

ecerulm commented Jan 12, 2024 •

edited

azuredream commented Jan 12, 2024 •

edited

zuiderkwast commented Feb 1, 2024 •

edited

azuredream commented Feb 4, 2024 •

edited

CLAassistant commented Mar 24, 2024 •

edited