From 0c3f9b37cd19f6f0731dbc7ce1fc7a6bb65fd406 Mon Sep 17 00:00:00 2001
From: Cyrill Gorcunov <gorcunov@gmail.com>
Date: Fri, 8 Jul 2022 00:12:51 +0300
Subject: [PATCH] log: free resources while event loop is running
The 'log' module uses fibers internally for logs rotation sake and
before we can free log's resources (on program exit) we need to wait
until rotation is complete, which implies that events loop is still
running. But we break the event loop in `on_shutdown_f` trigger and
calling any events based functionality later cause unexpected results
because fibers are no loner valid to use. Thus move `say_logger_free`
call into `on_shutdown_f` body where fibers are still alive.
N.B. Testing the issue is sensitive to timings, during local tests
found that minimal delay 1ms is enough to trigger, thus ERRINJ_LOG_ROTATE
get increased.
Fixes #4450
NO_DOC=bugfix
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
.../unreleased/gh-4450-logger-sigsegv.md | 4 ++
src/lib/core/say.c | 17 ++++++-
src/main.cc | 2 +-
test/app-tap/gh-4450-log-rotate-exit.test.lua | 46 +++++++++++++++++++
test/app-tap/suite.ini | 2 +-
5 files changed, 67 insertions(+), 4 deletions(-)
create mode 100644 changelogs/unreleased/gh-4450-logger-sigsegv.md
create mode 100755 test/app-tap/gh-4450-log-rotate-exit.test.lua
diff --git a/changelogs/unreleased/gh-4450-logger-sigsegv.md b/changelogs/unreleased/gh-4450-logger-sigsegv.md
new file mode 100644
index 0000000000..3b898a605a
--- /dev/null
+++ b/changelogs/unreleased/gh-4450-logger-sigsegv.md
@@ -0,0 +1,4 @@
+## bugfix/core
+
+* Fix potential nil dereference and crash in case of an active
+ log rotation during the program exit stage (gh-4450).
diff --git a/src/lib/core/say.c b/src/lib/core/say.c
index 69c826264b..e38237e358 100644
--- a/src/lib/core/say.c
+++ b/src/lib/core/say.c
@@ -267,7 +267,7 @@ log_rotate(struct log *log)
if (pm_atomic_load(&log->type) != SAY_LOGGER_FILE)
return 0;
- ERROR_INJECT(ERRINJ_LOG_ROTATE, { usleep(10); });
+ ERROR_INJECT(ERRINJ_LOG_ROTATE, { usleep(1000); });
int fd = open(log->path, O_WRONLY | O_APPEND | O_CREAT,
S_IRUSR | S_IWUSR | S_IRGRP);
@@ -750,11 +750,24 @@ say_logger_init(const char *init_str, int level, int nonblock,
panic("failed to initialize logging subsystem");
}
+/*
+ * Logger uses events loop and to free resources we need
+ * to wait until logs rotation is complete. Thus make sure
+ * this routine is called before events loop is finished.
+ */
void
say_logger_free(void)
{
- if (say_logger_initialized())
+ if (say_logger_initialized()) {
log_destroy(&log_std);
+ /*
+ * Once destroyed switch to boot logger
+ * because boot logger is safe to use
+ * anytime and might be suitable for
+ * debugging.
+ */
+ log_default = &log_boot;
+ }
}
/** {{{ Formatters */
diff --git a/src/main.cc b/src/main.cc
index 6b5f5ede85..3c52d1a80e 100644
--- a/src/main.cc
+++ b/src/main.cc
@@ -141,6 +141,7 @@ on_shutdown_f(va_list ap)
(void) ap;
trigger_fiber_run(&box_on_shutdown_trigger_list, NULL,
on_shutdown_trigger_timeout);
+ say_logger_free();
ev_break(loop(), EVBREAK_ALL);
return 0;
}
@@ -583,7 +584,6 @@ tarantool_free(void)
memtx_tx_manager_free();
coll_free();
systemd_free();
- say_logger_free();
fiber_free();
memory_free();
random_free();
diff --git a/test/app-tap/gh-4450-log-rotate-exit.test.lua b/test/app-tap/gh-4450-log-rotate-exit.test.lua
new file mode 100755
index 0000000000..a1ca9abee2
--- /dev/null
+++ b/test/app-tap/gh-4450-log-rotate-exit.test.lua
@@ -0,0 +1,46 @@
+#!/usr/bin/env tarantool
+
+local tap = require('tap')
+local test = tap.test("gh-4450-log-rotate-exit")
+local fio = require('fio')
+local tarantool_bin = arg[-1]
+
+test:plan(1)
+
+local function run_script(code)
+ local dir = fio.tempdir()
+ local script_path = fio.pathjoin(dir, 'gh-4450-script.lua')
+ local script = fio.open(script_path,
+ {'O_CREAT', 'O_WRONLY', 'O_APPEND'},
+ tonumber('0777', 8))
+ script:write(code)
+ script:close()
+ local output_file = fio.pathjoin(fio.cwd(), 'gh-4450-out.txt')
+ local cmd = [[/bin/sh -c 'cd "%s" && "%s" ./gh-4450-script.lua 0> %s 2> %s']]
+ local code = os.execute(
+ string.format(cmd, dir, tarantool_bin, output_file, output_file)
+ )
+ fio.rmtree(dir)
+ local out_fd = fio.open(output_file, {'O_RDONLY'})
+ local output = out_fd:read(100000)
+ out_fd:close()
+ return code, output
+end
+
+--
+-- gh-4382: an error in main script should be handled gracefully,
+-- with proper logging.
+--
+local code = "log = require('log')\n"
+code = code .. "box.cfg{log = 'gh-4550.log'}\n"
+code = code .. "box.error.injection.set('ERRINJ_LOG_ROTATE', true)\n"
+code = code .. "log.rotate()\n"
+code = code .. "os.exit()\n"
+local _, output = run_script(code)
+
+test:diag(output)
+test:ok(not string.find(output, "SEGV_MAPERR"),
+ "program exited without SEGV_MAPERR")
+
+test:check()
+os.exit(0)
diff --git a/test/app-tap/suite.ini b/test/app-tap/suite.ini
index 06f549ca36..3263185067 100644
--- a/test/app-tap/suite.ini
+++ b/test/app-tap/suite.ini
@@ -4,7 +4,7 @@ description = application server tests (TAP)
lua_libs = lua/require_mod.lua lua/serializer_test.lua lua/process_timeout.lua
is_parallel = True
use_unix_sockets_iproto = True
-release_disabled = gh-5040-inter-mode-isatty-via-errinj.test.lua gh-2717-no-quit-sigint.test.lua
+release_disabled = gh-5040-inter-mode-isatty-via-errinj.test.lua gh-2717-no-quit-sigint.test.lua gh-4450-log-rotate-exit.test.lua
fragile = {
"retries": 10,
"tests": {
--
GitLab