From 1a3ec406de913313ae11c2cf7a3300ca9249f47b Mon Sep 17 00:00:00 2001 From: Simo Piiroinen Date: Tue, 25 May 2021 09:00:45 +0300 Subject: [PATCH] [mapplauncherd] Avoid using signals for peer termination. Fixes JB#53845 OMP#JOLLA-44 Invoker and booster instance make up a process pair that are meant to exit at the same time. To arrange this a) when invoker is about to exit, it sends a terminating signal to booster instance, and b) when booster instance exits, booster daemon sends a terminating signal to invoker. Overall this has worked well enough - save some hiccups from potential race conditions - but it is not compatible with setup where invoker and booster daemon are running in different namespaces and sending signals is not possible. There is already an unix domain socket that is kept open for the lifetime of boosted application - used for transferring application information from invoker to booster daemon during startup and exit status from booster daemon to invoker at exit time. This socket can be utilized also for detecting when peer process exits. Normally when application (booster instance) exits, booster daemon receives SIGCHLD, collects application exit reason, forwards it to invoker via booster socket, and invoker then makes exit with the same exit status as what application used. Augment this by having booster daemon watch over booster sockets and terminate booster instance upon eof on socket. This accomplishes that application gets killed if/when invoker dies. Additionally all booster instances are terminated if booster daemon exits due to SIGTERM. In general, instead of simply closing booster socket at each end at exit time, an orderly disconnect is done via: shutdown write end of the socket, read data until eof is received, then close socket. If this is accomplished successfully within reasonable time limit, there is no need to send signals - both peers know that the other end is going to make an appropriate exit. Previously booster daemon and invoker made an attempt to reproduce application getting killed by some signal such as as SIGSEGV also at the invoker side. As this produces false positive crash reports and complicates things (some of the signals are terminal and can't be handled in asynchronous manner) this is no longer done - only standard TERM and KILL signals are used for terminating peers and even then it is done as a last resort. Invoker signal handler used non async signal safe functions, those have been removed. To ease ad-hoc debugging, logging is automatically switched from syslog to stderr when booster/invoker is executed from interactive command line. Signed-off-by: Simo Piiroinen --- src/common/report.c | 46 +++- src/common/report.h | 1 + src/invoker/invoker.c | 380 ++++++++++++++++++----------- src/launcherlib/daemon.cpp | 472 ++++++++++++++++++++++++++++++------- src/launcherlib/logger.cpp | 75 ++++-- src/launcherlib/logger.h | 6 + 6 files changed, 722 insertions(+), 258 deletions(-) diff --git a/src/common/report.c b/src/common/report.c index ce9d8b7..bf6b11a 100644 --- a/src/common/report.c +++ b/src/common/report.c @@ -21,10 +21,33 @@ #include #include #include +#include +#include #include "report.h" -static enum report_output output = report_console; +static enum report_output output = report_guess; + +static char *strip(char *str) +{ + if (str) { + char *dst = str; + char *src = str; + while (*src && isspace(*src)) + ++src; + for (;;) { + while (*src && !isspace(*src)) + *dst++ = *src++; + while (*src && isspace(*src)) + ++src; + if (!*src) + break; + *dst++ = ' '; + } + *dst = 0; + } + return str; +} void report_set_output(enum report_output new_output) { @@ -71,20 +94,19 @@ static void vreport(enum report_type type, const char *msg, va_list arg) vsnprintf(str, sizeof(str), msg, arg); - // report errors and fatals to syslog even if it's not default output - if ((output != report_syslog) && - ((type == report_error) || (type == report_fatal))) - { - enum report_output old_output = output; - report_set_output(report_syslog); - syslog(log_type, "%s%s", str_type, str); - report_set_output(old_output); + if (output == report_guess) { + if (isatty(STDIN_FILENO)) + output = report_console; + else + output = report_syslog; } - if (output == report_console) - printf("%s: %s%s", PROG_NAME_INVOKER, str_type, str); - else if (output == report_syslog) + if (output == report_console) { + fprintf(stderr, "%s: %s%s\n", PROG_NAME_INVOKER, str_type, strip(str)); + fflush(stderr); + } else if (output == report_syslog) { syslog(log_type, "%s%s", str_type, str); + } } void report(enum report_type type, const char *msg, ...) diff --git a/src/common/report.h b/src/common/report.h index 4bc3405..a6f904f 100644 --- a/src/common/report.h +++ b/src/common/report.h @@ -29,6 +29,7 @@ #endif enum report_output { + report_guess, report_console, report_syslog, report_none diff --git a/src/invoker/invoker.c b/src/invoker/invoker.c index 87c7b33..a06910c 100644 --- a/src/invoker/invoker.c +++ b/src/invoker/invoker.c @@ -40,6 +40,8 @@ #include #include #include +#include +#include #include #include "report.h" @@ -47,6 +49,12 @@ #include "invokelib.h" #include "search.h" +/* Setting VERBOSE_SIGNALS to non-zero value logs receiving of + * async-signals - which is useful only when actively debugging + * booster / invoker interoperation. + */ +#define VERBOSE_SIGNALS 0 + // Utility functions static char *strip(char *str) { @@ -135,75 +143,34 @@ static void sigs_restore(void); static void sigs_init(void); //! Pipe used to safely catch Unix signals -static int g_signal_pipe[2]; +static int g_signal_pipe[2] = { -1, -1 }; // Forwards Unix signals from invoker to the invoked process static void sig_forwarder(int sig) { - if (g_invoked_pid >= 0) - { - if (kill(g_invoked_pid, sig) != 0) - { - if (sig == SIGTERM && errno == ESRCH) - { - report(report_info, - "Can't send signal SIGTERM to application [%i] " - "because application is already terminated. \n", - g_invoked_pid); - } - else - { - report(report_error, - "Can't send signal %i to application [%i]: %s \n", - sig, g_invoked_pid, strerror(errno)); - } - } - - // Restore signal handlers - sigs_restore(); - - // Write signal number to the self-pipe - char signal_id = (char) sig; - if (write(g_signal_pipe[1], &signal_id, 1) != 1) - _exit(EXIT_FAILURE); - - // Send the signal to itself using the default handler - raise(sig); -#ifdef WITH_COVERAGE - __gcov_flush(); +#if VERBOSE_SIGNALS + static const char m[] = "*** signal\n"; + if (write(STDERR_FILENO, m, sizeof m - 1) == -1) { + // dontcare + } #endif + + // Write signal number to the self-pipe + char signal_id = (char) sig; + if (g_signal_pipe[1] == -1 || write(g_signal_pipe[1], &signal_id, 1) != 1) { + const char m[] = "*** signal pipe write failure, terminating\n"; + if (write(STDERR_FILENO, m, sizeof m - 1) == -1) { + // dontcare + } + _exit(EXIT_FAILURE); } } // Sets signal actions for Unix signals static void sigs_set(struct sigaction *sig) { - sigaction(SIGABRT, sig, NULL); - sigaction(SIGALRM, sig, NULL); - sigaction(SIGBUS, sig, NULL); - sigaction(SIGCHLD, sig, NULL); - sigaction(SIGCONT, sig, NULL); - sigaction(SIGHUP, sig, NULL); sigaction(SIGINT, sig, NULL); - sigaction(SIGIO, sig, NULL); - sigaction(SIGIOT, sig, NULL); - sigaction(SIGPIPE, sig, NULL); - sigaction(SIGPROF, sig, NULL); - sigaction(SIGPWR, sig, NULL); - sigaction(SIGQUIT, sig, NULL); - sigaction(SIGSEGV, sig, NULL); - sigaction(SIGSYS, sig, NULL); sigaction(SIGTERM, sig, NULL); - sigaction(SIGTRAP, sig, NULL); - sigaction(SIGTSTP, sig, NULL); - sigaction(SIGTTIN, sig, NULL); - sigaction(SIGTTOU, sig, NULL); - sigaction(SIGUSR1, sig, NULL); - sigaction(SIGUSR2, sig, NULL); - sigaction(SIGVTALRM, sig, NULL); - sigaction(SIGWINCH, sig, NULL); - sigaction(SIGXCPU, sig, NULL); - sigaction(SIGXFSZ, sig, NULL); } // Sets up the signal forwarder @@ -230,6 +197,131 @@ static void sigs_restore(void) sigs_set(&sig); } +static unsigned timestamp(void) +{ + struct timespec ts = { 0, 0 }; + if (clock_gettime(CLOCK_BOOTTIME, &ts) == -1 && + clock_gettime(CLOCK_MONOTONIC, &ts) == -1) { + error("can't obtain a monotonic timestamp\n"); + exit(EXIT_FAILURE); + } + + /* NOTE: caller must assume overflow to happen i.e. + * the return values themselves mean nothing, only + * differences between return values should be used. + */ + return ((unsigned)(ts.tv_sec * 1000u) + + (unsigned)(ts.tv_nsec / (1000 * 1000u))); +} + +static bool shutdown_socket(int socket_fd) +{ + bool disconnected = false; + + /* Close transmit end from our side, then wait + * for peer to receive EOF and close the receive + * end too. + */ + + debug("trying to disconnect booster socket...\n"); + + if (shutdown(socket_fd, SHUT_WR) == -1) { + warning("socket shutdown failed: %m\n"); + goto EXIT; + } + + unsigned started = timestamp(); + unsigned timeout = 5000; + for (;;) { + unsigned elapsed = timestamp() - started; + if (elapsed >= timeout) + break; + + struct pollfd pfd = { + .fd = socket_fd, + .events = POLLIN, + .revents = 0, + }; + + debug("waiting for booster socket input...\n"); + int rc = poll(&pfd, 1, (int)(timeout - elapsed)); + + if (rc == 0) + break; + + if (rc == -1) { + if (errno == EINTR || errno == EAGAIN) + continue; + warning("socket poll failed: %m\n"); + goto EXIT; + } + + char buf[256]; + rc = recv(socket_fd, buf, sizeof buf, MSG_DONTWAIT); + if (rc == 0) { + /* EOF -> peer closed the socket */ + disconnected = true; + goto EXIT; + } + + if (rc == -1) { + warning("socket read failed: %m\n"); + goto EXIT; + } + } + warning("socket poll timeout\n"); + +EXIT: + if (disconnected) + debug("booster socket was succesfully disconnected\n"); + else + warning("could not disconnect booster socket\n"); + + return disconnected; +} + +static void kill_application(pid_t pid) +{ + if (pid == -1) { + warning("application pid is not known, can't kill it"); + goto EXIT; + } + + warning("sending SIGTERM to application (pid=%d)", (int)pid); + + if (kill(pid, SIGTERM) == -1) + goto FAIL; + + for (int i = 0; i < 10; ++i) { + sleep(1); + if (kill(pid, 0) == -1) + goto FAIL; + } + + warning("sending SIGKILL to application (pid=%d)", (int)pid); + + if (kill(pid, SIGKILL) == -1) + goto FAIL; + + for (int i = 0; i < 10; ++i) { + sleep(1); + if (kill(pid, 0) == -1) + goto FAIL; + } + + warning("application (pid=%d) did not exit", (int)pid); + goto EXIT; + +FAIL: + if (errno == ESRCH) + debug("application (pid=%d) has exited", (int)pid); + else + warning("application (pid=%d) kill failed: %m", (int)pid); + +EXIT: + return; +} + // Receive ACK static bool invoke_recv_ack(int fd) { @@ -554,96 +646,88 @@ static void notify_app_lauch(const char *desktop_file) } } -static int wait_for_launched_process_to_exit(int socket_fd, bool wait_term) +static int wait_for_launched_process_to_exit(int socket_fd) { - int status = 0; + int exit_status = EXIT_FAILURE; + int exit_signal = 0; - // Wait for launched process to exit - if (wait_term) - { - // coverity[tainted_string_return_content] - g_invoked_pid = invoker_recv_pid(socket_fd); - debug("Booster's pid is %d \n ", g_invoked_pid); + // coverity[tainted_string_return_content] + g_invoked_pid = invoker_recv_pid(socket_fd); + debug("Booster's pid is %d \n ", g_invoked_pid); - // Forward UNIX signals to the invoked process - sigs_init(); + // Setup signal handlers + sigs_init(); - while(1) - { - // Setup things for select() - fd_set readfds; - int ndfs = 0; - - FD_ZERO(&readfds); - - FD_SET(socket_fd, &readfds); - ndfs = (socket_fd > ndfs) ? socket_fd : ndfs; - - // sig_forwarder() handles signals. - // We only have to receive those here. - FD_SET(g_signal_pipe[0], &readfds); - ndfs = (g_signal_pipe[0] > ndfs) ? g_signal_pipe[0] : ndfs; - - // Wait for something appearing in the pipes. - if (select(ndfs + 1, &readfds, NULL, NULL, NULL) > 0) - { - // Check if an exit status from the invoked application - if (FD_ISSET(socket_fd, &readfds)) - { - bool res = invoker_recv_exit(socket_fd, &status); - - if (!res) - { - // Because we are here, applauncherd.bin must be dead. - // Now we check if the invoked process is also dead - // and if not, we will kill it. - char filename[50]; - snprintf(filename, sizeof(filename), "/proc/%d/cmdline", g_invoked_pid); - - // Open filename for reading only - int fd = open(filename, O_RDONLY); - if (fd != -1) - { - // Application is still running - close(fd); - - // Send a signal to kill the application too and exit. - // Sleep for some time to give - // the new applauncherd some time to load its boosters and - // the restart of g_invoked_pid succeeds. - - sleep(10); - kill(g_invoked_pid, SIGKILL); - raise(SIGKILL); - } - else - { - // connection to application was lost - status = EXIT_FAILURE; - } - } - break; - } - // Check if we got a UNIX signal. - else if (FD_ISSET(g_signal_pipe[0], &readfds)) - { - // Clean up the pipe - char signal_id; - if (read(g_signal_pipe[0], &signal_id, 1) != 1) - exit(EXIT_FAILURE); - - // Set signals forwarding to the invoked process again - // (they were reset by the signal forwarder). - sigs_init(); - } + for (;;) { + // Setup things for select() + fd_set readfds; + int ndfs = 0; + + FD_ZERO(&readfds); + + FD_SET(socket_fd, &readfds); + ndfs = (socket_fd > ndfs) ? socket_fd : ndfs; + + // sig_forwarder() handles signals. + // We only have to receive those here. + FD_SET(g_signal_pipe[0], &readfds); + ndfs = (g_signal_pipe[0] > ndfs) ? g_signal_pipe[0] : ndfs; + + // Wait for something appearing in the pipes. + if (select(ndfs + 1, &readfds, NULL, NULL, NULL) == -1) { + if (errno == EINTR || errno == EAGAIN) + continue; + warning("socket select failed: %m\n"); + break; + } + + // Check if we got exit status from the invoked application + if (FD_ISSET(socket_fd, &readfds)) { + if (!invoker_recv_exit(socket_fd, &exit_status)) { + // connection to application was lost + exit_status = EXIT_FAILURE; + } else { + // there is no need to kill the application + g_invoked_pid = -1; } + break; } - // Restore default signal handlers - sigs_restore(); + // Check if we got a UNIX signal. + if (FD_ISSET(g_signal_pipe[0], &readfds)) { + // Clean up the pipe + char signal_id = 0; + if (read(g_signal_pipe[0], &signal_id, 1) != 1) { + error("signal pipe read failure, terminating\n"); + exit(EXIT_FAILURE); + } + exit_signal = signal_id; + if (exit_signal == SIGTERM) + exit_status = EXIT_SUCCESS; + break; + } } - return status; + // Restore default signal handlers + sigs_restore(); + + if (exit_status != EXIT_SUCCESS) + warning("application (pid=%d) exit(%d) signal(%d)\n", + (int)g_invoked_pid, exit_status, exit_signal); + else + debug("application (pid=%d) exit(%d) signal(%d)\n", + (int)g_invoked_pid, exit_status, exit_signal); + + if (socket_fd != -1) { + if (shutdown_socket(socket_fd)) + g_invoked_pid = -1; + close(socket_fd), + socket_fd = -1; + if (g_invoked_pid != -1) + kill_application(g_invoked_pid); + } + + return exit_status; } typedef struct InvokeArgs { @@ -677,6 +761,8 @@ typedef struct InvokeArgs { // "normal" invoke through a socket connection static int invoke_remote(int socket_fd, const InvokeArgs *args) { + int exit_status = EXIT_FAILURE; + // Get process priority errno = 0; int prog_prio = getpriority(PRIO_PROCESS, 0); @@ -701,7 +787,14 @@ static int invoke_remote(int socket_fd, const InvokeArgs *args) if (args->desktop_file) notify_app_lauch(args->desktop_file); - int exit_status = wait_for_launched_process_to_exit(socket_fd, args->wait_term); + if (args->wait_term) { + exit_status = wait_for_launched_process_to_exit(socket_fd), + socket_fd = -1; + } + + if (socket_fd != -1) + close(socket_fd); + return exit_status; } @@ -783,8 +876,8 @@ static int invoke(InvokeArgs *args) if (fd != -1) { /* "normal" invoke through a socket connetion */ - status = invoke_remote(fd, args); - close(fd); + status = invoke_remote(fd, args), + fd = -1; } else if (tried_session) { warning("Launch failed, session booster is not available.\n"); } else if (strcmp(args->app_name, "default")) { @@ -972,9 +1065,9 @@ int main(int argc, char *argv[]) } if (pipe(g_signal_pipe) == -1) - { - report(report_error, "Creating a pipe for Unix signals failed!\n"); - exit(EXIT_FAILURE); + { + report(report_error, "Creating a pipe for Unix signals failed!\n"); + exit(EXIT_FAILURE); } // Send commands to the launcher daemon @@ -988,5 +1081,6 @@ int main(int argc, char *argv[]) sleep(args.exit_delay); } + debug("invoker exit(%d)\n", ret_val); return ret_val; } diff --git a/src/launcherlib/daemon.cpp b/src/launcherlib/daemon.cpp index 763d44c..d5c3f16 100644 --- a/src/launcherlib/daemon.cpp +++ b/src/launcherlib/daemon.cpp @@ -45,9 +45,17 @@ #include #include #include +#include #include "coverage.h" +/* Setting VERBOSE_SIGNALS to non-zero value logs receiving of + * async-signals - which is useful only when actively debugging + * booster / invoker interoperation. + */ +#define VERBOSE_SIGNALS 0 + + // Environment extern char ** environ; @@ -63,8 +71,45 @@ static void write_dontcare(int fd, const void *data, size_t size) Logger::logWarning("write to fd=%d failed", fd); } +#if VERBOSE_SIGNALS +static char *addstr(char *pos, char *end, const char *str) +{ + while (pos < end && *str) + *pos++ = *str++; + return pos; +} +static char *addnum(char *pos, char *end, int num) +{ + char stk[64]; + int sp = sizeof stk; + bool neg = (num < 0); + unsigned mag = (unsigned)(neg ? -num : num); + stk[--sp] = 0; + do { + stk[--sp] = '0' + mag % 10; + } while (mag /= 10); + if (neg) + stk[--sp] = '-'; + return addstr(pos, end, &stk[sp]); +} +#endif + static void write_to_signal_pipe(int sig) { +#if VERBOSE_SIGNALS + char m[256]; + char *p = m; + char *e = m + sizeof m - 1; + p = addstr(p, e, "*** signal="); + p = addnum(p, e, sig); + p = addstr(p, e, " pid="); + p = addnum(p, e, getpid()); + p = addstr(p, e, "\n"); + if (write(STDERR_FILENO, m, p - m) < 0) { + // dontcare + } +#endif + char v = (char)sig; if (write(Daemon::instance()->sigPipeFd(), &v, 1) != 1) { /* If we can't write to internal signal forwarding @@ -89,6 +134,164 @@ static int read_from_signal_pipe(int fd) return sig; } +static unsigned timestamp(void) +{ + struct timespec ts = { 0, 0 }; + if (clock_gettime(CLOCK_BOOTTIME, &ts) == -1 && + clock_gettime(CLOCK_MONOTONIC, &ts) == -1) { + error("can't obtain a monotonic timestamp\n"); + exit(EXIT_FAILURE); + } + + /* NOTE: caller must assume overflow to happen i.e. + * the return values themselves mean nothing, only + * differences between return values should be used. + */ + return ((unsigned)(ts.tv_sec * 1000u) + + (unsigned)(ts.tv_nsec / (1000 * 1000u))); +} + +static bool shutdown_socket(int socket_fd) +{ + bool disconnected = false; + + /* Close transmit end from our side, then wait + * for peer to receive EOF and close the receive + * end too. + */ + + debug("trying to disconnect booster socket...\n"); + + unsigned started = timestamp(); + unsigned timeout = 5000; + + if (shutdown(socket_fd, SHUT_WR) == -1) { + warning("socket shutdown failed: %m\n"); + goto EXIT; + } + + for (;;) { + unsigned elapsed = timestamp() - started; + if (elapsed >= timeout) + break; + + struct pollfd pfd = { + .fd = socket_fd, + .events = POLLIN, + .revents = 0, + }; + + debug("waiting for booster socket input...\n"); + int rc = poll(&pfd, 1, (int)(timeout - elapsed)); + + if (rc == 0) + break; + + if (rc == -1) { + if (errno == EINTR || errno == EAGAIN) + continue; + warning("socket poll failed: %m\n"); + goto EXIT; + } + + char buf[256]; + rc = recv(socket_fd, buf, sizeof buf, MSG_DONTWAIT); + if (rc == 0) { + /* EOF -> peer closed the socket */ + disconnected = true; + goto EXIT; + } + + if (rc == -1) { + warning("socket read failed: %m\n"); + goto EXIT; + } + } + warning("socket poll timeout\n"); + +EXIT: + if (disconnected) + debug("booster socket was succesfully disconnected\n"); + else + warning("could not disconnect booster socket\n"); + + return disconnected; +} + +static void kill_process(const char *label, pid_t pid) +{ + if (pid == -1) { + warning("%s pid is not known, can't kill it", label); + goto EXIT; + } + + warning("sending SIGTERM to %s (pid=%d)", label, (int)pid); + + if (kill(pid, SIGTERM) == -1) + goto FAIL; + + for (int i = 0; i < 10; ++i) { + sleep(1); + /* We use this function for both boosters and invokers. + * Boosters are child processes and we must use wait*() + * to reap them. But invokers are not descendants of + * booster daemon, so ECHILD failures are expected too. + */ + int status = 0; + if (waitpid(pid, &status, WNOHANG) == -1 && errno != ECHILD) + warning("%s pid=%d) waitpid error: %m", label, (int)pid); + if (kill(pid, 0) == -1) + goto FAIL; + } + + warning("sending SIGKILL to %s (pid=%d)", label, (int)pid); + + if (kill(pid, SIGKILL) == -1) + goto FAIL; + + for (int i = 0; i < 10; ++i) { + sleep(1); + int status = 0; + if (waitpid(pid, &status, WNOHANG) == -1 && errno != ECHILD) + warning("%s pid=%d) waitpid error: %m", label, (int)pid); + if (kill(pid, 0) == -1) + goto FAIL; + } + + warning("%s (pid=%d) did not exit", label, (int)pid); + goto EXIT; + +FAIL: + if (errno == ESRCH) + debug("%s (pid=%d) has exited", label, (int)pid); + else + warning("%s (pid=%d) kill failed: %m", label, (int)pid); + +EXIT: + return; +} + +static void close_invoker(pid_t invoker_pid, int socket_fd, int exit_status) +{ + if (socket_fd != -1) { + Logger::logWarning("Daemon: sending exit(%d) to invoker(%d)\n", + exit_status, (int)invoker_pid); + uint32_t msg = INVOKER_MSG_EXIT; + uint32_t dta = exit_status; + write_dontcare(socket_fd, &msg, sizeof msg); + write_dontcare(socket_fd, &dta, sizeof dta); + + if (shutdown_socket(socket_fd)) + invoker_pid = -1; + + close(socket_fd), + socket_fd = -1; + } + + if (invoker_pid != -1) + kill_process("invoker", invoker_pid); +} + Daemon::Daemon(int & argc, char * argv[]) : m_daemon(false), m_debugMode(false), @@ -106,6 +309,7 @@ Daemon::Daemon(int & argc, char * argv[]) : // Install signal handlers. The original handlers are saved // in the daemon instance so that they can be restored in boosters. setUnixSignalHandler(SIGCHLD, write_to_signal_pipe); // reap zombies + setUnixSignalHandler(SIGINT, write_to_signal_pipe); // exit launcher setUnixSignalHandler(SIGTERM, write_to_signal_pipe); // exit launcher setUnixSignalHandler(SIGUSR1, write_to_signal_pipe); // enter normal mode from boot mode setUnixSignalHandler(SIGUSR2, write_to_signal_pipe); // enter boot mode (same as --boot-mode) @@ -194,6 +398,15 @@ void Daemon::run(Booster *booster) FD_SET(m_sigPipeFd[0], &rfds); ndfs = std::max(ndfs, m_sigPipeFd[0]); + /* Listen to invoker EOFs */ + for (auto iter = m_boosterPidToInvokerFd.begin(); iter != m_boosterPidToInvokerFd.end(); ++iter) { + int fd = iter->second; + if (fd != -1) { + FD_SET(fd, &rfds); + ndfs = std::max(ndfs, fd); + } + } + // Wait for something appearing in the pipes. if (select(ndfs + 1, &rfds, NULL, NULL, NULL) > 0) { @@ -219,9 +432,11 @@ void Daemon::run(Booster *booster) reapZombies(); break; + case SIGINT: case SIGTERM: { - Logger::logDebug("Daemon: SIGTERM received."); + Logger::logDebug("Daemon: SIGINT / SIGTERM received."); + // FIXME: Legacy pid file path -> see daemonize() const std::string pidFilePath = m_socketManager->socketRootPath() + m_booster->boosterType() + ".pid"; FILE * const pidFile = fopen(pidFilePath.c_str(), "r"); if (pidFile) @@ -234,6 +449,43 @@ void Daemon::run(Booster *booster) fclose(pidFile); } + for (;;) { + PidVect::iterator iter(m_children.begin()); + if (iter == m_children.end()) + break; + pid_t booster_pid = *iter; + m_children.erase(iter); + + /* Get and remove booster socket fd */ + int socket_fd = -1; + FdMap::iterator fdIter = m_boosterPidToInvokerFd.find(booster_pid); + if (fdIter != m_boosterPidToInvokerFd.end()) { + socket_fd = (*fdIter).second; + m_boosterPidToInvokerFd.erase(fdIter); + } + /* Get and remove invoker pid */ + pid_t invoker_pid = -1; + PidMap::iterator pidIter = m_boosterPidToInvokerPid.find(booster_pid); + if (pidIter != m_boosterPidToInvokerPid.end()) { + invoker_pid = (*pidIter).second; + m_boosterPidToInvokerPid.erase(pidIter); + } + + /* Normally boosters are stopped on shutdown / user switch, + * and even then it should happen after applications have + * already been stopped. + */ + warning("terminating: booster:%d invoker:%d socket:%d", + (int)booster_pid, (int)invoker_pid, socket_fd); + + /* Terminate invoker */ + close_invoker(invoker_pid, socket_fd, EXIT_FAILURE); + + /* Terminate booster */ + kill_process("booster", booster_pid); + } + + Logger::logDebug("booster exit"); exit(EXIT_SUCCESS); break; } @@ -255,6 +507,41 @@ void Daemon::run(Booster *booster) default: break; } + continue; + } + + /* Handle closed booster sockets */ + for (auto iter = m_boosterPidToInvokerFd.begin(); iter != m_boosterPidToInvokerFd.end();) { + int socket_fd = iter->second; + if (socket_fd != -1 && FD_ISSET(socket_fd, &rfds)) { + /* Note: bookkeeping must be updated first to avoid + * any ringing due to socket closes / child + * process exits. + */ + pid_t booster_pid = iter->first; + iter = m_boosterPidToInvokerFd.erase(iter); + + pid_t invoker_pid = -1; + PidMap::iterator pidIter = m_boosterPidToInvokerPid.find(booster_pid); + if (pidIter != m_boosterPidToInvokerPid.end()) { + invoker_pid = pidIter->second; + m_boosterPidToInvokerPid.erase(pidIter); + } + + /* Note that it is slightly unexpected if we get here + * as it means invoker exited rather than application. + */ + warning("terminating: booster:%d invoker:%d socket:%d", + (int)booster_pid, (int)invoker_pid, socket_fd); + + /* Terminate invoker */ + close_invoker(invoker_pid, socket_fd, EXIT_FAILURE); + + /* Terminate booster */ + kill_process("booster", booster_pid); + } else { + ++iter; + } } } } @@ -283,21 +570,36 @@ void Daemon::readFromBoosterSocket(int fd) if (recvmsg(fd, &msg, 0) >= 0) { + Logger::logDebug("Daemon: boosters's pid: %d\n", m_boosterPid); Logger::logDebug("Daemon: invoker's pid: %d\n", invokerPid); Logger::logDebug("Daemon: respawn delay: %d \n", delay); - if (invokerPid != 0) - { - // Store booster - invoker pid pair - // Store booster - invoker socket pair - if (m_boosterPid) - { - cmsg = CMSG_FIRSTHDR(&msg); - int newFd; - memcpy(&newFd, CMSG_DATA(cmsg), sizeof(int)); - Logger::logDebug("Daemon: socket file descriptor: %d\n", newFd); - m_boosterPidToInvokerPid[m_boosterPid] = invokerPid; + + int newFd = -1; + + if (invokerPid > 0) { + /* invokerPid got filled in at recvmsg() => we have fd too */ + cmsg = CMSG_FIRSTHDR(&msg); + memcpy(&newFd, CMSG_DATA(cmsg), sizeof(int)); + Logger::logDebug("Daemon: socket file descriptor: %d\n", newFd); + } + + if (m_boosterPid > 0) { + /* We were expecting booster details => update bookkeeping */ + if (newFd != -1) { + // Store booster pid - invoker socket pair m_boosterPidToInvokerFd[m_boosterPid] = newFd; + newFd = -1; } + if (invokerPid > 0) { + // Store booster pid - invoker pid pair + m_boosterPidToInvokerPid[m_boosterPid] = invokerPid; + } + } + + if (newFd != -1) { + /* If we are not going to use the received fd, it needs to be closed */ + Logger::logWarning("Daemon: close stray socket file descriptor: %d\n", newFd); + close(newFd); } } else @@ -318,7 +620,7 @@ void Daemon::killProcess(pid_t pid, int signal) const { if (pid > 0) { - Logger::logDebug("Daemon: Killing pid %d with %d", pid, signal); + Logger::logWarning("Daemon: Killing pid %d with %d", pid, signal); if (kill(pid, signal) != 0) { Logger::logError("Daemon: Failed to kill %d: %s\n", @@ -413,8 +715,10 @@ void Daemon::forkBooster(int sleepTime) // Guarantee some time for the just launched application to // start up before initializing new booster if needed. // Not done if in the boot mode. - if (!m_bootMode && sleepTime) + if (!m_bootMode && sleepTime) { + Logger::logDebug("allow time for application startup - sleep(%ds)...\n", sleepTime); sleep(sleepTime); + } Logger::logDebug("Daemon: Running a new Booster of type '%s'", m_booster->boosterType().c_str()); @@ -425,7 +729,6 @@ void Daemon::forkBooster(int sleepTime) m_singleInstance, m_bootMode); } catch (const std::runtime_error &e) { Logger::logError("Booster: Failed to initialize: %s\n", e.what()); - fprintf(stderr, "Failed to initialize: %s\n", e.what()); delete m_booster; _exit(EXIT_FAILURE); } @@ -463,60 +766,50 @@ void Daemon::reapZombies() while (i != m_children.end()) { // Check if the pid had exited and become a zombie - int status; + int status = 0; pid_t pid = waitpid(*i, &status, WNOHANG); - if (pid) + if (pid > 0) { // The pid had exited. Remove it from the pid vector. i = m_children.erase(i); - // Find out if the exited process has a mapping with an invoker process. - // If this is the case, then kill the invoker process with the same signal - // that killed the exited process. - PidMap::iterator it = m_boosterPidToInvokerPid.find(pid); - if (it != m_boosterPidToInvokerPid.end()) - { - Logger::logDebug("Daemon: Terminated process had a mapping to an invoker pid"); - - if (WIFEXITED(status)) - { - Logger::logInfo("Boosted process (pid=%d) exited with status %d\n", pid, WEXITSTATUS(status)); - Logger::logDebug("Daemon: child exited by exit(x), _exit(x) or return x\n"); - Logger::logDebug("Daemon: x == %d\n", WEXITSTATUS(status)); - FdMap::iterator fd = m_boosterPidToInvokerFd.find(pid); - if (fd != m_boosterPidToInvokerFd.end()) - { - uint32_t command = INVOKER_MSG_EXIT; - uint32_t argument = WEXITSTATUS(status); - write_dontcare((*fd).second, &command, sizeof command); - write_dontcare((*fd).second, &argument, sizeof argument); - close((*fd).second); - m_boosterPidToInvokerFd.erase(fd); - } - } - else if (WIFSIGNALED(status)) - { - int signal = WTERMSIG(status); - pid_t invokerPid = (*it).second; - - Logger::logInfo("Boosted process (pid=%d) was terminated due to signal %d\n", pid, signal); - Logger::logDebug("Daemon: Booster (pid=%d) was terminated due to signal %d\n", pid, signal); - Logger::logDebug("Daemon: Killing invoker process (pid=%d) by signal %d..\n", invokerPid, signal); - - FdMap::iterator fd = m_boosterPidToInvokerFd.find(pid); - if (fd != m_boosterPidToInvokerFd.end()) - { - close((*fd).second); - m_boosterPidToInvokerFd.erase(fd); - } + // Find out what happened + int exit_status = EXIT_FAILURE; + int signal_no = 0; + + if (WIFSIGNALED(status)) { + signal_no = WTERMSIG(status); + Logger::logWarning("boosted process (pid=%d) signal(%s)\n", + pid, strsignal(signal_no)); + } else if (WIFEXITED(status)) { + exit_status = WEXITSTATUS(status); + if (exit_status != EXIT_SUCCESS) + Logger::logWarning("Boosted process (pid=%d) exit(%d)\n", + pid, exit_status); + else + Logger::logDebug("Boosted process (pid=%d) exit(%d)\n", + pid, exit_status); + } - killProcess(invokerPid, signal); - } + /* Get and remove booster socket fd */ + int socket_fd = -1; + FdMap::iterator fdIter = m_boosterPidToInvokerFd.find(pid); + if (fdIter != m_boosterPidToInvokerFd.end()) { + socket_fd = (*fdIter).second; + m_boosterPidToInvokerFd.erase(fdIter); + } - // Remove a dead booster - m_boosterPidToInvokerPid.erase(it); + /* Get and remove invoker pid */ + pid_t invoker_pid = -1; + PidMap::iterator pidIter = m_boosterPidToInvokerPid.find(pid); + if (pidIter != m_boosterPidToInvokerPid.end()) { + invoker_pid = (*pidIter).second; + m_boosterPidToInvokerPid.erase(pidIter); } + /* Terminate invoker associated with the booster */ + close_invoker(invoker_pid, socket_fd, exit_status); + // Check if pid belongs to a booster and restart the dead booster if needed if (pid == m_boosterPid) { @@ -528,6 +821,15 @@ void Daemon::reapZombies() i++; } } + + /* Handle stray child exits */ + for (;;) { + int status = 0; + pid_t pid = waitpid(-1, &status, WNOHANG); + if (pid <= 0) + break; + Logger::logWarning("unexpected child exit pid=%d status=0x%x\n", pid, status); + } } void Daemon::daemonize() @@ -557,7 +859,18 @@ void Daemon::daemonize() // If we got a good PID, then we can exit the parent process. if (pid > 0) { + /* FIXME: Existing booster systemd unit files etc are expecting + * pid file paths derived from booster type. As long as + * there are no application specific boosters using + * pid files we can continue using old style paths. + */ +#if 0 + // Path that takes also application name into account + const std::string pidFilePath = m_socketManager->socketRootPath() + m_booster->socketId() + ".pid"; +#else + // Legacy path const std::string pidFilePath = m_socketManager->socketRootPath() + m_booster->boosterType() + ".pid"; +#endif FILE * const pidFile = fopen(pidFilePath.c_str(), "w"); if (pidFile) { @@ -717,7 +1030,7 @@ void Daemon::enterBootMode() void Daemon::killBoosters() { - if (m_boosterPid) + if (m_boosterPid > 0) killProcess(m_boosterPid, SIGTERM); // NOTE!!: m_boosterPid must not be cleared @@ -726,33 +1039,29 @@ void Daemon::killBoosters() void Daemon::setUnixSignalHandler(int signum, sighandler_t handler) { - sighandler_t old_handler = signal(signum, handler); - - if (signum == SIGHUP && old_handler == SIG_IGN) - { - // SIGHUP is a special case. It is set to SIG_IGN - // when applauncherd does a re-exec, but we still want the - // boosters / launched applications to get the default - // handler. - m_originalSigHandlers[signum] = SIG_DFL; - } - else if (old_handler != SIG_ERR) - { - m_originalSigHandlers[signum] = old_handler; - } - else - { - throw std::runtime_error("Daemon: Failed to set signal handler"); - } + // needs to be undone in instance + m_originalSigHandlers[signum] = SIG_DFL; + + struct sigaction sig; + memset(&sig, 0, sizeof(sig)); + sig.sa_flags = SA_RESTART; + sig.sa_handler = handler; + if (sigaction(signum, &sig, NULL) == -1) + warning("trap(%s): %m", strsignal(signum)); + else + debug("trap(%s): ok", strsignal(signum)); } void Daemon::restoreUnixSignalHandlers() { for (SigHandlerMap::iterator it = m_originalSigHandlers.begin(); it != m_originalSigHandlers.end(); it++ ) { - signal(it->first, it->second); + int signum = it->first; + if (signal(signum, SIG_DFL) == SIG_ERR) + warning("untrap(%s): %m", strsignal(signum)); + else + debug("untrap(%s): ok", strsignal(signum)); } - m_originalSigHandlers.clear(); } @@ -764,4 +1073,3 @@ Daemon::~Daemon() Logger::closeLog(); } - diff --git a/src/launcherlib/logger.cpp b/src/launcherlib/logger.cpp index f2f6aa9..b659938 100644 --- a/src/launcherlib/logger.cpp +++ b/src/launcherlib/logger.cpp @@ -25,50 +25,83 @@ #include #include #include +#include #include "coverage.h" bool Logger::m_isOpened = false; bool Logger::m_debugMode = false; +static char *strip(char *str) +{ + if (str) { + char *dst = str; + char *src = str; + while (*src && isspace(*src)) + ++src; + for (;;) { + while (*src && !isspace(*src)) + *dst++ = *src++; + while (*src && isspace(*src)) + ++src; + if (!*src) + break; + *dst++ = ' '; + } + *dst = 0; + } + return str; +} + +static bool useSyslog() +{ + static bool checked = false; + static bool value = false; + if (!checked) { + checked = true; + value = !isatty(STDIN_FILENO); + } + return value; +} + void Logger::openLog(const char * progName) { if (!progName) progName = "mapplauncherd"; - if (Logger::m_isOpened) - { - Logger::closeLog(); + if (useSyslog()) { + if (Logger::m_isOpened) + Logger::closeLog(); + openlog(progName, LOG_PID, LOG_DAEMON); + Logger::m_isOpened = true; } - openlog(progName, LOG_PID, LOG_DAEMON); - Logger::m_isOpened = true; } void Logger::closeLog() { - if (Logger::m_isOpened) - { - // Close syslog - closelog(); + if (useSyslog()) { + if (Logger::m_isOpened) + closelog(); Logger::m_isOpened = false; } } void Logger::writeLog(const int priority, const char * format, va_list ap) { - // In debug mode everything is printed also to stdout - if (m_debugMode) - { - vprintf(format, ap); - printf("\n"); - } - - // Print to syslog - if (!Logger::m_isOpened) - { - Logger::openLog(); //open log with default name + if (useSyslog()) { + if (!Logger::m_isOpened) + Logger::openLog(); + vsyslog(priority, format, ap); + } else { + char *msg = 0; + if (vasprintf(&msg, format, ap) < 0) + msg = 0; + else + strip(msg); + fprintf(stderr, "BOOSTER(%d): %s\n", (int)getpid(), msg ?: format); + fflush(stderr); + free(msg); } - vsyslog(priority, format, ap); } void Logger::logDebug(const char * format, ...) diff --git a/src/launcherlib/logger.h b/src/launcherlib/logger.h index a5cc978..dd9d9b4 100644 --- a/src/launcherlib/logger.h +++ b/src/launcherlib/logger.h @@ -100,5 +100,11 @@ private: #endif }; +/* Allow the same logging API to be used in booster and invoker */ +#define error( FMT, ARGS...) Logger::logError( FMT, ##ARGS) +#define warning(FMT, ARGS...) Logger::logWarning(FMT, ##ARGS) +#define info( FMT, ARGS...) Logger::logInfo( FMT, ##ARGS) +#define debug( FMT, ARGS...) Logger::logDebug( FMT, ##ARGS) + #endif // LOGGER_H