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