xref: /lsquic/src/liblsquic/lsquic_logger.c

/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc.  See LICENSE. */
/*
 * LSQUIC Logger implementation.
 */

#include <assert.h>
#include <errno.h>
#include <inttypes.h>
#include <stdarg.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#ifndef WIN32
#include <sys/time.h>
#endif
#include <time.h>

#define LSQUIC_LOGGER_MODULE LSQLM_LOGGER /* Quis custodiet ipsos custodes? */
#include "lsquic.h"
#include "lsquic_logger.h"

#define MAX_LINE_LEN 8192
#define FORMAT_PROBLEM(lb, len, max) (((ssize_t)lb < 0) || ((ssize_t)lb + (ssize_t)len >= (ssize_t)max))

/* TODO: display GQUIC CIDs in Chrome-compatible format */

static enum lsquic_logger_timestamp_style g_llts = LLTS_NONE;

static int
null_log_buf (void *ctx, const char *buf, size_t len)
{
    return 0;
}

static int
file_log_buf (void *ctx, const char *buf, size_t len)
{
    return (int)fwrite(buf, sizeof(char), len, (FILE *) ctx);
}

static const struct lsquic_logger_if file_logger_if = {
    .log_buf    = file_log_buf,
};

static const struct lsquic_logger_if null_logger_if = {
    .log_buf    = null_log_buf,
};

static void *logger_ctx = NULL;
static const struct lsquic_logger_if *logger_if = &null_logger_if;

enum lsq_log_level lsq_log_levels[N_LSQUIC_LOGGER_MODULES] = {
    [LSQLM_NOMODULE]    = LSQ_LOG_WARN,
    [LSQLM_LOGGER]      = LSQ_LOG_WARN,
    [LSQLM_EVENT]       = LSQ_LOG_WARN,
    [LSQLM_ENGINE]      = LSQ_LOG_WARN,
    [LSQLM_CONN]        = LSQ_LOG_WARN,
    [LSQLM_RECHIST]     = LSQ_LOG_WARN,
    [LSQLM_STREAM]      = LSQ_LOG_WARN,
    [LSQLM_PARSE]       = LSQ_LOG_WARN,
    [LSQLM_CFCW]        = LSQ_LOG_WARN,
    [LSQLM_SFCW]        = LSQ_LOG_WARN,
    [LSQLM_SENDCTL]     = LSQ_LOG_WARN,
    [LSQLM_ALARMSET]    = LSQ_LOG_WARN,
    [LSQLM_CRYPTO]      = LSQ_LOG_WARN,
    [LSQLM_HANDSHAKE]   = LSQ_LOG_WARN,
    [LSQLM_HSK_ADAPTER] = LSQ_LOG_WARN,
    [LSQLM_BBR]         = LSQ_LOG_WARN,
    [LSQLM_CUBIC]       = LSQ_LOG_WARN,
    [LSQLM_HEADERS]     = LSQ_LOG_WARN,
    [LSQLM_FRAME_READER]= LSQ_LOG_WARN,
    [LSQLM_FRAME_WRITER]= LSQ_LOG_WARN,
    [LSQLM_MINI_CONN]   = LSQ_LOG_WARN,
    [LSQLM_TOKGEN]      = LSQ_LOG_WARN,
    [LSQLM_ENG_HIST]    = LSQ_LOG_WARN,
    [LSQLM_SPI]         = LSQ_LOG_WARN,
    [LSQLM_DI]          = LSQ_LOG_WARN,
    [LSQLM_PRQ]         = LSQ_LOG_WARN,
    [LSQLM_PACER]       = LSQ_LOG_WARN,
    [LSQLM_MIN_HEAP]    = LSQ_LOG_WARN,
    [LSQLM_HTTP1X]      = LSQ_LOG_WARN,
    [LSQLM_QLOG]        = LSQ_LOG_WARN,
    [LSQLM_TRAPA]       = LSQ_LOG_WARN,
    [LSQLM_PURGA]       = LSQ_LOG_WARN,
    [LSQLM_HCSI_READER] = LSQ_LOG_WARN,
    [LSQLM_HCSO_WRITER] = LSQ_LOG_WARN,
    [LSQLM_QENC_HDL]    = LSQ_LOG_WARN,
    [LSQLM_QDEC_HDL]    = LSQ_LOG_WARN,
    [LSQLM_QPACK_ENC]    = LSQ_LOG_WARN,
    [LSQLM_QPACK_DEC]    = LSQ_LOG_WARN,
    [LSQLM_PRIO]        = LSQ_LOG_WARN,
    [LSQLM_BW_SAMPLER]  = LSQ_LOG_WARN,
};

const char *const lsqlm_to_str[N_LSQUIC_LOGGER_MODULES] = {
    [LSQLM_NOMODULE]    = "",
    [LSQLM_LOGGER]      = "logger",
    [LSQLM_EVENT]       = "event",
    [LSQLM_ENGINE]      = "engine",
    [LSQLM_CONN]        = "conn",
    [LSQLM_RECHIST]     = "rechist",
    [LSQLM_STREAM]      = "stream",
    [LSQLM_PARSE]       = "parse",
    [LSQLM_CFCW]        = "cfcw",
    [LSQLM_SFCW]        = "sfcw",
    [LSQLM_SENDCTL]     = "sendctl",
    [LSQLM_ALARMSET]    = "alarmset",
    [LSQLM_CRYPTO]      = "crypto",
    [LSQLM_HANDSHAKE]   = "handshake",
    [LSQLM_HSK_ADAPTER] = "hsk-adapter",
    [LSQLM_BBR]         = "bbr",
    [LSQLM_CUBIC]       = "cubic",
    [LSQLM_HEADERS]     = "headers",
    [LSQLM_FRAME_READER]= "frame-reader",
    [LSQLM_FRAME_WRITER]= "frame-writer",
    [LSQLM_MINI_CONN]   = "mini-conn",
    [LSQLM_TOKGEN]      = "tokgen",
    [LSQLM_ENG_HIST]    = "eng-hist",
    [LSQLM_SPI]         = "spi",
    [LSQLM_DI]          = "di",
    [LSQLM_PRQ]         = "prq",
    [LSQLM_PACER]       = "pacer",
    [LSQLM_MIN_HEAP]    = "min-heap",
    [LSQLM_HTTP1X]      = "http1x",
    [LSQLM_QLOG]        = "qlog",
    [LSQLM_TRAPA]       = "trapa",
    [LSQLM_PURGA]       = "purga",
    [LSQLM_HCSI_READER] = "hcsi-reader",
    [LSQLM_HCSO_WRITER] = "hcso-writer",
    [LSQLM_QENC_HDL]    = "qenc-hdl",
    [LSQLM_QDEC_HDL]    = "qdec-hdl",
    [LSQLM_QPACK_ENC]    = "qpack-enc",
    [LSQLM_QPACK_DEC]    = "qpack-dec",
    [LSQLM_PRIO]        = "prio",
    [LSQLM_BW_SAMPLER]  = "bw-sampler",
};

const char *const lsq_loglevel2str[N_LSQUIC_LOG_LEVELS] = {
    [LSQ_LOG_ALERT]   =  "ALERT",
    [LSQ_LOG_CRIT]    =  "CRIT",
    [LSQ_LOG_DEBUG]   =  "DEBUG",
    [LSQ_LOG_EMERG]   =  "EMERG",
    [LSQ_LOG_ERROR]   =  "ERROR",
    [LSQ_LOG_INFO]    =  "INFO",
    [LSQ_LOG_NOTICE]  =  "NOTICE",
    [LSQ_LOG_WARN]    =  "WARN",
};


#ifdef WIN32
#define DELTA_EPOCH_IN_TICKS  116444736000000000Ui64
struct timezone
{
    time_t tz_minuteswest;         /* minutes W of Greenwich */
    time_t tz_dsttime;             /* type of dst correction */
};

static int
gettimeofday (struct timeval *tv, struct timezone *tz)
{
    FILETIME ft;
    uint64_t tmpres;
    static int tzflag;

    if (NULL != tv)
    {
        GetSystemTimeAsFileTime(&ft);

        tmpres = ((uint64_t) ft.dwHighDateTime << 32)
               | (ft.dwLowDateTime);

        tmpres -= DELTA_EPOCH_IN_TICKS;
        tv->tv_sec = tmpres / 10000000;
        tv->tv_usec = tmpres % 1000000;
    }

    if (NULL != tz)
    {
        if (!tzflag)
        {
            _tzset();
            tzflag++;
        }
        tz->tz_minuteswest = _timezone / 60;
        tz->tz_dsttime = _daylight;
    }

    return 0;
}
#endif


static size_t
print_timestamp (char *buf, size_t max)
{
    struct tm tm;
    struct timeval tv;
    size_t len = 0;

    gettimeofday(&tv, NULL);
#ifdef WIN32
    {
        time_t t = tv.tv_sec;
#ifndef NDEBUG
        errno_t e =
#endif
	localtime_s(&tm, &t);
	assert(!e);
    }
#else
    localtime_r(&tv.tv_sec, &tm);
#endif
    if (g_llts == LLTS_YYYYMMDD_HHMMSSUS)
        len = snprintf(buf, max, "%04d-%02d-%02d %02d:%02d:%02d.%06d ",
            tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec));
    else if (g_llts == LLTS_YYYYMMDD_HHMMSSMS)
        len = snprintf(buf, max, "%04d-%02d-%02d %02d:%02d:%02d.%03d ",
            tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec / 1000));
    else if (g_llts == LLTS_HHMMSSMS)
        len = snprintf(buf, max, "%02d:%02d:%02d.%03d ",
            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec / 1000));
    else if (g_llts == LLTS_HHMMSSUS)
        len = snprintf(buf, max, "%02d:%02d:%02d.%06d ",
            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) tv.tv_usec);
    else if (g_llts == LLTS_CHROMELIKE)
        len = snprintf(buf, max, "%02d%02d/%02d%02d%02d.%06d ",
            tm.tm_mon + 1, tm.tm_mday,tm.tm_hour, tm.tm_min,
            tm.tm_sec, (int) tv.tv_usec);
    return len;
}


void
lsquic_logger_log3 (enum lsq_log_level log_level,
                    enum lsquic_logger_module module,
                    const lsquic_cid_t *conn_id, lsquic_stream_id_t stream_id,
                    const char *fmt, ...)
{
    const int saved_errno = errno;
    char cidbuf_[MAX_CID_LEN * 2 + 1];
    size_t len = 0;
    size_t lb;
    size_t max = MAX_LINE_LEN;
    char buf[MAX_LINE_LEN];

    if (g_llts != LLTS_NONE)
    {
        lb = print_timestamp(buf, max);
        if (FORMAT_PROBLEM(lb, len, max))
            goto end;
        len += lb;
    }
    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"-%"PRIu64"] %s: ",
        lsq_loglevel2str[log_level], CID_BITS(conn_id),
        stream_id, lsqlm_to_str[module]);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    va_list ap;
    va_start(ap, fmt);
    lb = vsnprintf(buf + len, max - len, fmt, ap);
    va_end(ap);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    lb = snprintf(buf + len, max - len, "\n");
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    logger_if->log_buf(logger_ctx, buf, len);
end:
    errno = saved_errno;
}


void
lsquic_logger_log2 (enum lsq_log_level log_level,
                    enum lsquic_logger_module module,
                    const struct lsquic_cid *conn_id, const char *fmt, ...)
{
    const int saved_errno = errno;
    char cidbuf_[MAX_CID_LEN * 2 + 1];
    size_t len = 0;
    size_t lb;
    size_t max = MAX_LINE_LEN;
    char buf[MAX_LINE_LEN];

    if (g_llts != LLTS_NONE)
    {
        lb = print_timestamp(buf, max);
        if (FORMAT_PROBLEM(lb, len, max))
            goto end;
        len += lb;
    }

    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"] %s: ",
        lsq_loglevel2str[log_level], CID_BITS(conn_id), lsqlm_to_str[module]);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    va_list ap;
    va_start(ap, fmt);
    lb = vsnprintf(buf + len, max - len, fmt, ap);
    va_end(ap);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    lb = snprintf(buf + len, max - len, "\n");
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    logger_if->log_buf(logger_ctx, buf, len);
end:
    errno = saved_errno;
}


void
lsquic_logger_log1 (enum lsq_log_level log_level,
                    enum lsquic_logger_module module,
                    const char *fmt, ...)
{
    const int saved_errno = errno;
    size_t len = 0;
    size_t lb;
    size_t max = MAX_LINE_LEN;
    char buf[MAX_LINE_LEN];

    if (g_llts != LLTS_NONE)
    {
        lb = print_timestamp(buf, max);
        if (FORMAT_PROBLEM(lb, len, max))
            goto end;
        len += lb;
    }
    lb = snprintf(buf + len, max - len, "[%s] %s: ", lsq_loglevel2str[log_level],
                                                lsqlm_to_str[module]);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    va_list ap;
    va_start(ap, fmt);
    lb = vsnprintf(buf + len, max - len, fmt, ap);
    va_end(ap);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    lb = snprintf(buf + len, max - len, "\n");
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    logger_if->log_buf(logger_ctx, buf, len);
end:
    errno = saved_errno;
}


void
lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
{
    const int saved_errno = errno;
    size_t len = 0;
    size_t lb;
    size_t max = MAX_LINE_LEN;
    char buf[MAX_LINE_LEN];

    if (g_llts != LLTS_NONE)
    {
        lb = print_timestamp(buf, max);
        if (FORMAT_PROBLEM(lb, len, max))
            goto end;
        len += lb;
    }

    lb = snprintf(buf + len, max - len, "[%s] ", lsq_loglevel2str[log_level]);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    va_list ap;
    va_start(ap, fmt);
    lb = vsnprintf(buf + len, max - len, fmt, ap);
    va_end(ap);
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    lb = snprintf(buf + len, max - len, "\n");
    if (FORMAT_PROBLEM(lb, len, max))
        goto end;
    len += lb;
    logger_if->log_buf(logger_ctx, buf, len);
end:
    errno = saved_errno;
}


void
lsquic_logger_init (const struct lsquic_logger_if *lif, void *lctx,
                    unsigned llts)
{
    logger_if  = lif;
    logger_ctx = lctx;
    if (llts < N_LLTS)
        g_llts = llts;
    LSQ_DEBUG("%s called", __func__);
}


enum lsquic_logger_module
lsquic_str_to_logger_module (const char *str)
{
    enum lsquic_logger_module i;
    for (i = 0; i < sizeof(lsqlm_to_str) / sizeof(lsqlm_to_str[0]); ++i)
        if (0 == strcasecmp(lsqlm_to_str[i], str))
            return i;
    return -1;
}


enum lsq_log_level
lsquic_str_to_log_level (const char *str)
{
    if (0 == strcasecmp(str, "emerg"))
        return LSQ_LOG_EMERG;
    if (0 == strcasecmp(str, "alert"))
        return LSQ_LOG_ALERT;
    if (0 == strcasecmp(str, "crit"))
        return LSQ_LOG_CRIT;
    if (0 == strcasecmp(str, "error"))
        return LSQ_LOG_ERROR;
    if (0 == strcasecmp(str, "warn"))
        return LSQ_LOG_WARN;
    if (0 == strcasecmp(str, "notice"))
        return LSQ_LOG_NOTICE;
    if (0 == strcasecmp(str, "info"))
        return LSQ_LOG_INFO;
    if (0 == strcasecmp(str, "debug"))
        return LSQ_LOG_DEBUG;
    return -1;
}


void
lsquic_log_to_fstream (FILE *file, unsigned llts)
{
    lsquic_logger_init(&file_logger_if, file, llts);
}


int
lsquic_logger_lopt (const char *optarg_orig)
{
    char *const optarg = strdup(optarg_orig);
    char *mod_str;
    int i;
    for (i = 0; (mod_str = strtok(i ? NULL : optarg, ",")); ++i) {
        char *level_str = strchr(mod_str, '=');
        if (!level_str) {
            fprintf(stderr, "Invalid module specification `%s'\n", mod_str);
            break;
        }
        *level_str = '\0';
        ++level_str;
        enum lsquic_logger_module mod = lsquic_str_to_logger_module(mod_str);
        if (-1 == (int) mod) {
            fprintf(stderr, "`%s' is not a valid module name\n", mod_str);
            break;
        }
        enum lsq_log_level level = lsquic_str_to_log_level(level_str);
        if (-1 == (int) level) {
            fprintf(stderr, "`%s' is not a valid level\n", level_str);
            break;
        }
        lsq_log_levels[mod] = level;
        LSQ_INFO("set %s to %s", mod_str, level_str);
    }
    free(optarg);
    return mod_str == NULL ? 0 : -1;
}


int
lsquic_set_log_level (const char *level_str)
{
    enum lsq_log_level level;
    unsigned i;

    level = lsquic_str_to_log_level(level_str);
    if ((int) level >= 0)
    {
        for (i = 0; i < sizeof(lsq_log_levels) / sizeof(lsq_log_levels[0]); ++i)
            lsq_log_levels[i] = level;
        return 0;
    }
    else
        return -1;
}


/* `out' must be at least MAX_CID_LEN * 2 + 1 characters long */
void
lsquic_cid2str (const lsquic_cid_t *cid, char *out)
{
    static const char hex[] = "0123456789ABCDEF";
    int i;

    for (i = 0; i < (int) cid->len; ++i)
    {
        *out++ = hex[ cid->idbuf[i] >> 4 ];
        *out++ = hex[ cid->idbuf[i] & 0xF ];
    }
    *out = '\0';
}