Implement timeout correctly for subprocess

This changes timeout from seconds to milliseconds. This is consistent
with previous events design.
Previously used seconds had to be multiplied and milliseconds divided
respectively to hook to current code. This just makes more sense.

src/lib/autoload/a_08_backend.lua

@@ -69,6 +69,7 @@ these variables.
 -- Time after which we SIGTERM external commands. Something incredibly long, just prevent them from being stuck.
 cmd_timeout = 600000
 -- Time after which we SIGKILL external commands
+-- TODO instead of this if subprocess is used we set kill timeout globally so drop this
 cmd_kill_timeout = 900000
 
 --[[
@@ -1010,7 +1011,7 @@ function script_run(pkg_name, script_name, ...)
 		local ecode, output = subprocess(
 			LST_PKG_SCRIPT,
 			"Running " .. script_name .. " of " .. pkg_name,
-			cmd_timeout/1000,
+			cmd_timeout,
 			function()
 				-- If root is / then variable is empty otherwise absolute path is used
 				local dir = syscnf.root_dir:gsub('^/+$', '')

src/lib/interpreter.c

@@ -508,6 +508,11 @@ static int lua_subprocess(lua_State *L) {
 	return 2;
 }
 
+static int lua_subprocess_kill_timeout(lua_State *L) {
+	subproc_kill_t(luaL_checkinteger(L, 1));
+	return 0;
+}
+
 static int lua_mkdtemp(lua_State *L) {
 	int param_count = lua_gettop(L);
 	if (param_count > 1)
@@ -902,6 +907,7 @@ static const struct injected_func injected_funcs[] = {
 	 * seem to be a need for them at this moment.
 	 */
 	{ lua_subprocess, "subprocess" },
+	{ lua_subprocess_kill_timeout, "subprocess_kill_timeout" },
 	{ lua_mkdtemp, "mkdtemp" },
 	{ lua_chdir, "chdir" },
 	{ lua_getcwd, "getcwd" },

src/lib/subprocess.c

@@ -30,7 +30,7 @@
 #include <time.h>
 #include <sys/wait.h>
 
-static int kill_timeout = 3;
+static int kill_timeout = 60000;
 
 void subproc_kill_t(int timeout) {
 	kill_timeout = timeout;
@@ -129,11 +129,13 @@ int subprocloc(int timeout, FILE *fd[2], subproc_callback callback, void *data,
 	time_t t_start = time(NULL);
 	bool term_sent = false;
 	while (true) {
-		time_t rem_t = timeout - time(NULL) + t_start;
+		int poll_timeout = -1;
+		if (timeout >= 0) {
+			int rem_t = timeout - 1000*(time(NULL) - t_start);
+			poll_timeout = rem_t < 0 ? 0 : rem_t;
+		}
 		// We ignore interrupt errors as those are really not an errors
-		// TODO what if timeout is negative?
-		// TODO also this timeout is in ms not in s!!!
-		ASSERT_MSG(poll(pfds, 2, rem_t < 0 ? 0 : rem_t) != -1 || errno == EINTR, "Subprocess poll failed with error: %s", strerror(errno));
+		ASSERT_MSG(poll(pfds, 2, poll_timeout) != -1 || errno == EINTR, "Subprocess poll failed with error: %s", strerror(errno));
 		int dead = 0;
 		for (int i = 0; i < 2; i++) {
 			if (pfds[i].revents & POLLIN) {
@@ -148,7 +150,7 @@ int subprocloc(int timeout, FILE *fd[2], subproc_callback callback, void *data,
 		}
 		if (dead >= 2)
 			break; // Both feeds are dead so break this loop
-		if (timeout >= 0 && (time(NULL) - t_start) >= timeout) {
+		if (timeout >= 0 && 1000*(time(NULL) - t_start) >= timeout) {
 			if (term_sent) { // Send SIGKILL
 				ASSERT(kill(pid, SIGKILL) != -1);
 				break;

src/lib/subprocess.h

@@ -25,7 +25,8 @@
 #include "logging.h"
 
 // Set subproc kill timeout. This is timeout used when primary timeout runs out
-// and SIGTERM is send but process still doesn't dies.
+// and SIGTERM is send but process still doesn't dies. In default it's set to 60
+// seconds.
 void subproc_kill_t(int timeout);
 
 typedef void (*subproc_callback)(void *data);
@@ -33,8 +34,8 @@ typedef void (*subproc_callback)(void *data);
 /*
 This runs non-interactive programs as subprocess. It closes stdin and pipes stdout
 and stderr trough logging system.
-You can also specify timeout in seconds. If you specify timeout less then 0 then
-no timeout is set up.
+You can also specify timeout in milliseconds. If you specify timeout less then 0
+then no timeout is set up.
 For some functions you can also add fd argument for stdout end stderr feed for
 subprocess. This allows you to specify any other feed. In default {stdout, stderr}
 is used.

tests/backend.lua

@@ -864,6 +864,7 @@ function test_merge_control()
 end
 
 function test_script_run()
+	subprocess_kill_timeout(0) -- Run tests faster
 	syscnf.info_dir = (os.getenv("S") or ".") .. "/tests/data/scripts"
 	-- This one doesn't exist. So the call succeeds.
 	local result, stderr = B.script_run("xyz", "preinst", "install")

tests/luacheck.config

@@ -10,9 +10,15 @@ globals = {
 	-- lua51 doesn't contains?
 	"_M",
 	-- From interpreter.c
-	"log", "state_log_enabled", "update_state", "cleanup_register_handle", "cleanup_unregister_handle", "run_command", "run_util", "download", "events_wait", "mkdtemp", "chdir", "getcwd", "mkdir", "move", "copy", "ls", "stat", "lstat", "sync", "setenv", "md5", "sha256", "md5_file", "sha256_file", "reexec", "uri_internal_get", "system_reboot", "get_updater_version",
-	"subprocess", "LST_PKG_SCRIPT", "PST_HOOK",
-	"LS_INIT", "LS_CONF", "LS_PLAN", "LS_DOWN", "LS_PREUPD", "LS_UNPACK", "LS_CHECK", "LS_INST", "LS_POST", "LS_REM", "LS_CLEANUP", "LS_POSTUPD", "LS_EXIT", "LS_FAIL",
+	"log", "state_log_enabled", "update_state", "cleanup_register_handle",
+	"cleanup_unregister_handle", "run_command", "run_util", "download",
+	"events_wait", "mkdtemp", "chdir", "getcwd", "mkdir", "move", "copy", "ls",
+	"stat", "lstat", "sync", "setenv", "md5", "sha256", "md5_file", "sha256_file",
+	"reexec", "uri_internal_get", "system_reboot", "get_updater_version",
+	"subprocess", "subprocess_kill_timeout", "LST_PKG_SCRIPT", "PST_HOOK",
+	"LS_INIT", "LS_CONF", "LS_PLAN", "LS_DOWN", "LS_PREUPD", "LS_UNPACK",
+	"LS_CHECK", "LS_INST", "LS_POST", "LS_REM", "LS_CLEANUP", "LS_POSTUPD",
+	"LS_EXIT", "LS_FAIL",
 	-- From logging
 	"ERROR", "WARN", "INFO", "DBG", "TRACE", "DIE", "log_event", "c_pcall_error_handler",
 	-- Picosat

tests/subprocess.c

@@ -34,17 +34,17 @@ END_TEST
 START_TEST(timeout) {
 	FILE *devnull = fopen("/dev/null", "w");
 	FILE *fds[] = {devnull, devnull};
-	subproc_kill_t(1);
+	subproc_kill_t(1000);
 	// We should be able to terminate this process
-	ck_assert(subprocvo(1, fds, "sleep", "2", NULL) != 0);
+	ck_assert_int_ne(0, subprocvo(1000, fds, "sleep", "2", NULL));
 	// This process can't be terminated and has to be killed
-	ck_assert(subprocvo(1, fds, "sh", "-c", "trap true SIGTERM; sleep 5", NULL) != 0);
+	ck_assert_int_ne(0, subprocvo(1000, fds, "sh", "-c", "trap true SIGTERM; sleep 5", NULL));
 	// This process writes stuff to stdout and should be terminated
 	// This tests if we are able to correctly timeout process with non-empty pipes
-	ck_assert(subprocvo(1, fds, "sh", "-c", "while true; do echo Stuff; sleep 1; done", NULL) != 0);
+	ck_assert_int_ne(0, subprocvo(1000, fds, "sh", "-c", "while true; do echo Stuff; sleep 1; done", NULL));
 	// Just to test whole process fast we will also try both timeouts at zero
 	subproc_kill_t(0);
-	ck_assert(subprocvo(0, fds, "sleep", "1", NULL) != 0);
+	ck_assert_int_ne(0, subprocvo(0, fds, "sleep", "1", NULL));
 	fclose(devnull);
 }
 END_TEST
@@ -66,8 +66,8 @@ static void buffs_assert(struct buffs *bfs, const char *out, const char *err) {
 	fflush(bfs->fds[0]);
 	fflush(bfs->fds[1]);
 
-	ck_assert(strcmp(out, bfs->b_out) == 0);
-	ck_assert(strcmp(err, bfs->b_err) == 0);
+	ck_assert_str_eq(out, bfs->b_out);
+	ck_assert_str_eq(err, bfs->b_err);
 
 	rewind(bfs->fds[0]);
 	rewind(bfs->fds[1]);
@@ -89,10 +89,10 @@ START_TEST(output) {
 	struct buffs *bfs = buffs_init();
 
 	// Echo to stdout
-	ck_assert(subprocvo(1, bfs->fds, "echo", "hello", NULL) == 0);
+	ck_assert_int_eq(0, subprocvo(1000, bfs->fds, "echo", "hello", NULL));
 	buffs_assert(bfs, "hello\n", "");
 	// Echo to stderr
-	ck_assert(subprocvo(1, bfs->fds, "sh", "-c", "echo hello >&2", NULL) == 0);
+	ck_assert_int_eq(0, subprocvo(1000, bfs->fds, "sh", "-c", "echo hello >&2", NULL));
 	buffs_assert(bfs, "", "hello\n");
 
 	buffs_free(bfs);
@@ -112,10 +112,10 @@ START_TEST(callback) {
 	struct buffs *bfs = buffs_init();
 
 	// Without data
-	ck_assert(subprocloc(1, bfs->fds, callback_test, NULL, NULL, NULL) == 0);
+	ck_assert_int_eq(0, subprocloc(1000, bfs->fds, callback_test, NULL, NULL, NULL));
 	buffs_assert(bfs, "hello", "");
 	// With data
-	ck_assert(subprocvoc(1, bfs->fds, callback_test, "Hello again", NULL, NULL) == 0);
+	ck_assert_int_eq(0, subprocvoc(1000, bfs->fds, callback_test, "Hello again", NULL, NULL));
 	buffs_assert(bfs, "Hello again", "");
 
 	buffs_free(bfs);

tests/subprocess.lua

@@ -22,27 +22,28 @@ require 'lunit'
 module("subproc", package.seeall, lunit.testcase)
 
 function test_exit_code()
-	local ok, out = subprocess(LST_HOOK, "Test: true", 1, "true")
+	local ok, out = subprocess(LST_HOOK, "Test: true", 1000, "true")
 	assert_equal(0, ok)
 	assert_equal("", out)
 
-	local ok, out = subprocess(LST_HOOK, "Test: false", 1, "false")
+	local ok, out = subprocess(LST_HOOK, "Test: false", 1000, "false")
 	assert_not_equal(0, ok)
 	assert_equal("", out)
 end
 
 function test_output()
-	local ok, out = subprocess(LST_HOOK, "Test: echo", 1, "echo", "hello")
+	local ok, out = subprocess(LST_HOOK, "Test: echo", 1000, "echo", "hello")
 	assert_equal(0, ok)
 	assert_equal("hello\n", out)
 
-	local ok, out = subprocess(LST_HOOK, "Test: echo stderr", 1, "sh", "-c", "echo hello >&2")
+	local ok, out = subprocess(LST_HOOK, "Test: echo stderr", 1000, "sh", "-c", "echo hello >&2")
 	assert_equal(0, ok)
 	assert_equal("hello\n", out)
 end
 
 function test_timeout()
-	local ok, out = subprocess(LST_HOOK, "Test: sleep", 1, "sleep", "2")
+	subprocess_kill_timeout(0)
+	local ok, out = subprocess(LST_HOOK, "Test: sleep", 1000, "sleep", "2")
 	assert_not_equal(0, ok)
 	assert_equal("", out)
 end
@@ -50,7 +51,7 @@ end
 function test_callback()
 	subprocess_kill_timeout(0)
 
-	local ok, out = subprocess(LST_HOOK, "Test: env", 1, function () io.stderr:write("Hello callback\n") end, "true")
+	local ok, out = subprocess(LST_HOOK, "Test: env", 1000, function () io.stderr:write("Hello callback\n") end, "true")
 	assert_equal(0, ok)
 	assert_equal("Hello callback\n", out)
 	--[[
@@ -60,7 +61,7 @@ function test_callback()
 	subprocess on daily base so let's not care.
 	]]
 
-	local ok, out = subprocess(LST_HOOK, "Test: env", 1, function () setenv("TESTENV", "Hello env") end, "sh", "-c", "echo $TESTENV")
+	local ok, out = subprocess(LST_HOOK, "Test: env", 1000, function () setenv("TESTENV", "Hello env") end, "sh", "-c", "echo $TESTENV")
 	assert_equal(0, ok)
 	assert_equal("Hello env\n", out)
 end