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