Configuration option to output logs in logfmt

[azuredream]

See more disscussion: https://github.com/redis/redis/pull/12934

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.

#1006

$ ./valkey-server  /home/zhaoz12/git/valkey/valkey/valkey.conf
pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=warning message="WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect."
pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo"
pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="Valkey version=255.255.255, bits=64, commit=affbea5d, modified=1, pid=109463, just started"
pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="Configuration loaded"
pid=109463 role=master timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="monotonic clock: POSIX clock_gettime"
pid=109463 role=master timestamp="2024-09-10T20:37:25.739-04:00" level=warning message="Failed to write PID file: Permission denied"

[codecov[bot]]

Codecov Report

Attention: Patch coverage is 24.07407% with 41 lines in your changes missing coverage. Please review.

Project coverage is 70.62%. Comparing base (262d970) to head (3b0084d). Report is 30 commits behind head on unstable.

Files with missing lines	Patch %	Lines
src/server.c	24.07%	41 Missing :warning:

Additional details and impacted files

@@             Coverage Diff              @@
##           unstable    #1022      +/-   ##
============================================
+ Coverage     70.61%   70.62%   +0.01%     
============================================
  Files           114      114              
  Lines         61734    63125    +1391     
============================================
+ Hits          43595    44584     +989     
- Misses        18139    18541     +402     

Files with missing lines	Coverage Δ
src/config.c	78.84% <ø> (+0.14%)	:arrow_up:
src/server.h	100.00% <ø> (ø)
src/server.c	87.67% <24.07%> (-0.97%)	:arrow_down:

... and 90 files with indirect coverage changes

[madolson]

😀 thanks for opening this, we're working on launching the next version but will take a look shortly.

[PingXie]

I like this change. Free-form log lines can be tricky to parse and search, and this feels like a good step toward adopting more structured logging. We could even extend it further to include properties like "area" (e.g., "cluster," "normal replication," "dual channel replication," etc.). Thanks for your work on this, @azuredream!

[madolson]

@valkey-io/core-team Please indicate your vote on this comment. The open questions I still have are if we want to also do the larger investigation before 8.1 launches about also including the component the log was generated from. We also have the JSON format to add on.

[azuredream]

@madolson @zuiderkwast PR updated as you suggested. Thanks for reviewing.

[azuredream]

Demo logs:

log-format logfmt log-timestamp-format milliseconds

pid=557888 role=RDB/AOF timestamp="1728757076.562" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo"

log-format legacy log-timestamp-format milliseconds

558253:C 1728757310.034 * oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo

log-format logfmt log-timestamp-format iso8601

pid=558427 role=RDB/AOF timestamp="2024-10-12T14:24:28.141-04:00" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo"

log-format legacy log-timestamp-format iso8601

558523:C 2024-10-12T14:24:57.923-04:00 * oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo

log-format logfmt log-timestamp-format legacy

pid=558599 role=RDB/AOF timestamp="12 Oct 2024 14:25:59.813" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo"

log-format legacy log-timestamp-format legacy

558689:C 12 Oct 2024 14:26:30.872 * oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo

[azuredream]

Code updateded.

[azuredream]

Is the Valkey logo logged on startup? It must look very weird with logfmt?

Actually it looks fine

pid=716151 role=RDB/AOF timestamp="1729404137284" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo"
pid=716151 role=RDB/AOF timestamp="1729404137284" level=notice message="Valkey version=255.255.255, bits=64, commit=ca0cedf5, modified=1, pid=716151, just started"
pid=716151 role=RDB/AOF timestamp="1729404137284" level=notice message="Configuration loaded"
pid=716151 role=primary timestamp="1729404137285" level=notice message="monotonic clock: POSIX clock_gettime"
pid=716151 role=primary timestamp="1729404137286" level=warning message="Failed to write PID file: Permission denied"
                .+^+.                                                
            .+#########+.                                            
        .+########+########+.           Valkey 255.255.255 (ca0cedf5/1) 64 bit
    .+########+'     '+########+.                                    
 .########+'     .+.     '+########.    Running in standalone mode
 |####+'     .+#######+.     '+####|    Port: 6379
 |###|   .+###############+.   |###|    PID: 716151                     
 |###|   |#####*'' ''*#####|   |###|                                 
 |###|   |####'  .-.  '####|   |###|                                 
 |###|   |###(  (@@@)  )###|   |###|          https://valkey.io      
 |###|   |####.  '-'  .####|   |###|                                 
 |###|   |#####*.   .*#####|   |###|                                 
 |###|   '+#####|   |#####+'   |###|                                 
 |####+.     +##|   |#+'     .+####|                                 
 '#######+   |##|        .+########'                                 
    '+###|   |##|    .+########+'                                    
        '|   |####+########+'                                        
             +#########+'                                            
                '+v+' 

[azuredream]

Updated comment, fixed format, fixed unsigned commit.

I appreciate your continuous effort to review my contributions and provide valuable suggestions for improvements. Thanks to all of you. @zuiderkwast @madolson @PingXie

[zuiderkwast]

I appreciate your continuous effort to review my contributions and provide valuable suggestions for improvements.

Thanks, that's our job. :) Thanks for your patience!

It's a bit weird that we print role=RDB/AOF for the messages during startup, like "oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo". I guess it was always a "C" for these messages, but I never noticed it.

[azuredream]

It's a bit weird that we print role=RDB/AOF for the messages during startup, like "oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo". I guess it was always a "C" for these messages, but I never noticed it.

Please refer to the discussion around Jan 11th. We introduced reader friendly role string Intentionally. https://github.com/redis/redis/pull/12934

    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?

[zuiderkwast]

I know we want reader-friendly role. What I think is weird is that we print RDB/AOF during startup. This is not a forked child process performing RDB dump or AOF rewrite.

Now I see why: server.pid has not been initialized yet when these line are logged. (I think we can initialize server.pid earlier, but that is for another PR. It's a separate discussion.)

[azuredream]

Now I see why: server.pid has not been initialized yet when these line are logged. (I think we can initialize server.pid earlier, but that is for another PR. It's a separate discussion.)

I think that means I don't need to update this PR. I'll be glad to help if there is any further requirement.

[zuiderkwast]

Now I see why: server.pid has not been initialized yet when these line are logged. (I think we can initialize server.pid earlier, but that is for another PR. It's a separate discussion.)

I think that means I don't need to update this PR. I'll be glad to help if there is any further requirement.

That's right, I hope this PR is ready to merge now. @madolson do you have any more comments before we merge this?

@azuredream If you want to make a follow-up PR for the role during startup, please continue reading...

1. I'm looking at where server.pid = getpid() is done. Currently, it's done in initServer() but it would be better to do it before the first logging happens, in main() before we load config files. This is a simple fix. With this change, we will print "primary" instead of "RDB/AOF" during startup, which I think makes more sense. The server starts as a primary. Do you want to do it in a follow-up PR?

2. Another potential problem. Actually, I don't think this one is a problem we can solve, but maybe something we can mention in the documentation later.

   I see that loading config is done early during startup. It can happen that some messages are logged before we set the logging format config, so maybe we get some log lines with the legacy format before we switch to logfmt. That's also not good if we want to parse the file using logfmt tools.

   If we fail to load a config file, we log "Fatal error, can't open config file '%s': %s" and exit. We always load a config file before we read any config provided on the command line (in valkey-server dummy.conf --log-format logfmt, the file is loaded first) so there is no way to get this logged in logfmt format. We probably don't want to change the behaviour to load configs on the command line before the file. That would be a breaking change, I think.

   Another message is when we load config from stdin.

    serverLog(LL_NOTICE, "Reading config from stdin");
   

   To read config from stdin, you pass "-" on the command line. I tried this and I used echo to pipe some config to it. I got one line of "legacy" log before switching to logfmt:

   $ echo "save ''" | ./valkey-server --log-format logfmt -
   514332:C 21 Oct 2024 10:53:37.887 * Reading config from stdin
   pid=514332 role=RDB/AOF timestamp="21 Oct 2024 10:53:37.887" level=warning message="WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect."
   pid=514332 role=RDB/AOF timestamp="21 Oct 2024 10:53:37.888" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo"
   ...
   

   One line of legacy log format, before we switch to logfmt. I don't know if we can solve this. Just like when loading from a file, we load the stdin before any command line config flags.

[azuredream]

1. I'm looking at where server.pid = getpid() is done. Currently, it's done in initServer() but it would be better to do it before the first logging happens, in main() before we load config files. This is a simple fix. With this change, we will print "primary" instead of "RDB/AOF" during startup, which I think makes more sense. The server starts as a primary. Do you want to do it in a follow-up PR?

Sure. Please feel free to create an issue and assign to me.

[zuiderkwast]

Please feel free to create an issue and assign to me.

We don't need issues for everything, but if you insist...

[zuiderkwast]

Document log format configs in valkey.conf

Configs are documented there. We missed that. Let's do it as a follow-up.

[madolson]

That's right, I hope this PR is ready to merge now. @madolson do you have any more comments before we merge this?

@zuiderkwast Apparently I had some pending comments which I never published. The main was just I realized there was no tests here, which would probably be useful to add. If you agree I can make an issue for it.