10771056722

Committed 09 Sep 2024 10:18AM UTC coverage: 87.205% (-0.02%) from 87.229%

Build # 10771056722

Build Type

push

github

Committed by

locker

Commit Message

test/fuzz: fix error injections in engine test

Closes #10531

NO_DOC=testing
NO_CHANGELOG=testing

(cherry picked from commit 4bc191535)

Run Details

68320 of 121599 branches covered (56.18%)

101003 of 115822 relevant lines covered (87.21%)

2436497.95 hits per line

Source File
Press 'n' to go to next uncovered line, 'b' for previous

84.14

/src/lib/core/say.c

/*
 * Copyright 2010-2016, Tarantool AUTHORS, please see AUTHORS file.
 *
 * Redistribution and use in source and binary forms, with or
 * without modification, are permitted provided that the following
 * conditions are met:
 *
 * 1. Redistributions of source code must retain the above
 *    copyright notice, this list of conditions and the
 *    following disclaimer.
 *
 * 2. Redistributions in binary form must reproduce the above
 *    copyright notice, this list of conditions and the following
 *    disclaimer in the documentation and/or other materials
 *    provided with the distribution.
 *
 * THIS SOFTWARE IS PROVIDED BY <COPYRIGHT HOLDER> ``AS IS'' AND
 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED
 * TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
 * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL
 * <COPYRIGHT HOLDER> OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT,
 * INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
 * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR
 * BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
 * LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF
 * THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
 * SUCH DAMAGE.
 */
#include "say.h"
#include "fiber.h"
#include "errinj.h"
#include "tt_static.h"
#include "tt_strerror.h"

#include <errno.h>
#include <stdarg.h>
#include <stdio.h>
#include <string.h>
#include <netdb.h>
#include <netinet/in.h>
#include <sys/types.h>
#include <unistd.h>
#include <fcntl.h>
#include <syslog.h>
#include <sys/socket.h>
#include <sys/un.h>
#include <arpa/inet.h>
#include <coio_task.h>

pid_t log_pid = 0;
/**
 * The global log level. Used as an optimization by the say() macro to
 * avoid unnecessary calls to say_default().
 * Calculated as MAX(log_default->level, log_level_flightrec).
 */
int log_level = S_INFO;
/**
 * Log level of flight recorder. Log is passed to flight recorder only if
 * it's log level not less that this. -1 is used if we should not pass logs
 * to flight recorder (it is currently disabled). Used in Lua via FFI.
 */
int log_level_flightrec = -1;
/**
 * This function is called for every log which log level is not less than
 * log_level_flightrec.
 */
void
(*log_write_flightrec)(int level, const char *filename, int line,
                       const char *error, const char *format, va_list ap);

enum say_format log_format = SF_PLAIN;
enum { SAY_SYSLOG_DEFAULT_PORT = 512 };

/** List of logs to rotate */
static RLIST_HEAD(log_rotate_list);

static const char logger_syntax_reminder[] =
        "expecting a file name or a prefix, such as '|', 'pipe:', 'syslog:'";
/**
 * True if Tarantool process runs in background mode, i.e. has no
 * controlling terminal.
 */
static bool log_background;

static void
say_default(int level, const char *filename, int line, const char *error,
            const char *format, ...);

static int
say_format_boot(struct log *log, char *buf, int len, int level,
                const char *module, const char *filename, int line,
                const char *error, const char *format, va_list ap);

/*
 * Callbacks called before/after writing to stderr.
 */
static say_stderr_callback_t before_stderr_callback;
static say_stderr_callback_t after_stderr_callback;

/** Default logger used before logging subsystem is initialized. */
static struct log log_boot = {
        .fd = STDERR_FILENO,
        .level = S_INFO,
        .type = SAY_LOGGER_BOOT,
        .path = NULL, /* iff type == SAY_LOGGER_FILE */
        .nonblock = false,
        .format_func = say_format_boot,
        .pid = 0,
        .syslog_ident = NULL,
};

/** Default logger used after bootstrap. */
static struct log log_std;

static struct log *log_default = &log_boot;

sayfunc_t _say = say_default;

const char *
_say_strerror(int errnum)
{
        return tt_strerror(errnum);
}

static const char level_chars[] = {
        [S_FATAL] = 'F',
        [S_SYSERROR] = '!',
        [S_ERROR] = 'E',
        [S_CRIT] = 'C',
        [S_WARN] = 'W',
        [S_INFO] = 'I',
        [S_VERBOSE] = 'V',
        [S_DEBUG] = 'D',
};

static_assert(lengthof(level_chars) == say_level_MAX,
              "level_chars is not defined for one of log levels");

static const char *level_strs[] = {
        [S_FATAL] = "FATAL",
        [S_SYSERROR] = "SYSERROR",
        [S_ERROR] = "ERROR",
        [S_CRIT] = "CRIT",
        [S_WARN] = "WARN",
        [S_INFO] = "INFO",
        [S_VERBOSE] = "VERBOSE",
        [S_DEBUG] = "DEBUG",
};

static_assert(lengthof(level_strs) == say_level_MAX,
              "level_strs is not defined for one of log levels");

const char*
say_log_level_str(int level)
{
        if (level < 0 || level >= (int)lengthof(level_strs))
                return NULL;
        return level_strs[level];
}

static int
level_to_syslog_priority(int level)
{
        switch (level) {
        case S_FATAL:
                return LOG_ERR;
        case S_SYSERROR:
                return LOG_ERR;
        case S_ERROR:
                return LOG_ERR;
        case S_CRIT:
                return LOG_ERR;
        case S_WARN:
                return LOG_WARNING;
        case S_INFO:
                return LOG_INFO;
        case S_VERBOSE:
                return LOG_INFO;
        case S_DEBUG:
                return LOG_DEBUG;
        default:
                return LOG_ERR;
        }
}

/**
 * Helper function that fills the given tm struct with the current local time.
 * tm_sec is set to the number of seconds that passed since the last minute
 * (0-60). Note, in contrast to tm.tm_sec, it has a fractional part.
 */
static void
get_current_time(struct tm *tm, double *tm_sec)
{
        /* Don't use ev_now() since it requires a working event loop. */
        ev_tstamp now = ev_time();
        time_t now_seconds = (time_t)now;
        localtime_r(&now_seconds, tm);
        *tm_sec = now - now_seconds + tm->tm_sec;
}

enum say_logger_type
log_type(void)
{
        return log_default->type;
}

int
log_get_fd(void)
{
        return log_default->fd;
}

void
log_set_fd(int new_fd)
{
        log_default->fd = new_fd;
}

void
log_set_level(struct log *log, enum say_level level)
{
        log->level = level;
}

void
log_set_format(struct log *log, log_format_func_t format_func)
{
        log->format_func = format_func;
}

void
say_set_log_level(int new_level)
{
        log_level = MAX(new_level, log_level_flightrec);
        log_set_level(log_default, (enum say_level) new_level);
}

int
say_get_log_level(void)
{
        return log_default->level;
}

void
say_set_log_format(enum say_format format)
{
        log_format_func_t format_func;

        switch (format) {
        case SF_JSON:
                format_func = say_format_json;
                break;
        case SF_PLAIN:
                format_func = say_format_plain;
                break;
        default:
                unreachable();
        }

        log_set_format(log_default, format_func);
        log_format = format;
}

void
say_set_flightrec_log_level(int new_level)
{
        log_level = MAX(new_level, log_default->level);
        log_level_flightrec = new_level;
}

static const char *say_format_strs[] = {
        [SF_PLAIN] = "plain",
        [SF_JSON] = "json",
        [say_format_MAX] = "unknown"
};

enum say_format
say_format_by_name(const char *format)
{
        return STR2ENUM(say_format, format);
}

/**
 * Sets O_NONBLOCK flag in case if lognonblock is set.
 */
static void
log_set_nonblock(struct log *log)
{
        if (!log->nonblock)
                return;
        int flags;
        if ((flags = fcntl(log->fd, F_GETFL, 0)) < 0 ||
            fcntl(log->fd, F_SETFL, flags | O_NONBLOCK) < 0) {
                say_syserror("fcntl, fd=%i", log->fd);
        }
}

/**
 * Rotate logs on SIGHUP
 */
static int
log_rotate(struct log *log)
{
        if (pm_atomic_load(&log->type) != SAY_LOGGER_FILE)
                return 0;

        ERROR_INJECT(ERRINJ_LOG_ROTATE, { usleep(10); });

        int fd = open(log->path, O_WRONLY | O_APPEND | O_CREAT,
                      S_IRUSR | S_IWUSR | S_IRGRP);
        if (fd < 0) {
                diag_set(SystemError, "logrotate can't open %s", log->path);
                return -1;
        }
        /*
         * The whole charade's purpose is to avoid log->fd changing.
         * Remember, we are a signal handler.
         */
        dup2(fd, log->fd);
        close(fd);

        log_set_nonblock(log);

        /* We are in ev signal handler
         * so we don't have to be worry about async signal safety
         */
        log_say(log, S_INFO, __FILE__, __LINE__, NULL,
                "log file has been reopened");
        /*
         * log_background applies only to log_default logger
         */
        if (log == log_default && log_background &&
                log->type == SAY_LOGGER_FILE) {
                dup2(log_default->fd, STDOUT_FILENO);
                dup2(log_default->fd, STDERR_FILENO);
        }

        return 0;
}

struct rotate_task {
        struct coio_task base;
        struct log *log;
        struct ev_loop *loop;
};

static int
logrotate_cb(struct coio_task *ptr)
{
        struct rotate_task *task = (struct rotate_task *) ptr;
        struct log *log = task->log;
        if (log_rotate(log) < 0)
                diag_log();
        tt_pthread_mutex_lock(&log->rotate_mutex);
        assert(log->rotating_threads > 0);
        log->rotating_threads--;
        if (log->rotating_threads == 0)
                tt_pthread_cond_signal(&log->rotate_cond);
        tt_pthread_mutex_unlock(&log->rotate_mutex);
        return 0;
}

static int
logrotate_cleanup_cb(struct coio_task *ptr)
{
        struct rotate_task *task = (struct rotate_task *) ptr;
        coio_task_destroy(&task->base);
        free(task);
        return 0;
}

void
say_logrotate(struct ev_loop *loop, struct ev_signal *w, int revents)
{
        (void) loop;
        (void) w;
        (void) revents;
        int saved_errno = errno;
        struct log *log;
        rlist_foreach_entry(log, &log_rotate_list, in_log_list) {
                struct rotate_task *task =
                        (struct rotate_task *) calloc(1, sizeof(*task));
                if (task == NULL) {
                        diag_set(OutOfMemory, sizeof(*task), "malloc",
                                 "say_logrotate");
                        diag_log();
                        continue;
                }
                tt_pthread_mutex_lock(&log->rotate_mutex);
                log->rotating_threads++;
                tt_pthread_mutex_unlock(&log->rotate_mutex);
                coio_task_create(&task->base, logrotate_cb, logrotate_cleanup_cb);
                task->log = log;
                task->loop = loop();
                coio_task_post(&task->base);
        }
        errno = saved_errno;
}

/**
 * Initialize the logger pipe: a standalone
 * process which is fed all log messages.
 */
static int
log_pipe_init(struct log *log, const char *init_str)
{
        int pipefd[2];
        char cmd[] = { "/bin/sh" };
        char args[] = { "-c" };
        char *argv[] = { cmd, args, (char *) init_str, NULL };
        log->type = SAY_LOGGER_PIPE;
        sigset_t mask;
        sigemptyset(&mask);
        sigaddset(&mask, SIGCHLD);

        if (pthread_sigmask(SIG_BLOCK, &mask, NULL) == -1)
                say_syserror("pthread_sigmask");

        if (pipe(pipefd) == -1) {
                diag_set(SystemError, "failed to create pipe");
                return -1;
        }

        /* flush buffers to avoid multiple output */
        /* https://github.com/tarantool/tarantool/issues/366 */
        fflush(stdout);
        fflush(stderr);

        log->pid = fork();
        if (log->pid == -1) {
                diag_set(SystemError, "failed to create process");
                return -1;
        }

        if (log->pid == 0) {
                pthread_sigmask(SIG_UNBLOCK, &mask, NULL);

                close(pipefd[1]);
                dup2(pipefd[0], STDIN_FILENO);
                /*
                 * Move to an own process group, to not
                 * receive signals from the controlling
                 * tty. This keeps the log open as long as
                 * the parent is around. When the parent
                 * dies, we get SIGPIPE and terminate.
                 */
                setpgid(0, 0);
                execv(argv[0], argv); /* does not return */
                diag_set(SystemError, "can't start logger: %s", init_str);
                return -1;
        }
#if !TARGET_OS_DARWIN
        /*
         * A courtesy to a DBA who might have
         * misconfigured the logger option: check whether
         * or not the logger process has started, and if
         * it didn't, abort. Notice, that if the logger
         * makes a slow start this is futile.
         */
        struct timespec timeout;
        timeout.tv_sec = 0;
        timeout.tv_nsec = 1; /* Mostly to trigger preemption. */
#if defined(__OpenBSD__)
        int sig = 0;
        sigwait(&mask, &sig);
        if (sig ==SIGCHLD) {
                diag_set(IllegalParams, "logger process died");
                return -1;
        }
#else
        if (sigtimedwait(&mask, NULL, &timeout) == SIGCHLD) {
                diag_set(IllegalParams, "logger process died");
                return -1;
        }
#endif
#endif
        /* OK, let's hope for the best. */
        pthread_sigmask(SIG_UNBLOCK, &mask, NULL);
        close(pipefd[0]);
        log->fd = pipefd[1];
        return 0;
}

/**
 * Initialize logging to a file and set up a log
 * rotation signal.
 */
static int
log_file_init(struct log *log, const char *init_str)
{
        int fd;
        log->path = abspath(init_str);
        log->type = SAY_LOGGER_FILE;
        if (log->path == NULL) {
                diag_set(OutOfMemory, strlen(init_str), "malloc", "abspath");
                return -1;
        }
        fd = open(log->path, O_WRONLY | O_APPEND | O_CREAT,
                  S_IRUSR | S_IWUSR | S_IRGRP);
        if (fd < 0) {
                diag_set(SystemError, "can't open log file: %s", log->path);
                return -1;
        }
        log->fd = fd;
        return 0;
}

/**
 * Connect to syslogd using UNIX socket.
 * @param path UNIX socket path.
 * @retval not 0 Socket descriptor.
 * @retval    -1 Socket error.
 */
static inline int
syslog_connect_unix(const char *path)
{
        int fd = socket(PF_UNIX, SOCK_DGRAM, 0);
        if (fd < 0) {
                diag_set(SystemError, "socket");
                return -1;
        }
        struct sockaddr_un un;
        memset(&un, 0, sizeof(un));
        snprintf(un.sun_path, sizeof(un.sun_path), "%s", path);
        un.sun_family = AF_UNIX;
        if (connect(fd, (struct sockaddr *) &un, sizeof(un)) != 0) {
                diag_set(SystemError, "connect");
                close(fd);
                return -1;
        }
        return fd;
}

/**
 * Connect to remote syslogd using server:port.
 * @param server_address address of remote host.
 * @retval not 0 Socket descriptor.
 * @retval    -1 Socket error.
 */
static int
syslog_connect_remote(const char *server_address)
{
        struct addrinfo *inf, hints, *ptr;
        char *remote;
        char buf[10];
        char *portnum, *copy;
        int fd = -1;
        int ret;

        copy = strdup(server_address);
        if (copy == NULL) {
                diag_set(OutOfMemory, strlen(server_address), "malloc",
                         "stslog server address");
                return fd;
        }
        portnum = copy;
        remote = strsep(&portnum, ":");
        if (portnum == NULL) {
                snprintf(buf, sizeof(buf), "%d", SAY_SYSLOG_DEFAULT_PORT);
                portnum = buf;
        }
        memset(&hints, 0, sizeof(hints));
        hints.ai_family = AF_INET;
        hints.ai_socktype = SOCK_DGRAM;
        hints.ai_protocol = IPPROTO_UDP;

        ret = getaddrinfo(remote, portnum, &hints, &inf);
        if (ret != 0) {
                errno = EIO;
                diag_set(SystemError, "getaddrinfo: %s",
                         gai_strerror(ret));
                goto out;
        }
        for (ptr = inf; ptr; ptr = ptr->ai_next) {
                fd = socket(ptr->ai_family, ptr->ai_socktype, ptr->ai_protocol);
                if (fd < 0) {
                        diag_set(SystemError, "socket");
                        continue;
                }
                if (connect(fd, inf->ai_addr, inf->ai_addrlen) != 0) {
                        close(fd);
                        fd = -1;
                        diag_set(SystemError, "connect");
                        continue;
                }
                break;
        }
        freeaddrinfo(inf);
out:
        free(copy);
        return fd;
}

static inline int
log_syslog_connect(struct log *log)
{
        /*
         * If server option is not set use '/dev/log' for Linux and
         * '/var/run/syslog' for Mac.
         */
        switch (log->syslog_server_type) {
        case SAY_SYSLOG_UNIX:
                log->fd = syslog_connect_unix(log->path);
                break;
        case SAY_SYSLOG_REMOTE:
                log->fd = syslog_connect_remote(log->path);
                break;
        default:
                log->fd = syslog_connect_unix("/dev/log");
                if (log->fd < 0)
                        log->fd = syslog_connect_unix("/var/run/syslog");

        }
        return log->fd;
}

/** Initialize logging to syslog */
static int
log_syslog_init(struct log *log, const char *init_str)
{
        struct say_syslog_opts opts;
        log->type = SAY_LOGGER_SYSLOG;

        if (say_parse_syslog_opts(init_str, &opts) < 0)
                return -1;

        log->syslog_server_type = opts.server_type;
        if (log->syslog_server_type != SAY_SYSLOG_DEFAULT) {
                log->path = strdup(opts.server_path);
                if (log->path == NULL) {
                        diag_set(OutOfMemory, strlen(opts.server_path),
                                 "malloc", "server address");
                        return -1;
                }
        }
        if (opts.identity == NULL)
                log->syslog_ident = strdup("tarantool");
        else
                log->syslog_ident = strdup(opts.identity);
        if (log->syslog_ident == NULL) {
                diag_set(OutOfMemory, strlen(opts.identity), "malloc",
                         "log->syslog_ident");
                return -1;
        }

        if (opts.facility == syslog_facility_MAX)
                log->syslog_facility = SYSLOG_LOCAL7;
        else
                log->syslog_facility = opts.facility;
        say_free_syslog_opts(&opts);
        log->fd = log_syslog_connect(log);
        if (log->fd < 0) {
                diag_log();
                /* syslog indent is freed in atexit(). */
                diag_set(SystemError, "syslog logger");
                return -1;
        }
        return 0;
}

/**
 * Initialize logging subsystem to use in daemon mode.
 */
int
log_create(struct log *log, const char *init_str, int nonblock)
{
        log->pid = 0;
        log->syslog_ident = NULL;
        log->path = NULL;
        log->format_func = say_format_plain;
        log->level = S_INFO;
        log->rotating_threads = 0;
        tt_pthread_mutex_init(&log->rotate_mutex, NULL);
        tt_pthread_cond_init(&log->rotate_cond, NULL);
        setvbuf(stderr, NULL, _IONBF, 0);

        if (init_str != NULL) {
                enum say_logger_type type;
                if (say_parse_logger_type(&init_str, &type))
                        return -1;

                int rc;
                switch (type) {
                case SAY_LOGGER_PIPE:
                        log->nonblock = (nonblock >= 0)? nonblock: true;
                        rc = log_pipe_init(log, init_str);
                        break;
                case SAY_LOGGER_SYSLOG:
                        log->nonblock = (nonblock >= 0)? nonblock: true;
                        rc = log_syslog_init(log, init_str);
                        break;
                case SAY_LOGGER_FILE:
                default:
                        log->nonblock = (nonblock >= 0)? nonblock: false;
                        rc = log_file_init(log, init_str);
                        break;
                }
                if (rc < 0) {
                        return -1;
                }
                /*
                 * Set non-blocking mode if a non-default log
                 * output is set. Avoid setting stdout to
                 * non-blocking: this will garble interactive
                 * console output.
                 */
                log_set_nonblock(log);
        } else {
                log->type = SAY_LOGGER_STDERR;
                log->fd = STDERR_FILENO;
        }
        if (log->type == SAY_LOGGER_FILE)
                rlist_add_entry(&log_rotate_list, log, in_log_list);
        else
                rlist_create(&log->in_log_list);
        return 0;
}

bool
say_logger_initialized(void)
{
        return log_default == &log_std;
}

void
say_logger_init(const char *init_str, int level, int nonblock,
                const char *format)
{
        /*
         * The logger may be early configured
         * by hands without configuing the whole box.
         */
        if (say_logger_initialized()) {
                say_set_log_level(level);
                say_set_log_format(say_format_by_name(format));
                return;
        }

        if (log_create(&log_std, init_str, nonblock) < 0)
                goto fail;

        log_default = &log_std;

        switch (log_default->type) {
        case SAY_LOGGER_PIPE:
                fprintf(stderr, "started logging into a pipe,"
                        " SIGHUP log rotation disabled\n");
                break;
        case SAY_LOGGER_SYSLOG:
                fprintf(stderr, "started logging into a syslog,"
                        " SIGHUP log rotation disabled\n");
        default:
                break;
        }
        _say = say_default;
        say_set_log_level(level);
        log_pid = log_default->pid;
        say_set_log_format(say_format_by_name(format));

        return;
fail:
        diag_log();
        panic("failed to initialize logging subsystem");
}

int
say_set_background(void)
{
        assert(say_logger_initialized());

        if (log_background)
                return 0;

        log_background = true;

        fflush(stderr);
        fflush(stdout);

        int fd;
        int fd_null = -1;
        if (log_default->fd == STDERR_FILENO) {
                fd_null = open("/dev/null", O_WRONLY);
                if (fd_null < 0) {
                        diag_set(SystemError, "open(/dev/null)");
                        return -1;
                }
                fd = fd_null;
        } else {
                fd = log_default->fd;
        }

        dup2(fd, STDERR_FILENO);
        dup2(fd, STDOUT_FILENO);
        if (fd_null != -1)
                close(fd_null);

        return 0;
}

void
say_logger_free(void)
{
        if (say_logger_initialized())
                log_destroy(&log_std);
}

/** {{{ Formatters */

/**
 * Format the log message in compact form:
 * MESSAGE: ERROR
 *
 * Used during boot time, e.g. without box.cfg().
 */
static int
say_format_boot(struct log *log, char *buf, int len, int level,
                const char *module, const char *filename, int line,
                const char *error, const char *format, va_list ap)
{
        (void)log;
        (void)module;
        (void)filename;
        (void)line;
        (void)level;
        int total = 0;
        SNPRINT(total, vsnprintf, buf, len, format, ap);
        if (error != NULL)
                SNPRINT(total, snprintf, buf, len, ": %s", error);
        SNPRINT(total, snprintf, buf, len, "\n");
        return total;
}

/**
 * Format the log message in Tarantool format:
 * YYYY-MM-DD hh:mm:ss.ms [PID]: CORD/FID/FIBERNAME/MODULENAME LEVEL> MSG
 */
int
say_format_plain(struct log *log, char *buf, int len, int level,
                 const char *module, const char *filename, int line,
                 const char *error, const char *format, va_list ap)
{
        int total = 0;

        /*
         * Every message written to syslog has a header that contains
         * the current time and pid (see format_syslog_header) so we
         * exclude them from the message body.
         */
        if (log->type != SAY_LOGGER_SYSLOG) {
                struct tm tm;
                double tm_sec;
                get_current_time(&tm, &tm_sec);
                /* Print time in format 2012-08-07 18:30:00.634 */
                SNPRINT(total, strftime, buf, len, "%F %H:%M", &tm);
                SNPRINT(total, snprintf, buf, len, ":%06.3f ", tm_sec);
                /* Print pid */
                SNPRINT(total, snprintf, buf, len, "[%i] ", getpid());
        }

        SNPRINT(total, snprintf, buf, len, "%s", cord()->name);
        if (fiber() && fiber()->fid != FIBER_ID_SCHED) {
                SNPRINT(total, snprintf, buf, len, "/%llu/%s",
                        (long long)fiber()->fid, fiber_name(fiber()));
        }

        if (module != NULL)
                SNPRINT(total, snprintf, buf, len, "/%s", module);

        if (level == S_WARN || level == S_ERROR || level == S_SYSERROR) {
                /* Primitive basename(filename) */
                if (filename) {
                        for (const char *f = filename; *f; f++)
                                if (*f == '/' && *(f + 1) != '\0')
                                        filename = f + 1;
                        SNPRINT(total, snprintf, buf, len, " %s:%i", filename,
                                line);
                }
        }

        SNPRINT(total, snprintf, buf, len, " %c> ", level_chars[level]);

        SNPRINT(total, vsnprintf, buf, len, format, ap);
        if (error != NULL)
                SNPRINT(total, snprintf, buf, len, ": %s", error);

        SNPRINT(total, snprintf, buf, len, "\n");
        return total;
}

/**
 * Format log message in json format:
 * {"time": 1507026445.23232, "level": "WARN", "message": <message>,
 * "pid": <pid>, "cord_name": <name>, "fiber_id": <id>,
 * "fiber_name": <fiber_name>, file": <filename>, "line": <fds>,
 * "module": <module_name>}
 */
int
say_format_json(struct log *log, char *buf, int len, int level,
                const char *module, const char *filename, int line,
                const char *error, const char *format, va_list ap)
{
        (void) log;
        int total = 0;

        SNPRINT(total, snprintf, buf, len, "{\"time\": \"");

        struct tm tm;
        double tm_sec;
        get_current_time(&tm, &tm_sec);
        int written = strftime(buf, len, "%FT%H:%M", &tm);
        buf += written, len -= written, total += written;
        SNPRINT(total, snprintf, buf, len, ":%06.3f", tm_sec);
        written = strftime(buf, len, "%z", &tm);
        buf += written, len -= written, total += written;
        SNPRINT(total, snprintf, buf, len, "\", ");

        SNPRINT(total, snprintf, buf, len, "\"level\": \"%s\", ",
                        level_strs[level]);

        if (strncmp(format, "json", sizeof("json")) == 0) {
                /*
                 * Message is already JSON-formatted.
                 * Get rid of {} brackets and append to the output buffer.
                 */
                const char *str = va_arg(ap, const char *);
                assert(str != NULL);
                int str_len = strlen(str);
                assert(str_len > 2 && str[0] == '{' && str[str_len - 1] == '}');
                SNPRINT(total, snprintf, buf, len, "%.*s, ",
                        str_len - 2, str + 1);
        } else {
                /* Format message */
                char *tmp = tt_static_buf();
                if (vsnprintf(tmp, TT_STATIC_BUF_LEN, format, ap) < 0)
                        return -1;
                SNPRINT(total, snprintf, buf, len, "\"message\": \"");
                /* Escape and print message */
                SNPRINT(total, json_escape, buf, len, tmp);
                SNPRINT(total, snprintf, buf, len, "\", ");
        }

        /* in case of system errors */
        if (error) {
                SNPRINT(total, snprintf, buf, len, "\"error\": \"");
                SNPRINT(total, json_escape, buf, len, error);
                SNPRINT(total, snprintf, buf, len, "\", ");
        }

        SNPRINT(total, snprintf, buf, len, "\"pid\": %i ", getpid());
        SNPRINT(total, snprintf, buf, len, ", \"cord_name\": \"");
        SNPRINT(total, json_escape, buf, len, cord()->name);
        SNPRINT(total, snprintf, buf, len, "\"");
        if (fiber() && fiber()->fid != FIBER_ID_SCHED) {
                SNPRINT(total, snprintf, buf, len, ", \"fiber_id\": %llu, ",
                        (long long)fiber()->fid);
                SNPRINT(total, snprintf, buf, len, "\"fiber_name\": \"");
                SNPRINT(total, json_escape, buf, len, fiber()->name);
                SNPRINT(total, snprintf, buf, len, "\"");
        }

        if (filename) {
                SNPRINT(total, snprintf, buf, len, ", \"file\": \"");
                SNPRINT(total, json_escape, buf, len, filename);
                SNPRINT(total, snprintf, buf, len, "\", \"line\": %i", line);
        }
        if (module != NULL) {
                SNPRINT(total, snprintf, buf, len, ", \"module\": \"");
                SNPRINT(total, json_escape, buf, len, module);
                SNPRINT(total, snprintf, buf, len, "\"");
        }
        SNPRINT(total, snprintf, buf, len, "}\n");
        return total;
}

/** Wrapper around log->format_func to be used with SNPRINT. */
static int
format_func_adapter(char *buf, int len, struct log *log, int level,
                    const char *module, const char *filename, int line,
                    const char *error, const char *format, va_list ap)
{
        return log->format_func(log, buf, len, level, module, filename, line,
                                error, format, ap);
}

/**
 * Format the header of a log message in syslog format.
 *
 * See RFC 5424 and RFC 3164. RFC 3164 is compatible with RFC 5424,
 * so it is implemented.
 * Protocol:
 * <PRIORITY_VALUE>TIMESTAMP IDENTATION[PID]: CORD/FID/FIBERNAME LEVEL> MSG
 * - Priority value is encoded as message subject * 8 and bitwise
 *   OR with message level;
 * - Timestamp must be encoded in the format: Mmm dd hh:mm:ss;
 *   Mmm - moth abbreviation;
 * - Identation is application name. By default it is "tarantool";
 */
static int
format_syslog_header(char *buf, int len, int level,
                     enum syslog_facility facility, const char *ident)
{
        struct tm tm;
        double tm_sec;
        get_current_time(&tm, &tm_sec);

        int total = 0;

        /* Format syslog header according to RFC */
        int prio = (facility << 3) | level_to_syslog_priority(level);
        SNPRINT(total, snprintf, buf, len, "<%d>", prio);
        SNPRINT(total, strftime, buf, len, "%h %e %T ", &tm);
        SNPRINT(total, snprintf, buf, len, "%s[%d]: ", ident,
                getpid());
        return total;
}

/** Formatters }}} */

/** {{{ Loggers */

/*
 * From pipe(7):
 * POSIX.1 says that write(2)s of less than PIPE_BUF bytes must be atomic:
 * the output data is written to the pipe as a contiguous sequence. Writes
 * of more than PIPE_BUF bytes may be nonatomic: the kernel may interleave
 * the data with data written by other processes. PIPE_BUF is 4k on Linux.
 *
 * Nevertheless, let's ignore the fact that messages can be interleaved in
 * some situations and set SAY_BUF_LEN_MAX to 16k for now.
 */
enum { SAY_BUF_LEN_MAX = 16 * 1024 };
static __thread char say_buf[SAY_BUF_LEN_MAX];

/**
 * Wrapper over write which ensures, that writes not more than buffer size.
 */
static ssize_t
safe_write(int fd, const char *buf, int size)
{
        assert(size >= 0);
        /* Writes at most SAY_BUF_LEN_MAX - 1
         * (1 byte was taken for 0 byte in vsnprintf).
         */
        return write(fd, buf, MIN(size, SAY_BUF_LEN_MAX - 1));
}

/**
 * Common part of say_default() and say_from_lua().
 */
static void
say_internal(int level, bool check_level, const char *module,
             const char *filename, int line, const char *error,
             const char *format, va_list ap)
{
        int errsv = errno;
        int total = log_vsay(log_default, level, check_level, module, filename,
                             line, error, format, ap);
        if (total > 0 &&
            level == S_FATAL && log_default->fd != STDERR_FILENO) {
                ssize_t r = safe_write(STDERR_FILENO, say_buf, total);
                (void)r;
        }
        errno = errsv; /* Preserve the errno. */
}

/**
 * Default say function.
 */
static void
say_default(int level, const char *filename, int line, const char *error,
            const char *format, ...)
{
        va_list ap;
        va_start(ap, format);
        if (level <= log_level_flightrec) {
                assert(log_write_flightrec != NULL);
                int errsv = errno;
                va_list ap_copy;
                va_copy(ap_copy, ap);
                log_write_flightrec(level, filename, line, error, format,
                                    ap_copy);
                va_end(ap_copy);
                errno = errsv; /* Preserve the errno. */
        }
        say_internal(level, true, NULL, filename, line, error, format, ap);
        va_end(ap);
}

/**
 * Format and print a message to the default Tarantool log.
 * This function is used by Lua say().
 * Unlike say_default(), it doesn't compare level against log->level, the check
 * is performed in Lua, because each module can have its own log level.
 * Also it takes module name, and doesn't take an error argument.
 */
void
say_from_lua(int level, const char *module, const char *filename, int line,
             const char *format, ...)
{
        va_list ap;
        va_start(ap, format);
        say_internal(level, false, module, filename, line, NULL, format, ap);
        va_end(ap);
}

/**
 * A variadic wrapper over log_write_flightrec(), used by Lua say().
 */
void
log_write_flightrec_from_lua(int level, const char *filename, int line, ...)
{
        assert(log_write_flightrec != NULL);
        int errsv = errno;
        va_list ap;
        va_start(ap, line);
        /* ap contains a single string, which is already formatted. */
        log_write_flightrec(level, filename, line, NULL, "%s", ap);
        errno = errsv; /* Preserve the errno. */
        va_end(ap);
}

/**
 * File and pipe logger
 */
static void
write_to_file(struct log *log, int total)
{
        assert(log->type == SAY_LOGGER_FILE ||
               log->type == SAY_LOGGER_PIPE ||
               log->type == SAY_LOGGER_STDERR);
        assert(total >= 0);
        ssize_t r = safe_write(log->fd, say_buf, total);
        (void) r;                               /* silence gcc warning */
}

/**
 * Syslog logger
 */
static void
write_to_syslog(struct log *log, int total)
{
        assert(log->type == SAY_LOGGER_SYSLOG);
        assert(total >= 0);
        if (log->fd < 0 || safe_write(log->fd, say_buf, total) <= 0) {
                /*
                 * Try to reconnect, if write to syslog has
                 * failed. Syslog write can fail, if, for example,
                 * syslogd is restarted. In such a case write to
                 * UNIX socket starts return -1 even for UDP.
                 */
                if (log->fd >= 0)
                        close(log->fd);
                log->fd = log_syslog_connect(log);
                if (log->fd >= 0) {
                        log_set_nonblock(log);
                        /*
                         * In a case or error the log message is
                         * lost. We can not wait for connection -
                         * it would block thread. Try to reconnect
                         * on next vsay().
                         */
                        ssize_t r = safe_write(log->fd, say_buf, total);
                        (void) r;               /* silence gcc warning */
                }
        }
}

/** Loggers }}} */

/*
 * Init string parser(s)
 */

/**
 * @retval string after prefix if a prefix is found,
 *         *str also is advanced to the prefix
 *           NULL a prefix is not found, str is left intact
 */
static const char *
say_parse_prefix(const char **str, const char *prefix)
{
        size_t len = strlen(prefix);
        if (strncmp(*str, prefix, len) == 0) {
                *str = *str + len;
                return *str;
        }
        return NULL;
}

int
say_parse_logger_type(const char **str, enum say_logger_type *type)
{
        if (say_parse_prefix(str, "|"))
                *type = SAY_LOGGER_PIPE;
        else if (say_parse_prefix(str, "file:"))
                *type = SAY_LOGGER_FILE;
        else if (say_parse_prefix(str, "pipe:"))
                *type = SAY_LOGGER_PIPE;
        else if (say_parse_prefix(str, "syslog:"))
                *type = SAY_LOGGER_SYSLOG;
        else if (strchr(*str, ':') == NULL)
                *type = SAY_LOGGER_FILE;
        else {
                diag_set(IllegalParams, logger_syntax_reminder);
                return -1;
        }
        return 0;
}

static const char *syslog_facility_strs[] = {
        [SYSLOG_KERN] = "kern",
        [SYSLOG_USER] = "user",
        [SYSLOG_MAIL] = "mail",
        [SYSLOG_DAEMON] = "daemon",
        [SYSLOG_AUTH] = "auth",
        [SYSLOG_INTERN] = "intern",
        [SYSLOG_LPR] = "lpr",
        [SYSLOG_NEWS] = "news",
        [SYSLOG_UUCP] = "uucp",
        [SYSLOG_CLOCK] = "clock",
        [SYSLOG_AUTHPRIV] = "authpriv",
        [SYSLOG_FTP] = "ftp",
        [SYSLOG_NTP] = "ntp",
        [SYSLOG_AUDIT] = "audit",
        [SYSLOG_ALERT] = "alert",
        [SYSLOG_CRON] = "cron",
        [SYSLOG_LOCAL0] = "local0",
        [SYSLOG_LOCAL1] = "local1",
        [SYSLOG_LOCAL2] = "local2",
        [SYSLOG_LOCAL3] = "local3",
        [SYSLOG_LOCAL4] = "local4",
        [SYSLOG_LOCAL5] = "local5",
        [SYSLOG_LOCAL6] = "local6",
        [SYSLOG_LOCAL7] = "local7",
        [syslog_facility_MAX] = "unknown",
};

enum syslog_facility
say_syslog_facility_by_name(const char *facility)
{
        return STR2ENUM(syslog_facility, facility);
}

int
say_parse_syslog_opts(const char *init_str, struct say_syslog_opts *opts)
{
        opts->server_path = NULL;
        opts->server_type = SAY_SYSLOG_DEFAULT;
        opts->identity = NULL;
        opts->facility = syslog_facility_MAX;
        opts->copy = strdup(init_str);
        if (opts->copy == NULL) {
                diag_set(OutOfMemory, strlen(init_str), "malloc", "opts->copy");
                return -1;
        }
        char *ptr = opts->copy;
        const char *option, *value;

        /* strsep() overwrites the separator with '\0' */
        while ((option = strsep(&ptr, ","))) {
                if (*option == '\0')
                        break;

                value = option;
                if (say_parse_prefix(&value, "server=")) {
                        if (opts->server_path != NULL ||
                            opts->server_type != SAY_SYSLOG_DEFAULT)
                                goto duplicate;
                        if (say_parse_prefix(&value, "unix:")) {
                                opts->server_type = SAY_SYSLOG_UNIX;
                                opts->server_path = value;
                        } else {
                                opts->server_type = SAY_SYSLOG_REMOTE;
                                opts->server_path = value;
                        }
                } else if (say_parse_prefix(&value, "identity=")) {
                        if (opts->identity != NULL)
                                goto duplicate;
                        opts->identity = value;
                } else if (say_parse_prefix(&value, "facility=")) {
                        if (opts->facility != syslog_facility_MAX)
                                goto duplicate;
                        opts->facility = say_syslog_facility_by_name(value);
                        if (opts->facility == syslog_facility_MAX) {
                                diag_set(IllegalParams, "bad syslog facility option '%s'",
                                         value);
                                goto error;
                        }
                } else {
                        diag_set(IllegalParams, "bad option '%s'", option);
                        goto error;
                }
        }
        return 0;
duplicate:
        /* Terminate the "bad" option, by overwriting '=' sign */
        ((char *)value)[-1] = '\0';
        diag_set(IllegalParams, "duplicate option '%s'", option);
error:
        free(opts->copy); opts->copy = NULL;
        return -1;
}

void
say_free_syslog_opts(struct say_syslog_opts *opts)
{
        free(opts->copy);
        opts->copy = NULL;
}

void
log_destroy(struct log *log)
{
        assert(log != NULL);
        tt_pthread_mutex_lock(&log->rotate_mutex);
        while(log->rotating_threads > 0)
                tt_pthread_cond_wait(&log->rotate_cond, &log->rotate_mutex);
        tt_pthread_mutex_unlock(&log->rotate_mutex);
        pm_atomic_store(&log->type, SAY_LOGGER_BOOT);

        if (log->fd != -1)
                close(log->fd);
        free(log->syslog_ident);
        free(log->path);
        rlist_del_entry(log, in_log_list);
        tt_pthread_mutex_destroy(&log->rotate_mutex);
        tt_pthread_cond_destroy(&log->rotate_cond);
}

/**
 * Format a line of log.
 */
static int
format_log_entry(struct log *log, int level, const char *module,
                 const char *filename, int line, const char *error,
                 const char *format, va_list ap)
{
        int total = 0;
        char *buf = say_buf;
        int len = SAY_BUF_LEN_MAX;

        if (log->type == SAY_LOGGER_SYSLOG) {
                SNPRINT(total, format_syslog_header, buf, len,
                        level, log->syslog_facility, log->syslog_ident);
        }
        SNPRINT(total, format_func_adapter, buf, len, log, level, module,
                filename, line, error, format, ap);

        return total;
}

int
log_vsay(struct log *log, int level, bool check_level, const char *module,
         const char *filename, int line, const char *error, const char *format,
         va_list ap)
{
        int errsv = errno;
        int total = 0;

        assert(level >= 0 && level < say_level_MAX);

        if (check_level && level > log->level)
                goto out;

        total = format_log_entry(log, level, module, filename, line, error,
                                 format, ap);
        if (total <= 0)
                goto out;

        switch (log->type) {
        case SAY_LOGGER_FILE:
        case SAY_LOGGER_PIPE:
                write_to_file(log, total);
                break;
        case SAY_LOGGER_STDERR:
                if (before_stderr_callback != NULL)
                        before_stderr_callback();
                write_to_file(log, total);
                if (after_stderr_callback != NULL)
                        after_stderr_callback();
                break;
        case SAY_LOGGER_SYSLOG:
                write_to_syslog(log, total);
                if (level == S_FATAL && log->fd != STDERR_FILENO)
                        (void)safe_write(STDERR_FILENO, say_buf, total);
                break;
        case SAY_LOGGER_BOOT:
        {
                if (before_stderr_callback != NULL)
                        before_stderr_callback();
                ssize_t r = safe_write(STDERR_FILENO, say_buf, total);
                (void) r;                       /* silence gcc warning */
                if (after_stderr_callback != NULL)
                        after_stderr_callback();
                break;
        }
        default:
                unreachable();
        }
out:
        errno = errsv; /* Preserve the errno. */
        return total;
}

void
say_set_stderr_callback(say_stderr_callback_t before,
                        say_stderr_callback_t after)
{
        before_stderr_callback = before;
        after_stderr_callback = after;
}

tarantool / tarantool / 10771056722

Source File Press 'n' to go to next uncovered line, 'b' for previous

Source File
Press 'n' to go to next uncovered line, 'b' for previous