diff options
Diffstat (limited to 'common/msg.c')
| -rw-r--r-- | common/msg.c | 1069 |
1 files changed, 1069 insertions, 0 deletions
diff --git a/common/msg.c b/common/msg.c new file mode 100644 index 0000000..b14bd5a --- /dev/null +++ b/common/msg.c @@ -0,0 +1,1069 @@ +/* + * This file is part of mpv. + * + * mpv is free software; you can redistribute it and/or + * modify it under the terms of the GNU Lesser General Public + * License as published by the Free Software Foundation; either + * version 2.1 of the License, or (at your option) any later version. + * + * mpv 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 Lesser General Public License for more details. + * + * You should have received a copy of the GNU Lesser General Public + * License along with mpv. If not, see <http://www.gnu.org/licenses/>. + */ + +#include <assert.h> +#include <stdarg.h> +#include <stdatomic.h> +#include <stdint.h> +#include <stdio.h> +#include <stdlib.h> +#include <string.h> +#include <unistd.h> + +#include "mpv_talloc.h" + +#include "misc/bstr.h" +#include "common/common.h" +#include "common/global.h" +#include "misc/bstr.h" +#include "options/options.h" +#include "options/path.h" +#include "osdep/terminal.h" +#include "osdep/io.h" +#include "osdep/threads.h" +#include "osdep/timer.h" + +#include "libmpv/client.h" + +#include "msg.h" +#include "msg_control.h" + +// log buffer size (lines) for terminal level and logfile level +#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; + mp_mutex lock; + mp_mutex log_file_lock; + mp_cond log_file_wakeup; + // --- protected by lock + char **msg_levels; + bool use_terminal; // make accesses to stderr/stdout + bool module; + bool show_time; + int blank_lines; // number of lines usable by status + int status_lines; // number of current status lines + bool color[STDERR_FILENO + 1]; + bool isatty[STDERR_FILENO + 1]; + int verbose; + bool really_quiet; + bool force_stderr; + 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; + bstr term_msg; + bstr term_msg_tmp; + bstr status_line; + struct mp_log *status_log; + bstr term_status_msg; + // --- must be accessed atomically + /* This is incremented every time the msglevels must be reloaded. + * (This is perhaps better than maintaining a globally accessible and + * synchronized mp_log tree.) */ + atomic_ulong reload_counter; + // --- owner thread only (caller of mp_msg_init() etc.) + char *log_path; + char *stats_path; + mp_thread log_file_thread; + // --- owner thread only, but frozen while log_file_thread is running + FILE *log_file; + struct mp_log_buffer *log_file_buffer; + // --- protected by log_file_lock + bool log_file_thread_active; // also termination signal for the thread + int module_indent; +}; + +struct mp_log { + struct mp_log_root *root; + const char *prefix; + const char *verbose_prefix; + int max_level; // minimum log level for this instance + int level; // minimum log level for any outputs + int terminal_level; // minimum log level for terminal output + atomic_ulong reload_counter; + bstr partial[MSGL_MAX + 1]; +}; + +struct mp_log_buffer { + struct mp_log_root *root; + mp_mutex lock; + // --- protected by lock + struct mp_log_buffer_entry **entries; // ringbuffer + int capacity; // total space in entries[] + int entry0; // first (oldest) entry index + int num_entries; // number of valid entries after entry0 + uint64_t dropped; // number of skipped entries + bool silent; + // --- immutable + void (*wakeup_cb)(void *ctx); + void *wakeup_cb_ctx; + int level; +}; + +static const struct mp_log null_log = {0}; +struct mp_log *const mp_null_log = (struct mp_log *)&null_log; + +static bool match_mod(const char *name, const char *mod) +{ + if (!strcmp(mod, "all")) + return true; + // Path prefix matches + bstr b = bstr0(name); + return bstr_eatstart0(&b, mod) && (bstr_eatstart0(&b, "/") || !b.len); +} + +static void update_loglevel(struct mp_log *log) +{ + struct mp_log_root *root = log->root; + mp_mutex_lock(&root->lock); + log->level = MSGL_STATUS + root->verbose; // default log level + if (root->really_quiet) + log->level = -1; + for (int n = 0; root->msg_levels && root->msg_levels[n * 2 + 0]; n++) { + if (match_mod(log->verbose_prefix, root->msg_levels[n * 2 + 0])) + log->level = mp_msg_find_level(root->msg_levels[n * 2 + 1]); + } + log->terminal_level = log->level; + for (int n = 0; n < log->root->num_buffers; n++) { + int buffer_level = log->root->buffers[n]->level; + if (buffer_level == MP_LOG_BUFFER_MSGL_LOGFILE) + buffer_level = MSGL_DEBUG; + if (buffer_level != MP_LOG_BUFFER_MSGL_TERM) + log->level = MPMAX(log->level, buffer_level); + } + if (log->root->log_file) + log->level = MPMAX(log->level, MSGL_DEBUG); + if (log->root->stats_file) + log->level = MPMAX(log->level, MSGL_STATS); + log->level = MPMIN(log->level, log->max_level); + atomic_store(&log->reload_counter, atomic_load(&log->root->reload_counter)); + mp_mutex_unlock(&root->lock); +} + +// Set (numerically) the maximum level that should still be output for this log +// instances. E.g. lev=MSGL_WARN => show only warnings and errors. +void mp_msg_set_max_level(struct mp_log *log, int lev) +{ + if (!log->root) + return; + mp_mutex_lock(&log->root->lock); + log->max_level = MPCLAMP(lev, -1, MSGL_MAX); + mp_mutex_unlock(&log->root->lock); + update_loglevel(log); +} + +// Get the current effective msg level. +// Thread-safety: see mp_msg(). +int mp_msg_level(struct mp_log *log) +{ + struct mp_log_root *root = log->root; + if (!root) + return -1; + if (atomic_load_explicit(&log->reload_counter, memory_order_relaxed) != + atomic_load_explicit(&root->reload_counter, memory_order_relaxed)) + { + update_loglevel(log); + } + return log->level; +} + +static inline int term_msg_fileno(struct mp_log_root *root, int lev) +{ + return (root->force_stderr || lev == MSGL_STATUS || lev == MSGL_FATAL || + lev == MSGL_ERR || lev == MSGL_WARN) ? STDERR_FILENO : STDOUT_FILENO; +} + +// Reposition cursor and clear lines for outputting the status line. In certain +// cases, like term OSD and subtitle display, the status can consist of +// multiple lines. +static void prepare_prefix(struct mp_log_root *root, bstr *out, int lev, int term_lines) +{ + int new_lines = lev == MSGL_STATUS ? term_lines : 0; + out->len = 0; + + if (!root->isatty[term_msg_fileno(root, lev)]) { + if (root->status_lines) + bstr_xappend(root, out, bstr0("\n")); + root->status_lines = new_lines; + return; + } + + // Set cursor state + if (new_lines && !root->status_lines) { + bstr_xappend(root, out, bstr0("\033[?25l")); + } else if (!new_lines && root->status_lines) { + bstr_xappend(root, out, bstr0("\033[?25h")); + } + + int line_skip = 0; + if (root->status_lines) { + // Clear previous status line + bstr_xappend(root, out, bstr0("\033[1K\r")); + bstr up_clear = bstr0("\033[A\033[K"); + for (int i = 1; i < root->status_lines; ++i) + bstr_xappend(root, out, up_clear); + // Reposition cursor after last message + line_skip = (new_lines ? new_lines : root->blank_lines) - root->status_lines; + line_skip = MPMIN(root->blank_lines - root->status_lines, line_skip); + if (line_skip) + bstr_xappend_asprintf(root, out, "\033[%dA", line_skip); + } else if (new_lines) { + line_skip = new_lines - root->blank_lines; + } + + if (line_skip < 0) { + // Reposition cursor to keep status line at the same line + line_skip = MPMIN(root->blank_lines, -line_skip); + if (line_skip) + bstr_xappend_asprintf(root, out, "\033[%dB", line_skip); + } + + root->blank_lines = MPMAX(0, root->blank_lines - term_lines); + root->status_lines = new_lines; + root->blank_lines += root->status_lines; +} + +void mp_msg_flush_status_line(struct mp_log *log) +{ + if (log->root) { + mp_mutex_lock(&log->root->lock); + if (log->root->status_lines) { + bstr term_msg = (bstr){0}; + prepare_prefix(log->root, &term_msg, MSGL_STATUS, 0); + if (term_msg.len) { + fprintf(stderr, "%.*s", BSTR_P(term_msg)); + talloc_free(term_msg.start); + } + } + mp_mutex_unlock(&log->root->lock); + } +} + +void mp_msg_set_term_title(struct mp_log *log, const char *title) +{ + if (log->root && title) { + // Lock because printf to terminal is not necessarily atomic. + mp_mutex_lock(&log->root->lock); + fprintf(stderr, "\e]0;%s\007", title); + mp_mutex_unlock(&log->root->lock); + } +} + +bool mp_msg_has_status_line(struct mpv_global *global) +{ + struct mp_log_root *root = global->log->root; + mp_mutex_lock(&root->lock); + bool r = root->status_lines > 0; + mp_mutex_unlock(&root->lock); + return r; +} + +static void set_term_color(void *talloc_ctx, bstr *text, int c) +{ + return c == -1 ? bstr_xappend(talloc_ctx, text, bstr0("\033[0m")) + : bstr_xappend_asprintf(talloc_ctx, text, + "\033[%d;3%dm", c >> 3, c & 7); +} + +static void set_msg_color(void *talloc_ctx, bstr *text, int lev) +{ + static const int v_colors[] = {9, 1, 3, -1, -1, 2, 8, 8, 8, -1}; + return set_term_color(talloc_ctx, text, v_colors[lev]); +} + +static void pretty_print_module(struct mp_log_root *root, bstr *text, + const char *prefix, int lev) +{ + size_t prefix_len = strlen(prefix); + root->module_indent = MPMAX(10, MPMAX(root->module_indent, prefix_len)); + bool color = root->color[term_msg_fileno(root, lev)]; + + // Use random color based on the name of the module + if (color) { + unsigned int mod = 0; + for (int i = 0; i < prefix_len; ++i) + mod = mod * 33 + prefix[i]; + set_term_color(root, text, (mod + 1) % 15 + 1); + } + + bstr_xappend_asprintf(root, text, "%*s", root->module_indent, prefix); + if (color) + set_term_color(root, text, -1); + bstr_xappend(root, text, bstr0(": ")); + if (color) + set_msg_color(root, text, lev); +} + +static bool test_terminal_level(struct mp_log *log, int lev) +{ + return lev <= log->terminal_level && log->root->use_terminal && + !(lev == MSGL_STATUS && terminal_in_background()); +} + +// This is very basic way to infer needed width for a string. +static int term_disp_width(bstr str, size_t start, size_t end) +{ + int width = 0; + bool escape = false; + + const char *line = str.start; + for (size_t i = start; i < end && i < str.len; ++i) { + if (escape) { + escape = !(line[i] >= '@' && line[i] <= '~'); + continue; + } + + if (line[i] == '\033' && line[i + 1] == '[') { + escape = true; + ++i; + continue; + } + + if (line[i] == '\n') + continue; + + width++; + + // Assume that everything before \r should be discarded for simplicity + if (line[i] == '\r') + width = 0; + } + + return width; +} + +static void append_terminal_line(struct mp_log *log, int lev, + bstr text, bstr *term_msg, int *line_w) +{ + struct mp_log_root *root = log->root; + + size_t start = term_msg->len; + + if (root->show_time) + bstr_xappend_asprintf(root, term_msg, "[%10.6f] ", mp_time_sec()); + + const char *log_prefix = (lev >= MSGL_V) || root->verbose || root->module + ? log->verbose_prefix : log->prefix; + if (log_prefix) { + if (root->module) { + pretty_print_module(root, term_msg, log_prefix, lev); + } else { + bstr_xappend_asprintf(root, term_msg, "[%s] ", log_prefix); + } + } + + bstr_xappend(root, term_msg, text); + *line_w = root->isatty[term_msg_fileno(root, lev)] + ? term_disp_width(*term_msg, start, term_msg->len) : 0; +} + +static struct mp_log_buffer_entry *log_buffer_read(struct mp_log_buffer *buffer) +{ + assert(buffer->num_entries); + struct mp_log_buffer_entry *res = buffer->entries[buffer->entry0]; + buffer->entry0 = (buffer->entry0 + 1) % buffer->capacity; + buffer->num_entries -= 1; + return res; +} + +static void write_msg_to_buffers(struct mp_log *log, int lev, bstr text) +{ + struct mp_log_root *root = log->root; + for (int n = 0; n < root->num_buffers; n++) { + struct mp_log_buffer *buffer = root->buffers[n]; + bool wakeup = false; + mp_mutex_lock(&buffer->lock); + int buffer_level = buffer->level; + if (buffer_level == MP_LOG_BUFFER_MSGL_TERM) + buffer_level = log->terminal_level; + if (buffer_level == MP_LOG_BUFFER_MSGL_LOGFILE) + 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, + // 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 + // buffer can't go away because the global log lock is held. + mp_mutex_unlock(&buffer->lock); + mp_mutex_lock(&root->log_file_lock); + if (root->log_file_thread_active) { + mp_cond_wait(&root->log_file_wakeup, + &root->log_file_lock); + } else { + dead = true; + } + mp_mutex_unlock(&root->log_file_lock); + mp_mutex_lock(&buffer->lock); + } + } + if (buffer->num_entries == buffer->capacity) { + struct mp_log_buffer_entry *skip = log_buffer_read(buffer); + talloc_free(skip); + buffer->dropped += 1; + } + struct mp_log_buffer_entry *entry = talloc_ptrtype(NULL, entry); + *entry = (struct mp_log_buffer_entry) { + .prefix = talloc_strdup(entry, log->verbose_prefix), + .level = lev, + .text = bstrdup0(entry, text), + }; + int pos = (buffer->entry0 + buffer->num_entries) % buffer->capacity; + buffer->entries[pos] = entry; + buffer->num_entries += 1; + if (buffer->wakeup_cb && !buffer->silent) + wakeup = true; + } + mp_mutex_unlock(&buffer->lock); + if (wakeup) + buffer->wakeup_cb(buffer->wakeup_cb_ctx); + } +} + +static void dump_stats(struct mp_log *log, int lev, bstr text) +{ + struct mp_log_root *root = log->root; + if (lev == MSGL_STATS && root->stats_file) + fprintf(root->stats_file, "%"PRId64" %.*s\n", mp_time_ns(), BSTR_P(text)); +} + +static void write_term_msg(struct mp_log *log, int lev, bstr text, bstr *out) +{ + struct mp_log_root *root = log->root; + bool print_term = test_terminal_level(log, lev); + int fileno = term_msg_fileno(root, lev); + int term_w = 0, term_h = 0; + if (print_term && root->isatty[fileno]) + terminal_get_size(&term_w, &term_h); + + out->len = 0; + + // Split away each line. Normally we require full lines; buffer partial + // lines if they happen. + root->term_msg_tmp.len = 0; + int term_msg_lines = 0; + + bstr str = text; + while (str.len) { + bstr line = bstr_getline(str, &str); + if (line.start[line.len - 1] != '\n') { + assert(str.len == 0); + str = line; + break; + } + + if (print_term) { + int line_w; + append_terminal_line(log, lev, line, &root->term_msg_tmp, &line_w); + term_msg_lines += (!line_w || !term_w) + ? 1 : (line_w + term_w - 1) / term_w; + } + write_msg_to_buffers(log, lev, line); + } + + if (lev == MSGL_STATUS && print_term) { + int line_w = 0; + if (str.len) + append_terminal_line(log, lev, str, &root->term_msg_tmp, &line_w); + term_msg_lines += !term_w ? (str.len ? 1 : 0) + : (line_w + term_w - 1) / term_w; + } else if (str.len) { + bstr_xappend(NULL, &log->partial[lev], str); + } + + if (print_term && (root->term_msg_tmp.len || lev == MSGL_STATUS)) { + prepare_prefix(root, out, lev, term_msg_lines); + if (root->color[fileno] && root->term_msg_tmp.len) { + set_msg_color(root, out, lev); + set_term_color(root, &root->term_msg_tmp, -1); + } + bstr_xappend(root, out, root->term_msg_tmp); + } +} + +void mp_msg_va(struct mp_log *log, int lev, const char *format, va_list va) +{ + if (!mp_msg_test(log, lev)) + return; // do not display + + struct mp_log_root *root = log->root; + + mp_mutex_lock(&root->lock); + + root->buffer.len = 0; + + if (log->partial[lev].len) + bstr_xappend(root, &root->buffer, log->partial[lev]); + log->partial[lev].len = 0; + + bstr_xappend_vasprintf(root, &root->buffer, format, va); + + // Remember last status message and restore it to ensure that it is + // always displayed + if (lev == MSGL_STATUS) { + root->status_log = log; + root->status_line.len = 0; + // Use bstr_xappend instead bstrdup to reuse allocated memory + if (root->buffer.len) + bstr_xappend(root, &root->status_line, root->buffer); + } + + if (lev == MSGL_STATS) { + dump_stats(log, lev, root->buffer); + } else if (lev == MSGL_STATUS && !test_terminal_level(log, lev)) { + /* discard */ + } else { + write_term_msg(log, lev, root->buffer, &root->term_msg); + + root->term_status_msg.len = 0; + if (lev != MSGL_STATUS && root->status_line.len && root->status_log && + test_terminal_level(root->status_log, MSGL_STATUS)) + { + write_term_msg(root->status_log, MSGL_STATUS, root->status_line, + &root->term_status_msg); + } + + int fileno = term_msg_fileno(root, lev); + FILE *stream = fileno == STDERR_FILENO ? stderr : stdout; + if (root->term_msg.len) { + if (root->term_status_msg.len) { + fprintf(stream, "%.*s%.*s", BSTR_P(root->term_msg), + BSTR_P(root->term_status_msg)); + } else { + fprintf(stream, "%.*s", BSTR_P(root->term_msg)); + } + fflush(stream); + } + } + + mp_mutex_unlock(&root->lock); +} + +static void destroy_log(void *ptr) +{ + struct mp_log *log = ptr; + // This is not managed via talloc itself, because mp_msg calls must be + // thread-safe, while talloc is not thread-safe. + for (int lvl = 0; lvl <= MSGL_MAX; ++lvl) + talloc_free(log->partial[lvl].start); +} + +// Create a new log context, which uses talloc_ctx as talloc parent, and parent +// as logical parent. +// The name is the prefix put before the output. It's usually prefixed by the +// parent's name. If the name starts with "/", the parent's name is not +// prefixed (except in verbose mode), and if it starts with "!", the name is +// not printed at all (except in verbose mode). +// If name is NULL, the parent's name/prefix is used. +// Thread-safety: fully thread-safe, but keep in mind that talloc is not (so +// talloc_ctx must be owned by the current thread). +struct mp_log *mp_log_new(void *talloc_ctx, struct mp_log *parent, + const char *name) +{ + assert(parent); + struct mp_log *log = talloc_zero(talloc_ctx, struct mp_log); + if (!parent->root) + return log; // same as null_log + talloc_set_destructor(log, destroy_log); + log->root = parent->root; + log->max_level = MSGL_MAX; + if (name) { + if (name[0] == '!') { + name = &name[1]; + } else if (name[0] == '/') { + name = &name[1]; + log->prefix = talloc_strdup(log, name); + } else { + log->prefix = parent->prefix + ? talloc_asprintf(log, "%s/%s", parent->prefix, name) + : talloc_strdup(log, name); + } + log->verbose_prefix = parent->prefix + ? talloc_asprintf(log, "%s/%s", parent->prefix, name) + : talloc_strdup(log, name); + if (log->prefix && !log->prefix[0]) + log->prefix = NULL; + if (!log->verbose_prefix[0]) + log->verbose_prefix = "global"; + } else { + log->prefix = talloc_strdup(log, parent->prefix); + log->verbose_prefix = talloc_strdup(log, parent->verbose_prefix); + } + return log; +} + +void mp_msg_init(struct mpv_global *global) +{ + assert(!global->log); + + struct mp_log_root *root = talloc_zero(NULL, struct mp_log_root); + *root = (struct mp_log_root){ + .global = global, + .reload_counter = 1, + }; + + mp_mutex_init(&root->lock); + mp_mutex_init(&root->log_file_lock); + mp_cond_init(&root->log_file_wakeup); + + struct mp_log dummy = { .root = root }; + struct mp_log *log = mp_log_new(root, &dummy, ""); + + global->log = log; +} + +static MP_THREAD_VOID log_file_thread(void *p) +{ + struct mp_log_root *root = p; + + mp_thread_set_name("log"); + + mp_mutex_lock(&root->log_file_lock); + + while (root->log_file_thread_active) { + struct mp_log_buffer_entry *e = + mp_msg_log_buffer_read(root->log_file_buffer); + if (e) { + mp_mutex_unlock(&root->log_file_lock); + fprintf(root->log_file, "[%8.3f][%c][%s] %s", + mp_time_sec(), + mp_log_levels[e->level][0], e->prefix, e->text); + fflush(root->log_file); + mp_mutex_lock(&root->log_file_lock); + talloc_free(e); + // Multiple threads might be blocked if the log buffer was full. + mp_cond_broadcast(&root->log_file_wakeup); + } else { + mp_cond_wait(&root->log_file_wakeup, &root->log_file_lock); + } + } + + mp_mutex_unlock(&root->log_file_lock); + + MP_THREAD_RETURN(); +} + +static void wakeup_log_file(void *p) +{ + struct mp_log_root *root = p; + + mp_mutex_lock(&root->log_file_lock); + mp_cond_broadcast(&root->log_file_wakeup); + mp_mutex_unlock(&root->log_file_lock); +} + +// Only to be called from the main thread. +static void terminate_log_file_thread(struct mp_log_root *root) +{ + bool wait_terminate = false; + + mp_mutex_lock(&root->log_file_lock); + if (root->log_file_thread_active) { + root->log_file_thread_active = false; + mp_cond_broadcast(&root->log_file_wakeup); + wait_terminate = true; + } + mp_mutex_unlock(&root->log_file_lock); + + if (wait_terminate) + mp_thread_join(root->log_file_thread); + + mp_msg_log_buffer_destroy(root->log_file_buffer); + root->log_file_buffer = NULL; + + if (root->log_file) + fclose(root->log_file); + root->log_file = NULL; +} + +// If opt is different from *current_path, update *current_path and return true. +// No lock must be held; passed values must be accessible without. +static bool check_new_path(struct mpv_global *global, char *opt, + char **current_path) +{ + void *tmp = talloc_new(NULL); + bool res = false; + + char *new_path = mp_get_user_path(tmp, global, opt); + if (!new_path) + new_path = ""; + + char *old_path = *current_path ? *current_path : ""; + if (strcmp(old_path, new_path) != 0) { + talloc_free(*current_path); + *current_path = NULL; + if (new_path[0]) + *current_path = talloc_strdup(NULL, new_path); + res = true; + } + + talloc_free(tmp); + + return res; +} + +void mp_msg_update_msglevels(struct mpv_global *global, struct MPOpts *opts) +{ + struct mp_log_root *root = global->log->root; + + mp_mutex_lock(&root->lock); + + root->verbose = opts->verbose; + root->really_quiet = opts->msg_really_quiet; + root->module = opts->msg_module; + root->use_terminal = opts->use_terminal; + root->show_time = opts->msg_time; + for (int i = STDOUT_FILENO; i <= STDERR_FILENO && root->use_terminal; ++i) { + root->isatty[i] = isatty(i); + root->color[i] = opts->msg_color && root->isatty[i]; + } + + m_option_type_msglevels.free(&root->msg_levels); + m_option_type_msglevels.copy(NULL, &root->msg_levels, &opts->msg_levels); + + atomic_fetch_add(&root->reload_counter, 1); + mp_mutex_unlock(&root->lock); + + if (check_new_path(global, opts->log_file, &root->log_path)) { + terminate_log_file_thread(root); + 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 + mp_mutex_lock(&root->lock); + struct mp_log_buffer *earlybuf = root->early_filebuffer; + if (earlybuf) + root->early_filebuffer = NULL; // but it still logs msgs + mp_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); + root->log_file_thread_active = true; + if (mp_thread_create(&root->log_file_thread, log_file_thread, + root)) + { + root->log_file_thread_active = false; + terminate_log_file_thread(root); + } + } else { + mp_err(global->log, "Failed to open log file '%s'\n", + root->log_path); + } + } + } + + if (check_new_path(global, opts->dump_stats, &root->stats_path)) { + bool open_error = false; + + mp_mutex_lock(&root->lock); + if (root->stats_file) + fclose(root->stats_file); + root->stats_file = NULL; + if (root->stats_path) { + root->stats_file = fopen(root->stats_path, "wb"); + open_error = !root->stats_file; + } + mp_mutex_unlock(&root->lock); + + if (open_error) { + mp_err(global->log, "Failed to open stats file '%s'\n", + root->stats_path); + } + } +} + +void mp_msg_force_stderr(struct mpv_global *global, bool force_stderr) +{ + struct mp_log_root *root = global->log->root; + + mp_mutex_lock(&root->lock); + root->force_stderr = force_stderr; + mp_mutex_unlock(&root->lock); +} + +// Only to be called from the main thread. +bool mp_msg_has_log_file(struct mpv_global *global) +{ + struct mp_log_root *root = global->log->root; + + return !!root->log_file; +} + +void mp_msg_uninit(struct mpv_global *global) +{ + struct mp_log_root *root = global->log->root; + mp_msg_flush_status_line(global->log); + 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); + talloc_free(root->stats_path); + talloc_free(root->log_path); + m_option_type_msglevels.free(&root->msg_levels); + mp_mutex_destroy(&root->lock); + mp_mutex_destroy(&root->log_file_lock); + mp_cond_destroy(&root->log_file_wakeup); + talloc_free(root); + global->log = NULL; +} + +// 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; + mp_mutex_lock(&root->lock); + + if (enable != !!*root_logbuf) { + if (enable) { + mp_mutex_unlock(&root->lock); + struct mp_log_buffer *buf = + mp_msg_log_buffer_new(global, size, level, NULL, NULL); + mp_mutex_lock(&root->lock); + assert(!*root_logbuf); // no concurrent calls to this function + *root_logbuf = buf; + } else { + struct mp_log_buffer *buf = *root_logbuf; + *root_logbuf = NULL; + mp_mutex_unlock(&root->lock); + mp_msg_log_buffer_destroy(buf); + return; + } + } + + mp_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), + void *wakeup_cb_ctx) +{ + struct mp_log_root *root = global->log->root; + + mp_mutex_lock(&root->lock); + + if (level == MP_LOG_BUFFER_MSGL_TERM) { + size = TERM_BUF; + + // The first thing which creates a terminal-level log buffer gets the + // early log buffer, if it exists. This is supposed to enable a script + // to grab log messages from before it was initialized. It's OK that + // this works only for 1 script and only once. + if (root->early_buffer) { + struct mp_log_buffer *buffer = root->early_buffer; + root->early_buffer = NULL; + buffer->wakeup_cb = wakeup_cb; + buffer->wakeup_cb_ctx = wakeup_cb_ctx; + mp_mutex_unlock(&root->lock); + return buffer; + } + } + + assert(size > 0); + + struct mp_log_buffer *buffer = talloc_ptrtype(NULL, buffer); + *buffer = (struct mp_log_buffer) { + .root = root, + .level = level, + .entries = talloc_array(buffer, struct mp_log_buffer_entry *, size), + .capacity = size, + .wakeup_cb = wakeup_cb, + .wakeup_cb_ctx = wakeup_cb_ctx, + }; + + mp_mutex_init(&buffer->lock); + + MP_TARRAY_APPEND(root, root->buffers, root->num_buffers, buffer); + + atomic_fetch_add(&root->reload_counter, 1); + mp_mutex_unlock(&root->lock); + + return buffer; +} + +void mp_msg_log_buffer_set_silent(struct mp_log_buffer *buffer, bool silent) +{ + mp_mutex_lock(&buffer->lock); + buffer->silent = silent; + mp_mutex_unlock(&buffer->lock); +} + +void mp_msg_log_buffer_destroy(struct mp_log_buffer *buffer) +{ + if (!buffer) + return; + + struct mp_log_root *root = buffer->root; + + mp_mutex_lock(&root->lock); + + for (int n = 0; n < root->num_buffers; n++) { + if (root->buffers[n] == buffer) { + MP_TARRAY_REMOVE_AT(root->buffers, root->num_buffers, n); + goto found; + } + } + + MP_ASSERT_UNREACHABLE(); + +found: + + while (buffer->num_entries) + talloc_free(log_buffer_read(buffer)); + + mp_mutex_destroy(&buffer->lock); + talloc_free(buffer); + + atomic_fetch_add(&root->reload_counter, 1); + mp_mutex_unlock(&root->lock); +} + +// Return a queued message, or if the buffer is empty, NULL. +// Thread-safety: one buffer can be read by a single thread only. +struct mp_log_buffer_entry *mp_msg_log_buffer_read(struct mp_log_buffer *buffer) +{ + struct mp_log_buffer_entry *res = NULL; + + mp_mutex_lock(&buffer->lock); + + if (!buffer->silent && buffer->num_entries) { + if (buffer->dropped) { + res = talloc_ptrtype(NULL, res); + *res = (struct mp_log_buffer_entry) { + .prefix = "overflow", + .level = MSGL_FATAL, + .text = talloc_asprintf(res, + "log message buffer overflow: %"PRId64" messages skipped\n", + buffer->dropped), + }; + buffer->dropped = 0; + } else { + res = log_buffer_read(buffer); + } + } + + mp_mutex_unlock(&buffer->lock); + + return res; +} + +// Thread-safety: fully thread-safe, but keep in mind that the lifetime of +// log must be guaranteed during the call. +// Never call this from signal handlers. +void mp_msg(struct mp_log *log, int lev, const char *format, ...) +{ + va_list va; + va_start(va, format); + mp_msg_va(log, lev, format, va); + va_end(va); +} + +const char *const mp_log_levels[MSGL_MAX + 1] = { + [MSGL_FATAL] = "fatal", + [MSGL_ERR] = "error", + [MSGL_WARN] = "warn", + [MSGL_INFO] = "info", + [MSGL_STATUS] = "status", + [MSGL_V] = "v", + [MSGL_DEBUG] = "debug", + [MSGL_TRACE] = "trace", + [MSGL_STATS] = "stats", +}; + +const int mp_mpv_log_levels[MSGL_MAX + 1] = { + [MSGL_FATAL] = MPV_LOG_LEVEL_FATAL, + [MSGL_ERR] = MPV_LOG_LEVEL_ERROR, + [MSGL_WARN] = MPV_LOG_LEVEL_WARN, + [MSGL_INFO] = MPV_LOG_LEVEL_INFO, + [MSGL_STATUS] = 0, // never used + [MSGL_V] = MPV_LOG_LEVEL_V, + [MSGL_DEBUG] = MPV_LOG_LEVEL_DEBUG, + [MSGL_TRACE] = MPV_LOG_LEVEL_TRACE, + [MSGL_STATS] = 0, // never used +}; + +int mp_msg_find_level(const char *s) +{ + for (int n = 0; n < MP_ARRAY_SIZE(mp_log_levels); n++) { + if (mp_log_levels[n] && !strcasecmp(s, mp_log_levels[n])) + return n; + } + return -1; +} |