From 8eb7a00fa1f091e1766997f3d972d6c5fe9ac018 Mon Sep 17 00:00:00 2001 From: "Avi Halachmi (:avih)" Date: Thu, 15 Dec 2022 18:09:03 +0200 Subject: [PATCH] msg: log-file set at mpv.conf: don't ignore early messages Previously, if log-file was set not via a CLI option (e.g. set via mpv.conf or other config file, or set from a script init phase), then meaningful early log messages were thrown away because the log file name was unknown initially. Such early log messages include the command line arguments, any options set from mpv.conf, and possibly more. Now we store up to 5000 early messages before the log file name is known, and flush them once/if it becomes known, or destroy this buffer once mpv init is complete. The implementation is similar and adjacent, but not identical, to an existing early log system for mpv clients which request a log buffer. --- common/msg.c | 83 +++++++++++++++++++++++++++++++++++++++++++++------ player/main.c | 8 +++-- 2 files changed, 80 insertions(+), 11 deletions(-) diff --git a/common/msg.c b/common/msg.c index 256456e3a6..8e5ad26a11 100644 --- a/common/msg.c +++ b/common/msg.c @@ -47,6 +47,12 @@ #define TERM_BUF 100 #define FILE_BUF 100 +// logfile lines to accumulate during init before we know the log file name. +// thousands of logfile lines during init can happen (especially with many +// scripts, big config, etc), so we set 5000. If it cycles and messages are +// overwritten, then the first (virtual) log line indicates how many were lost. +#define EARLY_FILE_BUF 5000 + struct mp_log_root { struct mpv_global *global; pthread_mutex_t lock; @@ -66,6 +72,7 @@ struct mp_log_root { struct mp_log_buffer **buffers; int num_buffers; struct mp_log_buffer *early_buffer; + struct mp_log_buffer *early_filebuffer; FILE *stats_file; bstr buffer; // --- must be accessed atomically @@ -352,7 +359,8 @@ static void write_msg_to_buffers(struct mp_log *log, int lev, char *text) buffer_level = MPMAX(log->terminal_level, MSGL_DEBUG); if (lev <= buffer_level && lev != MSGL_STATUS) { if (buffer->level == MP_LOG_BUFFER_MSGL_LOGFILE) { - // If the buffer is full, block until we can write again. + // If the buffer is full, block until we can write again, + // unless there's no write thread (died, or early filebuffer) bool dead = false; while (buffer->num_entries == buffer->capacity && !dead) { // Temporary unlock is OK; buffer->level is immutable, and @@ -643,6 +651,31 @@ void mp_msg_update_msglevels(struct mpv_global *global, struct MPOpts *opts) if (root->log_path) { root->log_file = fopen(root->log_path, "wb"); if (root->log_file) { + + // if a logfile is created and the early filebuf still exists, + // flush and destroy the early buffer + pthread_mutex_lock(&root->lock); + struct mp_log_buffer *earlybuf = root->early_filebuffer; + if (earlybuf) + root->early_filebuffer = NULL; // but it still logs msgs + pthread_mutex_unlock(&root->lock); + + if (earlybuf) { + // flush, destroy before creating the normal logfile buf, + // as once the new one is created (specifically, its write + // thread), then MSGL_LOGFILE messages become blocking, but + // the early logfile buf is without dequeue - can deadlock. + // note: timestamp is unknown, we use 0.000 as indication. + // note: new messages while iterating are still flushed. + struct mp_log_buffer_entry *e; + while ((e = mp_msg_log_buffer_read(earlybuf))) { + fprintf(root->log_file, "[%8.3f][%c][%s] %s", 0.0, + mp_log_levels[e->level][0], e->prefix, e->text); + talloc_free(e); + } + mp_msg_log_buffer_destroy(earlybuf); // + remove from root + } + root->log_file_buffer = mp_msg_log_buffer_new(global, FILE_BUF, MP_LOG_BUFFER_MSGL_LOGFILE, wakeup_log_file, root); @@ -702,6 +735,7 @@ void mp_msg_uninit(struct mpv_global *global) struct mp_log_root *root = global->log->root; terminate_log_file_thread(root); mp_msg_log_buffer_destroy(root->early_buffer); + mp_msg_log_buffer_destroy(root->early_filebuffer); assert(root->num_buffers == 0); if (root->stats_file) fclose(root->stats_file); @@ -715,23 +749,42 @@ void mp_msg_uninit(struct mpv_global *global) global->log = NULL; } -void mp_msg_set_early_logging(struct mpv_global *global, bool enable) +// early logging store log messages before they have a known destination. +// there are two early log buffers which are similar logically, and both cease +// function (if still exist, independently) once the log destination is known, +// or mpv init is complete (typically, after all clients/scripts init is done). +// +// - "normal" early_buffer, holds early terminal-level logs, and is handed over +// to the first client which requests such log buffer, so that it sees older +// messages too. further clients which request a log buffer get a new one +// which accumulates messages starting at this point in time. +// +// - early_filebuffer - early log-file messages until a log file name is known. +// main cases where meaningful messages are accumulated before the filename +// is known are when log-file is set at mpv.conf, or from script/client init. +// once a file name is known, the early buffer is flushed and destroyed. +// unlike the "proper" log-file buffer, the early filebuffer is not backed by +// a write thread, and hence non-blocking (can overwrite old messages). +// it's also bigger than the actual file buffer (early: 5000, actual: 100). + +static void mp_msg_set_early_logging_raw(struct mpv_global *global, bool enable, + struct mp_log_buffer **root_logbuf, + int size, int level) { struct mp_log_root *root = global->log->root; pthread_mutex_lock(&root->lock); - if (enable != !!root->early_buffer) { + if (enable != !!*root_logbuf) { if (enable) { pthread_mutex_unlock(&root->lock); struct mp_log_buffer *buf = - mp_msg_log_buffer_new(global, TERM_BUF, MP_LOG_BUFFER_MSGL_TERM, - NULL, NULL); + mp_msg_log_buffer_new(global, size, level, NULL, NULL); pthread_mutex_lock(&root->lock); - assert(!root->early_buffer); // no concurrent calls to this function - root->early_buffer = buf; + assert(!*root_logbuf); // no concurrent calls to this function + *root_logbuf = buf; } else { - struct mp_log_buffer *buf = root->early_buffer; - root->early_buffer = NULL; + struct mp_log_buffer *buf = *root_logbuf; + *root_logbuf = NULL; pthread_mutex_unlock(&root->lock); mp_msg_log_buffer_destroy(buf); return; @@ -741,6 +794,18 @@ void mp_msg_set_early_logging(struct mpv_global *global, bool enable) pthread_mutex_unlock(&root->lock); } +void mp_msg_set_early_logging(struct mpv_global *global, bool enable) +{ + struct mp_log_root *root = global->log->root; + + mp_msg_set_early_logging_raw(global, enable, &root->early_buffer, + TERM_BUF, MP_LOG_BUFFER_MSGL_TERM); + + // normally MSGL_LOGFILE buffer gets a write thread, but not the early buf + mp_msg_set_early_logging_raw(global, enable, &root->early_filebuffer, + EARLY_FILE_BUF, MP_LOG_BUFFER_MSGL_LOGFILE); +} + struct mp_log_buffer *mp_msg_log_buffer_new(struct mpv_global *global, int size, int level, void (*wakeup_cb)(void *ctx), diff --git a/player/main.c b/player/main.c index 2f4bede898..1dde63e31f 100644 --- a/player/main.c +++ b/player/main.c @@ -137,8 +137,12 @@ void mp_update_logging(struct MPContext *mpctx, bool preinit) } } - if (mp_msg_has_log_file(mpctx->global) && !had_log_file) - mp_print_version(mpctx->log, false); // for log-file=... in config files + if (mp_msg_has_log_file(mpctx->global) && !had_log_file) { + // for log-file=... in config files. + // we did flush earlier messages, but they were in a cyclic buffer, so + // the version might have been overwritten. ensure we have it. + mp_print_version(mpctx->log, false); + } if (enabled && !preinit && mpctx->opts->consolecontrols) terminal_setup_getch(mpctx->input);