diff options
Diffstat (limited to 'tests/unit/slowlog.tcl')
| -rw-r--r-- | tests/unit/slowlog.tcl | 228 |
1 files changed, 228 insertions, 0 deletions
diff --git a/tests/unit/slowlog.tcl b/tests/unit/slowlog.tcl new file mode 100644 index 0000000..3c547b9 --- /dev/null +++ b/tests/unit/slowlog.tcl @@ -0,0 +1,228 @@ +start_server {tags {"slowlog"} overrides {slowlog-log-slower-than 1000000}} { + test {SLOWLOG - check that it starts with an empty log} { + if {$::external} { + r slowlog reset + } + r slowlog len + } {0} + + test {SLOWLOG - only logs commands taking more time than specified} { + r config set slowlog-log-slower-than 100000 + r ping + assert_equal [r slowlog len] 0 + r debug sleep 0.2 + assert_equal [r slowlog len] 1 + } {} {needs:debug} + + test {SLOWLOG - max entries is correctly handled} { + r config set slowlog-log-slower-than 0 + r config set slowlog-max-len 10 + for {set i 0} {$i < 100} {incr i} { + r ping + } + r slowlog len + } {10} + + test {SLOWLOG - GET optional argument to limit output len works} { + + assert_equal 5 [llength [r slowlog get 5]] + assert_equal 10 [llength [r slowlog get -1]] + assert_equal 10 [llength [r slowlog get 20]] + } + + test {SLOWLOG - RESET subcommand works} { + r config set slowlog-log-slower-than 100000 + r slowlog reset + r slowlog len + } {0} + + test {SLOWLOG - logged entry sanity check} { + r client setname foobar + r debug sleep 0.2 + set e [lindex [r slowlog get] 0] + assert_equal [llength $e] 6 + if {!$::external} { + assert_equal [lindex $e 0] 107 + } + assert_equal [expr {[lindex $e 2] > 100000}] 1 + assert_equal [lindex $e 3] {debug sleep 0.2} + assert_equal {foobar} [lindex $e 5] + } {} {needs:debug} + + test {SLOWLOG - Certain commands are omitted that contain sensitive information} { + r config set slowlog-log-slower-than 0 + r slowlog reset + catch {r acl setuser "slowlog test user" +get +set} _ + r config set masterauth "" + r acl setuser slowlog-test-user +get +set + r config set slowlog-log-slower-than 0 + r config set slowlog-log-slower-than -1 + set slowlog_resp [r slowlog get] + + # Make sure normal configs work, but the two sensitive + # commands are omitted or redacted + assert_equal 5 [llength $slowlog_resp] + assert_equal {slowlog reset} [lindex [lindex $slowlog_resp 4] 3] + assert_equal {acl setuser (redacted) (redacted) (redacted)} [lindex [lindex $slowlog_resp 3] 3] + assert_equal {config set masterauth (redacted)} [lindex [lindex $slowlog_resp 2] 3] + assert_equal {acl setuser (redacted) (redacted) (redacted)} [lindex [lindex $slowlog_resp 1] 3] + assert_equal {config set slowlog-log-slower-than 0} [lindex [lindex $slowlog_resp 0] 3] + } {} {needs:repl} + + test {SLOWLOG - Some commands can redact sensitive fields} { + r config set slowlog-log-slower-than 0 + r slowlog reset + r migrate [srv 0 host] [srv 0 port] key 9 5000 + r migrate [srv 0 host] [srv 0 port] key 9 5000 AUTH user + r migrate [srv 0 host] [srv 0 port] key 9 5000 AUTH2 user password + r config set slowlog-log-slower-than -1 + set slowlog_resp [r slowlog get] + + # Make sure all 3 commands were logged, but the sensitive fields are omitted + assert_equal 4 [llength $slowlog_resp] + assert_match {* key 9 5000} [lindex [lindex $slowlog_resp 2] 3] + assert_match {* key 9 5000 AUTH (redacted)} [lindex [lindex $slowlog_resp 1] 3] + assert_match {* key 9 5000 AUTH2 (redacted) (redacted)} [lindex [lindex $slowlog_resp 0] 3] + } {} {needs:repl} + + 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] + + # blocked BLPOP is replicated as LPOP + set rd [redis_deferring_client] + $rd blpop l 0 + wait_for_blocked_clients_count 1 50 100 + r multi + r lpush l foo + r slowlog reset + r exec + $rd read + $rd close + assert_equal {blpop l 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 + 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] end-1] + 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] end-1] + lindex $e 3 + } {sadd set foo {AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA... (1 more bytes)}} + + test {SLOWLOG - EXEC is not logged, just executed commands} { + r config set slowlog-log-slower-than 100000 + r slowlog reset + assert_equal [r slowlog len] 0 + r multi + r debug sleep 0.2 + r exec + assert_equal [r slowlog len] 1 + set e [lindex [r slowlog get] 0] + assert_equal [lindex $e 3] {debug sleep 0.2} + } {} {needs:debug} + + test {SLOWLOG - can clean older entries} { + r client setname lastentry_client + r config set slowlog-max-len 1 + r debug sleep 0.2 + assert {[llength [r slowlog get]] == 1} + set e [lindex [r slowlog get] 0] + assert_equal {lastentry_client} [lindex $e 5] + } {} {needs:debug} + + test {SLOWLOG - can be disabled} { + r config set slowlog-max-len 1 + r config set slowlog-log-slower-than 1 + r slowlog reset + r debug sleep 0.2 + assert_equal [r slowlog len] 1 + r config set slowlog-log-slower-than -1 + r slowlog reset + r debug sleep 0.2 + assert_equal [r slowlog len] 0 + } {} {needs:debug} + + test {SLOWLOG - count must be >= -1} { + assert_error "ERR count should be greater than or equal to -1" {r slowlog get -2} + assert_error "ERR count should be greater than or equal to -1" {r slowlog get -222} + } + + test {SLOWLOG - get all slow logs} { + r config set slowlog-log-slower-than 0 + r config set slowlog-max-len 3 + r slowlog reset + + r set key test + r sadd set a b c + r incr num + r lpush list a + + assert_equal [r slowlog len] 3 + assert_equal 0 [llength [r slowlog get 0]] + assert_equal 1 [llength [r slowlog get 1]] + assert_equal 3 [llength [r slowlog get -1]] + assert_equal 3 [llength [r slowlog get 3]] + } + + test {SLOWLOG - blocking command is reported only after unblocked} { + # Cleanup first + r del mylist + # create a test client + set rd [redis_deferring_client] + + # config the slowlog and reset + r config set slowlog-log-slower-than 0 + r config set slowlog-max-len 110 + r slowlog reset + + $rd BLPOP mylist 0 + wait_for_blocked_clients_count 1 50 20 + assert_equal 0 [llength [regexp -all -inline (?=BLPOP) [r slowlog get]]] + + r LPUSH mylist 1 + wait_for_blocked_clients_count 0 50 20 + assert_equal 1 [llength [regexp -all -inline (?=BLPOP) [r slowlog get]]] + + $rd close + } +} |