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