path: root/common/msg.c

/*
 * 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) 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 || 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(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);
        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;
}

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

    mp_mutex_lock(&log->root->lock);
    if (!log->root->status_lines)
        goto done;

    if (!clear) {
        if (log->root->isatty[STDERR_FILENO])
            fprintf(stderr, TERM_ESC_RESTORE_CURSOR);
        fprintf(stderr, "\n");
        log->root->blank_lines = 0;
        log->root->status_lines = 0;
        goto done;
    }

    bstr term_msg = {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);
    }

done:
    log->root->status_line.len = 0;
    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, "\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;
    }

    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};
    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)
{
    int width = 0;

    while (str.len) {
        if (bstr_eatstart0(&str, "\033[")) {
            while (str.len && !((*str.start >= '@' && *str.start <= '~') || *str.start == 'm'))
                str = bstr_cut(str, 1);
            str = bstr_cut(str, 1);
            continue;
        }

        bstr code = bstr_split_utf8(str, &str);
        if (code.len == 0)
            return 0;

        if (code.len == 1 && *code.start == '\n')
            continue;

        // Only single-width characters are supported
        width++;

        // Assume that everything before \r should be discarded for simplicity
        if (code.len == 1 && *code.start == '\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(bstr_splice(*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) {
        int line_w = 0;
        if (str.len && print_term)
            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) {
            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)
{
    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