/* Serval DNA logging Copyright (C) 2013-2015 Serval Project Inc. Copyright (C) 2016 Flinders University This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation; either version 2 of the License, or (at your option) any later version. This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with this program; if not, write to the Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. */ #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include "version_servald.h" #include "instance.h" #include "log.h" #include "net.h" #include "os.h" #include "conf.h" #include "str.h" #include "strbuf.h" #include "strbuf_helpers.h" #include "xprintf.h" int logLevel_NoLogFileConfigured = LOG_LEVEL_INFO; #define NO_FILE ((FILE *)1) /* The _log_state structure records the persistent state associated with a single log output * destination. The state is only persistent for the lifetime of the process (eg, while the daemon * is running), and is not stored anywhere else. It is initially zerofilled. * * @author Andrew Bettison */ struct _log_state { /* Whether the software version has been logged in the current file yet. */ bool_t version_logged; /* The time stamp of the last logged message, used to detect when the date advances so that * the date can be logged. */ struct tm last_tm; /* Whether the current configuration has been logged in the current file yet. */ bool_t config_logged; }; /* The _log_iterator structure is a transient structure that is used to iterate over all the * supported log output destinations. Generally, one of these is created (as an auto variable) * every time a log message is generated, and destroyed immediately after the message has been sent * to all the log outputs. * * The log iterator is controlled using various _log_iterator_xxx() functions. * * @author Andrew Bettison */ typedef struct _log_iterator { const struct config_log_format *config; struct _log_state *state; struct timeval tv; struct tm tm; XPRINTF xpf; time_t file_start_time; } _log_iterator; /* Static variables for sending log output to a file. * * The _log_file_strbuf is used to accumulate log messages before the log file is open and ready for * writing. */ const char *_log_file_path; char _log_file_path_buf[400]; static FILE *_log_file = NULL; static void _open_log_file(_log_iterator *); static void _rotate_log_file(_log_iterator *it); static void _flush_log_file(); static struct _log_state state_file; static struct config_log_format config_file; static struct { size_t len; mode_t mode; } mkdir_trace[10]; static mode_t mkdir_trace_latest_mode; static unsigned mkdir_count; static time_t _log_file_start_time; static char _log_file_buf[8192]; static struct strbuf _log_file_strbuf = STRUCT_STRBUF_EMPTY; #ifdef ANDROID /* Static variables for sending log output to the Android log. * * The _android_strbuf is used to accumulate a single log line before printing to Android's logging * API. */ #include struct _log_state state_android; static char _log_android_buf[1024]; static struct strbuf _android_strbuf; #endif // ANDROID /* Static variables for sending log output to standard error. */ static FILE *logfile_stderr = NULL; struct _log_state state_stderr; static void _open_log_stderr(); static void _flush_log_stderr(); /* Primitive operations for _log_iterator structures. */ static void _log_iterator_start(_log_iterator *it) { memset(it, 0, sizeof *it); gettimeofday(&it->tv, NULL); localtime_r(&it->tv.tv_sec, &it->tm); } static void _log_iterator_rewind(_log_iterator *it) { it->config = NULL; it->state = NULL; } static void _log_iterator_advance_to_file(_log_iterator *it) { cf_dfl_config_log_format(&config_file); cf_cpy_config_log_format(&config_file, &config.log.file); it->config = &config_file; it->state = &state_file; } #ifdef ANDROID static void _log_iterator_advance_to_android(_log_iterator *it) { it->config = &config.log.android; it->state = &state_android; } #endif // ANDROID static void _log_iterator_advance_to_stderr(_log_iterator *it) { it->config = &config.log.console; it->state = &state_stderr; } static int _log_iterator_advance(_log_iterator *it) { if (it->config == NULL) { _log_iterator_advance_to_file(it); return 1; } if (it->config == &config_file) { #ifdef ANDROID _log_iterator_advance_to_android(it); return 1; } if (it->config == &config.log.android) { #endif // ANDROID _log_iterator_advance_to_stderr(it); return 1; } return 0; } static int _log_enabled(_log_iterator *it) { if (it->config == &config_file) { _open_log_file(it); // puts initial INFO message(s) at head of log file if (_log_file == NO_FILE) return 0; } else if (it->config == &config.log.console) { _open_log_stderr(); if (logfile_stderr == NULL || logfile_stderr == NO_FILE) return 0; } return 1; } static void _log_prefix_level(_log_iterator *it, int level) { const char *levelstr = "UNKWN:"; switch (level) { case LOG_LEVEL_FATAL: levelstr = "FATAL:"; break; case LOG_LEVEL_ERROR: levelstr = "ERROR:"; break; case LOG_LEVEL_WARN: levelstr = "WARN:"; break; case LOG_LEVEL_HINT: levelstr = "HINT:"; break; case LOG_LEVEL_INFO: levelstr = "INFO:"; break; case LOG_LEVEL_DEBUG: levelstr = "DEBUG:"; break; } xprintf(it->xpf, "%-6.6s", levelstr); } static void _log_prefix_context(_log_iterator *it) { if (it->config->show_pid) xprintf(it->xpf, "[%5u] ", getpid()); if (it->config->show_time) { if (it->tv.tv_sec == 0) { xputs("NOTIME______ ", it->xpf); } else { char buf[50]; if (strftime(buf, sizeof buf, "%T", &it->tm) == 0) xputs("EMPTYTIME___ ", it->xpf); else xprintf(it->xpf, "%s.%03u ", buf, (unsigned int)it->tv.tv_usec / 1000); } } if (strbuf_len(&log_context)) { xputs("[", it->xpf); xputs(strbuf_str(&log_context), it->xpf); xputs("] ", it->xpf); } } static void _log_prefix(_log_iterator *it, int level) { if (it->config == &config_file) { if (strbuf_is_empty(&_log_file_strbuf)) strbuf_init(&_log_file_strbuf, _log_file_buf, sizeof _log_file_buf); else if (strbuf_len(&_log_file_strbuf)) strbuf_putc(&_log_file_strbuf, '\n'); it->xpf = XPRINTF_STRBUF(&_log_file_strbuf); _log_prefix_level(it, level); } #ifdef ANDROID else if (it->config == &config.log.android) { strbuf_init(&_android_strbuf, _log_android_buf, sizeof _log_android_buf); it->xpf = XPRINTF_STRBUF(&_android_strbuf); } #endif // ANDROID else if (it->config == &config.log.console) { it->xpf = XPRINTF_STDIO(logfile_stderr); _log_prefix_level(it, level); } else abort(); _log_prefix_context(it); } static void _log_prefix_whence(_log_iterator *it, struct __sourceloc whence) { if ((whence.file && whence.file[0]) || (whence.function && whence.function[0])) { xprint_sourceloc(it->xpf, whence); xputs(" ", it->xpf); } } static void _log_end_line(_log_iterator *it, int UNUSED(level)) { #ifdef ANDROID if (it->config == &config.log.android) { int alevel = ANDROID_LOG_UNKNOWN; switch (level) { case LOG_LEVEL_FATAL: alevel = ANDROID_LOG_FATAL; break; case LOG_LEVEL_ERROR: alevel = ANDROID_LOG_ERROR; break; case LOG_LEVEL_WARN: alevel = ANDROID_LOG_WARN; break; case LOG_LEVEL_HINT: case LOG_LEVEL_INFO: alevel = ANDROID_LOG_INFO; break; case LOG_LEVEL_DEBUG: alevel = ANDROID_LOG_DEBUG; break; default: abort(); } __android_log_print(alevel, "servald", "%s", _log_android_buf); } else #endif // ANDROID if (it->config == &config.log.console) { fputc('\n', logfile_stderr); } } static void _log_flush(_log_iterator *it) { if (it->config == &config_file) { _flush_log_file(); } else if (it->config == &config.log.console) { _flush_log_stderr(); } } static void _log_vprintf_nl(_log_iterator *it, int level, const char *fmt, va_list ap) { _log_prefix(it, level); vxprintf(it->xpf, fmt, ap); _log_end_line(it, level); } static void _log_printf_nl(_log_iterator *it, int level, const char *fmt, ...) { va_list ap; va_start(ap, fmt); _log_vprintf_nl(it, level, fmt, ap); va_end(ap); } static void _log_current_datetime(_log_iterator *it, int level) { char buf[50]; if (strftime(buf, sizeof buf, "%F %T %z", &it->tm)) { _log_printf_nl(it, level, "Local date/time: %s", buf); it->state->last_tm = it->tm; } } static void _log_software_version(_log_iterator *it, int level) { _log_printf_nl(it, level, "Serval DNA version: %s", version_servald); it->state->version_logged = 1; } static int _log_current_config(_log_iterator *it, int level) { if (!cf_limbo) { // if formatting config causes anything else to be logged, ignore it. cf_limbo=1; struct cf_om_node *root = NULL; int ret = cf_fmt_config_main(&root, &config); if (ret == CFERROR) { _log_printf_nl(it, level, "Cannot dump current configuration: cf_fmt_config_main() returned CFERROR"); } else { _log_printf_nl(it, level, "Current configuration:"); struct cf_om_iterator oit; int empty = 1; for (cf_om_iter_start(&oit, root); oit.node; cf_om_iter_next(&oit)) { if (oit.node->text && oit.node->line_number) { empty = 0; _log_printf_nl(it, level, " %s=%s", oit.node->fullkey, oit.node->text); } } if (empty) _log_printf_nl(it, level, " (empty)"); } cf_om_free_node(&root); it->state->config_logged = 1; cf_limbo=0; } return 1; } static void _log_update(_log_iterator *it) { if ( it->tm.tm_mday != it->state->last_tm.tm_mday || it->tm.tm_mon != it->state->last_tm.tm_mon || it->tm.tm_year != it->state->last_tm.tm_year ) _log_current_datetime(it, LOG_LEVEL_INFO); if (!it->state->version_logged) _log_software_version(it, LOG_LEVEL_INFO); if (it->config->dump_config && !it->state->config_logged) _log_current_config(it, LOG_LEVEL_INFO); } static int _log_iterator_next(_log_iterator *it, int level) { assert(level >= LOG_LEVEL_SILENT); assert(level <= LOG_LEVEL_FATAL); _log_end_line(it, level); _log_flush(it); while (_log_iterator_advance(it)) { if (level >= it->config->level && _log_enabled(it)) { _log_update(it); _log_prefix(it, level); return 1; } } return 0; } static void _log_iterator_vprintf_nl(_log_iterator *it, int level, struct __sourceloc whence, const char *fmt, va_list ap) { _log_iterator_rewind(it); while (_log_iterator_next(it, level)) { _log_prefix_whence(it, whence); va_list ap1; va_copy(ap1, ap); vxprintf(it->xpf, fmt, ap1); va_end(ap1); } } static void _logs_vprintf_nl(int level, struct __sourceloc whence, const char *fmt, va_list ap) { _log_iterator it; _log_iterator_start(&it); _log_iterator_vprintf_nl(&it, level, whence, fmt, ap); } static void _logs_printf_nl(int level, struct __sourceloc whence, const char *fmt, ...) { va_list ap; va_start(ap, fmt); _logs_vprintf_nl(level, whence, fmt, ap); va_end(ap); } static void _compute_file_start_time(_log_iterator *it) { if (it->file_start_time == 0) { assert(!cf_limbo); assert(it->tv.tv_sec != 0); it->file_start_time = it->tv.tv_sec; if (config.log.file.duration) it->file_start_time -= it->file_start_time % config.log.file.duration; } } static void trace_mkdir(struct __sourceloc UNUSED(whence), const char *path, mode_t mode) { if (mkdir_count < NELS(mkdir_trace)) { mkdir_trace[mkdir_count].len = strlen(path); mkdir_trace[mkdir_count].mode = mode; } ++mkdir_count; mkdir_trace_latest_mode = mode; } static void log_mkdir_trace(const char *dir) { unsigned i; for (i = 0; i < mkdir_count && i < NELS(mkdir_trace); ++i) _logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Created %s (mode %04o)", alloca_toprint(-1, dir, mkdir_trace[i].len), mkdir_trace[i].mode); if (mkdir_count > NELS(mkdir_trace) + 1) _logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Created ..."); if (mkdir_count > NELS(mkdir_trace)) _logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Created %s (mode %04o)", alloca_str_toprint(dir), mkdir_trace_latest_mode); } static void _open_log_file(_log_iterator *it) { assert(it->state == &state_file); if (_log_file != NO_FILE) { if (_log_file_path == NULL) _log_file_path = getenv("SERVALD_LOG_FILE"); if (_log_file_path == NULL && !cf_limbo) { strbuf sbfile = strbuf_local_buf(_log_file_path_buf); strbuf_serval_log_path(sbfile); strbuf_path_join(sbfile, config.log.file.directory_path, "", NULL); // with trailing '/' _compute_file_start_time(it); if (config.log.file.path[0]) { strbuf_path_join(sbfile, config.log.file.path, NULL); } else { struct tm tm; (void)localtime_r(&it->file_start_time, &tm); strbuf_append_strftime(sbfile, "serval-%Y%m%d%H%M%S.log", &tm); } if (strbuf_overrun(sbfile)) { _log_file = NO_FILE; _logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot form log file name - buffer overrun"); } else { _log_file_start_time = it->file_start_time; _log_file_path = strbuf_str(sbfile); } } if (!_log_file) { if (_log_file_path == NULL) { if (cf_limbo) return; _log_file = NO_FILE; _logs_printf_nl(logLevel_NoLogFileConfigured, __NOWHERE__, "No log file configured"); } else { // Create the new log file. size_t dirsiz = strlen(_log_file_path) + 1; char _dir[dirsiz]; strcpy(_dir, _log_file_path); const char *dir = dirname(_dir); // modifies _dir[] mkdir_count = 0; if (mkdirs_log(dir, 0700, trace_mkdir) == -1) { _log_file = NO_FILE; log_mkdir_trace(dir); _logs_printf_nl(LOG_LEVEL_WARN, __HERE__, "Cannot mkdir %s - %s [errno=%d]", alloca_str_toprint(dir), strerror(errno), errno); } else if ((_log_file = fopen(_log_file_path, "a")) == NULL) { _log_file = NO_FILE; log_mkdir_trace(dir); _logs_printf_nl(LOG_LEVEL_WARN, __HERE__, "Cannot create-append %s - %s [errno=%d]", _log_file_path, strerror(errno), errno); } else { setlinebuf(_log_file); memset(it->state, 0, sizeof *it->state); // The first line in every log file must be the starting time stamp. (After that, it is up // to _log_update() to insert other mandatory messages in any suitable order.) _log_current_datetime(it, LOG_LEVEL_INFO); log_mkdir_trace(dir); _logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Logging to %s (fd %d)", _log_file_path, fileno(_log_file)); // if stderr should be redirected if (logfile_stderr == NO_FILE) dup2(fileno(_log_file),STDERR_FILENO); // Update the log symlink to point to the latest log file. strbuf sbsymlink = strbuf_alloca(400); strbuf_system_log_path(sbsymlink); strbuf_path_join(sbsymlink, "serval.log", NULL); if (strbuf_overrun(sbsymlink)) _logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot form log symlink name - buffer overrun"); else { const char *f = _log_file_path; const char *s = strbuf_str(sbsymlink); const char *relpath = f; for (; *f && *f == *s; ++f, ++s) if (*f == '/') relpath = f; while (*relpath == '/') ++relpath; while (*s == '/') ++s; if (strchr(s, '/')) relpath = _log_file_path; // If racing with another process at this exact same point, then the symlink(2) call may // fail with EEXIST, in which case log a warning, not an error. unlink(strbuf_str(sbsymlink)); if (symlink(relpath, strbuf_str(sbsymlink)) == -1) _logs_printf_nl(errno == EEXIST ? LOG_LEVEL_WARN : LOG_LEVEL_ERROR, __HERE__, "Cannot symlink %s -> %s - %s [errno=%d]", strbuf_str(sbsymlink), relpath, strerror(errno), errno); } // Expire old log files. size_t pathsiz = strlen(_log_file_path) + 1; char path[pathsiz]; while (1) { strcpy(path, _log_file_path); const char *base = basename(path); // modifies path[] DIR *d = opendir(dir); if (!d) { _logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot expire log files: opendir(%s) - %s [errno=%d]", dir, strerror(errno), errno); break; } struct dirent oldest; memset(&oldest, 0, sizeof oldest); unsigned count = 0; while (1) { errno = 0; struct dirent *ent = readdir(d); if (ent == NULL) { if (errno) _logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot expire log files: readdir(%s) - %s [errno=%d]", dir, strerror(errno), errno); break; } const char *e; if ( str_startswith(ent->d_name, "serval-", &e) && isdigit(e[0]) && isdigit(e[1]) && isdigit(e[2]) && isdigit(e[3]) // YYYY && isdigit(e[4]) && isdigit(e[5]) // MM && isdigit(e[6]) && isdigit(e[7]) // DD && isdigit(e[8]) && isdigit(e[9]) // HH && isdigit(e[10]) && isdigit(e[11]) // MM && isdigit(e[12]) && isdigit(e[13]) // SS && strcmp(&e[14], ".log") == 0 ) { ++count; if ( strcmp(ent->d_name, base) != 0 && (!oldest.d_name[0] || strcmp(ent->d_name, oldest.d_name) < 0) ) oldest = *ent; } } closedir(d); if (count <= config.log.file.rotate || !oldest.d_name[0]) break; strbuf b = strbuf_local(path, pathsiz); strbuf_path_join(b, dir, oldest.d_name, NULL); assert(!strbuf_overrun(b)); _logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Unlink %s", path); unlink(path); } } } } } } static void _rotate_log_file(_log_iterator *it) { if (!cf_limbo && _log_file != NO_FILE && _log_file_path == _log_file_path_buf) { if (!config.log.file.path[0] && config.log.file.duration) { _compute_file_start_time(it); if (it->file_start_time != _log_file_start_time) { // Close the current log file, which will cause _open_log_file() to open the next one. if (_log_file) fclose(_log_file); _log_file = NULL; _log_file_path = NULL; } } } } static void _flush_log_file() { if (_log_file && _log_file != NO_FILE && strbuf_len(&_log_file_strbuf) != 0) { fprintf(_log_file, "%s%s%s", strbuf_len(&_log_file_strbuf) ? strbuf_str(&_log_file_strbuf) : "", strbuf_len(&_log_file_strbuf) ? "\n" : "", strbuf_overrun(&_log_file_strbuf) ? "LOG OVERRUN\n" : "" ); strbuf_reset(&_log_file_strbuf); } } /* Discard any unwritten log messages and close the log file immediately. This should be called in * any child process immediately after fork() to prevent any buffered log messages from being * written twice into the log file. * * @author Andrew Bettison */ void close_log_file() { strbuf_reset(&_log_file_strbuf); if (_log_file && _log_file != NO_FILE) fclose(_log_file); _log_file = NULL; } static void _open_log_stderr() { if (!logfile_stderr) { logfile_stderr = stderr; setlinebuf(logfile_stderr); } } static void _flush_log_stderr() { if (logfile_stderr && logfile_stderr != NO_FILE) fflush(logfile_stderr); } void redirect_stderr_to_log() { if (logfile_stderr && logfile_stderr != NO_FILE) { fflush(logfile_stderr); logfile_stderr = NO_FILE; } } void logFlush() { _log_iterator it; _log_iterator_start(&it); while (_log_iterator_advance(&it)) _log_flush(&it); } void vlogMessage(int level, struct __sourceloc whence, const char *fmt, va_list ap) { if (level != LOG_LEVEL_SILENT) { _log_iterator it; _log_iterator_start(&it); _rotate_log_file(&it); while (_log_iterator_next(&it, level)) { _log_prefix_whence(&it, whence); va_list ap1; va_copy(ap1, ap); vxprintf(it.xpf, fmt, ap1); va_end(ap1); } } } static void logConfigChanged(); DEFINE_TRIGGER(conf_log, logConfigChanged); static void logConfigChanged() { _log_iterator it; _log_iterator_start(&it); while (_log_iterator_advance(&it)) it.state->config_logged = 0; logFlush(); }