From 307042443785444a8ad1e65132dc847d6aee0b54 Mon Sep 17 00:00:00 2001 From: Michael Martin <3277009+flrgh@users.noreply.github.com> Date: Wed, 6 Jul 2022 13:10:28 -0700 Subject: [PATCH 1/2] chore(healthcheck) increase verbosity for locked function failures --- lib/resty/healthcheck.lua | 24 ++++++++++++++---------- 1 file changed, 14 insertions(+), 10 deletions(-) diff --git a/lib/resty/healthcheck.lua b/lib/resty/healthcheck.lua index 2973453e..60031882 100644 --- a/lib/resty/healthcheck.lua +++ b/lib/resty/healthcheck.lua @@ -235,16 +235,25 @@ do timer = true, } - local function run_in_timer(premature, fn, ...) + local function run_in_timer(premature, self, key, fn, ...) if premature then return end - return fn(...) + local ok, err = run_locked(self, key, fn, ...) + if not ok then + self:log(ERR, "locked function for key '", key, "' failed in timer: ", err) + end end - local function schedule(fn, ...) - return ngx.timer.at(0, run_in_timer, fn, ...) + local function schedule(self, key, fn, ...) + local ok, err = ngx.timer.at(0, run_in_timer, self, key, fn, ...) + if not ok then + return nil, "failed scheduling locked function for key '" .. key .. + "', " .. err + end + + return "scheduled" end -- timeout when yieldable @@ -310,12 +319,7 @@ do if not elapsed and err == "timeout" and not yield then -- yielding is not possible in the current phase, so retry in a timer - local ok, terr = schedule(run_locked, self, key, fn, ...) - if not ok then - return nil, terr - end - - return "scheduled" + return schedule(self, key, fn, ...) elseif not elapsed then return nil, "failed acquiring lock for '" .. key .. "', " .. err From 4cf2f0499fbe56cd6d98a4b430e88866dfeb70b1 Mon Sep 17 00:00:00 2001 From: Michael Martin <3277009+flrgh@users.noreply.github.com> Date: Wed, 6 Jul 2022 14:52:44 -0700 Subject: [PATCH 2/2] tests(healthcheck) add tests for run_locked() --- lib/resty/healthcheck.lua | 27 ++- t/21-run_locked.t | 347 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 366 insertions(+), 8 deletions(-) create mode 100644 t/21-run_locked.t diff --git a/lib/resty/healthcheck.lua b/lib/resty/healthcheck.lua index 60031882..2df9a245 100644 --- a/lib/resty/healthcheck.lua +++ b/lib/resty/healthcheck.lua @@ -51,6 +51,9 @@ local new_tab local nkeys local is_array + +local TESTING = _G.__TESTING_HEALTHCHECKER or false + do local ok @@ -96,7 +99,6 @@ local EMPTY = setmetatable({},{ end }) - --- timer constants -- evaluate active checks every 0.1s local CHECK_INTERVAL = 0.1 @@ -216,6 +218,10 @@ local function key_for(key_prefix, ip, port, hostname) return string.format("%s:%s:%s%s", key_prefix, ip, port, hostname and ":" .. hostname or "") end + +-- resty.lock timeout when yieldable +local LOCK_TIMEOUT = 5 + local run_locked do -- resty_lock is restricted to this scope in order to keep sensitive @@ -256,13 +262,10 @@ do return "scheduled" end - -- timeout when yieldable - local timeout = 5 - -- resty.lock consumes these options immediately, so this table can be reused local opts = { - exptime = 10, -- timeout after which lock is released anyway - timeout = timeout, -- max wait time to acquire lock + exptime = 10, -- timeout after which lock is released anyway + timeout = LOCK_TIMEOUT, -- max wait time to acquire lock } --- @@ -300,7 +303,7 @@ do local yield = yieldable[get_phase()] if yield then - opts.timeout = timeout + opts.timeout = LOCK_TIMEOUT else -- if yielding is not possible in the current phase, use a zero timeout -- so that resty.lock will return `nil, "timeout"` immediately instead of @@ -334,7 +337,7 @@ do end if not pok then - return nil, perr + return nil, "locked function threw an exception: " .. tostring(perr) end return perr, res @@ -1704,4 +1707,12 @@ function _M.new(opts) end +if TESTING then + checker._run_locked = run_locked + checker._set_lock_timeout = function(t) + LOCK_TIMEOUT = t + end +end + + return _M diff --git a/t/21-run_locked.t b/t/21-run_locked.t new file mode 100644 index 00000000..aae19330 --- /dev/null +++ b/t/21-run_locked.t @@ -0,0 +1,347 @@ +use Test::Nginx::Socket::Lua; +use Cwd qw(cwd); + +workers(1); + +plan tests => repeat_each() * (blocks() * 3) + 1; + +my $pwd = cwd(); + +our $HttpConfig = qq{ + lua_package_path "$pwd/lib/?.lua;;"; + lua_shared_dict test_shm 8m; + lua_shared_dict my_worker_events 8m; + + init_worker_by_lua_block { + local we = require "resty.worker.events" + + assert(we.configure{ shm = "my_worker_events", interval = 0.1 }) + + _G.__TESTING_HEALTHCHECKER = true + + local healthcheck = require("resty.healthcheck") + + _G.checker = assert(healthcheck.new({ + name = "testing", + shm_name = "test_shm", + checks = { + active = { + healthy = { + interval = 0, + }, + unhealthy = { + interval = 0, + } + } + } + })) + + checker._set_lock_timeout(1) + } +}; + +run_tests(); + +__DATA__ + +=== TEST 1: run_locked() runs a function immediately and returns its result +--- http_config eval: $::HttpConfig +--- config + location = /t { + content_by_lua_block { + local checker = _G.checker + + local flag = false + local ok, err = checker:_run_locked("key", function() + flag = true + return "OK" + end) + + ngx.say(ok) + ngx.say(err) + ngx.say(flag) + } + } +--- request +GET /t +--- response_body +OK +nil +true +--- no_error_log +[error] + + + +=== TEST 2: run_locked() can run a function immediately in an non-yieldable phase if no lock is held +--- http_config eval: $::HttpConfig +--- config + location = /t { + set_by_lua_block $test { + local checker = _G.checker + local value + local ok, err = checker:_run_locked("key", function() + value = "SET" + return "OK" + end) + + if not ok then + ngx.log(ngx.ERR, "run_locked failed: ", err) + return + end + + ngx.ctx.ok = ok + return value + } + + content_by_lua_block { + ngx.say(ngx.ctx.ok) + ngx.say(ngx.var.test) + } + } +--- request +GET /t +--- response_body +OK +SET +--- no_error_log +[error] + + + +=== TEST 3: run_locked() schedules a function in a timer if a lock cannot be acquired during a non-yieldable phase +--- http_config eval: $::HttpConfig +--- config + location = /t { + set_by_lua_block $test { + local checker = _G.checker + + local key = "my_lock_key" + + local resty_lock = require "resty.lock" + local lock = assert(resty_lock:new(checker.shm_name)) + assert(lock:lock(key)) + ngx.ctx.lock = lock + + local t = {} + ngx.ctx.t = t + + local ok, err = checker:_run_locked(key, function() + t.flag = true + t.phase = ngx.get_phase() + return true + end) + + assert(err == nil, "expected no error") + assert(ok == "scheduled", "expected the function to be scheduled") + } + + content_by_lua_block { + assert(ngx.ctx.lock:unlock()) + + local t = ngx.ctx.t + + for i = 1, 10 do + if t.flag then + break + end + ngx.sleep(0.25) + end + + ngx.say(t.phase or "none") + ngx.say(t.flag or "timeout") + } + } +--- request +GET /t +--- response_body +timer +true +--- no_error_log +[error] + + + +=== TEST 4: run_locked() doesn't schedule a function in a timer during a yieldable phase +--- http_config eval: $::HttpConfig +--- config + location = /t { + content_by_lua_block { + local checker = _G.checker + + local key = "my_lock_key" + + local resty_lock = require "resty.lock" + local lock = assert(resty_lock:new(checker.shm_name)) + assert(lock:lock(key)) + + local flag = false + local ok, err = checker:_run_locked(key, function() + flag = true + return true + end) + + ngx.say(ok) + ngx.say(err) + ngx.say(flag) + } + } +--- request +GET /t +--- response_body +nil +failed acquiring lock for 'my_lock_key', timeout +false +--- no_error_log +[error] + + + +=== TEST 5: run_locked() handles function exceptions +--- http_config eval: $::HttpConfig +--- config + location = /t { + content_by_lua_block { + local checker = _G.checker + + local ok, err = checker:_run_locked("key", function() + error("oh no!") + return true + end) + + -- remove "content_by_lua(nginx.conf:)" context and such from + -- the error string so that our test is a little more stable + err = err:gsub(" content_by_lua[^ ]+", "") + + ngx.say(ok) + ngx.say(err) + } + } +--- request +GET /t +--- response_body +nil +locked function threw an exception: oh no! +--- no_error_log +[error] + + + +=== TEST 6: run_locked() returns errors from the locked function +--- http_config eval: $::HttpConfig +--- config + location = /t { + content_by_lua_block { + local checker = _G.checker + + local ok, err = checker:_run_locked("key", function() + return nil, "I've failed you" + end) + + ngx.say(ok) + ngx.say(err) + } + } +--- request +GET /t +--- response_body +nil +I've failed you +--- no_error_log +[error] + + + +=== TEST 7: run_locked() logs errors/exceptions from scheduled functions +--- http_config eval: $::HttpConfig +--- config + location = /t { + set_by_lua_block $test { + local checker = _G.checker + + local key = "my_lock_key" + + local resty_lock = require "resty.lock" + local lock = assert(resty_lock:new(checker.shm_name)) + assert(lock:lock(key)) + ngx.ctx.lock = lock + + local t = { count = 0 } + ngx.ctx.t = t + + local ok, err = checker:_run_locked(key, function() + t.count = t.count + 1 + error("LOCK EXCEPTION") + end) + + assert(err == nil, "expected no error") + assert(ok == "scheduled", "expected the function to be scheduled") + + local ok, err = checker:_run_locked(key, function() + t.count = t.count + 1 + return nil, "LOCK ERROR" + end) + + assert(err == nil, "expected no error") + assert(ok == "scheduled", "expected the function to be scheduled") + + local ok, err = checker:_run_locked(key, function() + t.count = t.count + 1 + return true + end) + + assert(err == nil, "expected no error") + assert(ok == "scheduled", "expected the function to be scheduled") + } + + content_by_lua_block { + assert(ngx.ctx.lock:unlock()) + + local t = ngx.ctx.t + + for i = 1, 10 do + if t.count >= 3 then + break + end + ngx.sleep(0.25) + end + + ngx.say(t.count) + } + } +--- request +GET /t +--- response_body +3 +--- error_log +LOCK ERROR +LOCK EXCEPTION + + + +=== TEST 8: run_locked() passes any/all arguments to the locked function +--- http_config eval: $::HttpConfig +--- config + location = /t { + content_by_lua_block { + local checker = _G.checker + + local sum = 0 + local ok, err = checker:_run_locked("key", function(a, b, c) + sum = sum + a + b + c + return true + end, 1, 2, 3) + + ngx.say(ok) + ngx.say(err) + ngx.say(sum) + } + } +--- request +GET /t +--- response_body +true +nil +6 +--- no_error_log +[error]