Redis 2.4.13

Every matched key in a KEYS call is checked for expiration. When the key
is set to expire, the call to `getExpire` will assert that the key also
exists in the main dictionary. This in turn causes a rehashing step to
be executed. Rehashing a dictionary when there is an iterator active may
result in the iterator emitting duplicate entries, or not emitting some
entries at all. By using a safe iterator, the rehash step is omitted.

00-RELEASENOTES

@@ -18,6 +18,24 @@ to modify your program in order to use Redis 2.4.
 CHANGELOG
 ---------
 
+What's new in Redis 2.4.13
+=========================
+
+UPGRADE URGENCY: high for all the users of the KEYS command, otherwise low.
+
+* [BUGFIX] Fix for KEYS command: if the DB contains keys with expires the KEYS
+           command may return the wrong output, having duplicated or missing
+           keys. See issue #487 and #488 on github for details.
+
+What's new in Redis 2.4.12
+=========================
+
+UPGRADE URGENCY: low if you don't experience any of the fixed problems.
+
+* [BUGFIX] Limit the amount of memory consumed by the slow log.
+* [BUGFIX] --test-memory option fixes.
+* [BUGFIX] Less false positives in tests.
+
 What's new in Redis 2.4.11
 =========================
 

redis.conf

@@ -356,7 +356,7 @@ slowlog-log-slower-than 10000
 
 # There is no limit to this length. Just be aware that it will consume memory.
 # You can reclaim memory used by the slow log with SLOWLOG RESET.
-slowlog-max-len 1024
+slowlog-max-len 128
 
 ################################ VIRTUAL MEMORY ###############################
 

src/db.c

@@ -273,7 +273,7 @@ void keysCommand(redisClient *c) {
     unsigned long numkeys = 0;
     void *replylen = addDeferredMultiBulkLength(c);
 
-    di = dictGetIterator(c->db->dict);
+    di = dictGetSafeIterator(c->db->dict);
     allkeys = (pattern[0] == '*' && pattern[1] == '\0');
     while((de = dictNext(di)) != NULL) {
         sds key = dictGetEntryKey(de);

src/memtest.c

@@ -132,13 +132,13 @@ void memtest_fill_value(unsigned long *l, size_t bytes, unsigned long v1,
         v = (off & 1) ? v2 : v1;
         for (w = 0; w < iwords; w++) {
 #ifdef MEMTEST_32BIT
-            *l1 = *l2 = ((unsigned long)     (rand()&0xffff)) |
-                        (((unsigned long)    (rand()&0xffff)) << 16);
+            *l1 = *l2 = ((unsigned long)     v) |
+                        (((unsigned long)    v) << 16);
 #else
-            *l1 = *l2 = ((unsigned long)     (rand()&0xffff)) |
-                        (((unsigned long)    (rand()&0xffff)) << 16) |
-                        (((unsigned long)    (rand()&0xffff)) << 32) |
-                        (((unsigned long)    (rand()&0xffff)) << 48);
+            *l1 = *l2 = ((unsigned long)     v) |
+                        (((unsigned long)    v) << 16) |
+                        (((unsigned long)    v) << 32) |
+                        (((unsigned long)    v) << 48);
 #endif
             l1 += step;
             l2 += step;

src/redis-cli.c

@@ -800,7 +800,7 @@ static int noninteractive(int argc, char **argv) {
 
 static void latencyMode(void) {
     redisReply *reply;
-    long long start, latency, min, max, tot, count = 0;
+    long long start, latency, min = 0, max = 0, tot = 0, count = 0;
     double avg;
 
     if (!context) exit(1);
@@ -887,7 +887,7 @@ static void slaveMode(void) {
 static void findBigKeys(void) {
     unsigned long long biggest[5] = {0,0,0,0,0};
     unsigned long long samples = 0;
-    redisReply *reply1, *reply2, *reply3;
+    redisReply *reply1, *reply2, *reply3 = NULL;
     char *sizecmd, *typename[] = {"string","list","set","hash","zset"};
     int type;
 

src/redis.h

@@ -55,7 +55,7 @@
 #define REDIS_AUTO_AOFREWRITE_PERC  100
 #define REDIS_AUTO_AOFREWRITE_MIN_SIZE (1024*1024)
 #define REDIS_SLOWLOG_LOG_SLOWER_THAN 10000
-#define REDIS_SLOWLOG_MAX_LEN 64
+#define REDIS_SLOWLOG_MAX_LEN 128
 
 #define REDIS_REPL_TIMEOUT 60
 #define REDIS_REPL_PING_SLAVE_PERIOD 10

src/slowlog.c

@@ -16,13 +16,36 @@
  * this function. */
 slowlogEntry *slowlogCreateEntry(robj **argv, int argc, long long duration) {
     slowlogEntry *se = zmalloc(sizeof(*se));
-    int j;
+    int j, slargc = argc;
 
-    se->argc = argc;
-    se->argv = zmalloc(sizeof(robj*)*argc);
-    for (j = 0; j < argc; j++) {
-        se->argv[j] = argv[j];
-        incrRefCount(argv[j]);
+    if (slargc > SLOWLOG_ENTRY_MAX_ARGC) slargc = SLOWLOG_ENTRY_MAX_ARGC;
+    se->argc = slargc;
+    se->argv = zmalloc(sizeof(robj*)*slargc);
+    for (j = 0; j < slargc; j++) {
+        /* Logging too many arguments is a useless memory waste, so we stop
+         * at SLOWLOG_ENTRY_MAX_ARGC, but use the last argument to specify
+         * how many remaining arguments there were in the original command. */
+        if (slargc != argc && j == slargc-1) {
+            se->argv[j] = createObject(REDIS_STRING,
+                sdscatprintf(sdsempty(),"... (%d more arguments)",
+                argc-slargc+1));
+        } else {
+            /* Trim too long strings as well... */
+            if (argv[j]->type == REDIS_STRING &&
+                argv[j]->encoding == REDIS_ENCODING_RAW &&
+                sdslen(argv[j]->ptr) > SLOWLOG_ENTRY_MAX_STRING)
+            {
+                sds s = sdsnewlen(argv[j]->ptr, SLOWLOG_ENTRY_MAX_STRING);
+
+                s = sdscatprintf(s,"... (%lu more bytes)",
+                    (unsigned long)
+                    sdslen(argv[j]->ptr) - SLOWLOG_ENTRY_MAX_STRING);
+                se->argv[j] = createObject(REDIS_STRING,s);
+            } else {
+                se->argv[j] = argv[j];
+                incrRefCount(argv[j]);
+            }
+        }
     }
     se->time = time(NULL);
     se->duration = duration;

src/slowlog.h

@@ -1,3 +1,6 @@
+#define SLOWLOG_ENTRY_MAX_ARGC 32
+#define SLOWLOG_ENTRY_MAX_STRING 128
+
 /* This structure defines an entry inside the slow log list */
 typedef struct slowlogEntry {
     robj **argv;

src/t_zset.c

@@ -1261,7 +1261,9 @@ int zuiNext(zsetopsrc *op, zsetopval *val) {
     if (op->type == REDIS_SET) {
         iterset *it = &op->iter.set;
         if (op->encoding == REDIS_ENCODING_INTSET) {
-            if (!intsetGet(it->is.is,it->is.ii,(int64_t*)&val->ell))
+            int64_t ell = val->ell;
+
+            if (!intsetGet(it->is.is,it->is.ii,&ell))
                 return 0;
             val->score = 1.0;
 

src/version.h

@@ -1 +1 @@
-#define REDIS_VERSION "2.4.11"
+#define REDIS_VERSION "2.4.13"

tests/integration/replication.tcl

@@ -2,16 +2,23 @@ start_server {tags {"repl"}} {
     start_server {} {
         test {First server should have role slave after SLAVEOF} {
             r -1 slaveof [srv 0 host] [srv 0 port]
-            after 1000
-            s -1 role
-        } {slave}
+            wait_for_condition 50 100 {
+                [s -1 role] eq {slave} &&
+                [string match {*master_link_status:up*} [r -1 info]]
+            } else {
+                fail "Can't turn the instance into a slave"
+            }
+        }
 
         test {BRPOPLPUSH replication, when blocking against empty list} {
             set rd [redis_deferring_client]
             $rd brpoplpush a b 5
             r lpush a foo
-            after 1000
-            assert_equal [r debug digest] [r -1 debug digest]
+            wait_for_condition 50 100 {
+                [r debug digest] eq [r -1 debug digest]
+            } else {
+                fail "Master and slave have different digest: [r debug digest] VS [r -1 debug digest]"
+            }
         }
 
         test {BRPOPLPUSH replication, list exists} {
@@ -79,12 +86,11 @@ start_server {tags {"repl"}} {
     set master_host [srv 0 host]
     set master_port [srv 0 port]
     set slaves {}
-    set load_handle0 [start_write_load $master_host $master_port 20]
-    set load_handle1 [start_write_load $master_host $master_port 20]
+    set load_handle0 [start_write_load $master_host $master_port 3]
+    set load_handle1 [start_write_load $master_host $master_port 5]
     set load_handle2 [start_write_load $master_host $master_port 20]
-    set load_handle3 [start_write_load $master_host $master_port 20]
-    set load_handle4 [start_write_load $master_host $master_port 20]
-    after 2000
+    set load_handle3 [start_write_load $master_host $master_port 8]
+    set load_handle4 [start_write_load $master_host $master_port 4]
     start_server {} {
         lappend slaves [srv 0 client]
         start_server {} {
@@ -92,6 +98,7 @@ start_server {tags {"repl"}} {
             start_server {} {
                 lappend slaves [srv 0 client]
                 test "Connect multiple slaves at the same time (issue #141)" {
+                    # Send SALVEOF commands to slaves
                     [lindex $slaves 0] slaveof $master_host $master_port
                     [lindex $slaves 1] slaveof $master_host $master_port
                     [lindex $slaves 2] slaveof $master_host $master_port
@@ -110,16 +117,33 @@ start_server {tags {"repl"}} {
                     if {$retry == 0} {
                         error "assertion:Slaves not correctly synchronized"
                     }
+
+                    # Stop the write load
                     stop_write_load $load_handle0
                     stop_write_load $load_handle1
                     stop_write_load $load_handle2
                     stop_write_load $load_handle3
                     stop_write_load $load_handle4
-                    set retry 10
-                    while {$retry && ([$master debug digest] ne [[lindex $slaves 0] debug digest])} {
-                        after 1000
-                        incr retry -1
+
+                    # Wait that slaves exit the "loading" state
+                    wait_for_condition 500 100 {
+                        ![string match {*loading:1*} [[lindex $slaves 0] info]] &&
+                        ![string match {*loading:1*} [[lindex $slaves 1] info]] &&
+                        ![string match {*loading:1*} [[lindex $slaves 2] info]]
+                    } else {
+                        fail "Slaves still loading data after too much time"
                     }
+
+                    # Make sure that slaves and master have same number of keys
+                    wait_for_condition 500 100 {
+                        [$master dbsize] == [[lindex $slaves 0] dbsize] &&
+                        [$master dbsize] == [[lindex $slaves 1] dbsize] &&
+                        [$master dbsize] == [[lindex $slaves 2] dbsize]
+                    } else {
+                        fail "Different number of keys between masted and slave after too long time."
+                    }
+
+                    # Check digests
                     set digest [$master debug digest]
                     set digest0 [[lindex $slaves 0] debug digest]
                     set digest1 [[lindex $slaves 1] debug digest]
@@ -128,10 +152,6 @@ start_server {tags {"repl"}} {
                     assert {$digest eq $digest0}
                     assert {$digest eq $digest1}
                     assert {$digest eq $digest2}
-                    #puts [$master dbsize]
-                    #puts [[lindex $slaves 0] dbsize]
-                    #puts [[lindex $slaves 1] dbsize]
-                    #puts [[lindex $slaves 2] dbsize]
                 }
            }
         }

tests/support/redis.tcl

@@ -142,9 +142,15 @@ proc ::redis::redis_multi_bulk_read fd {
     set count [redis_read_line $fd]
     if {$count == -1} return {}
     set l {}
+    set err {}
     for {set i 0} {$i < $count} {incr i} {
-        lappend l [redis_read_reply $fd]
+        if {[catch {
+            lappend l [redis_read_reply $fd]
+        } e] && $err eq {}} {
+            set err $e
+        }
     }
+    if {$err ne {}} {return -code error $err}
     return $l
 }
 
@@ -160,7 +166,7 @@ proc ::redis::redis_read_reply fd {
         - {return -code error [redis_read_line $fd]}
         $ {redis_bulk_read $fd}
         * {redis_multi_bulk_read $fd}
-        default {return -code error "Bad protocol, $type as reply type byte"}
+        default {return -code error "Bad protocol, '$type' as reply type byte"}
     }
 }
 

tests/support/server.tcl

@@ -2,13 +2,14 @@ set ::global_overrides {}
 set ::tags {}
 set ::valgrind_errors {}
 
-proc error_and_quit {config_file error} {
-    puts "!!COULD NOT START REDIS-SERVER\n"
-    puts "CONFIGURATION:"
-    puts [exec cat $config_file]
-    puts "\nERROR:"
-    puts [string trim $error]
-    exit 1
+proc start_server_error {config_file error} {
+    set err {}
+    append err "Cant' start the Redis server\n"
+    append err "CONFIGURATION:"
+    append err [exec cat $config_file]
+    append err "\nERROR:"
+    append err [string trim $error]
+    send_data_packet $::test_server_fd err $err
 }
 
 proc check_valgrind_errors stderr {
@@ -16,7 +17,7 @@ proc check_valgrind_errors stderr {
     set buf [read $fd]
     close $fd
 
-    if {![regexp -- {ERROR SUMMARY: 0 errors} $buf] ||
+    if {[regexp -- { at 0x} $buf] ||
         (![regexp -- {definitely lost: 0 bytes} $buf] &&
          ![regexp -- {no leaks are possible} $buf])} {
         send_data_packet $::test_server_fd err "Valgrind error: $buf\n"
@@ -45,11 +46,16 @@ proc kill_server config {
     }
 
     # kill server and wait for the process to be totally exited
+    catch {exec kill $pid}
     while {[is_alive $config]} {
-        if {[incr wait 10] % 1000 == 0} {
+        incr wait 10
+
+        if {$wait >= 5000} {
+            puts "Forcing process $pid to exit..."
+            catch {exec kill -KILL $pid}
+        } elseif {$wait % 1000 == 0} {
             puts "Waiting for process $pid to exit..."
         }
-        catch {exec kill $pid}
         after 10
     }
 
@@ -175,14 +181,14 @@ proc start_server {options {code undefined}} {
     set stderr [format "%s/%s" [dict get $config "dir"] "stderr"]
 
     if {$::valgrind} {
-        exec valgrind --suppressions=src/valgrind.sup src/redis-server $config_file > $stdout 2> $stderr &
+        exec valgrind --suppressions=src/valgrind.sup --show-reachable=no --show-possibly-lost=no --leak-check=full src/redis-server $config_file > $stdout 2> $stderr &
     } else {
         exec src/redis-server $config_file > $stdout 2> $stderr &
     }
     
     # check that the server actually started
     # ugly but tries to be as fast as possible...
-    set retrynum 100
+    if {$::valgrind} {set retrynum 1000} else {set retrynum 100}
     set serverisup 0
 
     if {$::verbose} {
@@ -209,7 +215,10 @@ proc start_server {options {code undefined}} {
     }
 
     if {!$serverisup} {
-        error_and_quit $config_file [exec cat $stderr]
+        set err {}
+        append err [exec cat $stdout] "\n" [exec cat $stderr]
+        start_server_error $config_file $err
+        return
     }
     
     # find out the pid
@@ -243,7 +252,7 @@ proc start_server {options {code undefined}} {
 
         while 1 {
             # check that the server actually started and is ready for connections
-            if {[exec cat $stdout | grep "ready to accept" | wc -l] > 0} {
+            if {[exec grep "ready to accept" | wc -l < $stdout] > 0} {
                 break
             }
             after 10

tests/support/test.tcl

@@ -3,6 +3,10 @@ set ::num_passed 0
 set ::num_failed 0
 set ::tests_failed {}
 
+proc fail {msg} {
+    error "assertion:$msg"
+}
+
 proc assert {condition} {
     if {![uplevel 1 [list expr $condition]]} {
         error "assertion:Expected condition '$condition' to be true ([uplevel 1 [list subst -nocommands $condition]])"
@@ -44,6 +48,19 @@ proc assert_type {type key} {
     assert_equal $type [r type $key]
 }
 
+# Wait for the specified condition to be true, with the specified number of
+# max retries and delay between retries. Otherwise the 'elsescript' is
+# executed.
+proc wait_for_condition {maxtries delay e _else_ elsescript} {
+    while {[incr maxtries -1] >= 0} {
+        if {[uplevel 1 [list expr $e]]} break
+        after $delay
+    }
+    if {$maxtries == -1} {
+        uplevel 1 $elsescript
+    }
+}
+
 # Test if TERM looks like to support colors
 proc color_term {} {
     expr {[info exists ::env(TERM)] && [string match *xterm* $::env(TERM)]}

tests/support/util.tcl

@@ -294,3 +294,7 @@ proc csvdump r {
 proc csvstring s {
     return "\"$s\""
 }
+
+proc roundFloat f {
+    format "%.10g" $f
+}

tests/unit/slowlog.tcl

@@ -38,4 +38,21 @@ start_server {tags {"slowlog"} overrides {slowlog-log-slower-than 1000000}} {
         assert_equal [expr {[lindex $e 2] > 100000}] 1
         assert_equal [lindex $e 3] {debug sleep 0.2}
     }
+
+    test {SLOWLOG - commands with too many arguments are trimmed} {
+        r config set slowlog-log-slower-than 0
+        r slowlog reset
+        r sadd set 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33
+        set e [lindex [r slowlog get] 0]
+        lindex $e 3
+    } {sadd set 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 {... (2 more arguments)}}
+
+    test {SLOWLOG - too long arguments are trimmed} {
+        r config set slowlog-log-slower-than 0
+        r slowlog reset
+        set arg [string repeat A 129]
+        r sadd set foo $arg
+        set e [lindex [r slowlog get] 0]
+        lindex $e 3
+    } {sadd set foo {AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA... (1 more bytes)}}
 }