lsquic_logger.c revision 5392f7a3 
1/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc.  See LICENSE. */
2/*
3 * LSQUIC Logger implementation.
4 */
5
6#include <assert.h>
7#include <errno.h>
8#include <inttypes.h>
9#include <stdarg.h>
10#include <stdio.h>
11#include <stdlib.h>
12#include <string.h>
13#ifndef WIN32
14#include <sys/time.h>
15#endif
16#include <time.h>
17
18#define LSQUIC_LOGGER_MODULE LSQLM_LOGGER /* Quis custodiet ipsos custodes? */
19#include "lsquic.h"
20#include "lsquic_logger.h"
21
22#define MAX_LINE_LEN 8192
23#define FORMAT_PROBLEM(lb, len, max) (((ssize_t)lb < 0) || ((ssize_t)lb + (ssize_t)len >= (ssize_t)max))
24
25/* TODO: display GQUIC CIDs in Chrome-compatible format */
26
27static enum lsquic_logger_timestamp_style g_llts = LLTS_NONE;
28
29static int
30null_log_buf (void *ctx, const char *buf, size_t len)
31{
32    return 0;
33}
34
35static int
36file_log_buf (void *ctx, const char *buf, size_t len)
37{
38    return (int)fwrite(buf, sizeof(char), len, (FILE *) ctx);
39}
40
41static const struct lsquic_logger_if file_logger_if = {
42    .log_buf    = file_log_buf,
43};
44
45static const struct lsquic_logger_if null_logger_if = {
46    .log_buf    = null_log_buf,
47};
48
49static void *logger_ctx = NULL;
50static const struct lsquic_logger_if *logger_if = &null_logger_if;
51
52enum lsq_log_level lsq_log_levels[N_LSQUIC_LOGGER_MODULES] = {
53    [LSQLM_NOMODULE]    = LSQ_LOG_WARN,
54    [LSQLM_LOGGER]      = LSQ_LOG_WARN,
55    [LSQLM_EVENT]       = LSQ_LOG_WARN,
56    [LSQLM_ENGINE]      = LSQ_LOG_WARN,
57    [LSQLM_CONN]        = LSQ_LOG_WARN,
58    [LSQLM_RECHIST]     = LSQ_LOG_WARN,
59    [LSQLM_STREAM]      = LSQ_LOG_WARN,
60    [LSQLM_PARSE]       = LSQ_LOG_WARN,
61    [LSQLM_CFCW]        = LSQ_LOG_WARN,
62    [LSQLM_SFCW]        = LSQ_LOG_WARN,
63    [LSQLM_SENDCTL]     = LSQ_LOG_WARN,
64    [LSQLM_ALARMSET]    = LSQ_LOG_WARN,
65    [LSQLM_CRYPTO]      = LSQ_LOG_WARN,
66    [LSQLM_HANDSHAKE]   = LSQ_LOG_WARN,
67    [LSQLM_HSK_ADAPTER] = LSQ_LOG_WARN,
68    [LSQLM_BBR]         = LSQ_LOG_WARN,
69    [LSQLM_CUBIC]       = LSQ_LOG_WARN,
70    [LSQLM_HEADERS]     = LSQ_LOG_WARN,
71    [LSQLM_FRAME_READER]= LSQ_LOG_WARN,
72    [LSQLM_FRAME_WRITER]= LSQ_LOG_WARN,
73    [LSQLM_MINI_CONN]   = LSQ_LOG_WARN,
74    [LSQLM_TOKGEN]      = LSQ_LOG_WARN,
75    [LSQLM_ENG_HIST]    = LSQ_LOG_WARN,
76    [LSQLM_SPI]         = LSQ_LOG_WARN,
77    [LSQLM_DI]          = LSQ_LOG_WARN,
78    [LSQLM_PRQ]         = LSQ_LOG_WARN,
79    [LSQLM_PACER]       = LSQ_LOG_WARN,
80    [LSQLM_MIN_HEAP]    = LSQ_LOG_WARN,
81    [LSQLM_HTTP1X]      = LSQ_LOG_WARN,
82    [LSQLM_QLOG]        = LSQ_LOG_WARN,
83    [LSQLM_TRAPA]       = LSQ_LOG_WARN,
84    [LSQLM_PURGA]       = LSQ_LOG_WARN,
85    [LSQLM_HCSI_READER] = LSQ_LOG_WARN,
86    [LSQLM_HCSO_WRITER] = LSQ_LOG_WARN,
87    [LSQLM_QENC_HDL]    = LSQ_LOG_WARN,
88    [LSQLM_QDEC_HDL]    = LSQ_LOG_WARN,
89    [LSQLM_QPACK_ENC]    = LSQ_LOG_WARN,
90    [LSQLM_QPACK_DEC]    = LSQ_LOG_WARN,
91    [LSQLM_PRIO]        = LSQ_LOG_WARN,
92    [LSQLM_BW_SAMPLER]  = LSQ_LOG_WARN,
93};
94
95const char *const lsqlm_to_str[N_LSQUIC_LOGGER_MODULES] = {
96    [LSQLM_NOMODULE]    = "",
97    [LSQLM_LOGGER]      = "logger",
98    [LSQLM_EVENT]       = "event",
99    [LSQLM_ENGINE]      = "engine",
100    [LSQLM_CONN]        = "conn",
101    [LSQLM_RECHIST]     = "rechist",
102    [LSQLM_STREAM]      = "stream",
103    [LSQLM_PARSE]       = "parse",
104    [LSQLM_CFCW]        = "cfcw",
105    [LSQLM_SFCW]        = "sfcw",
106    [LSQLM_SENDCTL]     = "sendctl",
107    [LSQLM_ALARMSET]    = "alarmset",
108    [LSQLM_CRYPTO]      = "crypto",
109    [LSQLM_HANDSHAKE]   = "handshake",
110    [LSQLM_HSK_ADAPTER] = "hsk-adapter",
111    [LSQLM_BBR]         = "bbr",
112    [LSQLM_CUBIC]       = "cubic",
113    [LSQLM_HEADERS]     = "headers",
114    [LSQLM_FRAME_READER]= "frame-reader",
115    [LSQLM_FRAME_WRITER]= "frame-writer",
116    [LSQLM_MINI_CONN]   = "mini-conn",
117    [LSQLM_TOKGEN]      = "tokgen",
118    [LSQLM_ENG_HIST]    = "eng-hist",
119    [LSQLM_SPI]         = "spi",
120    [LSQLM_DI]          = "di",
121    [LSQLM_PRQ]         = "prq",
122    [LSQLM_PACER]       = "pacer",
123    [LSQLM_MIN_HEAP]    = "min-heap",
124    [LSQLM_HTTP1X]      = "http1x",
125    [LSQLM_QLOG]        = "qlog",
126    [LSQLM_TRAPA]       = "trapa",
127    [LSQLM_PURGA]       = "purga",
128    [LSQLM_HCSI_READER] = "hcsi-reader",
129    [LSQLM_HCSO_WRITER] = "hcso-writer",
130    [LSQLM_QENC_HDL]    = "qenc-hdl",
131    [LSQLM_QDEC_HDL]    = "qdec-hdl",
132    [LSQLM_QPACK_ENC]    = "qpack-enc",
133    [LSQLM_QPACK_DEC]    = "qpack-dec",
134    [LSQLM_PRIO]        = "prio",
135    [LSQLM_BW_SAMPLER]  = "bw-sampler",
136};
137
138const char *const lsq_loglevel2str[N_LSQUIC_LOG_LEVELS] = {
139    [LSQ_LOG_ALERT]   =  "ALERT",
140    [LSQ_LOG_CRIT]    =  "CRIT",
141    [LSQ_LOG_DEBUG]   =  "DEBUG",
142    [LSQ_LOG_EMERG]   =  "EMERG",
143    [LSQ_LOG_ERROR]   =  "ERROR",
144    [LSQ_LOG_INFO]    =  "INFO",
145    [LSQ_LOG_NOTICE]  =  "NOTICE",
146    [LSQ_LOG_WARN]    =  "WARN",
147};
148
149
150#ifdef WIN32
151#define DELTA_EPOCH_IN_TICKS  116444736000000000Ui64
152struct timezone
153{
154    time_t tz_minuteswest;         /* minutes W of Greenwich */
155    time_t tz_dsttime;             /* type of dst correction */
156};
157
158static int
159gettimeofday (struct timeval *tv, struct timezone *tz)
160{
161    FILETIME ft;
162    uint64_t tmpres;
163    static int tzflag;
164
165    if (NULL != tv)
166    {
167        GetSystemTimeAsFileTime(&ft);
168
169        tmpres = ((uint64_t) ft.dwHighDateTime << 32)
170               | (ft.dwLowDateTime);
171
172        tmpres -= DELTA_EPOCH_IN_TICKS;
173        tv->tv_sec = tmpres / 10000000;
174        tv->tv_usec = tmpres % 1000000;
175    }
176
177    if (NULL != tz)
178    {
179        if (!tzflag)
180        {
181            _tzset();
182            tzflag++;
183        }
184        tz->tz_minuteswest = _timezone / 60;
185        tz->tz_dsttime = _daylight;
186    }
187
188    return 0;
189}
190#endif
191
192
193static size_t
194print_timestamp (char *buf, size_t max)
195{
196    struct tm tm;
197    struct timeval tv;
198    size_t len = 0;
199
200    gettimeofday(&tv, NULL);
201#ifdef WIN32
202    {
203        time_t t = tv.tv_sec;
204#ifndef NDEBUG
205        errno_t e =
206#endif
207	localtime_s(&tm, &t);
208	assert(!e);
209    }
210#else
211    localtime_r(&tv.tv_sec, &tm);
212#endif
213    if (g_llts == LLTS_YYYYMMDD_HHMMSSUS)
214        len = snprintf(buf, max, "%04d-%02d-%02d %02d:%02d:%02d.%06d ",
215            tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
216            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec));
217    else if (g_llts == LLTS_YYYYMMDD_HHMMSSMS)
218        len = snprintf(buf, max, "%04d-%02d-%02d %02d:%02d:%02d.%03d ",
219            tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
220            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec / 1000));
221    else if (g_llts == LLTS_HHMMSSMS)
222        len = snprintf(buf, max, "%02d:%02d:%02d.%03d ",
223            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec / 1000));
224    else if (g_llts == LLTS_HHMMSSUS)
225        len = snprintf(buf, max, "%02d:%02d:%02d.%06d ",
226            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) tv.tv_usec);
227    else if (g_llts == LLTS_CHROMELIKE)
228        len = snprintf(buf, max, "%02d%02d/%02d%02d%02d.%06d ",
229            tm.tm_mon + 1, tm.tm_mday,tm.tm_hour, tm.tm_min,
230            tm.tm_sec, (int) tv.tv_usec);
231    return len;
232}
233
234
235void
236lsquic_logger_log3 (enum lsq_log_level log_level,
237                    enum lsquic_logger_module module,
238                    const lsquic_cid_t *conn_id, lsquic_stream_id_t stream_id,
239                    const char *fmt, ...)
240{
241    const int saved_errno = errno;
242    char cidbuf_[MAX_CID_LEN * 2 + 1];
243    size_t len = 0;
244    size_t lb;
245    size_t max = MAX_LINE_LEN;
246    char buf[MAX_LINE_LEN];
247
248    if (g_llts != LLTS_NONE)
249    {
250        lb = print_timestamp(buf, max);
251        if (FORMAT_PROBLEM(lb, len, max))
252            goto end;
253        len += lb;
254    }
255    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"-%"PRIu64"] %s: ",
256        lsq_loglevel2str[log_level], CID_BITS(conn_id),
257        stream_id, lsqlm_to_str[module]);
258    if (FORMAT_PROBLEM(lb, len, max))
259        goto end;
260    len += lb;
261    va_list ap;
262    va_start(ap, fmt);
263    lb = vsnprintf(buf + len, max - len, fmt, ap);
264    if (FORMAT_PROBLEM(lb, len, max))
265        goto end;
266    len += lb;
267    va_end(ap);
268    lb = snprintf(buf + len, max - len, "\n");
269    if (FORMAT_PROBLEM(lb, len, max))
270        goto end;
271    len += lb;
272    logger_if->log_buf(logger_ctx, buf, len);
273end:
274    errno = saved_errno;
275}
276
277
278void
279lsquic_logger_log2 (enum lsq_log_level log_level,
280                    enum lsquic_logger_module module,
281                    const struct lsquic_cid *conn_id, const char *fmt, ...)
282{
283    const int saved_errno = errno;
284    char cidbuf_[MAX_CID_LEN * 2 + 1];
285    size_t len = 0;
286    size_t lb;
287    size_t max = MAX_LINE_LEN;
288    char buf[MAX_LINE_LEN];
289
290    if (g_llts != LLTS_NONE)
291    {
292        lb = print_timestamp(buf, max);
293        if (FORMAT_PROBLEM(lb, len, max))
294            goto end;
295        len += lb;
296    }
297
298    lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"] %s: ",
299        lsq_loglevel2str[log_level], CID_BITS(conn_id), lsqlm_to_str[module]);
300    if (FORMAT_PROBLEM(lb, len, max))
301        goto end;
302    len += lb;
303    va_list ap;
304    va_start(ap, fmt);
305    lb = vsnprintf(buf + len, max - len, fmt, ap);
306    if (FORMAT_PROBLEM(lb, len, max))
307        goto end;
308    len += lb;
309    va_end(ap);
310    lb = snprintf(buf + len, max - len, "\n");
311    if (FORMAT_PROBLEM(lb, len, max))
312        goto end;
313    len += lb;
314    logger_if->log_buf(logger_ctx, buf, len);
315end:
316    errno = saved_errno;
317}
318
319
320void
321lsquic_logger_log1 (enum lsq_log_level log_level,
322                    enum lsquic_logger_module module,
323                    const char *fmt, ...)
324{
325    const int saved_errno = errno;
326    size_t len = 0;
327    size_t lb;
328    size_t max = MAX_LINE_LEN;
329    char buf[MAX_LINE_LEN];
330
331    if (g_llts != LLTS_NONE)
332    {
333        lb = print_timestamp(buf, max);
334        if (FORMAT_PROBLEM(lb, len, max))
335            goto end;
336        len += lb;
337    }
338    lb = snprintf(buf + len, max - len, "[%s] %s: ", lsq_loglevel2str[log_level],
339                                                lsqlm_to_str[module]);
340    if (FORMAT_PROBLEM(lb, len, max))
341        goto end;
342    len += lb;
343    va_list ap;
344    va_start(ap, fmt);
345    lb = vsnprintf(buf + len, max - len, fmt, ap);
346    if (FORMAT_PROBLEM(lb, len, max))
347        goto end;
348    len += lb;
349    va_end(ap);
350    lb = snprintf(buf + len, max - len, "\n");
351    if (FORMAT_PROBLEM(lb, len, max))
352        goto end;
353    len += lb;
354    logger_if->log_buf(logger_ctx, buf, len);
355end:
356    errno = saved_errno;
357}
358
359
360void
361lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
362{
363    const int saved_errno = errno;
364    size_t len = 0;
365    size_t lb;
366    size_t max = MAX_LINE_LEN;
367    char buf[MAX_LINE_LEN];
368
369    if (g_llts != LLTS_NONE)
370    {
371        lb = print_timestamp(buf, max);
372        if (FORMAT_PROBLEM(lb, len, max))
373            goto end;
374        len += lb;
375    }
376
377    lb = snprintf(buf + len, max - len, "[%s] ", lsq_loglevel2str[log_level]);
378    if (FORMAT_PROBLEM(lb, len, max))
379        goto end;
380    len += lb;
381    va_list ap;
382    va_start(ap, fmt);
383    lb = vsnprintf(buf + len, max - len, fmt, ap);
384    va_end(ap);
385    if (FORMAT_PROBLEM(lb, len, max))
386        goto end;
387    len += lb;
388    lb = snprintf(buf + len, max - len, "\n");
389    if (FORMAT_PROBLEM(lb, len, max))
390        goto end;
391    len += lb;
392    logger_if->log_buf(logger_ctx, buf, len);
393end:
394    errno = saved_errno;
395}
396
397
398void
399lsquic_logger_init (const struct lsquic_logger_if *lif, void *lctx,
400                    unsigned llts)
401{
402    logger_if  = lif;
403    logger_ctx = lctx;
404    if (llts < N_LLTS)
405        g_llts = llts;
406    LSQ_DEBUG("%s called", __func__);
407}
408
409
410enum lsquic_logger_module
411lsquic_str_to_logger_module (const char *str)
412{
413    enum lsquic_logger_module i;
414    for (i = 0; i < sizeof(lsqlm_to_str) / sizeof(lsqlm_to_str[0]); ++i)
415        if (0 == strcasecmp(lsqlm_to_str[i], str))
416            return i;
417    return -1;
418}
419
420
421enum lsq_log_level
422lsquic_str_to_log_level (const char *str)
423{
424    if (0 == strcasecmp(str, "emerg"))
425        return LSQ_LOG_EMERG;
426    if (0 == strcasecmp(str, "alert"))
427        return LSQ_LOG_ALERT;
428    if (0 == strcasecmp(str, "crit"))
429        return LSQ_LOG_CRIT;
430    if (0 == strcasecmp(str, "error"))
431        return LSQ_LOG_ERROR;
432    if (0 == strcasecmp(str, "warn"))
433        return LSQ_LOG_WARN;
434    if (0 == strcasecmp(str, "notice"))
435        return LSQ_LOG_NOTICE;
436    if (0 == strcasecmp(str, "info"))
437        return LSQ_LOG_INFO;
438    if (0 == strcasecmp(str, "debug"))
439        return LSQ_LOG_DEBUG;
440    return -1;
441}
442
443
444void
445lsquic_log_to_fstream (FILE *file, unsigned llts)
446{
447    lsquic_logger_init(&file_logger_if, file, llts);
448}
449
450
451int
452lsquic_logger_lopt (const char *optarg_orig)
453{
454    char *const optarg = strdup(optarg_orig);
455    char *mod_str;
456    int i;
457    for (i = 0; (mod_str = strtok(i ? NULL : optarg, ",")); ++i) {
458        char *level_str = strchr(mod_str, '=');
459        if (!level_str) {
460            fprintf(stderr, "Invalid module specification `%s'\n", mod_str);
461            break;
462        }
463        *level_str = '\0';
464        ++level_str;
465        enum lsquic_logger_module mod = lsquic_str_to_logger_module(mod_str);
466        if (-1 == (int) mod) {
467            fprintf(stderr, "`%s' is not a valid module name\n", mod_str);
468            break;
469        }
470        enum lsq_log_level level = lsquic_str_to_log_level(level_str);
471        if (-1 == (int) level) {
472            fprintf(stderr, "`%s' is not a valid level\n", level_str);
473            break;
474        }
475        lsq_log_levels[mod] = level;
476        LSQ_INFO("set %s to %s", mod_str, level_str);
477    }
478    free(optarg);
479    return mod_str == NULL ? 0 : -1;
480}
481
482
483int
484lsquic_set_log_level (const char *level_str)
485{
486    enum lsq_log_level level;
487    unsigned i;
488
489    level = lsquic_str_to_log_level(level_str);
490    if ((int) level >= 0)
491    {
492        for (i = 0; i < sizeof(lsq_log_levels) / sizeof(lsq_log_levels[0]); ++i)
493            lsq_log_levels[i] = level;
494        return 0;
495    }
496    else
497        return -1;
498}
499
500
501/* `out' must be at least MAX_CID_LEN * 2 + 1 characters long */
502void
503lsquic_cid2str (const lsquic_cid_t *cid, char *out)
504{
505    static const char hex[] = "0123456789ABCDEF";
506    int i;
507
508    for (i = 0; i < (int) cid->len; ++i)
509    {
510        *out++ = hex[ cid->idbuf[i] >> 4 ];
511        *out++ = hex[ cid->idbuf[i] & 0xF ];
512    }
513    *out = '\0';
514}
515