From 9b5c0bd91eaead592fa7a44658896cee8b13006d Mon Sep 17 00:00:00 2001 From: Binbin Date: Sat, 10 Aug 2024 23:46:56 +0800 Subject: [PATCH] Correctly recode client infomation to the slowlog when runing script (#805) Currently when we are runing a script, we will passing a fake client. So if the command executed in the script is recoded in the slowlog, the client's ip:port and name information will be empty. before: ``` 127.0.0.1:6379> client setname myclient OK 127.0.0.1:6379> config set slowlog-log-slower-than 0 OK 127.0.0.1:6379> eval "redis.call('ping')" 0 (nil) 127.0.0.1:6379> slowlog get 2 1) 1) (integer) 2 2) (integer) 1721314289 3) (integer) 96 4) 1) "eval" 2) "redis.call('ping')" 3) "0" 5) "127.0.0.1:61106" 6) "myclient" 2) 1) (integer) 1 2) (integer) 1721314289 3) (integer) 4 4) 1) "ping" 5) "" 6) "" ``` after: ``` 127.0.0.1:6379> client setname myclient OK 127.0.0.1:6379> config set slowlog-log-slower-than 0 OK 127.0.0.1:6379> eval "redis.call('ping')" 0 (nil) 127.0.0.1:6379> slowlog get 2 1) 1) (integer) 2 2) (integer) 1721314371 3) (integer) 53 4) 1) "eval" 2) "redis.call('ping')" 3) "0" 5) "127.0.0.1:51983" 6) "myclient" 2) 1) (integer) 1 2) (integer) 1721314371 3) (integer) 1 4) 1) "ping" 5) "127.0.0.1:51983" 6) "myclient" ``` Signed-off-by: Binbin --- src/server.c | 7 +++++++ tests/unit/slowlog.tcl | 38 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 45 insertions(+) diff --git a/src/server.c b/src/server.c index 0f63bcb02..6979d0981 100644 --- a/src/server.c +++ b/src/server.c @@ -3275,6 +3275,13 @@ void slowlogPushCurrentCommand(client *c, struct serverCommand *cmd, ustime_t du * arguments. */ robj **argv = c->original_argv ? c->original_argv : c->argv; int argc = c->original_argv ? c->original_argc : c->argc; + + /* If a script is currently running, the client passed in is a + * fake client. Or the client passed in is the original client + * if this is a EVAL or alike, doesn't matter. In this case, + * use the original client to get the client information. */ + c = scriptIsRunning() ? scriptGetCaller() : c; + slowlogPushEntryIfNeeded(c, argv, argc, duration); } diff --git a/tests/unit/slowlog.tcl b/tests/unit/slowlog.tcl index f1acbaa0f..1be530d37 100644 --- a/tests/unit/slowlog.tcl +++ b/tests/unit/slowlog.tcl @@ -248,4 +248,42 @@ start_server {tags {"slowlog"} overrides {slowlog-log-slower-than 1000000}} { $rd close } + + foreach is_eval {0 1} { + test "SLOWLOG - the commands in script are recorded normally - is_eval: $is_eval" { + if {$is_eval == 0} { + r function load replace "#!lua name=mylib \n redis.register_function('myfunc', function(KEYS, ARGS) server.call('ping') end)" + } + + r client setname test-client + r config set slowlog-log-slower-than 0 + r slowlog reset + + if {$is_eval} { + r eval "server.call('ping')" 0 + } else { + r fcall myfunc 0 + } + set slowlog_resp [r slowlog get 2] + assert_equal 2 [llength $slowlog_resp] + + # The first one is the script command, and the second one is the ping command executed in the script + # Each slowlog contains: id, timestamp, execution time, command array, ip:port, client name + set script_cmd [lindex $slowlog_resp 0] + set ping_cmd [lindex $slowlog_resp 1] + + # Make sure the command are logged. + if {$is_eval} { + assert_equal {eval server.call('ping') 0} [lindex $script_cmd 3] + } else { + assert_equal {fcall myfunc 0} [lindex $script_cmd 3] + } + assert_equal {ping} [lindex $ping_cmd 3] + + # Make sure the client info are the logged. + assert_equal [lindex $script_cmd 4] [lindex $ping_cmd 4] + assert_equal {test-client} [lindex $script_cmd 5] + assert_equal {test-client} [lindex $ping_cmd 5] + } + } }