Thu, 23 Mar 2023 12:14:53 +0000
client: Fix timeout handling
Previously, the timeout handler would fire an error that would get caught and
logged by the timer code. However that error never reached the upper levels of
scansion, leading to the whole thing just hanging.
Now we just trigger resumption of the async runner, and throw the error from
there if we haven't received the stanza yet.
With this change, timeouts are now correctly handled and reported as failures.
#!/usr/bin/env luajit local json = require "cjson"; local time = require "socket".gettime; local sleep = require "socket".sleep; local is_scansion_error = require "scansion.error".is; local new_error = require "scansion.error".new_error; local result_log_filename = nil; local server_log_reader = nil; local test_metadata = {}; local server_log_wait_time = 0.2; local skip_server_startup_log = false; local action_timeout = 10; local verse_log_levels = { "warn", "error" }; local quiet = false; local force_summary = false; local serve_mode = false; local serve_origin = nil; local only_tags, skip_tags; local property_rules = {}; local function apply_object_properties(class, name, object) for _, rule in ipairs(property_rules) do if (not(rule.class) or tostring(rule.class):lower() == tostring(class):lower()) and (not(rule.name) or tostring(rule.name):lower() == tostring(name):lower()) then for prop_key, prop_value in pairs(rule.properties) do object[prop_key] = prop_value; end end end end local function process_options() local function get_value() return (assert(table.remove(arg, 1), "unexpected end of command-line options")); end local files = {}; while arg[1] and arg[1]:sub(1,1) == "-" do local opt = arg[1]; if opt == "--" then table.remove(arg, 1); break; end table.remove(arg, 1); if opt == "--port" or opt == "-p" then local port = assert(tonumber(get_value()), "port number must be a number"); table.insert(property_rules, { class = "client", properties = { connect_port = port } }); elseif opt == "--host" or opt == "-h" then local host = get_value(); table.insert(property_rules, { class = "client", properties = { connect_host = host } }); elseif opt == "--out" or opt == "-o" then result_log_filename = get_value(); elseif opt == "--server-log" or opt == "-s" then local server_log = assert(io.open(get_value(), "r")); function server_log_reader() local new_lines = {}; local last_line_time = time(); while time() - last_line_time < server_log_wait_time do sleep(0.05); for line in server_log:lines() do table.insert(new_lines, line); last_line_time = time(); end end return new_lines; end elseif opt == "--skip-server-startup-log" then skip_server_startup_log = true; elseif opt == "--step-timeout" then action_timeout = assert(tonumber(get_value()), "number expected for --step-timeout"); elseif opt == "--meta" then local tag = get_value(); local key, value = tag:match("^([^=]+):(.+)$"); if key and value then test_metadata[key] = value; else error("Unable to parse metadata: "..tag); end elseif opt == "--with-tag" then if not only_tags then only_tags = {}; end local tag = get_value(); local key, value = tag:match("^([^=]+):(.+)$"); table.insert(only_tags, { key or tag, value }); elseif opt == "--skip-tag" then if not skip_tags then skip_tags = {}; end local tag = get_value(); local key, value = tag:match("^([^=]+):(.+)$"); table.insert(skip_tags, { key or tag, value }); elseif opt == "--verbose" or opt == "-v" then verse_log_levels = { "debug", "info", "warn", "error" }; quiet = false; elseif opt == "--quiet" or opt == "-q" then verse_log_levels = { "error" }; quiet = true; elseif opt == "--script-dir" or opt == "-d" then local have_lfs, lfs = pcall(require, "lfs"); if not have_lfs then error("The '-d' parameter requires LuaFileSystem (lfs), please make sure this library is available"); end local path = assert(get_value(), "path expected for '-d'"):gsub("/*$", ""); for f in lfs.dir(path) do if f:sub(1,1) ~= "." and f:sub(-4) == ".scs" then table.insert(files, path.."/"..f); end end elseif opt == "--summary" then force_summary = true; elseif opt == "--serve" then serve_mode = 8007; serve_origin = assert(get_value(), "origin expected for '--serve'"); elseif opt == "--serve-port" then serve_mode = assert(tonumber(get_value()), "expected port number"); serve_origin = assert(get_value(), "origin expected for '--serve-port'"); else error("Unhandled command-line option: "..opt); end end for _, file in ipairs(arg) do table.insert(files, file); end return files; end local function read_script(script_name) io.input(script_name); return io.read("*a"); end local function parse_script(data) local parser = require "scansion.parser"; return assert(parser.parse(data)); end local function initialize_script(script, context) local c = 0; for name, object in pairs(script.objects) do --luacheck: ignore name context.line = object.defined_line local o = require("scansion.objects."..object.type); object.handler = o; object.script = script; apply_object_properties(object.type, object.name, object); if object.type == "client" and not object.stanza_timeout then object.stanza_timeout = action_timeout - 1; end o._validate(object); c = c + 1; end end local function uninitialize_script(script) script.finished = true; for name, obj in pairs(script.objects) do --luacheck: ignore name if obj.handler._finish then obj.handler._finish(obj); end end end local function initialize_verse(errcb) local verse = require "verse"; verse.set_log_handler(verse._default_log_handler, verse_log_levels); local function error_handler(err) -- Only log actual errors. Those reported by Scansion will be handled gracefully higher up. if not is_scansion_error(err) then verse.log("error", "Error: %s", err); verse.log("error", "Traceback: %s", debug.traceback()); end errcb(err); end verse.set_error_handler(error_handler); return verse; end local function main(log_data, script, context) local ok, err = true; initialize_script(script, context); context.line = nil; if server_log_reader then if skip_server_startup_log then server_log_reader(); else log_data("server", { lines = server_log_reader() }); end end local verse = initialize_verse(function (_err) ok, err = false, _err end); local async = require "scansion.async"; local runner = async.runner(function () for i, action in ipairs(script.actions) do context.line = action.line_start; local object = script.objects[action.object_name]; local handler = object.handler; log_data("action", { action = action.action; object = object.name; object_type = object.type; extra = action.extra; annotation = action.annotation; line_start = action.line_start; line_end = action.line_end; }); if not handler[action.action] then local e = new_error("unsupported-action", { text = "Objects of type '"..object.type.."' do not support action '"..action.action.."'"; }); error(e); end if server_log_reader then log_data("server", { lines = server_log_reader() }); end if action_timeout and action_timeout > 0 then local action_number = i; verse.add_task(action_timeout, function () if i == action_number and not script.finished then local e = new_error("action-timeout", { text = "Timeout waiting for response" }); error(e); end end); end do --luacheck: ignore ok err local ok, err = pcall(handler[action.action], object, action.extra); if server_log_reader then log_data("server", { lines = server_log_reader() }); end if not ok then log_data("error", { message = err, line = context.line }); error(err); end end end context.line = nil; script.finished = true; verse.log("info", "Completed script!"); verse.quit(); end, { error = function (runner, _err) --luacheck: ignore runner verse.log("error", "Runner caught error: %s", _err); ok, err = false, _err; verse.quit(); end; }); runner:run(true); verse.log("debug", "runner paused") verse.loop(); if server_log_reader then log_data("server", { lines = server_log_reader() }); end uninitialize_script(script); return ok, err; end -- Process command-line options local files = process_options(); local console_handlers = require "scansion.console".new({ summary = not(quiet) or force_summary; quiet = quiet; }); local function console_logger(event, data) local h = console_handlers[event]; if h then io.write(h(data), "\n"); end end local result_log; if result_log_filename then result_log = assert(io.open(result_log_filename, "w+")); result_log:write("[\n"); end local function log_data(type, data) console_logger(type, data); if result_log then local entry = { type = type, data = data, time = time() }; result_log:write(" ", json.encode(entry), type ~= "end" and ",\n" or "\n"); result_log:flush(); if type == "end" then result_log:write("]\n"); result_log:close(); result_log = nil; end end end; local function run_test_script(script_name, script_text, log_data) local script = parse_script(script_text) local script_data = { title = script.title, summary = script.summary, tags = script.tags, filename = script_name }; local tags = script.tags or {}; if skip_tags then for _, skip in ipairs(skip_tags) do local k, v = skip[1], skip[2]; if tags[k] and (not(v) or tags[k] == v) then return { name = script.title or script.name, status = "skipped", reason = "skipping tag "..k }; end end end if only_tags then for _, only in ipairs(only_tags) do local k, v = only[1], only[2]; if not tags[k] or (v and tags[k] ~= v) then return { name = script.title or script.name, status = "skipped", reason = "not tagged "..k }; end end end log_data("script", script_data); local context = { line = nil }; local ok, result, err = pcall(main, log_data, script, context); local event, status, reason; if not ok then event, status, reason = "test-error", "error", result; elseif not result then event, status, reason = "test-failed", "fail", err; else event, status, reason = "test-passed", "ok", nil; end local result_data = { name = script.title or script_name, status = status, reason = reason, line = context.line }; log_data(event, result_data); return result_data; end if serve_mode then local have_serve, serve = pcall(require, "scansion.serve"); if not have_serve then error("This version of scansion was not built with --with-server"); end initialize_verse(function (e) --luacheck: ignore e -- This function handles scansion errors, -- but they shouldn't reach here anyway end); serve.run({ port = serve_mode, origin = serve_origin }, run_test_script); os.exit(0); end log_data("start", { metadata = test_metadata }); local result_tally = { all = {} }; assert(#files > 0, "No test script provided"); for i = 1, #files do local script_text = read_script(files[i]); local ret = run_test_script(files[i], script_text, log_data); if not result_tally[ret.status] then result_tally[ret.status] = {}; end table.insert(result_tally[ret.status], ret); table.insert(result_tally.all, ret); end log_data("end", { time = time(), summary = result_tally }); local exit_code = 0; if result_tally.error then exit_code = 2; elseif result_tally.fail then exit_code = 1; end os.exit(exit_code);