summaryrefslogtreecommitdiff
path: root/tests
diff options
context:
space:
mode:
authorMeir Shpilraien (Spielrein) <meir@redis.com>2022-02-27 13:40:57 +0200
committerGitHub <noreply@github.com>2022-02-27 13:40:57 +0200
commitaa856b39f2ca65dbcc0eaae2d2c52f7a35291bbf (patch)
tree9811909f3ee9ab5c95737022f127eafe6119ce28 /tests
parent9f30dd03cd136eda00f5eb82f28f503452fdd11a (diff)
downloadredis-aa856b39f2ca65dbcc0eaae2d2c52f7a35291bbf.tar.gz
Sort out the mess around Lua error messages and error stats (#10329)
This PR fix 2 issues on Lua scripting: * Server error reply statistics (some errors were counted twice). * Error code and error strings returning from scripts (error code was missing / misplaced). ## Statistics a Lua script user is considered part of the user application, a sophisticated transaction, so we want to count an error even if handled silently by the script, but when it is propagated outwards from the script we don't wanna count it twice. on the other hand, if the script decides to throw an error on its own (using `redis.error_reply`), we wanna count that too. Besides, we do count the `calls` in command statistics for the commands the script calls, we we should certainly also count `failed_calls`. So when a simple `eval "return redis.call('set','x','y')" 0` fails, it should count the failed call to both SET and EVAL, but the `errorstats` and `total_error_replies` should be counted only once. The PR changes the error object that is raised on errors. Instead of raising a simple Lua string, Redis will raise a Lua table in the following format: ``` { err='<error message (including error code)>', source='<User source file name>', line='<line where the error happned>', ignore_error_stats_update=true/false, } ``` The `luaPushError` function was modified to construct the new error table as describe above. The `luaRaiseError` was renamed to `luaError` and is now simply called `lua_error` to raise the table on the top of the Lua stack as the error object. The reason is that since its functionality is changed, in case some Redis branch / fork uses it, it's better to have a compilation error than a bug. The `source` and `line` fields are enriched by the error handler (if possible) and the `ignore_error_stats_update` is optional and if its not present then the default value is `false`. If `ignore_error_stats_update` is true, the error will not be counted on the error stats. When parsing Redis call reply, each error is translated to a Lua table on the format describe above and the `ignore_error_stats_update` field is set to `true` so we will not count errors twice (we counted this error when we invoke the command). The changes in this PR might have been considered as a breaking change for users that used Lua `pcall` function. Before, the error was a string and now its a table. To keep backward comparability the PR override the `pcall` implementation and extract the error message from the error table and return it. Example of the error stats update: ``` 127.0.0.1:6379> lpush l 1 (integer) 2 127.0.0.1:6379> eval "return redis.call('get', 'l')" 0 (error) WRONGTYPE Operation against a key holding the wrong kind of value. script: e471b73f1ef44774987ab00bdf51f21fd9f7974a, on @user_script:1. 127.0.0.1:6379> info Errorstats # Errorstats errorstat_WRONGTYPE:count=1 127.0.0.1:6379> info commandstats # Commandstats cmdstat_eval:calls=1,usec=341,usec_per_call=341.00,rejected_calls=0,failed_calls=1 cmdstat_info:calls=1,usec=35,usec_per_call=35.00,rejected_calls=0,failed_calls=0 cmdstat_lpush:calls=1,usec=14,usec_per_call=14.00,rejected_calls=0,failed_calls=0 cmdstat_get:calls=1,usec=10,usec_per_call=10.00,rejected_calls=0,failed_calls=1 ``` ## error message We can now construct the error message (sent as a reply to the user) from the error table, so this solves issues where the error message was malformed and the error code appeared in the middle of the error message: ```diff 127.0.0.1:6379> eval "return redis.call('set','x','y')" 0 -(error) ERR Error running script (call to 71e6319f97b0fe8bdfa1c5df3ce4489946dda479): @user_script:1: OOM command not allowed when used memory > 'maxmemory'. +(error) OOM command not allowed when used memory > 'maxmemory' @user_script:1. Error running script (call to 71e6319f97b0fe8bdfa1c5df3ce4489946dda479) ``` ```diff 127.0.0.1:6379> eval "redis.call('get', 'l')" 0 -(error) ERR Error running script (call to f_8a705cfb9fb09515bfe57ca2bd84a5caee2cbbd1): @user_script:1: WRONGTYPE Operation against a key holding the wrong kind of value +(error) WRONGTYPE Operation against a key holding the wrong kind of value script: 8a705cfb9fb09515bfe57ca2bd84a5caee2cbbd1, on @user_script:1. ``` Notica that `redis.pcall` was not change: ``` 127.0.0.1:6379> eval "return redis.pcall('get', 'l')" 0 (error) WRONGTYPE Operation against a key holding the wrong kind of value ``` ## other notes Notice that Some commands (like GEOADD) changes the cmd variable on the client stats so we can not count on it to update the command stats. In order to be able to update those stats correctly we needed to promote `realcmd` variable to be located on the client struct. Tests was added and modified to verify the changes. Related PR's: #10279, #10218, #10278, #10309 Co-authored-by: Oran Agra <oran@redislabs.com>
Diffstat (limited to 'tests')
-rw-r--r--tests/unit/introspection-2.tcl9
-rw-r--r--tests/unit/scripting.tcl105
2 files changed, 101 insertions, 13 deletions
diff --git a/tests/unit/introspection-2.tcl b/tests/unit/introspection-2.tcl
index 52ed54a29..46dac50b7 100644
--- a/tests/unit/introspection-2.tcl
+++ b/tests/unit/introspection-2.tcl
@@ -33,6 +33,15 @@ start_server {tags {"introspection"}} {
assert_match {} [cmdstat zadd]
} {} {needs:config-resetstat}
+ test {errors stats for GEOADD} {
+ r config resetstat
+ # make sure geo command will failed
+ r set foo 1
+ assert_error {WRONGTYPE Operation against a key holding the wrong kind of value*} {r GEOADD foo 0 0 bar}
+ assert_match {*calls=1*,rejected_calls=0,failed_calls=1*} [cmdstat geoadd]
+ assert_match {} [cmdstat zadd]
+ } {} {needs:config-resetstat}
+
test {command stats for EXPIRE} {
r config resetstat
r SET foo bar
diff --git a/tests/unit/scripting.tcl b/tests/unit/scripting.tcl
index cfbe60faf..6c40844c3 100644
--- a/tests/unit/scripting.tcl
+++ b/tests/unit/scripting.tcl
@@ -73,10 +73,10 @@ start_server {tags {"scripting"}} {
test {EVAL - Lua error reply -> Redis protocol type conversion} {
catch {
- run_script {return {err='this is an error'}} 0
+ run_script {return {err='ERR this is an error'}} 0
} e
set _ $e
- } {this is an error}
+ } {ERR this is an error}
test {EVAL - Lua table -> Redis protocol type conversion} {
run_script {return {1,2,3,'ciao',{1,2}}} 0
@@ -378,7 +378,7 @@ start_server {tags {"scripting"}} {
r set foo bar
catch {run_script_ro {redis.call('del', KEYS[1]);} 1 foo} e
set e
- } {*Write commands are not allowed from read-only scripts*}
+ } {ERR Write commands are not allowed from read-only scripts*}
if {$is_eval eq 1} {
# script command is only relevant for is_eval Lua
@@ -439,12 +439,12 @@ start_server {tags {"scripting"}} {
test {Globals protection reading an undeclared global variable} {
catch {run_script {return a} 0} e
set e
- } {*ERR*attempted to access * global*}
+ } {ERR*attempted to access * global*}
test {Globals protection setting an undeclared global*} {
catch {run_script {a=10} 0} e
set e
- } {*ERR*attempted to create global*}
+ } {ERR*attempted to create global*}
test {Test an example script DECR_IF_GT} {
set decr_if_gt {
@@ -599,8 +599,8 @@ start_server {tags {"scripting"}} {
} {ERR Number of keys can't be negative}
test {Scripts can handle commands with incorrect arity} {
- assert_error "*Wrong number of args calling Redis command from script" {run_script "redis.call('set','invalid')" 0}
- assert_error "*Wrong number of args calling Redis command from script" {run_script "redis.call('incr')" 0}
+ assert_error "ERR Wrong number of args calling Redis command from script*" {run_script "redis.call('set','invalid')" 0}
+ assert_error "ERR Wrong number of args calling Redis command from script*" {run_script "redis.call('incr')" 0}
}
test {Correct handling of reused argv (issue #1939)} {
@@ -723,7 +723,7 @@ start_server {tags {"scripting"}} {
} 0] {}
# Check error due to invalid command
- assert_error {ERR *Invalid command passed to redis.acl_check_cmd()} {run_script {
+ assert_error {ERR *Invalid command passed to redis.acl_check_cmd()*} {run_script {
return redis.acl_check_cmd('invalid-cmd','arg')
} 0}
}
@@ -1288,7 +1288,7 @@ start_server {tags {"scripting"}} {
r config set maxmemory 1
# Fail to execute deny-oom command in OOM condition (backwards compatibility mode without flags)
- assert_error {ERR Error running script *OOM command not allowed when used memory > 'maxmemory'.} {
+ assert_error {OOM command not allowed when used memory > 'maxmemory'*} {
r eval {
redis.call('set','x',1)
return 1
@@ -1319,7 +1319,7 @@ start_server {tags {"scripting"}} {
}
test "no-writes shebang flag" {
- assert_error {ERR Error running script *Write commands are not allowed from read-only scripts.} {
+ assert_error {ERR Write commands are not allowed from read-only scripts*} {
r eval {#!lua flags=no-writes
redis.call('set','x',1)
return 1
@@ -1404,12 +1404,19 @@ start_server {tags {"scripting"}} {
# Additional eval only tests
start_server {tags {"scripting"}} {
test "Consistent eval error reporting" {
+ r config resetstat
r config set maxmemory 1
# Script aborted due to Redis state (OOM) should report script execution error with detailed internal error
- assert_error {ERR Error running script (call to *): @user_script:*: OOM command not allowed when used memory > 'maxmemory'.} {
+ assert_error {OOM command not allowed when used memory > 'maxmemory'*} {
r eval {return redis.call('set','x','y')} 1 x
}
+ assert_equal [errorrstat OOM r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=0*rejected_calls=1,failed_calls=0*} [cmdrstat set r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat eval r]
+
# redis.pcall() failure due to Redis state (OOM) returns lua error table with Redis error message without '-' prefix
+ r config resetstat
assert_equal [
r eval {
local t = redis.pcall('set','x','y')
@@ -1420,16 +1427,37 @@ start_server {tags {"scripting"}} {
end
} 1 x
] 1
+ # error stats were not incremented
+ assert_equal [errorrstat ERR r] {}
+ assert_equal [errorrstat OOM r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=0*rejected_calls=1,failed_calls=0*} [cmdrstat set r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=0*} [cmdrstat eval r]
+
# Returning an error object from lua is handled as a valid RESP error result.
+ r config resetstat
assert_error {OOM command not allowed when used memory > 'maxmemory'.} {
r eval { return redis.pcall('set','x','y') } 1 x
}
+ assert_equal [errorrstat ERR r] {}
+ assert_equal [errorrstat OOM r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=0*rejected_calls=1,failed_calls=0*} [cmdrstat set r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat eval r]
+
r config set maxmemory 0
+ r config resetstat
# Script aborted due to error result of Redis command
- assert_error {ERR Error running script (call to *): @user_script:*: ERR DB index is out of range} {
+ assert_error {ERR DB index is out of range*} {
r eval {return redis.call('select',99)} 0
}
+ assert_equal [errorrstat ERR r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat select r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat eval r]
+
# redis.pcall() failure due to error in Redis command returns lua error table with redis error message without '-' prefix
+ r config resetstat
assert_equal [
r eval {
local t = redis.pcall('select',99)
@@ -1440,11 +1468,23 @@ start_server {tags {"scripting"}} {
end
} 0
] 1
+ assert_equal [errorrstat ERR r] {count=1} ;
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat select r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=0*} [cmdrstat eval r]
+
# Script aborted due to scripting specific error state (write cmd with eval_ro) should report script execution error with detailed internal error
- assert_error {ERR Error running script (call to *): @user_script:*: ERR Write commands are not allowed from read-only scripts.} {
+ r config resetstat
+ assert_error {ERR Write commands are not allowed from read-only scripts*} {
r eval_ro {return redis.call('set','x','y')} 1 x
}
+ assert_equal [errorrstat ERR r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=0*rejected_calls=1,failed_calls=0*} [cmdrstat set r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat eval_ro r]
+
# redis.pcall() failure due to scripting specific error state (write cmd with eval_ro) returns lua error table with Redis error message without '-' prefix
+ r config resetstat
assert_equal [
r eval_ro {
local t = redis.pcall('set','x','y')
@@ -1455,20 +1495,59 @@ start_server {tags {"scripting"}} {
end
} 1 x
] 1
+ assert_equal [errorrstat ERR r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=0*rejected_calls=1,failed_calls=0*} [cmdrstat set r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=0*} [cmdrstat eval_ro r]
+
+ r config resetstat
+ # make sure geoadd will failed
+ r set Sicily 1
+ assert_error {WRONGTYPE Operation against a key holding the wrong kind of value*} {
+ r eval {return redis.call('GEOADD', 'Sicily', '13.361389', '38.115556', 'Palermo', '15.087269', '37.502669', 'Catania')} 1 x
+ }
+ assert_equal [errorrstat WRONGTYPE r] {count=1}
+ assert_equal [s total_error_replies] {1}
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat geoadd r]
+ assert_match {calls=1*rejected_calls=0,failed_calls=1*} [cmdrstat eval r]
} {} {cluster:skip}
test "LUA redis.error_reply API" {
+ r config resetstat
assert_error {MY_ERR_CODE custom msg} {
r eval {return redis.error_reply("MY_ERR_CODE custom msg")} 0
}
+ assert_equal [errorrstat MY_ERR_CODE r] {count=1}
+ }
+
+ test "LUA redis.error_reply API with empty string" {
+ r config resetstat
+ assert_error {ERR} {
+ r eval {return redis.error_reply("")} 0
+ }
+ assert_equal [errorrstat ERR r] {count=1}
}
test "LUA redis.status_reply API" {
+ r config resetstat
r readraw 1
assert_equal [
r eval {return redis.status_reply("MY_OK_CODE custom msg")} 0
] {+MY_OK_CODE custom msg}
r readraw 0
+ assert_equal [errorrstat MY_ERR_CODE r] {} ;# error stats were not incremented
+ }
+
+ test "LUA test pcall" {
+ assert_equal [
+ r eval {local status, res = pcall(function() return 1 end); return 'status: ' .. tostring(status) .. ' result: ' .. res} 0
+ ] {status: true result: 1}
+ }
+
+ test "LUA test pcall with error" {
+ assert_match {status: false result:*Script attempted to access nonexistent global variable 'foo'} [
+ r eval {local status, res = pcall(function() return foo end); return 'status: ' .. tostring(status) .. ' result: ' .. res} 0
+ ]
}
}