/src/mpv/common/msg.c

Source (jump to first uncovered line)
/*
 * 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 "mpv_talloc.h"

#include "common/common.h"
#include "common/global.h"
#include "misc/codepoint_width.h"
#include "options/options.h"
#include "options/path.h"
#include "osdep/io.h"
#include "osdep/terminal.h"
#include "osdep/threads.h"
#include "osdep/timer.h"

#include "mpv/client.h"

#include "msg.h"
#include "msg_control.h"

// log buffer size (lines) logfile level
#define FILE_BUF 100

// lines to accumulate before any client requests the terminal loglevel
#define EARLY_TERM_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 ? STDERR_FILENO : STDOUT_FILENO;
}

static inline FILE *term_msg_fp(struct mp_log_root *root, int lev)
{
    return term_msg_fileno(root, lev) == STDERR_FILENO ? stderr : stdout;
}

static inline bool is_status_output(struct mp_log_root *root, int lev)
{
    if (lev == MSGL_STATUS)
        return true;
    int msg_out = term_msg_fileno(root, lev);
    int status_out = term_msg_fileno(root, MSGL_STATUS);
    if (msg_out != status_out && root->isatty[msg_out] != root->isatty[status_out])
        return false;
    return true;
}

// 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 (!is_status_output(root, lev))
        return;

    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(TERM_ESC_HIDE_CURSOR));
    } else if (!new_lines && root->status_lines) {
        bstr_xappend(root, out, bstr0(TERM_ESC_RESTORE_CURSOR));
    }

    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);
        mp_assert(root->status_lines > 0 && root->blank_lines >= root->status_lines);
        line_skip = root->blank_lines - root->status_lines;
    }

    if (new_lines)
        line_skip -= MPMAX(0, root->blank_lines - new_lines);

    if (line_skip)
        bstr_xappend_asprintf(root, out, line_skip > 0 ? "\033[%dA" : "\033[%dB", abs(line_skip));

    root->blank_lines = MPMAX(0, root->blank_lines - term_lines);
    root->status_lines = new_lines;
    root->blank_lines += root->status_lines;
}

static void msg_flush_status_line(struct mp_log_root *root, bool clear)
{
    if (!root->status_lines)
        goto done;

    FILE *fp = term_msg_fp(root, MSGL_STATUS);
    if (!clear) {
        if (root->isatty[term_msg_fileno(root, MSGL_STATUS)])
            fprintf(fp, TERM_ESC_RESTORE_CURSOR);
        fprintf(fp, "\n");
        root->blank_lines = 0;
        root->status_lines = 0;
        goto done;
    }

    bstr term_msg = {0};
    prepare_prefix(root, &term_msg, MSGL_STATUS, 0);
    if (term_msg.len) {
        fprintf(fp, "%.*s", BSTR_P(term_msg));
        talloc_free(term_msg.start);
    }

done:
    root->status_line.len = 0;
}

void mp_msg_flush_status_line(struct mp_log *log, bool clear)
{
    if (!log->root)
        return;

    mp_mutex_lock(&log->root->lock);
    msg_flush_status_line(log->root, clear);
    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(term_msg_fp(log->root, MSGL_STATUS), "\033]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)
{
    if (c == -1) {
        bstr_xappend(talloc_ctx, text, bstr0("\033[0m"));
        return;
    }
    // Pure black to gray
    if (c == 0)
        c += 8;
    // Pure white to light one
    if (c == 15)
        c -= 8;
    bstr_xappend_asprintf(talloc_ctx, text, "\033[%d%dm", c >= 8 ? 9 : 3, c & 7);
}

static void set_msg_color(void *talloc_ctx, bstr *text, int lev)
{
    static const int v_colors[] = {
        [MSGL_FATAL]  = 9,  // bright red
        [MSGL_ERR]    = 1,  // red
        [MSGL_WARN]   = 3,  // yellow
        [MSGL_INFO]   = -1, // default
        [MSGL_STATUS] = -1, // default
        [MSGL_V]      = 2,  // green
        [MSGL_DEBUG]  = 4,  // blue
        [MSGL_TRACE]  = 8,  // bright black aka. gray
    };
    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());
}

static void append_terminal_line(struct mp_log *log, int lev,
                                 bstr text, bstr *term_msg, int *line_w, int term_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);

    const unsigned char *cut_pos = NULL;
    int ellipsis_width = 2;
    int width = term_disp_width(bstr_splice(*term_msg, start, term_msg->len),
                                term_w - ellipsis_width, &cut_pos);
    if (cut_pos) {
        int new_len = cut_pos - term_msg->start;
        bstr rem = bstrdup(NULL, (bstr){(unsigned char *)cut_pos, term_msg->len - new_len});
        void *ptr = rem.start;
        term_msg->len = new_len;

        bstr_xappend(root, term_msg, bstr0(".."));

        while (rem.len) {
            if (bstr_eatstart0(&rem, "\n")) {
                bstr_xappend(root, term_msg, bstr0("\n"));
                continue;
            }
            if (bstr_eatstart0(&rem, "\033[")) {
                bstr_xappend(root, term_msg, bstr0("\033["));

                while (rem.len && !((*rem.start >= '@' && *rem.start <= '~') || *rem.start == 'm')) {
                    bstr_xappend(root, term_msg, bstr_splice(rem, 0, 1));
                    rem = bstr_cut(rem, 1);
                }
                bstr_xappend(root, term_msg, bstr_splice(rem, 0, 1));
            }
            rem = bstr_cut(rem, 1);
        }
        talloc_free(ptr);

        width += ellipsis_width;
    }
    *line_w = root->isatty[term_msg_fileno(root, lev)] ? width : 0;
}

static struct mp_log_buffer_entry *log_buffer_read(struct mp_log_buffer *buffer)
{
    mp_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') {
            mp_assert(str.len == 0);
            str = line;
            break;
        }

        bool clip = bstr_eatstart0(&line, TERM_MSG_0);
        if (print_term) {
            int line_w;
            append_terminal_line(log, lev, line, &root->term_msg_tmp, &line_w,
                                 clip && term_w ? term_w : INT_MAX);
            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) {
        int line_w = 0;
        bool clip = bstr_eatstart0(&str, TERM_MSG_0);
        if (str.len && print_term)
            append_terminal_line(log, lev, str, &root->term_msg_tmp, &line_w,
                                 clip && term_w ? term_w : INT_MAX);
        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;

    if (bstr_xappend_vasprintf(root, &root->buffer, format, va) < 0) {
        bstr_xappend(root, &root->buffer, bstr0("format error: "));
        bstr_xappend(root, &root->buffer, bstr0(format));
    }

    // 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);

        FILE *stream = term_msg_fp(root, lev);
        if (root->term_msg.len) {
            root->term_status_msg.len = 0;
            if (lev != MSGL_STATUS && root->status_line.len && root->status_log &&
                is_status_output(root, lev) && test_terminal_level(root->status_log, MSGL_STATUS))
            {
                write_term_msg(root->status_log, MSGL_STATUS, root->status_line,
                               &root->term_status_msg);
            }
            fwrite(root->term_msg.start, root->term_msg.len, 1, stream);
            if (root->term_status_msg.len)
                fwrite(root->term_status_msg.start, root->term_status_msg.len, 1, stream);
            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)
{
    mp_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)
{
    mp_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;

    if (root->really_quiet)
        root->status_lines = 0;

    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, true);
    if (root->really_quiet && root->isatty[term_msg_fileno(root, MSGL_STATUS)])
        fprintf(term_msg_fp(root, MSGL_STATUS), TERM_ESC_RESTORE_CURSOR);
    terminate_log_file_thread(root);
    mp_msg_log_buffer_destroy(root->early_buffer);
    mp_msg_log_buffer_destroy(root->early_filebuffer);
    mp_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);
            mp_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,
                                 EARLY_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) {
        // 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;
            mp_msg_log_buffer_resize(buffer, size);
            buffer->wakeup_cb = wakeup_cb;
            buffer->wakeup_cb_ctx = wakeup_cb_ctx;
            mp_mutex_unlock(&root->lock);
            return buffer;
        }
    }

    mp_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_resize(struct mp_log_buffer *buffer, int size)
{
    mp_mutex_lock(&buffer->lock);

    mp_assert(size > 0);
    if (buffer->capacity < size &&
        buffer->entry0 + buffer->num_entries <= buffer->capacity) {
        // shortcut if buffer doesn't wrap
        buffer->entries = talloc_realloc(buffer, buffer->entries,
                                         struct mp_log_buffer_entry *, size);
    } else if (buffer->capacity != size) {
        struct mp_log_buffer_entry **entries =
            talloc_array(buffer, struct mp_log_buffer_entry *, size);
        int num_entries = 0;
        for (int i = buffer->num_entries - 1; i >= 0; i--) {
            int entry = (buffer->entry0 + i) % buffer->num_entries;
            struct mp_log_buffer_entry *res = buffer->entries[entry];
            if (num_entries < size) {
                entries[num_entries++] = res;
            } else {
                talloc_free(res);
                buffer->dropped += 1;
            }
        }
        talloc_free(buffer->entries);
        buffer->entries = entries;
        buffer->entry0 = 0;
        buffer->num_entries = num_entries;
    }
    buffer->capacity = size;

    mp_mutex_unlock(&buffer->lock);
}

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;
}

Coverage Report

Created: 2025-08-11 06:44