lsquic_logger.c revision 55cd0b38 
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_logger.h"
20#include "lsquic_byteswap.h"
21#include "lsquic.h"
22
23/* The switch to big-endian format in GQUIC also resulted in Chrome swapping
24 * the CID in its log.  We do the same thing in our log messages so that the
25 * CIDs are easy to match.  The exception is Q035, which is the last little-
26 * endian GQUIC version this library supports.
27 */
28#if __BYTE_ORDER == __LITTLE_ENDIAN
29#define DISP_CID(cid) bswap_64(cid)
30#else
31#define DISP_CID(cid) (cid)
32#endif
33
34static enum lsquic_logger_timestamp_style g_llts = LLTS_NONE;
35
36static int
37null_vprintf (void *ctx, const char *fmt, va_list ap)
38{
39    return 0;
40}
41
42
43static int
44file_vprintf (void *ctx, const char *fmt, va_list ap)
45{
46    return vfprintf((FILE *) ctx, fmt, ap);
47}
48
49
50static const struct lsquic_logger_if file_logger_if = {
51    .vprintf    = file_vprintf,
52};
53
54static const struct lsquic_logger_if null_logger_if = {
55    .vprintf    = null_vprintf,
56};
57
58static void *logger_ctx = NULL;
59static const struct lsquic_logger_if *logger_if = &null_logger_if;
60
61enum lsq_log_level lsq_log_levels[N_LSQUIC_LOGGER_MODULES] = {
62    [LSQLM_NOMODULE]    = LSQ_LOG_WARN,
63    [LSQLM_LOGGER]      = LSQ_LOG_WARN,
64    [LSQLM_EVENT]       = LSQ_LOG_WARN,
65    [LSQLM_ENGINE]      = LSQ_LOG_WARN,
66    [LSQLM_CONN]        = LSQ_LOG_WARN,
67    [LSQLM_RECHIST]     = LSQ_LOG_WARN,
68    [LSQLM_STREAM]      = LSQ_LOG_WARN,
69    [LSQLM_PARSE]       = LSQ_LOG_WARN,
70    [LSQLM_CFCW]        = LSQ_LOG_WARN,
71    [LSQLM_SFCW]        = LSQ_LOG_WARN,
72    [LSQLM_SENDCTL]     = LSQ_LOG_WARN,
73    [LSQLM_ALARMSET]    = LSQ_LOG_WARN,
74    [LSQLM_CRYPTO]      = LSQ_LOG_WARN,
75    [LSQLM_HANDSHAKE]   = LSQ_LOG_WARN,
76    [LSQLM_HSK_ADAPTER] = LSQ_LOG_WARN,
77    [LSQLM_CUBIC]       = LSQ_LOG_WARN,
78    [LSQLM_HEADERS]     = LSQ_LOG_WARN,
79    [LSQLM_FRAME_READER]= LSQ_LOG_WARN,
80    [LSQLM_FRAME_WRITER]= LSQ_LOG_WARN,
81    [LSQLM_CONN_HASH]   = LSQ_LOG_WARN,
82    [LSQLM_ENG_HIST]    = LSQ_LOG_WARN,
83    [LSQLM_SPI]         = LSQ_LOG_WARN,
84    [LSQLM_DI]          = LSQ_LOG_WARN,
85    [LSQLM_PACER]       = LSQ_LOG_WARN,
86    [LSQLM_MIN_HEAP]    = LSQ_LOG_WARN,
87    [LSQLM_HTTP1X]      = LSQ_LOG_WARN,
88    [LSQLM_QLOG]        = LSQ_LOG_WARN,
89};
90
91const char *const lsqlm_to_str[N_LSQUIC_LOGGER_MODULES] = {
92    [LSQLM_NOMODULE]    = "",
93    [LSQLM_LOGGER]      = "logger",
94    [LSQLM_EVENT]       = "event",
95    [LSQLM_ENGINE]      = "engine",
96    [LSQLM_CONN]        = "conn",
97    [LSQLM_RECHIST]     = "rechist",
98    [LSQLM_STREAM]      = "stream",
99    [LSQLM_PARSE]       = "parse",
100    [LSQLM_CFCW]        = "cfcw",
101    [LSQLM_SFCW]        = "sfcw",
102    [LSQLM_SENDCTL]     = "sendctl",
103    [LSQLM_ALARMSET]    = "alarmset",
104    [LSQLM_CRYPTO]      = "crypto",
105    [LSQLM_HANDSHAKE]   = "handshake",
106    [LSQLM_HSK_ADAPTER] = "hsk-adapter",
107    [LSQLM_CUBIC]       = "cubic",
108    [LSQLM_HEADERS]     = "headers",
109    [LSQLM_FRAME_READER]= "frame-reader",
110    [LSQLM_FRAME_WRITER]= "frame-writer",
111    [LSQLM_CONN_HASH]   = "conn-hash",
112    [LSQLM_ENG_HIST]    = "eng-hist",
113    [LSQLM_SPI]         = "spi",
114    [LSQLM_DI]          = "di",
115    [LSQLM_PACER]       = "pacer",
116    [LSQLM_MIN_HEAP]    = "min-heap",
117    [LSQLM_HTTP1X]      = "http1x",
118    [LSQLM_QLOG]        = "qlog",
119};
120
121const char *const lsq_loglevel2str[N_LSQUIC_LOG_LEVELS] = {
122    [LSQ_LOG_ALERT]   =  "ALERT",
123    [LSQ_LOG_CRIT]    =  "CRIT",
124    [LSQ_LOG_DEBUG]   =  "DEBUG",
125    [LSQ_LOG_EMERG]   =  "EMERG",
126    [LSQ_LOG_ERROR]   =  "ERROR",
127    [LSQ_LOG_INFO]    =  "INFO",
128    [LSQ_LOG_NOTICE]  =  "NOTICE",
129    [LSQ_LOG_WARN]    =  "WARN",
130};
131
132
133static void
134lsquic_printf (const char *fmt, ...)
135{
136    va_list ap;
137    va_start(ap, fmt);
138    logger_if->vprintf(logger_ctx, fmt, ap);
139    va_end(ap);
140}
141
142
143#ifdef WIN32
144#define DELTA_EPOCH_IN_TICKS  116444736000000000Ui64
145struct timezone
146{
147    time_t tz_minuteswest;         /* minutes W of Greenwich */
148    time_t tz_dsttime;             /* type of dst correction */
149};
150
151static int
152gettimeofday (struct timeval *tv, struct timezone *tz)
153{
154    FILETIME ft;
155    uint64_t tmpres;
156    static int tzflag;
157
158    if (NULL != tv)
159    {
160        GetSystemTimeAsFileTime(&ft);
161
162        tmpres = ((uint64_t) ft.dwHighDateTime << 32)
163               | (ft.dwLowDateTime);
164
165        tmpres -= DELTA_EPOCH_IN_TICKS;
166        tv->tv_sec = tmpres / 10000000;
167        tv->tv_usec = tmpres % 1000000;
168    }
169
170    if (NULL != tz)
171    {
172        if (!tzflag)
173        {
174            _tzset();
175            tzflag++;
176        }
177        tz->tz_minuteswest = _timezone / 60;
178        tz->tz_dsttime = _daylight;
179    }
180
181    return 0;
182}
183
184
185#endif
186
187
188static void
189print_timestamp (void)
190{
191    struct tm tm;
192    struct timeval tv;
193    gettimeofday(&tv, NULL);
194#ifdef WIN32
195    {
196        time_t t = tv.tv_sec;
197#ifndef NDEBUG
198        errno_t e =
199#endif
200	localtime_s(&tm, &t);
201	assert(!e);
202    }
203#else
204    localtime_r(&tv.tv_sec, &tm);
205#endif
206    if (g_llts == LLTS_YYYYMMDD_HHMMSSUS)
207        lsquic_printf("%04d-%02d-%02d %02d:%02d:%02d.%06d ",
208            tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
209            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec));
210    else if (g_llts == LLTS_YYYYMMDD_HHMMSSMS)
211        lsquic_printf("%04d-%02d-%02d %02d:%02d:%02d.%03d ",
212            tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
213            tm.tm_hour, tm.tm_min, tm.tm_sec, (int) (tv.tv_usec / 1000));
214    else if (g_llts == LLTS_HHMMSSMS)
215        lsquic_printf("%02d:%02d:%02d.%03d ", tm.tm_hour, tm.tm_min,
216                                    tm.tm_sec, (int) (tv.tv_usec / 1000));
217    else if (g_llts == LLTS_HHMMSSUS)
218        lsquic_printf("%02d:%02d:%02d.%06d ", tm.tm_hour, tm.tm_min,
219                                    tm.tm_sec, (int) tv.tv_usec);
220    else if (g_llts == LLTS_CHROMELIKE)
221        lsquic_printf("%02d%02d/%02d%02d%02d.%06d ", tm.tm_mon + 1,
222            tm.tm_mday,tm.tm_hour, tm.tm_min, tm.tm_sec, (int) tv.tv_usec);
223}
224
225
226void
227lsquic_logger_log3 (enum lsq_log_level log_level,
228                    enum lsquic_logger_module module,
229                    uint64_t conn_id, uint32_t stream_id, const char *fmt, ...)
230{
231    const int saved_errno = errno;
232
233    if (g_llts != LLTS_NONE)
234        print_timestamp();
235
236    lsquic_printf("[%s] [QUIC:%"PRIu64"-%"PRIu32"] %s: ",
237        lsq_loglevel2str[log_level], DISP_CID(conn_id), stream_id,
238        lsqlm_to_str[module]);
239    va_list ap;
240    va_start(ap, fmt);
241    logger_if->vprintf(logger_ctx, fmt, ap);
242    va_end(ap);
243    lsquic_printf("\n");
244    errno = saved_errno;
245}
246
247
248void
249lsquic_logger_log2 (enum lsq_log_level log_level,
250                    enum lsquic_logger_module module,
251                    uint64_t conn_id, const char *fmt, ...)
252{
253    const int saved_errno = errno;
254
255    if (g_llts != LLTS_NONE)
256        print_timestamp();
257
258    lsquic_printf("[%s] [QUIC:%"PRIu64"] %s: ",
259        lsq_loglevel2str[log_level], DISP_CID(conn_id), lsqlm_to_str[module]);
260    va_list ap;
261    va_start(ap, fmt);
262    logger_if->vprintf(logger_ctx, fmt, ap);
263    va_end(ap);
264    lsquic_printf("\n");
265    errno = saved_errno;
266}
267
268
269void
270lsquic_logger_log1 (enum lsq_log_level log_level,
271                    enum lsquic_logger_module module,
272                    const char *fmt, ...)
273{
274    const int saved_errno = errno;
275
276    if (g_llts != LLTS_NONE)
277        print_timestamp();
278
279    lsquic_printf("[%s] %s: ", lsq_loglevel2str[log_level],
280                                                lsqlm_to_str[module]);
281    va_list ap;
282    va_start(ap, fmt);
283    logger_if->vprintf(logger_ctx, fmt, ap);
284    va_end(ap);
285    lsquic_printf("\n");
286    errno = saved_errno;
287}
288
289
290void
291lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
292{
293    const int saved_errno = errno;
294
295    if (g_llts != LLTS_NONE)
296        print_timestamp();
297
298    lsquic_printf("[%s] ", lsq_loglevel2str[log_level]);
299    va_list ap;
300    va_start(ap, fmt);
301    logger_if->vprintf(logger_ctx, fmt, ap);
302    va_end(ap);
303    lsquic_printf("\n");
304    errno = saved_errno;
305}
306
307
308void
309lsquic_logger_init (const struct lsquic_logger_if *lif, void *lctx,
310                    unsigned llts)
311{
312    logger_if  = lif;
313    logger_ctx = lctx;
314    if (llts < N_LLTS)
315        g_llts = llts;
316    LSQ_DEBUG("%s called", __func__);
317}
318
319
320enum lsquic_logger_module
321lsquic_str_to_logger_module (const char *str)
322{
323    enum lsquic_logger_module i;
324    for (i = 0; i < sizeof(lsqlm_to_str) / sizeof(lsqlm_to_str[0]); ++i)
325        if (0 == strcasecmp(lsqlm_to_str[i], str))
326            return i;
327    return -1;
328}
329
330
331enum lsq_log_level
332lsquic_str_to_log_level (const char *str)
333{
334    if (0 == strcasecmp(str, "emerg"))
335        return LSQ_LOG_EMERG;
336    if (0 == strcasecmp(str, "alert"))
337        return LSQ_LOG_ALERT;
338    if (0 == strcasecmp(str, "crit"))
339        return LSQ_LOG_CRIT;
340    if (0 == strcasecmp(str, "error"))
341        return LSQ_LOG_ERROR;
342    if (0 == strcasecmp(str, "warn"))
343        return LSQ_LOG_WARN;
344    if (0 == strcasecmp(str, "notice"))
345        return LSQ_LOG_NOTICE;
346    if (0 == strcasecmp(str, "info"))
347        return LSQ_LOG_INFO;
348    if (0 == strcasecmp(str, "debug"))
349        return LSQ_LOG_DEBUG;
350    return -1;
351}
352
353
354void
355lsquic_log_to_fstream (FILE *file, unsigned llts)
356{
357    lsquic_logger_init(&file_logger_if, file, llts);
358}
359
360
361int
362lsquic_logger_lopt (const char *optarg_orig)
363{
364    char *const optarg = strdup(optarg_orig);
365    char *mod_str;
366    int i;
367    for (i = 0; (mod_str = strtok(i ? NULL : optarg, ",")); ++i) {
368        char *level_str = strchr(mod_str, '=');
369        if (!level_str) {
370            fprintf(stderr, "Invalid module specification `%s'\n", mod_str);
371            break;
372        }
373        *level_str = '\0';
374        ++level_str;
375        enum lsquic_logger_module mod = lsquic_str_to_logger_module(mod_str);
376        if (-1 == (int) mod) {
377            fprintf(stderr, "`%s' is not a valid module name\n", mod_str);
378            break;
379        }
380        enum lsq_log_level level = lsquic_str_to_log_level(level_str);
381        if (-1 == (int) level) {
382            fprintf(stderr, "`%s' is not a valid level\n", level_str);
383            break;
384        }
385        lsq_log_levels[mod] = level;
386        LSQ_INFO("set %s to %s", mod_str, level_str);
387    }
388    free(optarg);
389    return mod_str == NULL ? 0 : -1;
390}
391
392
393int
394lsquic_set_log_level (const char *level_str)
395{
396    enum lsq_log_level level;
397    unsigned i;
398
399    level = lsquic_str_to_log_level(level_str);
400    if ((int) level >= 0)
401    {
402        for (i = 0; i < sizeof(lsq_log_levels) / sizeof(lsq_log_levels[0]); ++i)
403            lsq_log_levels[i] = level;
404        return 0;
405    }
406    else
407        return -1;
408}
409