diff --git a/src/networking.c b/src/networking.c index 8aca33e85..13793590b 100644 --- a/src/networking.c +++ b/src/networking.c @@ -139,6 +139,8 @@ client *createClient(connection *conn) { c->argc = 0; c->argv = NULL; c->argv_len_sum = 0; + c->original_argc = 0; + c->original_argv = NULL; c->cmd = c->lastcmd = NULL; c->multibulklen = 0; c->bulklen = -1; @@ -1065,6 +1067,17 @@ void acceptUnixHandler(aeEventLoop *el, int fd, void *privdata, int mask) { } } +void freeClientOriginalArgv(client *c) { + /* We didn't rewrite this client */ + if (!c->original_argv) return; + + for (int j = 0; j < c->original_argc; j++) + decrRefCount(c->original_argv[j]); + zfree(c->original_argv); + c->original_argv = NULL; + c->original_argc = 0; +} + static void freeClientArgv(client *c) { int j; for (j = 0; j < c->argc; j++) @@ -1246,6 +1259,7 @@ void freeClient(client *c) { /* Free data structures. */ listRelease(c->reply); freeClientArgv(c); + freeClientOriginalArgv(c); /* Unlink the client: this will close the socket, remove the I/O * handlers, and remove references of the client from different @@ -2765,6 +2779,19 @@ void securityWarningCommand(client *c) { freeClientAsync(c); } +/* Keep track of the original command arguments so that we can generate + * an accurate slowlog entry after the command has been executed. */ +static void retainOriginalCommandVector(client *c) { + /* We already rewrote this command, so don't rewrite it again */ + if (c->original_argv) return; + c->original_argc = c->argc; + c->original_argv = zmalloc(sizeof(robj*)*(c->argc)); + for (int j = 0; j < c->argc; j++) { + c->original_argv[j] = c->argv[j]; + incrRefCount(c->argv[j]); + } +} + /* Rewrite the command vector of the client. All the new objects ref count * is incremented. The old command vector is freed, and the old objects * ref count is decremented. */ @@ -2782,26 +2809,14 @@ void rewriteClientCommandVector(client *c, int argc, ...) { argv[j] = a; incrRefCount(a); } - /* We free the objects in the original vector at the end, so we are - * sure that if the same objects are reused in the new vector the - * refcount gets incremented before it gets decremented. */ - for (j = 0; j < c->argc; j++) decrRefCount(c->argv[j]); - zfree(c->argv); - /* Replace argv and argc with our new versions. */ - c->argv = argv; - c->argc = argc; - c->argv_len_sum = 0; - for (j = 0; j < c->argc; j++) - if (c->argv[j]) - c->argv_len_sum += getStringObjectLen(c->argv[j]); - c->cmd = lookupCommandOrOriginal(c->argv[0]->ptr); - serverAssertWithInfo(c,NULL,c->cmd != NULL); + replaceClientCommandVector(c, argc, argv); va_end(ap); } /* Completely replace the client command vector with the provided one. */ void replaceClientCommandVector(client *c, int argc, robj **argv) { int j; + retainOriginalCommandVector(c); freeClientArgv(c); zfree(c->argv); c->argv = argv; @@ -2827,7 +2842,7 @@ void replaceClientCommandVector(client *c, int argc, robj **argv) { * free the no longer used objects on c->argv. */ void rewriteClientCommandArgument(client *c, int i, robj *newval) { robj *oldval; - + retainOriginalCommandVector(c); if (i >= c->argc) { c->argv = zrealloc(c->argv,sizeof(robj*)*(i+1)); c->argc = i+1; diff --git a/src/server.c b/src/server.c index 883a81305..0cc73dfe3 100644 --- a/src/server.c +++ b/src/server.c @@ -3467,8 +3467,13 @@ void call(client *c, int flags) { char *latency_event = (c->cmd->flags & CMD_FAST) ? "fast-command" : "command"; latencyAddSampleIfNeeded(latency_event,duration/1000); - slowlogPushEntryIfNeeded(c,c->argv,c->argc,duration); + /* If command argument vector was rewritten, use the original + * arguments. */ + robj **argv = c->original_argv ? c->original_argv : c->argv; + int argc = c->original_argv ? c->original_argc : c->argc; + slowlogPushEntryIfNeeded(c,argv,argc,duration); } + freeClientOriginalArgv(c); if (flags & CMD_CALL_STATS) { /* use the real command that was executed (cmd and lastamc) may be diff --git a/src/server.h b/src/server.h index 587779844..1ae96aee5 100644 --- a/src/server.h +++ b/src/server.h @@ -808,6 +808,8 @@ typedef struct client { size_t querybuf_peak; /* Recent (100ms or more) peak of querybuf size. */ int argc; /* Num of arguments of current command. */ robj **argv; /* Arguments of current command. */ + int original_argc; /* Num of arguments of original command if arguments were rewritten. */ + robj **original_argv; /* Arguments of original command if arguments were rewritten. */ size_t argv_len_sum; /* Sum of lengths of objects in argv list. */ struct redisCommand *cmd, *lastcmd; /* Last command executed. */ user *user; /* User associated with this connection. If the @@ -1668,6 +1670,7 @@ void closeTimedoutClients(void); void freeClient(client *c); void freeClientAsync(client *c); void resetClient(client *c); +void freeClientOriginalArgv(client *c); void sendReplyToClient(connection *conn); void *addReplyDeferredLen(client *c); void setDeferredArrayLen(client *c, void *node, long length); diff --git a/tests/unit/slowlog.tcl b/tests/unit/slowlog.tcl index c2ef23cf7..e782682e4 100644 --- a/tests/unit/slowlog.tcl +++ b/tests/unit/slowlog.tcl @@ -41,6 +41,41 @@ start_server {tags {"slowlog"} overrides {slowlog-log-slower-than 1000000}} { assert_equal {foobar} [lindex $e 5] } + test {SLOWLOG - Rewritten commands are logged as their original command} { + r config set slowlog-log-slower-than 0 + + # Test rewriting client arguments + r sadd set a b c d e + r slowlog reset + + # SPOP is rewritten as DEL when all keys are removed + r spop set 10 + assert_equal {spop set 10} [lindex [lindex [r slowlog get] 0] 3] + + # Test replacing client arguments + r slowlog reset + + # GEOADD is replicated as ZADD + r geoadd cool-cities -122.33207 47.60621 Seattle + assert_equal {geoadd cool-cities -122.33207 47.60621 Seattle} [lindex [lindex [r slowlog get] 0] 3] + + # Test replacing a single command argument + r set A 5 + r slowlog reset + + # GETSET is replicated as SET + r getset a 5 + assert_equal {getset a 5} [lindex [lindex [r slowlog get] 0] 3] + + # INCRBYFLOAT calls rewrite multiple times, so it's a special case + r set A 0 + r slowlog reset + + # INCRBYFLOAT is replicated as SET + r INCRBYFLOAT A 1.0 + assert_equal {INCRBYFLOAT A 1.0} [lindex [lindex [r slowlog get] 0] 3] + } + test {SLOWLOG - commands with too many arguments are trimmed} { r config set slowlog-log-slower-than 0 r slowlog reset