Cleanup around script_caller, fix tracking of scripts and ACL logging for RM_Call (#11770)

* Make it clear that current_client is the root client that was called by
  external connection
* add executing_client which is the client that runs the current command
  (can be a module or a script)
* Remove script_caller that was used for commands that have CLIENT_SCRIPT
  to get the client that called the script. in most cases, that's the current_client,
  and in others (when being called from a module), it could be an intermediate
  client when we actually want the original one used by the external connection.

bugfixes:
* RM_Call with C flag should log ACL errors with the requested user rather than
  the one used by the original client, this also solves a crash when RM_Call is used
  with C flag from a detached thread safe context.
* addACLLogEntry would have logged info about the script_caller, but in case the
  script was issued by a module command we actually want the current_client. the
  exception is when RM_Call is called from a timer event, in which case we don't
  have a current_client.

behavior changes:
* client side tracking for scripts now tracks the keys that are read by the script
  instead of the keys that are declared by the caller for EVAL

other changes:
* Log both current_client and executing_client in the crash log.
* remove prepareLuaClient and resetLuaClient, being dead code that was forgotten.
* remove scriptTimeSnapshot and snapshot_time and instead add cmd_time_snapshot
  that serves all commands and is reset only when execution nesting starts.
* remove code to propagate CLIENT_FORCE_REPL from the executed command
  to the script caller since scripts aren't propagated anyway these days and anyway
  this flag wouldn't have had an effect since CLIENT_PREVENT_PROP is added by scriptResetRun.
* fix a module GIL violation issue in afterSleep that was introduced in #10300 (unreleased)

6 files changed, 194 insertions, 13 deletions

diff --git a/tests/integration/replication.tcl b/tests/integration/replication.tcl
index e23edad9d..b4e9ee673 100644
--- a/tests/integration/replication.tcl
+++ b/tests/integration/replication.tcl
@@ -253,12 +253,15 @@ start_server {tags {"repl external:skip"}} {
             # DB is empty.
             r -1 flushdb
             r -1 flushdb
-            r -1 flushdb
+            r -1 eval {redis.call("flushdb")} 0
 
             # DBs are empty.
             r -1 flushall
             r -1 flushall
-            r -1 flushall
+            r -1 eval {redis.call("flushall")} 0
+
+            # add another command to check nothing else was propagated after the above
+            r -1 incr x
 
             # Assert that each FLUSHDB command is replicated even the DB is empty.
             # Assert that each FLUSHALL command is replicated even the DBs are empty.
@@ -273,6 +276,7 @@ start_server {tags {"repl external:skip"}} {
                 {flushall}
                 {flushall}
                 {flushall}
+                {incr x}
             }
             close_replication_stream $repl
         }
diff --git a/tests/modules/usercall.c b/tests/modules/usercall.c
index 9eb84ef39..6b23974d4 100644
--- a/tests/modules/usercall.c
+++ b/tests/modules/usercall.c
@@ -1,4 +1,8 @@
 #include "redismodule.h"
+#include <pthread.h>
+#include <assert.h>
+
+#define UNUSED(V) ((void) V)
 
 RedisModuleUser *user = NULL;
 
@@ -103,6 +107,98 @@ int reset_user(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) {
     return REDISMODULE_OK;
 }
 
+typedef struct {
+    RedisModuleString **argv;
+    int argc;
+    RedisModuleBlockedClient *bc;
+} bg_call_data;
+
+void *bg_call_worker(void *arg) {
+    bg_call_data *bg = arg;
+
+    // Get Redis module context
+    RedisModuleCtx *ctx = RedisModule_GetThreadSafeContext(bg->bc);
+
+    // Acquire GIL
+    RedisModule_ThreadSafeContextLock(ctx);
+
+    // Set user
+    RedisModule_SetContextUser(ctx, user);
+
+    // Call the command
+    size_t format_len;
+    RedisModuleString *format_redis_str = RedisModule_CreateString(NULL, "v", 1);
+    const char *format = RedisModule_StringPtrLen(bg->argv[1], &format_len);
+    RedisModule_StringAppendBuffer(NULL, format_redis_str, format, format_len);
+    RedisModule_StringAppendBuffer(NULL, format_redis_str, "E", 1);
+    format = RedisModule_StringPtrLen(format_redis_str, NULL);
+    const char *cmd = RedisModule_StringPtrLen(bg->argv[2], NULL);
+    RedisModuleCallReply *rep = RedisModule_Call(ctx, cmd, format, bg->argv + 3, bg->argc - 3);
+    RedisModule_FreeString(NULL, format_redis_str);
+
+    // Release GIL
+    RedisModule_ThreadSafeContextUnlock(ctx);
+
+    // Reply to client
+    if (!rep) {
+        RedisModule_ReplyWithError(ctx, "NULL reply returned");
+    } else {
+        RedisModule_ReplyWithCallReply(ctx, rep);
+        RedisModule_FreeCallReply(rep);
+    }
+
+    // Unblock client
+    RedisModule_UnblockClient(bg->bc, NULL);
+
+    /* Free the arguments */
+    for (int i=0; i<bg->argc; i++)
+        RedisModule_FreeString(ctx, bg->argv[i]);
+    RedisModule_Free(bg->argv);
+    RedisModule_Free(bg);
+
+    // Free the Redis module context
+    RedisModule_FreeThreadSafeContext(ctx);
+
+    return NULL;
+}
+
+int call_with_user_bg(RedisModuleCtx *ctx, RedisModuleString **argv, int argc)
+{
+    UNUSED(argv);
+    UNUSED(argc);
+
+    /* Make sure we're not trying to block a client when we shouldn't */
+    int flags = RedisModule_GetContextFlags(ctx);
+    int allFlags = RedisModule_GetContextFlagsAll();
+    if ((allFlags & REDISMODULE_CTX_FLAGS_MULTI) &&
+        (flags & REDISMODULE_CTX_FLAGS_MULTI)) {
+        RedisModule_ReplyWithSimpleString(ctx, "Blocked client is not supported inside multi");
+        return REDISMODULE_OK;
+    }
+    if ((allFlags & REDISMODULE_CTX_FLAGS_DENY_BLOCKING) &&
+        (flags & REDISMODULE_CTX_FLAGS_DENY_BLOCKING)) {
+        RedisModule_ReplyWithSimpleString(ctx, "Blocked client is not allowed");
+        return REDISMODULE_OK;
+    }
+
+    /* Make a copy of the arguments and pass them to the thread. */
+    bg_call_data *bg = RedisModule_Alloc(sizeof(bg_call_data));
+    bg->argv = RedisModule_Alloc(sizeof(RedisModuleString*)*argc);
+    bg->argc = argc;
+    for (int i=0; i<argc; i++)
+        bg->argv[i] = RedisModule_HoldString(ctx, argv[i]);
+
+    /* Block the client */
+    bg->bc = RedisModule_BlockClient(ctx, NULL, NULL, NULL, 0);
+
+    /* Start a thread to handle the request */
+    pthread_t tid;
+    int res = pthread_create(&tid, NULL, bg_call_worker, bg);
+    assert(res == 0);
+
+    return REDISMODULE_OK;
+}
+
 int RedisModule_OnLoad(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) {
     REDISMODULE_NOT_USED(argv);
     REDISMODULE_NOT_USED(argc);
@@ -116,6 +212,9 @@ int RedisModule_OnLoad(RedisModuleCtx *ctx, RedisModuleString **argv, int argc)
     if (RedisModule_CreateCommand(ctx,"usercall.call_with_user_flag", call_with_user_flag,"write",0,0,0) == REDISMODULE_ERR)
         return REDISMODULE_ERR;
 
+    if (RedisModule_CreateCommand(ctx, "usercall.call_with_user_bg", call_with_user_bg, "write", 0, 0, 0) == REDISMODULE_ERR)
+        return REDISMODULE_ERR;
+
     if (RedisModule_CreateCommand(ctx, "usercall.add_to_acl", add_to_acl, "write",0,0,0) == REDISMODULE_ERR)
         return REDISMODULE_ERR;
 
diff --git a/tests/unit/acl.tcl b/tests/unit/acl.tcl
index a6c2d6eff..59626caaf 100644
--- a/tests/unit/acl.tcl
+++ b/tests/unit/acl.tcl
@@ -652,6 +652,7 @@ start_server {tags {"acl external:skip"}} {
         assert {[dict get $entry context] eq {toplevel}}
         assert {[dict get $entry reason] eq {command}}
         assert {[dict get $entry object] eq {get}}
+        assert_match {*cmd=get*} [dict get $entry client-info]
     }
 
     test "ACL LOG shows failed subcommand executions at toplevel" {
@@ -728,6 +729,7 @@ start_server {tags {"acl external:skip"}} {
         set entry [lindex [r ACL LOG] 0]
         assert {[dict get $entry context] eq {multi}}
         assert {[dict get $entry object] eq {incr}}
+        assert_match {*cmd=exec*} [dict get $entry client-info]
         r ACL SETUSER antirez -incr
     }
 
@@ -738,6 +740,7 @@ start_server {tags {"acl external:skip"}} {
         set entry [lindex [r ACL LOG] 0]
         assert {[dict get $entry context] eq {lua}}
         assert {[dict get $entry object] eq {incr}}
+        assert_match {*cmd=eval*} [dict get $entry client-info]
     }
 
     test {ACL LOG can accept a numerical argument to show less entries} {
diff --git a/tests/unit/moduleapi/misc.tcl b/tests/unit/moduleapi/misc.tcl
index 8c17ca378..8d63ce5b6 100644
--- a/tests/unit/moduleapi/misc.tcl
+++ b/tests/unit/moduleapi/misc.tcl
@@ -116,6 +116,36 @@ start_server {tags {"modules"}} {
         r client tracking on
         set info [r test.clientinfo]
         assert { [dict get $info flags] == "${ssl_flag}::tracking::" }
+        r CLIENT TRACKING off
+    }
+
+    test {tracking with rm_call sanity} {
+        set rd_trk [redis_client]
+        $rd_trk HELLO 3
+        $rd_trk CLIENT TRACKING on
+        r MSET key1{t} 1 key2{t} 1
+
+        # GET triggers tracking, SET does not
+        $rd_trk test.rm_call GET key1{t}
+        $rd_trk test.rm_call SET key2{t} 2
+        r MSET key1{t} 2 key2{t} 2
+        assert_equal {invalidate key1{t}} [$rd_trk read]
+        assert_equal "PONG" [$rd_trk ping]
+        $rd_trk close
+    }
+
+    test {tracking with rm_call with script} {
+        set rd_trk [redis_client]
+        $rd_trk HELLO 3
+        $rd_trk CLIENT TRACKING on
+        r MSET key1{t} 1 key2{t} 1
+
+        # GET triggers tracking, SET does not
+        $rd_trk test.rm_call EVAL "redis.call('get', 'key1{t}')" 2 key1{t} key2{t}
+        r MSET key1{t} 2 key2{t} 2
+        assert_equal {invalidate key1{t}} [$rd_trk read]
+        assert_equal "PONG" [$rd_trk ping]
+        $rd_trk close
     }
 
     test {test module get/set client name by id api} {
diff --git a/tests/unit/moduleapi/usercall.tcl b/tests/unit/moduleapi/usercall.tcl
index c3d8b0312..51ee1a4af 100644
--- a/tests/unit/moduleapi/usercall.tcl
+++ b/tests/unit/moduleapi/usercall.tcl
@@ -39,16 +39,49 @@ start_server {tags {"modules usercall"}} {
     test {test module check regular redis command with user and acl} {
         assert_equal [r set x 5] OK
 
+        r ACL LOG RESET
         assert_equal [r usercall.reset_user] OK
         assert_equal [r usercall.add_to_acl "~* &* +@all -set"] OK
         # off and sanitize-payload because module user / default value
         assert_equal [r usercall.get_acl] "off sanitize-payload ~* &* +@all -set"
 
         # fails here as testing acl in rm call
-        assert_error {*NOPERM User default has no permissions*} {r usercall.call_with_user_flag C set x 10}
+        assert_error {*NOPERM User module_user has no permissions*} {r usercall.call_with_user_flag C set x 10}
 
         assert_equal [r usercall.call_with_user_flag C get x] 5
 
+        # verify that new log entry added
+        set entry [lindex [r ACL LOG] 0]
+        assert_equal [dict get $entry username] {module_user}
+        assert_equal [dict get $entry context] {module}
+        assert_equal [dict get $entry object] {set}
+        assert_equal [dict get $entry reason] {command}
+        assert_match {*cmd=usercall.call_with_user_flag*} [dict get $entry client-info]
+
+        assert_equal [r usercall.reset_user] OK
+    }
+
+    # call with user with acl set on it, but with testing the acl in rm_call (for cmd itself)
+    test {test module check regular redis command with user and acl from blocked background thread} {
+        assert_equal [r set x 5] OK
+
+        r ACL LOG RESET
+        assert_equal [r usercall.reset_user] OK
+        assert_equal [r usercall.add_to_acl "~* &* +@all -set"] OK
+
+        # fails here as testing acl in rm call from a background thread
+        assert_error {*NOPERM User module_user has no permissions*} {r usercall.call_with_user_bg C set x 10}
+
+        assert_equal [r usercall.call_with_user_bg C get x] 5
+
+        # verify that new log entry added
+        set entry [lindex [r ACL LOG] 0]
+        assert_equal [dict get $entry username] {module_user}
+        assert_equal [dict get $entry context] {module}
+        assert_equal [dict get $entry object] {set}
+        assert_equal [dict get $entry reason] {command}
+        assert_match {*cmd=NULL*} [dict get $entry client-info]
+
         assert_equal [r usercall.reset_user] OK
     }
 
@@ -82,6 +115,7 @@ start_server {tags {"modules usercall"}} {
         set sha_set [r script load $test_script_set]
         set sha_get [r script load $test_script_get]
 
+        r ACL LOG RESET
         assert_equal [r usercall.reset_user] OK
         assert_equal [r usercall.add_to_acl "~* &* +@all -set"] OK
 
@@ -90,5 +124,13 @@ start_server {tags {"modules usercall"}} {
         assert_match {*ERR ACL failure in script*} $e
 
         assert_equal [r usercall.call_with_user_flag C evalsha $sha_get 0] 1
+
+        # verify that new log entry added
+        set entry [lindex [r ACL LOG] 0]
+        assert_equal [dict get $entry username] {module_user}
+        assert_equal [dict get $entry context] {lua}
+        assert_equal [dict get $entry object] {set}
+        assert_equal [dict get $entry reason] {command}
+        assert_match {*cmd=usercall.call_with_user_flag*} [dict get $entry client-info]
     }
-}
\ No newline at end of file
+}
diff --git a/tests/unit/tracking.tcl b/tests/unit/tracking.tcl
index 8d4fd8c89..f4e6e27ab 100644
--- a/tests/unit/tracking.tcl
+++ b/tests/unit/tracking.tcl
@@ -229,22 +229,25 @@ start_server {tags {"tracking network"}} {
         # If a script doesn't call any read command, don't track any keys
         r EVAL "redis.call('set', 'key3{t}', 'bar')" 2 key1{t} key2{t} 
         $rd_sg MSET key2{t} 2 key1{t} 2
+        assert_equal "PONG" [r ping]
 
-        # If a script calls a read command, track all declared keys
-        r EVAL "redis.call('get', 'key3{t}')" 2 key1{t} key2{t} 
-        $rd_sg MSET key2{t} 2 key1{t} 2
+        # If a script calls a read command, just the read keys
+        r EVAL "redis.call('get', 'key2{t}')" 2 key1{t} key2{t}
+        $rd_sg MSET key2{t} 2 key3{t} 2
         assert_equal {invalidate key2{t}} [r read]
-        assert_equal {invalidate key1{t}} [r read]
+        assert_equal "PONG" [r ping]
 
         # RO variants work like the normal variants
-        r EVAL_RO "redis.call('ping')" 2 key1{t} key2{t} 
+
+        # If a RO script doesn't call any read command, don't track any keys
+        r EVAL_RO "redis.call('ping')" 2 key1{t} key2{t}
         $rd_sg MSET key2{t} 2 key1{t} 2
+        assert_equal "PONG" [r ping]
 
-        r EVAL_RO "redis.call('get', 'key1{t}')" 2 key1{t} key2{t} 
-        $rd_sg MSET key2{t} 3 key1{t} 3
+        # If a RO script calls a read command, just the read keys
+        r EVAL_RO "redis.call('get', 'key2{t}')" 2 key1{t} key2{t}
+        $rd_sg MSET key2{t} 2 key3{t} 2
         assert_equal {invalidate key2{t}} [r read]
-        assert_equal {invalidate key1{t}} [r read]
-
         assert_equal "PONG" [r ping]
     }