From a0fb0bbfe326b4cb07bc562107f0beaa6d61d39a Mon Sep 17 00:00:00 2001 From: Alan Jenkins Date: Mon, 28 May 2018 21:08:57 +0100 Subject: [PATCH 1/3] fix "Console" log to flush It's called "Console", which would be line-buffered anyway. But, it's implemented as std::cout. This might be piped to a logger, as in daemontools or systemd. In this case it will not be a TTY, and log lines should be flushed without too much delay. Let's just flush each message. Let's not introduce a static instance of StreamLogger (flushed by interval timer). That's too stressful to read, because static instances are really annoying to order. Example citation: "Yay, our static destructors are pretty much beyond repair at this point." -- application.cpp. I don't know if there will be any need to optimize logging syscalls. The init script uses `--daemonize`. I think the systemd service should also avoid using the "Console" log after startup (see next commit). The documentation does not warn that the syslog feature is less efficient in system calls than mainlog; deferred flusing does not seem to be a highly prominent feature. There's no cool comment in the code about how much the syscalls were slowing down some use case (or qualifying that this optimization can only eliminate syscalls on platforms with both mutexes and clocks that can work without syscalls). --- lib/base/logger.cpp | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/lib/base/logger.cpp b/lib/base/logger.cpp index 9a59d199f..8af34d6ca 100644 --- a/lib/base/logger.cpp +++ b/lib/base/logger.cpp @@ -245,8 +245,13 @@ Log::~Log() #endif /* I2_DEBUG */ } - if (Logger::IsConsoleLogEnabled() && entry.Severity >= Logger::GetConsoleLogSeverity()) + if (Logger::IsConsoleLogEnabled() && entry.Severity >= Logger::GetConsoleLogSeverity()) { StreamLogger::ProcessLogEntry(std::cout, entry); + + /* "Console" might be a pipe/socket (systemd, daemontools, docker, ...), + * then cout will not flush lines automatically. */ + std::cout << std::flush; + } } Log& Log::operator<<(const char *val) From 50463a6a10ea1d1295758e0c8489c28f78b66eab Mon Sep 17 00:00:00 2001 From: Alan Jenkins Date: Wed, 30 May 2018 12:21:39 +0100 Subject: [PATCH 2/3] Daemonize(): use one error convention, not three Standardize on exit() / _exit() (this depends whether we are considered to be the "main" fork, which should run anything registered with atexit()). Exclude `return false` and throwing exceptions. This fixes the error path for fork(). Daemonize() would return false, but the `return false` error convention was not tested in the caller. It also fixes the error message for fork() to show the error code. Everyone loves `strace`, but sysadmins should not have to rerun their daemons under it just to see an error code. Also in case an exception is thrown, show its diagnostic information instead of dropping it on the floor. In the log message, I mention why we are uninitializing and then initializing the app at this point. For the reader, it pushes all the weirdness into the error convention of Daemonize(). This comes back to the exit() / _exit() distinction. Once we have forked, we technically don't want to allow the parent process to exit(), so we don't want to return to the caller. --- lib/cli/daemoncommand.cpp | 40 +++++++++++++++++++++++++++------------ 1 file changed, 28 insertions(+), 12 deletions(-) diff --git a/lib/cli/daemoncommand.cpp b/lib/cli/daemoncommand.cpp index 0cf7d3b91..02d8b1ea1 100644 --- a/lib/cli/daemoncommand.cpp +++ b/lib/cli/daemoncommand.cpp @@ -52,14 +52,28 @@ static void SigHupHandler(int) } #endif /* _WIN32 */ -static bool Daemonize() +/* + * Daemonize(). On error, this function logs by itself and exits (i.e. does not return). + * + * Implementation note: We're only supposed to call exit() in one of the forked processes. + * The other process calls _exit(). This prevents issues with exit handlers like atexit(). + */ +static void Daemonize() noexcept { #ifndef _WIN32 - Application::UninitializeBase(); + try { + Application::UninitializeBase(); + } catch (const std::exception& ex) { + Log(LogCritical, "cli") + << "Failed to stop thread pool before daemonizing, unexpected error: " << DiagnosticInformation(ex); + exit(EXIT_FAILURE); + } pid_t pid = fork(); if (pid == -1) { - return false; + Log(LogCritical, "cli") + << "fork() failed with error code " << errno << ", \"" << Utility::FormatErrorNumber(errno) << "\""; + exit(EXIT_FAILURE); } if (pid) { @@ -91,10 +105,14 @@ static bool Daemonize() Log(LogDebug, "Daemonize()") << "Child process with PID " << Utility::GetPid() << " continues; re-initializing base."; - Application::InitializeBase(); + try { + Application::InitializeBase(); + } catch (const std::exception& ex) { + Log(LogCritical, "cli") + << "Failed to re-initialize thread pool after daemonizing: " << DiagnosticInformation(ex); + exit(EXIT_FAILURE); + } #endif /* _WIN32 */ - - return true; } static bool SetDaemonIO(const String& stderrFile) @@ -245,12 +263,10 @@ int DaemonCommand::Run(const po::variables_map& vm, const std::vector Date: Tue, 29 May 2018 17:24:05 +0100 Subject: [PATCH 3/3] Fix logging under systemd icinga2.service used `-e ${ICINGA2_ERROR_LOG}`, but this is documented as having no effect without `-d`. Furthermore, icinga2 under systemd unconditionally logged everything to the system log (but without setting the log level etc), which contradicted the documentation. (Issue #6339) Stop icinga2 on systemd from logging to stdout - and hence the system log - once it has finished starting up. Just like when you start icinga2 from a terminal using `-d`. And just like -d, we stop logging fatal errors to stderr, and instead write to the log file passed with `-e`. As per docs, mainlog (icinga2.log) is already enabled by default. And pre-startup messages including config errors will still appear in the system log. This uses a new option --close-stdio, which has the same effect on logging as --daemonize, but does not fork or call setsid(). For this purpose, I moved setsid() up and into Daemonize(). Consequence of that last point: if anyone is weird enough to specify a TTY device file as the fatal error log (-e option), that will become icinga's controlling terminal, which you generally don't want as a daemon. This makes it consistent with the existing behaviour for icinga mainlog. For this reason you're supposed to use O_NOCTTY in Linux daemons. But I wasn't sure where icinga would want to put the ugly `#ifdef _WIN32 ... #else ...`. --- doc/11-cli-commands.md | 4 +++- etc/initsystem/icinga2.service.cmake | 2 +- lib/cli/daemoncommand.cpp | 28 +++++++++++++++++----------- 3 files changed, 21 insertions(+), 13 deletions(-) diff --git a/doc/11-cli-commands.md b/doc/11-cli-commands.md index 012fe72f3..a6a625e5f 100644 --- a/doc/11-cli-commands.md +++ b/doc/11-cli-commands.md @@ -388,8 +388,10 @@ Command options: -z [ --no-config ] start without a configuration file -C [ --validate ] exit after validating the configuration -e [ --errorlog ] arg log fatal errors to the specified log file (only - works in combination with --daemonize) + works in combination with --daemonize or + --close-stdio) -d [ --daemonize ] detach from the controlling terminal + --close-stdio do not log to stdout (or stderr) after startup Report bugs at Icinga home page: diff --git a/etc/initsystem/icinga2.service.cmake b/etc/initsystem/icinga2.service.cmake index 94b7dcd2f..9c7d81748 100644 --- a/etc/initsystem/icinga2.service.cmake +++ b/etc/initsystem/icinga2.service.cmake @@ -6,7 +6,7 @@ After=syslog.target network-online.target postgresql.service mariadb.service car Type=notify EnvironmentFile=@ICINGA2_SYSCONFIGFILE@ ExecStartPre=@CMAKE_INSTALL_PREFIX@/lib/icinga2/prepare-dirs @ICINGA2_SYSCONFIGFILE@ -ExecStart=@CMAKE_INSTALL_FULL_SBINDIR@/icinga2 daemon -e ${ICINGA2_ERROR_LOG} +ExecStart=@CMAKE_INSTALL_FULL_SBINDIR@/icinga2 daemon --close-stdio -e ${ICINGA2_ERROR_LOG} PIDFile=@ICINGA2_INITRUNDIR@/icinga2.pid ExecReload=@CMAKE_INSTALL_PREFIX@/lib/icinga2/safe-reload @ICINGA2_SYSCONFIGFILE@ TimeoutStartSec=30m diff --git a/lib/cli/daemoncommand.cpp b/lib/cli/daemoncommand.cpp index 02d8b1ea1..d744d0dc1 100644 --- a/lib/cli/daemoncommand.cpp +++ b/lib/cli/daemoncommand.cpp @@ -105,6 +105,14 @@ static void Daemonize() noexcept Log(LogDebug, "Daemonize()") << "Child process with PID " << Utility::GetPid() << " continues; re-initializing base."; + // Detach from controlling terminal + pid_t sid = setsid(); + if (sid == -1) { + Log(LogCritical, "cli") + << "setsid() failed with error code " << errno << ", \"" << Utility::FormatErrorNumber(errno) << "\""; + exit(EXIT_FAILURE); + } + try { Application::InitializeBase(); } catch (const std::exception& ex) { @@ -115,7 +123,7 @@ static void Daemonize() noexcept #endif /* _WIN32 */ } -static bool SetDaemonIO(const String& stderrFile) +static void CloseStdIO(const String& stderrFile) { #ifndef _WIN32 int fdnull = open("/dev/null", O_RDWR); @@ -147,14 +155,7 @@ static bool SetDaemonIO(const String& stderrFile) if (fderr > 2) close(fderr); } - - pid_t sid = setsid(); - if (sid == -1) { - return false; - } #endif - - return true; } String DaemonCommand::GetDescription() const @@ -174,9 +175,10 @@ void DaemonCommand::InitParameters(boost::program_options::options_description& ("config,c", po::value >(), "parse a configuration file") ("no-config,z", "start without a configuration file") ("validate,C", "exit after validating the configuration") - ("errorlog,e", po::value(), "log fatal errors to the specified log file (only works in combination with --daemonize)") + ("errorlog,e", po::value(), "log fatal errors to the specified log file (only works in combination with --daemonize or --close-stdio)") #ifndef _WIN32 ("daemonize,d", "detach from the controlling terminal") + ("close-stdio", "do not log to stdout (or stderr) after startup") #endif /* _WIN32 */ ; @@ -290,12 +292,16 @@ int DaemonCommand::Run(const po::variables_map& vm, const std::vector(); - SetDaemonIO(errorLog); + CloseStdIO(errorLog); Logger::DisableConsoleLog(); }