From c20efbf78fad504c47e94420142f82032a65c7b7 Mon Sep 17 00:00:00 2001 From: bneradt Date: Mon, 17 Aug 2026 14:33:20 -0500 Subject: [PATCH] lua: run __shutdown__ with every Lua state quiesced A __shutdown__ function usually releases process global resources, and often does so through FFI into a native library. The shutdown handler locked only the state whose __shutdown__ it was invoking and released that lock before moving to the next state, so the callback running in state 0 could tear those resources down while a request callback was still using them in state 1. Production has crashed this way during restart, inside a global read-request callback rather than in any shutdown path. This patch hands the callbacks to a thread of its own, which acquires every main Lua state mutex, global and remap, before invoking any __shutdown__ function and keeps them for the rest of the process lifetime, so nothing queued behind one of them can enter Lua after the resources it uses are gone. A separate thread is required because ProxyMutex is recursive per event thread: the lifecycle thread would still enter Lua itself when it returns to its event loop for a final iteration. Acquisition is bounded, and the callbacks are skipped with an error rather than run against a state that never went idle. Remap instance teardown declines to wait on the retained mutexes, so it cannot deadlock the rest of shutdown. A single continuation now invokes every script's __shutdown__, so the states are quiesced exactly once no matter how many scripts define one. --- doc/admin-guide/plugins/lua.en.rst | 21 ++ plugins/lua/ts_lua.cc | 204 +++++++++++++++--- .../pluginTest/lua/global_shutdown.lua | 110 +++++++++- .../lua/lua_global_shutdown.test.py | 153 ++++++++++++- .../pluginTest/lua/remap_shutdown.lua | 90 ++++++++ .../pluginTest/lua/shutdown_race_client.py | 138 ++++++++++++ 6 files changed, 670 insertions(+), 46 deletions(-) create mode 100644 tests/gold_tests/pluginTest/lua/remap_shutdown.lua create mode 100644 tests/gold_tests/pluginTest/lua/shutdown_race_client.py diff --git a/doc/admin-guide/plugins/lua.en.rst b/doc/admin-guide/plugins/lua.en.rst index c5e7f784ce3..b93c99fb252 100644 --- a/doc/admin-guide/plugins/lua.en.rst +++ b/doc/admin-guide/plugins/lua.en.rst @@ -137,6 +137,27 @@ Example:: ts.debug('ATS shutting down, cleaning up resources') end +Because ``__shutdown__`` commonly releases process global resources, no Lua code +runs in any of the plugin's Lua states while the ``__shutdown__`` functions are +invoked: the plugin waits for every state to become idle first, and no Lua +callback enters a state after that. If a state is still executing Lua after five +seconds, the ``__shutdown__`` functions are skipped rather than run concurrently +with it, and that is reported in the error log. Requests are held for as long as a +``__shutdown__`` function runs, so it should return promptly. + +This covers the states used by remap instances of the plugin as well, and it +means that once ``__shutdown__`` has run, a remap instance is left in place +rather than torn down: its ``__clean__`` function is not called during shutdown. +|TS| already skips that teardown whenever a transaction still holds a lease on +the remap configuration at shutdown, so ``__clean__`` should not be relied on as +a shutdown hook in any case. + +Note that with ``proxy.config.plugin.dynamic_reload_mode`` enabled, which is the +default, a remap instance of this plugin is loaded from a private copy of the +plugin with Lua states of its own. Those states are not covered by a global +plugin's ``__shutdown__``, so resources shared between a global script and a +remap script should not be released from ``__shutdown__``. + We can write this in plugin.config: :: diff --git a/plugins/lua/ts_lua.cc b/plugins/lua/ts_lua.cc index f4af729070b..35dc04ec373 100644 --- a/plugins/lua/ts_lua.cc +++ b/plugins/lua/ts_lua.cc @@ -23,6 +23,11 @@ #include #include +#include +#include +#include +#include + #include "ts_lua_util.h" extern "C" { @@ -55,6 +60,10 @@ static char const *const ts_lua_mgmt_state_regex = "^[1-9][0-9]*$"; // this is set the first time global configuration is probed. static int ts_lua_max_state_count = 0; +// Set once the shutdown barrier owns every Lua state mutex and keeps them. Read by +// TSRemapDeleteInstance, on the event thread that continues shutting ATS down. +static std::atomic shutdown_barrier_engaged{false}; + // lifecycle message tag static char const *const print_tag = "stats_print"; static char const *const reset_tag = "stats_reset"; @@ -487,6 +496,18 @@ TSRemapNewInstance(int argc, char *argv[], void **ih, char *errbuf, int errbuf_s void TSRemapDeleteInstance(void *ih) { + // Once the shutdown barrier owns the Lua state mutexes it never gives them back, + // so ts_lua_del_module() would block here for good, on the event thread that + // still has the rest of ATS shutdown to run. ATS as it stands does not get here + // during shutdown -- it leaks the remap configuration instead, deliberately, + // because plugin teardown after shutdown is unsafe -- but a hung restart is a bad + // enough outcome to guard against that changing. The process is exiting, so + // leaving the instance alone costs nothing but a __clean__ call. + if (shutdown_barrier_engaged.load(std::memory_order_acquire)) { + Dbg(dbg_ctl, "shutdown barrier engaged, skipping remap instance teardown for '%s'", ((ts_lua_instance_conf *)ih)->script); + return; + } + int states = ((ts_lua_instance_conf *)ih)->states; ts_lua_del_module((ts_lua_instance_conf *)ih, ts_lua_main_ctx_array, states); ts_lua_del_instance(static_cast(ih)); @@ -830,44 +851,154 @@ globalHookHandler(TSCont contp, TSEvent event ATS_UNUSED, void *edata) return 0; } -static int -shutdownHookHandler(TSCont contp, TSEvent /* event ATS_UNUSED */, void * /* edata ATS_UNUSED */) +// Longest time the shutdown barrier waits for the Lua states to go idle. A Lua +// callback is expected to run for microseconds, so exceeding this means a script +// is stuck rather than merely busy. +constexpr std::chrono::milliseconds shutdown_barrier_timeout{5000}; +constexpr std::chrono::milliseconds shutdown_barrier_poll{5}; + +// The scripts with a __shutdown__ function, in plugin.config order. A single +// continuation runs all of them, so the barrier is taken exactly once. +static std::vector shutdown_confs; +static TSCont shutdown_contp = nullptr; + +static bool +lockStates(ts_lua_main_ctx *const ctx_array, std::chrono::steady_clock::time_point const deadline, std::vector &locked) +{ + if (nullptr == ctx_array) { + return true; + } + + // Ascending index order, matching every other multi-state walk in the plugin. + for (int index = 0; index < ts_lua_max_state_count; ++index) { + TSMutex const mutexp = ctx_array[index].mutexp; + + while (TS_SUCCESS != TSMutexLockTry(mutexp)) { + if (deadline <= std::chrono::steady_clock::now()) { + return false; + } + std::this_thread::sleep_for(shutdown_barrier_poll); + } + + locked.push_back(mutexp); + } + + return true; +} + +static void +unlockStates(std::vector &locked) { - ts_lua_instance_conf *const conf = (ts_lua_instance_conf *)TSContDataGet(contp); + for (auto mutexp = locked.rbegin(); mutexp != locked.rend(); ++mutexp) { + TSMutexUnlock(*mutexp); + } + + locked.clear(); +} - for (int index = 0; index < conf->states; ++index) { - ts_lua_main_ctx *const main_ctx = &ts_lua_g_main_ctx_array[index]; +// Invoke every __shutdown__ function with no Lua code running anywhere else in +// the process. +// +// A __shutdown__ function typically releases process global resources, often in +// a native library reached through FFI. Each Lua execution path locks only the +// one main state it was assigned, so locking a single state is not enough: the +// callback running in state 0 can tear those resources down while a request +// callback is still using them in state 1. Holding every main state mutex is +// what makes __shutdown__ exclusive with all Lua code. +// +// This runs on a thread of its own rather than on the event thread that +// dispatched TS_LIFECYCLE_SHUTDOWN_HOOK because ProxyMutex is recursive per +// thread: an event thread that holds these mutexes can still enter Lua itself, +// and the dispatching event thread does exactly that when it returns to its +// event loop for the last time. +static void * +runShutdownCallbacks(void * /* data ATS_UNUSED */) +{ + auto const deadline = std::chrono::steady_clock::now() + shutdown_barrier_timeout; + + std::vector global_states; + std::vector remap_states; + + global_states.reserve(ts_lua_max_state_count); + remap_states.reserve(ts_lua_max_state_count); + + // The remap states are only in this image when a remap instance was loaded + // without proxy.config.plugin.dynamic_reload_mode; with dynamic reload the + // remap instance is a private copy of the plugin with states of its own, which + // this barrier cannot reach. + if (!lockStates(ts_lua_g_main_ctx_array, deadline, global_states) || !lockStates(ts_lua_main_ctx_array, deadline, remap_states)) { + // A partial barrier excludes nothing that matters and stalls the states it + // did lock, so give them all back. + unlockStates(remap_states); + unlockStates(global_states); + TSError("[ts_lua][%s] Lua states still active after %lld ms, skipping %s", __FUNCTION__, + static_cast(shutdown_barrier_timeout.count()), TS_LUA_FUNCTION_G_SHUT_DOWN); + return nullptr; + } - TSMutexLock(main_ctx->mutexp); + Dbg(dbg_ctl, "[%s] shutdown barrier acquired for %zu Lua states", __FUNCTION__, global_states.size() + remap_states.size()); - lua_State *const L = main_ctx->lua; + // Published while every state mutex is owned here, so TSRemapDeleteInstance + // cannot see it change while it is entering Lua. + shutdown_barrier_engaged.store(true, std::memory_order_release); - // Restore the conf-specific global table so lua_getglobal resolves - // functions from the loaded script, matching ts_lua_reload_module. - lua_pushlightuserdata(L, conf); - lua_rawget(L, LUA_REGISTRYINDEX); - lua_replace(L, LUA_GLOBALSINDEX); + for (ts_lua_instance_conf *const conf : shutdown_confs) { + for (int index = 0; index < conf->states; ++index) { + ts_lua_main_ctx *const main_ctx = &ts_lua_g_main_ctx_array[index]; - lua_getglobal(L, TS_LUA_FUNCTION_G_SHUT_DOWN); + lua_State *const L = main_ctx->lua; - if (lua_type(L, -1) == LUA_TFUNCTION) { - if (lua_pcall(L, 0, 0, 0) != 0) { - TSError("[ts_lua][%s] lua_pcall failed for script '%s' state %d: %s", __FUNCTION__, conf->script, index, - lua_tostring(L, -1)); + // Restore the conf-specific global table so lua_getglobal resolves + // functions from the loaded script, matching ts_lua_reload_module. + lua_pushlightuserdata(L, conf); + lua_rawget(L, LUA_REGISTRYINDEX); + lua_replace(L, LUA_GLOBALSINDEX); + + lua_getglobal(L, TS_LUA_FUNCTION_G_SHUT_DOWN); + + if (lua_type(L, -1) == LUA_TFUNCTION) { + if (lua_pcall(L, 0, 0, 0) != 0) { + TSError("[ts_lua][%s] lua_pcall failed for script '%s' state %d: %s", __FUNCTION__, conf->script, index, + lua_tostring(L, -1)); + lua_pop(L, 1); + } + } else { lua_pop(L, 1); } - } else { - lua_pop(L, 1); + + // Restore LUA_GLOBALSINDEX to an empty table, matching the resting state + // established by ts_lua_add_module and ts_lua_reload_module. + lua_newtable(L); + lua_replace(L, LUA_GLOBALSINDEX); } + } - // Restore LUA_GLOBALSINDEX to an empty table, matching the resting state - // established by ts_lua_add_module and ts_lua_reload_module. - lua_newtable(L); - lua_replace(L, LUA_GLOBALSINDEX); + // Every state mutex is deliberately kept, by a thread that is about to exit. + // TS_LIFECYCLE_SHUTDOWN_HOOK is terminal and no event thread is joined before + // the process exits, so releasing any of them would only let a callback that is + // already queued behind one enter Lua after __shutdown__ freed what that + // callback uses. An event thread blocked on one of these mutexes does not keep + // the process from exiting. TSRemapDeleteInstance, which ATS runs later in + // shutdown and which would otherwise block on the remap mutexes, is what + // shutdown_barrier_engaged is for. + return nullptr; +} - TSMutexUnlock(main_ctx->mutexp); +static int +shutdownHookHandler(TSCont /* contp ATS_UNUSED */, TSEvent /* event ATS_UNUSED */, void * /* edata ATS_UNUSED */) +{ + TSThread const barrier = TSThreadCreate(runShutdownCallbacks, nullptr); + + if (nullptr == barrier) { + TSError("[ts_lua][%s] could not create the shutdown barrier thread, skipping %s", __FUNCTION__, TS_LUA_FUNCTION_G_SHUT_DOWN); + return 0; } + // ATS continues shutting down as soon as this returns, so wait for the + // callbacks. The thread itself is not destroyed: the mutexes it still holds + // record it as their owner. + TSThreadWait(barrier); + return 0; } @@ -1110,17 +1241,22 @@ TSPluginInit(int argc, const char *argv[]) lua_getglobal(sl, TS_LUA_FUNCTION_G_SHUT_DOWN); if (lua_type(sl, -1) == LUA_TFUNCTION) { - TSMutex shutdown_mutex = TSMutexCreate(); - TSCont shutdown_contp = TSContCreate(shutdownHookHandler, shutdown_mutex); - if (!shutdown_contp) { - TSError("[ts_lua][%s] could not create shutdown continuation", __FUNCTION__); - if (shutdown_mutex) { - TSMutexDestroy(shutdown_mutex); + shutdown_confs.push_back(conf); + + // One continuation invokes every script's __shutdown__, so that the shutdown + // barrier is taken once for the whole process. + if (nullptr == shutdown_contp) { + TSMutex shutdown_mutex = TSMutexCreate(); + shutdown_contp = TSContCreate(shutdownHookHandler, shutdown_mutex); + if (!shutdown_contp) { + TSError("[ts_lua][%s] could not create shutdown continuation", __FUNCTION__); + if (shutdown_mutex) { + TSMutexDestroy(shutdown_mutex); + } + } else { + TSLifecycleHookAdd(TS_LIFECYCLE_SHUTDOWN_HOOK, shutdown_contp); + Dbg(dbg_ctl, "shutdown_hook added"); } - } else { - TSContDataSet(shutdown_contp, conf); - TSLifecycleHookAdd(TS_LIFECYCLE_SHUTDOWN_HOOK, shutdown_contp); - Dbg(dbg_ctl, "shutdown_hook added"); } } lua_pop(sl, 1); diff --git a/tests/gold_tests/pluginTest/lua/global_shutdown.lua b/tests/gold_tests/pluginTest/lua/global_shutdown.lua index ab300078764..47c797db8e1 100644 --- a/tests/gold_tests/pluginTest/lua/global_shutdown.lua +++ b/tests/gold_tests/pluginTest/lua/global_shutdown.lua @@ -6,7 +6,7 @@ -- "License"); you may not use this file except in compliance -- with the License. You may obtain a copy of the License at -- --- http://www.apache.org/licenses/LICENSE-2.0 +-- http://www.apache.org/licenses/LICENSE-2.0 -- -- Unless required by applicable law or agreed to in writing, software -- distributed under the License is distributed on an "AS IS" BASIS, @@ -14,10 +14,114 @@ -- See the License for the specific language governing permissions and -- limitations under the License. +-- The test directory doubles as the handshake area with shutdown_race_client.py. +-- Without it this script only exercises the plain __shutdown__ path. +local test_directory = os.getenv('TS_LUA_SHUTDOWN_TEST_DIR') + +-- Which Lua state this copy of the script was loaded into. The script is loaded +-- once per state, in ascending state order, so a load-time counter names the +-- states the same way the plugin does. +local state_id = 0 + +-- The state that occupies itself with /hold requests. State 0 is the state whose +-- __shutdown__ runs first, so keeping the busy work out of state 0 is what makes +-- this a cross-state overlap rather than a same-state one. +local hold_state_id = 1 + +-- Written while hold_state_id is inside do_global_read_request. +local active_path = nil + +-- Written once the __shutdown__ functions have run. Any Lua executed after that +-- is Lua running against whatever __shutdown__ tore down. +local shutdown_path = nil + +-- How long a /hold request occupies its Lua state. Long enough that the state +-- stays busy across a shutdown, short enough to keep the load flowing. +local hold_seconds = 0.15 + +-- How long __shutdown__ spends releasing resources, standing in for a script that +-- does real cleanup work there. +local shutdown_seconds = 1.0 + +if test_directory then + local counter_path = test_directory .. '/lua-state-counter' + local counter = io.open(counter_path, 'r') + + if counter then + state_id = tonumber(counter:read('*a')) or 0 + counter:close() + end + + counter = assert(io.open(counter_path, 'w')) + counter:write(state_id + 1) + counter:close() + + active_path = test_directory .. '/lua-state-' .. hold_state_id .. '.active' + shutdown_path = test_directory .. '/lua-shutdown-done' +end + function do_global_read_request() - ts.debug('do_global_read_request called') + ts.debug('do_global_read_request called') + + if shutdown_path then + local done = io.open(shutdown_path, 'r') + + if done then + done:close() + ts.debug('do_global_read_request ran after __shutdown__') + end + end + + if not active_path or state_id ~= hold_state_id or ts.client_request.get_uri() ~= '/hold' then + return + end + + local active = assert(io.open(active_path, 'w')) + + active:write('active') + active:close() + + -- Busy-wait: ts.sleep() would yield and release the Lua state mutex, and + -- holding that mutex is the whole point of this callback. + local deadline = ts.now() + hold_seconds + + while ts.now() < deadline do + end + + os.remove(active_path) end function __shutdown__() - ts.debug('__shutdown__ called') + if active_path and state_id == 0 then + local active = io.open(active_path, 'r') + + if active then + active:close() + ts.debug('__shutdown__ overlapped an active Lua state') + end + end + + ts.debug('__shutdown__ called for state ' .. state_id) + + if not shutdown_path then + return + end + + local done = assert(io.open(shutdown_path, 'w')) + + done:write('done') + done:close() + + if state_id ~= 0 then + return + end + + -- A real __shutdown__ releases resources rather than returning immediately. + -- Spending that time here is what gives the request load a chance to pile up + -- on the Lua state mutexes the barrier is holding: those requests must not + -- enter Lua afterwards, in a global or in a remap state. + local deadline = ts.now() + shutdown_seconds + + while ts.now() < deadline do + end end diff --git a/tests/gold_tests/pluginTest/lua/lua_global_shutdown.test.py b/tests/gold_tests/pluginTest/lua/lua_global_shutdown.test.py index ca2bb95046f..e1622f5aa67 100644 --- a/tests/gold_tests/pluginTest/lua/lua_global_shutdown.test.py +++ b/tests/gold_tests/pluginTest/lua/lua_global_shutdown.test.py @@ -17,6 +17,9 @@ # See the License for the specific language governing permissions and # limitations under the License. +import os +import sys + Test.Summary = ''' Test __shutdown__ lua global plugin hook ''' @@ -25,24 +28,58 @@ Test.ContinueOnFail = True +# Helper script for signaling a traffic_server process by command-line identifier +# match. Reused from gold_tests/logging. +TS_PID_SCRIPT = 'ts_process_handler.py' + server = Test.MakeOriginServer("server") -ts = Test.MakeATSProcess("ts") + +# The identifier shutdown_race_client.py matches on to find this process. +ts = Test.MakeATSProcess("lua_shutdown_ts") Test.Setup.Copy("global_shutdown.lua") +Test.Setup.Copy("remap_shutdown.lua") +Test.Setup.Copy("shutdown_race_client.py") +Test.Setup.Copy(os.path.join(Test.TestDirectory, '..', '..', 'logging', TS_PID_SCRIPT)) + +# Where global_shutdown.lua numbers the Lua states and reports which one is busy. +ts.Env['TS_LUA_SHUTDOWN_TEST_DIR'] = Test.RunDirectory request_header = {"headers": "GET / HTTP/1.1\r\nHost: www.example.com\r\n\r\n", "timestamp": "1469733493.993", "body": ""} response_header = {"headers": "HTTP/1.1 200 OK\r\nConnection: close\r\n\r\n", "timestamp": "1469733493.993", "body": ""} server.addResponse("sessionfile.log", request_header, response_header) +# A remap instance of the plugin as well as the global one. A global script's +# __shutdown__ releases process global resources, so the remap Lua states have to +# be held across it too, and stay held: a remap callback queued on one of those +# mutexes would otherwise enter Lua as soon as they were released. +# A single remap Lua state, so that requests queue on its mutex rather than +# spreading across states. +ts.Disk.remap_config.AddLine( + 'map http://remap.example.com/ http://127.0.0.1:{}/' + ' @plugin=tslua.so @pparam=--states=1 @pparam={}/remap_shutdown.lua'.format(server.Variables.Port, Test.RunDirectory)) ts.Disk.remap_config.AddLine('map / http://127.0.0.1:{}/'.format(server.Variables.Port)) # Use 2 states so the shutdown handler is called a predictable number of times. ts.Disk.plugin_config.AddLine('tslua.so --states=2 {}/global_shutdown.lua'.format(Test.RunDirectory)) -ts.Disk.records_config.update({ - 'proxy.config.diags.debug.enabled': 1, - 'proxy.config.diags.debug.tags': 'ts_lua', -}) +ts.Disk.records_config.update( + { + # With 2 states and 4 event threads, each state is used by 2 event threads: + # concurrent /hold requests then keep state 1 busy no matter which event + # thread the shutdown continuation is dispatched to. + 'proxy.config.exec_thread.autoconfig.enabled': 0, + 'proxy.config.exec_thread.limit': 4, + # Shut down as soon as SIGTERM is received, while the load is still running. + 'proxy.config.stop.shutdown_timeout': 0, + # Load the remap instance of the plugin from the same image as the global + # instance, so that the shutdown handler sees the remap Lua states too. With + # dynamic reload enabled the remap instance is a private copy of the .so with + # Lua states of its own. + 'proxy.config.plugin.dynamic_reload_mode': 0, + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'ts_lua', + }) curl_and_args = '-s -D /dev/stdout -o /dev/stderr -x localhost:{} '.format(ts.Variables.port) @@ -50,15 +87,113 @@ tr = Test.AddTestRun("Lua global read request hook fires for HTTP requests") ps = tr.Processes.Default ps.StartBefore(server, ready=When.PortOpen(server.Variables.Port)) -ps.StartBefore(Test.Processes.ts) +ps.StartBefore(ts) tr.MakeCurlCommand(curl_and_args + 'http://www.example.com/', ts=ts) ps.ReturnCode = 0 tr.StillRunningAfter = ts +tr.StillRunningAfter = server # Verify do_global_read_request was invoked for the HTTP request above. ts.Disk.traffic_out.Content = Testers.ContainsExpression( r'do_global_read_request called', 'do_global_read_request should be called for HTTP requests') -# After all test runs complete AuTest stops ATS, which fires TS_LIFECYCLE_SHUTDOWN_HOOK. -# The shutdown handler calls __shutdown__ once per Lua state (2 states configured). -ts.Disk.traffic_out.Content += Testers.ContainsExpression(r'__shutdown__ called', '__shutdown__ should be called on ATS shutdown') +# 1 Test - Exercise the remap instance of the plugin. +tr = Test.AddTestRun("Lua remap instance handles requests") +ps = tr.Processes.Default +tr.MakeCurlCommand(curl_and_args + 'http://remap.example.com/remap-hello', ts=ts) +ps.ReturnCode = 0 +ps.Streams.stderr = Testers.ContainsExpression('Remap Lua response', 'the remap Lua script should generate the response') +tr.StillRunningAfter = ts +tr.StillRunningAfter = server + +# 2 Test - SIGTERM ATS while a Lua state is executing a request callback. +tr = Test.AddTestRun("Shut down while a Lua state is running Lua code") +ps = tr.Processes.Default +ps.Command = ( + f'{sys.executable} ./shutdown_race_client.py ' + f'127.0.0.1 {ts.Variables.port} {Test.RunDirectory} lua_shutdown_ts && sleep 3') +ps.ReturnCode = 0 +tr.StillRunningAfter = server + +# 3 Test - Traffic Server finished shutting down. The shutdown handler holds every +# Lua state mutex, so a deadlock there would leave the process alive. +tr = Test.AddTestRun("Traffic Server exited") +ps = tr.Processes.Default +# A non-zero return code means no matching traffic_server process was found. +ps.Command = f'{sys.executable} ./{TS_PID_SCRIPT} lua_shutdown_ts' +ps.ReturnCode = 1 +tr.StillRunningAfter = server + +# The shutdown handler calls __shutdown__ once per Lua state (2 states +# configured), and only after Lua execution in every state has quiesced. +ts.Disk.traffic_out.Content += Testers.ContainsExpression( + r'shutdown barrier acquired', 'the shutdown handler should exclude every Lua state before calling __shutdown__') +ts.Disk.traffic_out.Content += Testers.ContainsExpression( + r'__shutdown__ called for state 0', '__shutdown__ should be called for Lua state 0') +ts.Disk.traffic_out.Content += Testers.ContainsExpression( + r'__shutdown__ called for state 1', '__shutdown__ should be called for Lua state 1') +ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + r'__shutdown__ overlapped an active Lua state', '__shutdown__ should not overlap a request callback in another Lua state') + +# ProxyMutex is recursive per event thread, so the event thread that dispatches +# the shutdown hook can re-enter a Lua state it locked itself. The load runs past +# the hook, which catches that. +ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + r'do_global_read_request ran after __shutdown__', 'no Lua callback should run once __shutdown__ has been called') + +# The remap states are released to no one: a remap callback queued behind the +# barrier must not enter Lua after the global __shutdown__ freed what it uses. +ts.Disk.traffic_out.Content += Testers.ContainsExpression(r'do_remap called', 'the remap Lua script should run before shutdown') +ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + r'do_remap ran after __shutdown__', 'no remap Lua callback should run once __shutdown__ has been called') + +ts.Disk.diags_log.Content = Testers.ExcludesExpression( + r'skipping __shutdown__', 'the Lua states should go idle well inside the shutdown barrier timeout') + +# A second Traffic Server, shut down with nothing in flight, which is how a +# drained host restarts. The shutdown barrier keeps every Lua state mutex, so +# anything ATS does later in shutdown that wants one of them would hang here. No +# TS_LUA_SHUTDOWN_TEST_DIR here: the scripts then just run plainly. +quiet_ts = Test.MakeATSProcess("lua_shutdown_quiet_ts") +quiet_ts.Disk.remap_config.AddLine( + 'map http://remap.example.com/ http://127.0.0.1:{}/' + ' @plugin=tslua.so @pparam=--states=1 @pparam={}/remap_shutdown.lua'.format(server.Variables.Port, Test.RunDirectory)) +quiet_ts.Disk.plugin_config.AddLine('tslua.so --states=2 {}/global_shutdown.lua'.format(Test.RunDirectory)) +quiet_ts.Disk.records_config.update( + { + 'proxy.config.stop.shutdown_timeout': 0, + 'proxy.config.plugin.dynamic_reload_mode': 0, + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'ts_lua', + }) + +# 4 Test - Use the remap instance so that it has Lua states to tear down. +tr = Test.AddTestRun("Quiet Traffic Server serves a remap Lua request") +ps = tr.Processes.Default +ps.StartBefore(quiet_ts) +tr.MakeCurlCommand( + '-s -D /dev/stdout -o /dev/stderr -x localhost:{} http://remap.example.com/remap-hello'.format(quiet_ts.Variables.port), + ts=quiet_ts) +ps.ReturnCode = 0 +ps.Streams.stderr = Testers.ContainsExpression('Remap Lua response', 'the remap Lua script should generate the response') +tr.StillRunningAfter = quiet_ts +tr.StillRunningAfter = server + +# 5 Test - Shut it down with nothing in flight. +tr = Test.AddTestRun("Shut down the quiet Traffic Server") +ps = tr.Processes.Default +ps.Command = f'{sys.executable} ./{TS_PID_SCRIPT} lua_shutdown_quiet_ts --signal TERM && sleep 3' +ps.ReturnCode = 0 +tr.StillRunningAfter = server + +# 6 Test - It has to have exited: remap teardown must not block on the barrier. +tr = Test.AddTestRun("Quiet Traffic Server exited") +ps = tr.Processes.Default +# A non-zero return code means no matching traffic_server process was found. +ps.Command = f'{sys.executable} ./{TS_PID_SCRIPT} lua_shutdown_quiet_ts' +ps.ReturnCode = 1 + +quiet_ts.Disk.traffic_out.Content = Testers.ContainsExpression( + r'shutdown barrier acquired', 'the shutdown handler should take the barrier on a quiet shutdown too') +quiet_ts.Disk.traffic_out.Content += Testers.ContainsExpression( + r'__shutdown__ called for state 0', '__shutdown__ should be called on a quiet shutdown') diff --git a/tests/gold_tests/pluginTest/lua/remap_shutdown.lua b/tests/gold_tests/pluginTest/lua/remap_shutdown.lua new file mode 100644 index 00000000000..423ba578692 --- /dev/null +++ b/tests/gold_tests/pluginTest/lua/remap_shutdown.lua @@ -0,0 +1,90 @@ +-- Licensed to the Apache Software Foundation (ASF) under one +-- or more contributor license agreements. See the NOTICE file +-- distributed with this work for additional information +-- regarding copyright ownership. The ASF licenses this file +-- to you under the Apache License, Version 2.0 (the +-- "License"); you may not use this file except in compliance +-- with the License. You may obtain a copy of the License at +-- +-- http://www.apache.org/licenses/LICENSE-2.0 +-- +-- Unless required by applicable law or agreed to in writing, software +-- distributed under the License is distributed on an "AS IS" BASIS, +-- WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +-- See the License for the specific language governing permissions and +-- limitations under the License. + +-- The remap half of the shutdown race. A global script's __shutdown__ releases +-- process global resources, so remap Lua must not run after it either. These +-- states live in the same plugin image as the global ones only when +-- proxy.config.plugin.dynamic_reload_mode is disabled. +-- +-- The remap instance is configured with a single Lua state, so the first +-- /remap-hold request occupies it and every later one waits on its mutex. Those +-- waiting requests are the ones that must not enter Lua once __shutdown__ has run. +local test_directory = os.getenv('TS_LUA_SHUTDOWN_TEST_DIR') + +-- Written by global_shutdown.lua once the __shutdown__ functions have run. +local shutdown_path = nil + +-- Written while this state is occupied by the request below. +local active_path = nil + +-- Only the first /remap-hold occupies the state; the rest queue behind it and +-- return promptly, so the load keeps requests waiting on the mutex. +local held_once = false + +-- Long enough for the client to observe this state as occupied, short enough that +-- stalling this event thread does not starve the rest of the load. +local hold_seconds = 0.5 + +if test_directory then + shutdown_path = test_directory .. '/lua-shutdown-done' + active_path = test_directory .. '/lua-remap-state.active' +end + +function do_remap() + ts.debug('do_remap called') + + if shutdown_path then + local done = io.open(shutdown_path, 'r') + + if done then + done:close() + ts.debug('do_remap ran after __shutdown__') + end + end + + local uri = ts.client_request.get_uri() + + if uri == '/remap-hello' then + ts.http.set_resp(200, 'Remap Lua response') + return + end + + if not active_path or uri ~= '/remap-hold' then + return + end + + if held_once then + -- Answer from here rather than going to the origin, so the load stays + -- pointed at this Lua state. + ts.http.set_resp(200, 'Remap Lua queued') + return + end + + held_once = true + + local active = assert(io.open(active_path, 'w')) + + active:write('active') + active:close() + + local deadline = ts.now() + hold_seconds + + while ts.now() < deadline do + end + + os.remove(active_path) + ts.http.set_resp(200, 'Remap Lua hold') +end diff --git a/tests/gold_tests/pluginTest/lua/shutdown_race_client.py b/tests/gold_tests/pluginTest/lua/shutdown_race_client.py new file mode 100644 index 00000000000..65763c6c789 --- /dev/null +++ b/tests/gold_tests/pluginTest/lua/shutdown_race_client.py @@ -0,0 +1,138 @@ +#!/usr/bin/env python3 +''' +Shut Traffic Server down while a ts_lua state is executing a request callback. +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import argparse +import signal +import socket +import sys +import threading +import time +from pathlib import Path + +# Copied into the run directory alongside this script. +import ts_process_handler + +# Concurrent /hold requests. global_shutdown.lua holds one Lua state per request, +# so several in flight keep that state busy essentially all of the time, whichever +# event thread the shutdown continuation happens to land on. +LOAD_THREADS = 4 + +# The same idea for the remap instance of the plugin: keep remap Lua states busy, +# and requests queued on their mutexes, across the shutdown. +REMAP_LOAD_THREADS = 4 + +# How long the load keeps running after SIGTERM. It has to outlast the delay +# between the signal and TS_LIFECYCLE_SHUTDOWN_HOOK (SignalContinuation polls +# every 500ms), and it has to end well inside the plugin's barrier timeout so the +# __shutdown__ callbacks still run. +LOAD_AFTER_SIGNAL_SECONDS = 1.5 + +# How long to wait for the Lua states to start reporting themselves busy. +STATES_ACTIVE_TIMEOUT_SECONDS = 15 + + +def parse_args() -> argparse.Namespace: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument('host', help='The Traffic Server host to send requests to.') + parser.add_argument('port', type=int, help='The Traffic Server port to send requests to.') + parser.add_argument('test_directory', type=Path, help='The directory the Lua script writes its state markers in.') + parser.add_argument('ts_identifier', help='An identifier in the command line of the Traffic Server process to signal.') + return parser.parse_args() + + +def send_requests(host: str, port: int, stop: threading.Event, request: bytes) -> None: + """Send one request repeatedly until stop is set.""" + while not stop.is_set(): + try: + with socket.create_connection((host, port), timeout=10) as connection: + connection.settimeout(10) + connection.sendall(request) + while connection.recv(4096): + pass + except OSError: + # A Lua state held by another request stalls its event thread, so a + # connection can fail while the load is meant to keep running. Only + # stop asked for; giving up here would let the load die before the + # shutdown it is supposed to span. + if stop.is_set(): + return + time.sleep(0.05) + + +# The global script holds a Lua state for /hold; the remap script holds one of the +# remap states for /remap-hold. +GLOBAL_REQUEST = b'GET /hold HTTP/1.1\r\nHost: www.example.com\r\nConnection: close\r\n\r\n' +REMAP_REQUEST = b'GET /remap-hold HTTP/1.1\r\nHost: remap.example.com\r\nConnection: close\r\n\r\n' + + +def wait_for_active_state(marker: Path) -> bool: + """Wait until the Lua script reports a state busy in a request callback.""" + deadline = time.monotonic() + STATES_ACTIVE_TIMEOUT_SECONDS + while time.monotonic() < deadline: + if marker.exists(): + return True + time.sleep(0.01) + return False + + +def main() -> int: + args = parse_args() + stop = threading.Event() + loaders = [ + threading.Thread(target=send_requests, args=(args.host, args.port, stop, GLOBAL_REQUEST), daemon=True) + for _ in range(LOAD_THREADS) + ] + loaders += [ + threading.Thread(target=send_requests, args=(args.host, args.port, stop, REMAP_REQUEST), daemon=True) + for _ in range(REMAP_LOAD_THREADS) + ] + + for loader in loaders: + loader.start() + + # global_shutdown.lua holds Lua state 1; state 0 is left idle so that its + # __shutdown__ callback runs while state 1 is still executing Lua. + # remap_shutdown.lua holds the single remap state, with the remaining remap + # requests waiting on its mutex. + for marker in ('lua-state-1.active', 'lua-remap-state.active'): + if not wait_for_active_state(args.test_directory / marker): + print(f'{marker} never appeared', file=sys.stderr) + return 1 + + try: + process = ts_process_handler.get_ts_process_pid(args.ts_identifier) + except ts_process_handler.GetPidError as e: + print(e, file=sys.stderr) + return 1 + + process.send_signal(signal.SIGTERM) + + # Keep the states busy across the shutdown hook, then let them quiesce. + time.sleep(LOAD_AFTER_SIGNAL_SECONDS) + stop.set() + + for loader in loaders: + loader.join(timeout=15) + + return 0 + + +if __name__ == '__main__': + sys.exit(main())