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