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