main.lua

Thu, 23 Mar 2023 12:14:53 +0000

author
Matthew Wild <mwild1@gmail.com>
date
Thu, 23 Mar 2023 12:14:53 +0000
changeset 172
2c17151ed21b
parent 162
f888f236321f
child 173
14ed4cb241f4
permissions
-rwxr-xr-x

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);

mercurial