From 0d0f2fcfcac20cc9a7dd7d9cca21575e966e7d07 Mon Sep 17 00:00:00 2001 From: Lorenzo Miniero Date: Fri, 11 Oct 2024 10:52:58 +0200 Subject: [PATCH] Refactored logger internals (#3428) --- src/janus-cfgconv.c | 2 +- src/janus.c | 43 ++--- src/log.c | 286 +++++++++++------------------- src/log.h | 16 +- src/loggers/janus_jsonlog.c | 3 +- src/options.c | 3 +- src/postprocessing/janus-pp-rec.c | 2 +- src/postprocessing/mjr2pcap.c | 2 +- src/postprocessing/pcap2mjr.c | 2 +- 9 files changed, 143 insertions(+), 216 deletions(-) diff --git a/src/janus-cfgconv.c b/src/janus-cfgconv.c index 0332ffe7f48..bba5d7754fd 100644 --- a/src/janus-cfgconv.c +++ b/src/janus-cfgconv.c @@ -40,7 +40,7 @@ int lock_debug = 0; /* Main Code */ int main(int argc, char *argv[]) { - janus_log_init(FALSE, TRUE, NULL); + janus_log_init(FALSE, TRUE, NULL, NULL); atexit(janus_log_destroy); JANUS_LOG(LOG_INFO, "Janus version: %d (%s)\n", janus_version, janus_version_string); diff --git a/src/janus.c b/src/janus.c index 3151e8b1d48..2e7de77167c 100644 --- a/src/janus.c +++ b/src/janus.c @@ -4405,11 +4405,12 @@ gint main(int argc, char *argv[]) { core_limits.rlim_cur = core_limits.rlim_max = RLIM_INFINITY; setrlimit(RLIMIT_CORE, &core_limits); - g_print("Janus version: %d (%s)\n", janus_version, janus_version_string); - g_print("Janus commit: %s\n", janus_build_git_sha); - g_print("Compiled on: %s\n\n", janus_build_git_time); janus_mark_started(); + JANUS_PRINT("Janus version: %d (%s)\n", janus_version, janus_version_string); + JANUS_PRINT("Janus commit: %s\n", janus_build_git_sha); + JANUS_PRINT("Compiled on: %s\n\n", janus_build_git_time); + /* Initialize some command line options defaults */ options.debug_level = -1; options.session_timeout = -1; @@ -4443,7 +4444,7 @@ gint main(int argc, char *argv[]) { } if((config = janus_config_parse(config_file)) == NULL) { /* We failed to load the libconfig configuration file, let's try the INI */ - g_print("Failed to load %s, trying the INI instead...\n", config_file); + JANUS_PRINT("Failed to load %s, trying the INI instead...\n", config_file); g_free(config_file); char file[255]; g_snprintf(file, 255, "%s/janus.cfg", configs_folder); @@ -4451,11 +4452,11 @@ gint main(int argc, char *argv[]) { if((config = janus_config_parse(config_file)) == NULL) { if(options.config_file) { /* We only give up if the configuration file was explicitly provided */ - g_print("Error reading configuration from %s\n", config_file); + JANUS_PRINT("Error reading configuration from %s\n", config_file); janus_options_destroy(); exit(1); } - g_print("Error reading/parsing the configuration file in %s, going on with the defaults and the command line arguments\n", + JANUS_PRINT("Error reading/parsing the configuration file in %s, going on with the defaults and the command line arguments\n", configs_folder); config = janus_config_create("janus.cfg"); if(config == NULL) { @@ -4530,18 +4531,18 @@ gint main(int argc, char *argv[]) { } /* Daemonize now, if we need to */ if(daemonize) { - g_print("Running Janus as a daemon\n"); + JANUS_PRINT("Running Janus as a daemon\n"); /* Create a pipe for parent<->child communication during the startup phase */ if(pipe(pipefd) == -1) { - g_print("pipe error!\n"); + JANUS_PRINT("pipe error!\n"); exit(1); } /* Fork off the parent process */ pid_t pid = fork(); if(pid < 0) { - g_print("Fork error!\n"); + JANUS_PRINT("Fork error!\n"); exit(1); } if(pid > 0) { @@ -4570,7 +4571,7 @@ gint main(int argc, char *argv[]) { /* Leave the parent and return the exit code we received from the child */ if(code) - g_print("Error launching Janus (error code %d), check the logs for more details\n", code); + JANUS_PRINT("Error launching Janus (error code %d), check the logs for more details\n", code); exit(code); } /* Child here */ @@ -4582,13 +4583,13 @@ gint main(int argc, char *argv[]) { /* Create a new SID for the child process */ pid_t sid = setsid(); if(sid < 0) { - g_print("Error setting SID!\n"); + JANUS_PRINT("Error setting SID!\n"); exit(1); } /* Change the current working directory */ const char *cwd = options.cwd_path ? options.cwd_path : "/"; if((chdir(cwd)) < 0) { - g_print("Error changing the current working directory!\n"); + JANUS_PRINT("Error changing the current working directory!\n"); exit(1); } /* We close stdin/stdout/stderr when initializing the logger */ @@ -4606,10 +4607,7 @@ gint main(int argc, char *argv[]) { if(item && item->value && janus_is_true(item->value)) exit_on_dl_error = TRUE; - /* Initialize logger */ - if(janus_log_init(daemonize, use_stdout, logfile) < 0) - exit(1); - /* Check if there are external loggers we need to load as well */ + /* Check if there are external loggers we need to load */ const char *path = NULL; DIR *dir = NULL; /* External loggers are usually disabled by default: they need to be enabled in the configuration */ @@ -4664,16 +4662,16 @@ gint main(int argc, char *argv[]) { memset(eventpath, 0, 1024); g_snprintf(eventpath, 1024, "%s/%s", path, eventent->d_name); void *event = dlopen(eventpath, RTLD_NOW | RTLD_GLOBAL); - if (!event) { + if(!event) { JANUS_LOG(exit_on_dl_error ? LOG_FATAL : LOG_ERR, "\tCouldn't load logger plugin '%s': %s\n", eventent->d_name, dlerror()); - if (exit_on_dl_error) + if(exit_on_dl_error) exit(1); } else { create_l *create = (create_l*) dlsym(event, "create"); const char *dlsym_error = dlerror(); - if (dlsym_error) { + if(dlsym_error) { JANUS_LOG(exit_on_dl_error ? LOG_FATAL : LOG_ERR, "\tCouldn't load symbol 'create': %s\n", dlsym_error); - if (exit_on_dl_error) + if(exit_on_dl_error) exit(1); continue; } @@ -4717,7 +4715,10 @@ gint main(int argc, char *argv[]) { if(disabled_loggers != NULL) g_strfreev(disabled_loggers); disabled_loggers = NULL; - janus_log_set_loggers(loggers); + + /* Initialize logger */ + if(janus_log_init(daemonize, use_stdout, logfile, loggers) < 0) + exit(1); JANUS_PRINT("---------------------------------------------------\n"); JANUS_PRINT(" Starting Meetecho Janus (WebRTC Server) v%s\n", janus_version_string); diff --git a/src/log.c b/src/log.c index f9003cb90b8..e6884333563 100644 --- a/src/log.c +++ b/src/log.c @@ -3,10 +3,10 @@ * \copyright GNU General Public License v3 * \brief Buffered logging * \details Implementation of a simple buffered logger designed to remove - * I/O wait from threads that may be sensitive to such delays. Buffers are - * saved and reused to reduce allocation calls. The logger output can then - * be printed to stdout and/or a log file. If external loggers are added - * to the core, the logger output is passed to those as well. + * I/O wait from threads that may be sensitive to such delays. Each time + * there's stuff to be written (to stdout, log files, or external loggers), + * it's added to an async queue, which is consumed from a dedicated thread + * that then actually takes care of I/O. * * \ingroup core * \ref core @@ -17,21 +17,26 @@ #include #include "log.h" +#include "debug.h" #include "utils.h" #include "loggers/logger.h" #define THREAD_NAME "log" -typedef struct janus_log_buffer janus_log_buffer; -struct janus_log_buffer { +typedef struct janus_log_buffer { int64_t timestamp; - size_t allocated; - janus_log_buffer *next; - /* str is grown by allocating beyond the struct */ - char str[1]; -}; + char *str; +} janus_log_buffer; +static janus_log_buffer exit_message; +static void janus_log_buffer_free(janus_log_buffer *b) { + if(b == NULL || b == &exit_message) + return; + g_free(b->str); + g_free(b); +} -#define INITIAL_BUFSZ 2000 +static GAsyncQueue *janus_log_queue = NULL; +static GThread *log_thread = NULL; static gboolean janus_log_console = TRUE; static char *janus_log_filepath = NULL; @@ -41,17 +46,6 @@ static GHashTable *external_loggers = NULL; static volatile gint initialized = 0; static gint stopping = 0; -static gint poolsz = 0; -static gint maxpoolsz = 32; -/* Buffers over this size will be freed */ -static size_t maxbuffersz = 8000; -static GMutex lock; -static GCond cond; -static GThread *printthread = NULL; -static janus_log_buffer *printhead = NULL; -static janus_log_buffer *printtail = NULL; -static janus_log_buffer *bufferpool = NULL; - gboolean janus_log_is_stdout_enabled(void) { return janus_log_console; @@ -65,116 +59,49 @@ char *janus_log_get_logfile_path(void) { return janus_log_filepath; } - -static void janus_log_freebuffers(janus_log_buffer **list) { - janus_log_buffer *b, *head = *list; - - while (head) { - b = head; - head = b->next; - g_free(b); - } - *list = NULL; -} - -static janus_log_buffer *janus_log_getbuf(void) { - janus_log_buffer *b; - - g_mutex_lock(&lock); - b = bufferpool; - if (b) { - bufferpool = b->next; - b->next = NULL; - } else { - poolsz++; - } - g_mutex_unlock(&lock); - if (b == NULL) { - b = g_malloc(INITIAL_BUFSZ + sizeof(*b)); - b->allocated = INITIAL_BUFSZ; - b->next = NULL; +static void janus_log_print_buffer(janus_log_buffer *b) { + if(janus_log_console) + fputs(b->str, stdout); + if(janus_log_file) + fputs(b->str, janus_log_file); + if(external_loggers != NULL) { + GHashTableIter iter; + gpointer value; + g_hash_table_iter_init(&iter, external_loggers); + while(g_hash_table_iter_next(&iter, NULL, &value)) { + janus_logger *l = value; + if(l == NULL) + continue; + l->incoming_logline(b->timestamp, b->str); + } } - return b; + /* Flush the buffers */ + if(janus_log_console) + fflush(stdout); + if(janus_log_file) + fflush(janus_log_file); } static void *janus_log_thread(void *ctx) { - janus_log_buffer *head, *b, *tofree = NULL; - - while (!g_atomic_int_get(&stopping)) { - g_mutex_lock(&lock); - if (!printhead) { - g_cond_wait(&cond, &lock); - } - head = printhead; - printhead = printtail = NULL; - g_mutex_unlock(&lock); - - if (head) { - for (b = head; b; b = b->next) { - if(janus_log_console) - fputs(b->str, stdout); - if(janus_log_file) - fputs(b->str, janus_log_file); - if(external_loggers != NULL) { - GHashTableIter iter; - gpointer value; - g_hash_table_iter_init(&iter, external_loggers); - while(g_hash_table_iter_next(&iter, NULL, &value)) { - janus_logger *l = value; - if(l == NULL) - continue; - l->incoming_logline(b->timestamp, b->str); - } - } - } - g_mutex_lock(&lock); - while (head) { - b = head; - head = b->next; - if (poolsz >= maxpoolsz || b->allocated > maxbuffersz) { - b->next = tofree; - tofree = b; - poolsz--; - } else { - b->next = bufferpool; - bufferpool = b; - } - } - g_mutex_unlock(&lock); - if(janus_log_console) - fflush(stdout); - if(janus_log_file) - fflush(janus_log_file); - janus_log_freebuffers(&tofree); - } - } - /* print any remaining messages, stdout flushed on exit */ - for (b = printhead; b; b = b->next) { - if(janus_log_console) - fputs(b->str, stdout); - if(janus_log_file) - fputs(b->str, janus_log_file); - if(external_loggers != NULL) { - GHashTableIter iter; - gpointer value; - g_hash_table_iter_init(&iter, external_loggers); - while(g_hash_table_iter_next(&iter, NULL, &value)) { - janus_logger *l = value; - if(l == NULL) - continue; - l->incoming_logline(b->timestamp, b->str); - } + janus_log_buffer *b = NULL; + + while(!g_atomic_int_get(&stopping)) { + b = g_async_queue_pop(janus_log_queue); + if(b == NULL || b == &exit_message) + break; + if(b->str == NULL) { + janus_log_buffer_free(b); + continue; } + /* We have something to log */ + janus_log_print_buffer(b); + /* Done, get rid of this log line */ + janus_log_buffer_free(b); } - janus_log_set_loggers(NULL); if(janus_log_console) fflush(stdout); if(janus_log_file) fflush(janus_log_file); - janus_log_freebuffers(&printhead); - janus_log_freebuffers(&bufferpool); - g_mutex_clear(&lock); - g_cond_clear(&cond); if(janus_log_file) fclose(janus_log_file); @@ -186,91 +113,90 @@ static void *janus_log_thread(void *ctx) { } void janus_vprintf(const char *format, ...) { - int len; - va_list ap, ap2; - janus_log_buffer *b = janus_log_getbuf(); - b->timestamp = janus_get_real_time(); - + if(g_atomic_int_get(&stopping)) + return; + if(janus_log_queue == NULL) + janus_log_queue = g_async_queue_new_full((GDestroyNotify)janus_log_buffer_free); + /* Serialize it to a string */ + va_list ap; va_start(ap, format); - va_copy(ap2, ap); - /* first try */ - len = vsnprintf(b->str, b->allocated, format, ap); + char *str = NULL; + int len = g_vasprintf(&str, format, ap); va_end(ap); - if (len >= (int) b->allocated) { - /* buffer wasn't big enough */ - b = g_realloc(b, len + 1 + sizeof(*b)); - b->allocated = len + 1; - vsnprintf(b->str, b->allocated, format, ap2); - } - va_end(ap2); - - g_mutex_lock(&lock); - if (!printhead) { - printhead = printtail = b; - } else { - printtail->next = b; - printtail = b; - } - g_cond_signal(&cond); - g_mutex_unlock(&lock); + if(len < 0 || str == NULL) + return; + /* Queue the new log buffer */ + janus_log_buffer *b = g_malloc(sizeof(janus_log_buffer)); + b->timestamp = janus_get_real_time(); + b->str = str; + g_async_queue_push(janus_log_queue, b); } -int janus_log_init(gboolean daemon, gboolean console, const char *logfile) { - if (!g_atomic_int_compare_and_exchange(&initialized, 0, 1)) { +int janus_log_init(gboolean daemon, gboolean console, const char *logfile, GHashTable *loggers) { + /* Make sure we only initialize once */ + if(!g_atomic_int_compare_and_exchange(&initialized, 0, 1)) return 0; - } - g_mutex_init(&lock); - g_cond_init(&cond); if(console) { /* Set stdout to block buffering, see BUFSIZ in stdio.h */ setvbuf(stdout, NULL, _IOFBF, 0); } janus_log_console = console; + external_loggers = loggers; if(logfile != NULL) { /* Open a log file for writing (and append) */ janus_log_file = fopen(logfile, "awt"); if(janus_log_file == NULL) { - g_print("Error opening log file %s: %s\n", logfile, g_strerror(errno)); - return -1; + JANUS_PRINT("Error opening log file %s: %s\n", logfile, g_strerror(errno)); + goto error; } janus_log_filepath = g_strdup(logfile); } - if(!janus_log_console && logfile == NULL) { - g_print("WARNING: logging completely disabled!\n"); - g_print(" (no stdout and no logfile, this may not be what you want...)\n"); + if(external_loggers != NULL) + JANUS_PRINT("Adding %d external loggers\n", g_hash_table_size(external_loggers)); + if(!janus_log_console && logfile == NULL && external_loggers == NULL) { + JANUS_PRINT("WARNING: logging completely disabled!\n"); + JANUS_PRINT(" (no stdout, no logfile and no external loggers, this may not be what you want...)\n"); } if(daemon && !console) { /* Replace the standard file descriptors */ - if (freopen("/dev/null", "r", stdin) == NULL) { - g_print("Error replacing stdin with /dev/null\n"); - return -1; + if(freopen("/dev/null", "r", stdin) == NULL) { + JANUS_PRINT("Error replacing stdin with /dev/null\n"); + goto error; } - if (freopen("/dev/null", "w", stdout) == NULL) { - g_print("Error replacing stdout with /dev/null\n"); - return -1; + if(freopen("/dev/null", "w", stdout) == NULL) { + JANUS_PRINT("Error replacing stdout with /dev/null\n"); + goto error; } - if (freopen("/dev/null", "w", stderr) == NULL) { - g_print("Error replacing stderr with /dev/null\n"); - return -1; + if(freopen("/dev/null", "w", stderr) == NULL) { + JANUS_PRINT("Error replacing stderr with /dev/null\n"); + goto error; } } - printthread = g_thread_new(THREAD_NAME, &janus_log_thread, NULL); + if(janus_log_queue == NULL) + janus_log_queue = g_async_queue_new_full((GDestroyNotify)janus_log_buffer_free); + log_thread = g_thread_new(THREAD_NAME, &janus_log_thread, NULL); return 0; -} -void janus_log_set_loggers(GHashTable *loggers) { - g_mutex_lock(&lock); - external_loggers = loggers; - if(external_loggers != NULL) - g_print("Adding %d external loggers\n", g_hash_table_size(external_loggers)); - g_mutex_unlock(&lock); +error: + g_atomic_int_set(&initialized, 0); + janus_log_destroy(); + return -1; } void janus_log_destroy(void) { g_atomic_int_set(&stopping, 1); - g_mutex_lock(&lock); - /* Signal print thread to print any remaining message */ - g_cond_signal(&cond); - g_mutex_unlock(&lock); - g_thread_join(printthread); + if(log_thread != NULL) { + g_async_queue_push(janus_log_queue, &exit_message); + g_thread_join(log_thread); + } else if(!g_atomic_int_get(&initialized)) { + /* Never initialized Print what was in the buffer to stdout */ + janus_log_buffer *b = NULL; + while((b = g_async_queue_try_pop(janus_log_queue)) != NULL) { + if(b->str != NULL) + janus_log_print_buffer(b); + janus_log_buffer_free(b); + } + } + g_async_queue_unref(janus_log_queue); + janus_log_queue = NULL; } diff --git a/src/log.h b/src/log.h index 58b8a7abf19..f5b4eca560f 100644 --- a/src/log.h +++ b/src/log.h @@ -2,11 +2,11 @@ * \author Jay Ridgeway * \copyright GNU General Public License v3 * \brief Buffered logging (headers) - * \details Implementation of a simple buffered logger designed to remove - * I/O wait from threads that may be sensitive to such delays. Buffers are - * saved and reused to reduce allocation calls. The logger output can then - * be printed to stdout and/or a log file. If external loggers are added - * to the core, the logger output is passed to those as well. + * \details Implementation of a simple buffered logger designed to remove + * I/O wait from threads that may be sensitive to such delays. Each time + * there's stuff to be written (to stdout, log files, or external loggers), + * it's added to an async queue, which is consumed from a dedicated thread + * that then actually takes care of I/O. * * \ingroup core * \ref core @@ -30,11 +30,9 @@ void janus_vprintf(const char *format, ...) G_GNUC_PRINTF(1, 2); * @param daemon Whether the Janus is running as a daemon or not * @param console Whether the output should be printed on stdout or not * @param logfile Log file to save the output to, if any +* @param loggers Hash table of external loggers registered in the core, if any * @returns 0 in case of success, a negative integer otherwise */ -int janus_log_init(gboolean daemon, gboolean console, const char *logfile); -/*! \brief Method to add a list of external loggers to the log management - * @param loggers Hash table of external loggers registered in the core */ -void janus_log_set_loggers(GHashTable *loggers); +int janus_log_init(gboolean daemon, gboolean console, const char *logfile, GHashTable *loggers); /*! \brief Log destruction */ void janus_log_destroy(void); diff --git a/src/loggers/janus_jsonlog.c b/src/loggers/janus_jsonlog.c index 94a756755bf..4f054b596f8 100644 --- a/src/loggers/janus_jsonlog.c +++ b/src/loggers/janus_jsonlog.c @@ -347,7 +347,8 @@ static void *janus_jsonlog_thread(void *data) { json_len -= written; offset += written; } - fwrite("\n", sizeof(char), sizeof("\n"), logfile); + const char *lf = "\n"; + fwrite(lf, sizeof(char), strlen(lf), logfile); fflush(logfile); free(json_text); } diff --git a/src/options.c b/src/options.c index 7def7168a65..b29e19bbcc2 100644 --- a/src/options.c +++ b/src/options.c @@ -9,6 +9,7 @@ */ #include "options.h" +#include "debug.h" static GOptionContext *opts = NULL; @@ -66,7 +67,7 @@ gboolean janus_options_parse(janus_options *options, int argc, char *argv[]) { g_option_context_set_help_enabled(opts, TRUE); g_option_context_add_main_entries(opts, opt_entries, NULL); if(!g_option_context_parse(opts, &argc, &argv, &error)) { - g_print("%s\n", error->message); + JANUS_PRINT("%s\n", error->message); g_error_free(error); janus_options_destroy(); return FALSE; diff --git a/src/postprocessing/janus-pp-rec.c b/src/postprocessing/janus-pp-rec.c index 3e2d98fe047..70d408c22cf 100644 --- a/src/postprocessing/janus-pp-rec.c +++ b/src/postprocessing/janus-pp-rec.c @@ -207,7 +207,7 @@ static char *janus_pp_extensions_string(const char **allowed, char *supported, s /* Main Code */ int main(int argc, char *argv[]) { - janus_log_init(FALSE, TRUE, NULL); + janus_log_init(FALSE, TRUE, NULL, NULL); atexit(janus_log_destroy); /* Initialize some command line options defaults */ diff --git a/src/postprocessing/mjr2pcap.c b/src/postprocessing/mjr2pcap.c index 17ccadc39cb..ed1a98026e9 100644 --- a/src/postprocessing/mjr2pcap.c +++ b/src/postprocessing/mjr2pcap.c @@ -150,7 +150,7 @@ static void janus_pp_handle_signal(int signum) { /* Main Code */ int main(int argc, char *argv[]) { - janus_log_init(FALSE, TRUE, NULL); + janus_log_init(FALSE, TRUE, NULL, NULL); atexit(janus_log_destroy); JANUS_LOG(LOG_INFO, "Janus version: %d (%s)\n", janus_version, janus_version_string); diff --git a/src/postprocessing/pcap2mjr.c b/src/postprocessing/pcap2mjr.c index 9338ff4bafb..5ee3c28b2d3 100644 --- a/src/postprocessing/pcap2mjr.c +++ b/src/postprocessing/pcap2mjr.c @@ -103,7 +103,7 @@ static GOptionEntry opt_entries[] = { /* Main Code */ int main(int argc, char *argv[]) { - janus_log_init(FALSE, TRUE, NULL); + janus_log_init(FALSE, TRUE, NULL, NULL); atexit(janus_log_destroy); JANUS_LOG(LOG_INFO, "Janus version: %d (%s)\n", janus_version, janus_version_string);