[NEW] Output logs as JSON

[4mig4]

Would it be possible to get Redis logs output in JSON format with a timestamp that has timezone information as the first field. This is useful when integrating and using redis in large kubernetes based systems which ingest and demand JSON logs to stdout for all apps.

[madolson]

There was a previous PR in Redis where we discussed some log format:

Copied from a copy of Redis #12934, explicitly didn't include a reference to avoid having folks reference Redis issue. 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"

More information as well

The problem/use-case that the feature addresses

The redis logs include datetime / timestamps in local timezone like the one below:

26838:C 27 Oct 2024 02:30:00.000 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

the utc offset for the timezone is not included.

So for the log entry above is not possible to determine if it happened 2024-10-27 02:30:00 +0100 or "2024-10-27 02:30:00 +0200". Specially since on 2024-10-27 03:00:00 +02:00 is when the daylight saving from CEST to CET happen, so on 2024-10-27 03:00:00 +0200 changes to 2024-10-27 02:00:00 +0100.

Description of the feature

I want a new configuration parameter that enables the printing of the timezone, so when the configuration parameter is set the log format will change from

26838:C 27 Oct 2024 02:30:00.000 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

to

26838:C 27 Oct 2024 02:30:00.000+0200 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

note the +0200

Alternatives you've considered

Forcing the timezone to be UTC by setting TZ="UTC", then the timestamp can be consistently parsed since the time printed does not shift due to daylight savings.

For example

date
Wed Jan 10 15:35:04 CET 2024

TZ="UTC" redis-server
27354:C 10 Jan 2024 14:35:04.766 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

Additional information

Any additional information that is relevant to the feature request.

@azuredream I see you opened the old PR to Redis, would you be willing to also contribute your change to Valkey?

[madolson]

It's very timely for you to open this issue, we talked about this morning as thinking about revamping logs. Can you add a bit more context about what JSON format you want? Either a similar system that outputs in a format that is a bit of a standard.

[4mig4]

{ "time": "ISO8601 timestamp", "severity": "critical" , "message": "some message" }

Of course you can have any other fields you want in the JSON such as PID , role , etc...

the ISO8601 timestamping is particularly important, because TZ Offset , as we have many geographical locations and need to be able to canonize/reconciliate timestamp in a single timezone wherever the logs are consolidated. The ability to also specify the TZ offset in a particular location is also important in case we are asked to log everything in UTC.

Also the ability to log to a local file and/or to STDOUT is very important ( in Kubernetes) and thus to be able to choose either or both from the config file of Valkey as an option.

Something along these lines

[azuredream]

Hi @madolson. I'm glad to contribute to Valkey. PR: #1022

[andoks]

An example of why being able to get the logs in a structured format (like json or logfmt) would be a good thing, is that it makes it easier to consume and automatically tag log entries in systems like Grafana Loki (which has support for parsing both json and logfmt). It would help a lot if all log entries also was defined with a log level (a list of what for example Grafana Loki recognizes as levels can be seen here).

EDIT: A more in depth description of structured logs and their pros can be found at https://github.com/go-logr/logr?tab=readme-ov-file#why-structured-logging

EDIT2: For anyone wanting to parse the current format, I built this RE2 regex expression for parsing the log entries with loki and the loki-pipeline-stages.regex support: ^(?P<pid>\d+):(?P<mode>\S) (?P<ts>\d{1,2} \S{1,3} \d{4} \d{1,2}:\d{1,2}:\d{1,2}\.\d{0,3}) (?P<level>[\.\-\*\#]) (?P<message>.*)$

See full loki pipeline stage code

```yaml options: loki-pipeline-stages: | - regex: # information about log format found in source code here: # https://github.com/valkey-io/valkey/blob/bf8183d065f07b40d465cca818a51689036b7488/src/server.c#L114 # levels found at: # https://github.com/valkey-io/valkey/blob/bf8183d065f07b40d465cca818a51689036b7488/src/server.h#L463 # (NB: LL_NOTHING is only used internally in valkey for disabling # logging entirely) expression: '^(?P\d+):(?P\S) (?P\d{1,2} \S{1,3} \d{4} \d{1,2}:\d{1,2}:\d{1,2}\.\d{0,3}) (?P[\.\-\*\#]) (?P.*)$' - replace: expression: '(\.)' source: "level" replace: "debug" - replace: expression: '(-)' source: "level" replace: "info" - replace: expression: '(\*)' source: "level" replace: "info" - replace: expression: '(#)' source: "level" replace: "warn" - labels: level: - timestamp: source: "timestamp" format: "02 Jan 2006 15:04:05.999" # not setting output to msg, as we would lose pid and mode information, in case that is interesting ```

[andoks]

Could it be worth looking into making the logs "compatible" with OpenTelemetry as part of this effort? I see OpenTelemetry is a CNCF project, which "belongs" to the Linux Foundation.