a4514206bae289bdc8e0b6509fb9f4534308e57b
[vpp.git] / src / vlib / log.c
1 /*
2  * Copyright (c) 2018 Cisco and/or its affiliates.
3  * Licensed under the Apache License, Version 2.0 (the "License");
4  * you may not use this file except in compliance with the License.
5  * You may obtain a copy of the License at:
6  *
7  *     http://www.apache.org/licenses/LICENSE-2.0
8  *
9  * Unless required by applicable law or agreed to in writing, software
10  * distributed under the License is distributed on an "AS IS" BASIS,
11  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12  * See the License for the specific language governing permissions and
13  * limitations under the License.
14  */
15
16 #include <stdbool.h>
17 #include <vlib/vlib.h>
18 #include <vlib/log.h>
19 #include <vlib/unix/unix.h>
20 #include <syslog.h>
21
22 vlib_log_main_t log_main = {
23   .default_log_level = VLIB_LOG_LEVEL_NOTICE,
24   .default_syslog_log_level = VLIB_LOG_LEVEL_WARNING,
25   .unthrottle_time = 3,
26   .size = 512,
27   .default_rate_limit = 50,
28 };
29
30 static const int colors[] = {
31   [VLIB_LOG_LEVEL_EMERG] = 1,   /* red */
32   [VLIB_LOG_LEVEL_ALERT] = 1,   /* red */
33   [VLIB_LOG_LEVEL_CRIT] = 1,    /* red */
34   [VLIB_LOG_LEVEL_ERR] = 1,     /* red */
35   [VLIB_LOG_LEVEL_WARNING] = 3, /* yellow */
36   [VLIB_LOG_LEVEL_NOTICE] = 2,  /* green */
37   [VLIB_LOG_LEVEL_INFO] = 4,    /* blue */
38   [VLIB_LOG_LEVEL_DEBUG] = 6,   /* cyan */
39 };
40
41 int
42 last_log_entry ()
43 {
44   vlib_log_main_t *lm = &log_main;
45   int i;
46
47   i = lm->next - lm->count;
48
49   if (i < 0)
50     i += lm->size;
51   return i;
52 }
53
54 static vlib_log_class_data_t *
55 get_class_data (vlib_log_class_t ci)
56 {
57   vlib_log_main_t *lm = &log_main;
58   return vec_elt_at_index (lm->classes, (ci >> 16));
59 }
60
61 static vlib_log_subclass_data_t *
62 get_subclass_data (vlib_log_class_t ci)
63 {
64   vlib_log_class_data_t *c = get_class_data (ci);
65   return vec_elt_at_index (c->subclasses, (ci & 0xffff));
66 }
67
68 static int
69 vlib_log_level_to_syslog_priority (vlib_log_level_t level)
70 {
71   switch (level)
72     {
73 #define LOG_DISABLED LOG_DEBUG
74 #define _(n,uc,lc) \
75     case VLIB_LOG_LEVEL_##uc:\
76       return LOG_##uc;
77       foreach_vlib_log_level
78 #undef _
79 #undef LOG_DISABLED
80     }
81   return LOG_DEBUG;
82 }
83
84 u8 *
85 format_vlib_log_class (u8 * s, va_list * args)
86 {
87   vlib_log_class_t ci = va_arg (*args, vlib_log_class_t);
88   vlib_log_class_data_t *c = get_class_data (ci);
89   vlib_log_subclass_data_t *sc = get_subclass_data (ci);
90
91   if (sc->name)
92     return format (s, "%v/%v", c->name, sc->name);
93   else
94     return format (s, "%v", c->name, 0);
95 }
96
97 u8 *
98 format_indent (u8 * s, va_list * args)
99 {
100   u8 *v = va_arg (*args, u8 *);
101   u32 indent = va_arg (*args, u32);
102   u8 *c;
103
104   /* *INDENT-OFF* */
105   vec_foreach (c, v)
106     {
107       vec_add (s, c, 1);
108       if (c[0] == '\n')
109         for (u32 i = 0; i < indent; i++)
110           vec_add1 (s, (u8) ' ');
111     }
112   /* *INDENT-ON* */
113   return s;
114 }
115
116 static int
117 log_level_is_enabled (vlib_log_level_t level, vlib_log_level_t configured)
118 {
119   if (configured == VLIB_LOG_LEVEL_DISABLED)
120     return 0;
121   if (level > configured)
122     return 0;
123   return 1;
124 }
125
126 void
127 vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
128 {
129   vlib_main_t *vm = vlib_get_main ();
130   vlib_log_main_t *lm = &log_main;
131   vlib_log_entry_t *e;
132   vlib_log_subclass_data_t *sc = get_subclass_data (class);
133   va_list va;
134   f64 t = vlib_time_now (vm);
135   f64 delta = t - sc->last_event_timestamp;
136   int log_enabled = log_level_is_enabled (level, sc->level);
137   int syslog_enabled = log_level_is_enabled (level, sc->syslog_level);
138   u8 *s = 0;
139
140   /* make sure we are running on the main thread to avoid use in dataplane
141      code, for dataplane logging consider use of event-logger */
142   ASSERT (vlib_get_thread_index () == 0);
143
144   if ((log_enabled || syslog_enabled) == 0)
145     return;
146
147   vec_validate (lm->entries, lm->size);
148
149   if ((delta > lm->unthrottle_time) ||
150       (sc->is_throttling == 0 && (delta > 1)))
151     {
152       sc->last_event_timestamp = t;
153       sc->last_sec_count = 0;
154       sc->is_throttling = 0;
155     }
156   else
157     {
158       sc->last_sec_count++;
159       if (sc->last_sec_count > sc->rate_limit)
160         return;
161       else if (sc->last_sec_count == sc->rate_limit)
162         {
163           vec_reset_length (s);
164           s = format (s, "--- message(s) throttled ---");
165           sc->is_throttling = 1;
166         }
167     }
168
169   if (s == 0)
170     {
171       va_start (va, fmt);
172       s = va_format (s, fmt, &va);
173       va_end (va);
174     }
175
176   if (syslog_enabled)
177     {
178       u8 *l = 0;
179       if (unix_main.flags & (UNIX_FLAG_INTERACTIVE | UNIX_FLAG_NOSYSLOG))
180         {
181           int indent = 0;
182           int with_colors = (unix_main.flags & UNIX_FLAG_NOCOLOR) == 0;
183           u8 *fmt;
184           if (with_colors)
185             {
186               l = format (l, "\x1b[%um", 90 + colors[level]);
187               indent = vec_len (l);
188             }
189           fmt = format (0, "%%-%uU [%%-6U]: ", lm->max_class_name_length);
190           l = format (l, (char *) fmt, format_vlib_log_class, class,
191                       format_vlib_log_level, level);
192           vec_free (fmt);
193           indent = vec_len (l) - indent;
194           if (with_colors)
195             l = format (l, "\x1b[0m");
196           l = format (l, "%U", format_indent, s, indent);
197           fformat (stderr, "%v\n", l);
198           fflush (stderr);
199         }
200       else
201         {
202           l = format (l, "%U", format_vlib_log_class, class);
203           int prio = vlib_log_level_to_syslog_priority (level);
204           int is_term = vec_c_string_is_terminated (l) ? 1 : 0;
205
206           syslog (prio, "%.*s: %.*s", (int) vec_len (l), l,
207                   (int) vec_len (s) - is_term, s);
208         }
209       vec_free (l);
210     }
211
212   if (log_enabled)
213     {
214       e = vec_elt_at_index (lm->entries, lm->next);
215       vec_free (e->string);
216       e->level = level;
217       e->class = class;
218       e->string = s;
219       e->timestamp = t;
220       s = 0;
221
222       lm->next = (lm->next + 1) % lm->size;
223       if (lm->size > lm->count)
224         lm->count++;
225     }
226
227   vec_free (s);
228 }
229
230 static vlib_log_class_t
231 vlib_log_register_class_internal (char *class, char *subclass, u32 limit)
232 {
233   vlib_log_main_t *lm = &log_main;
234   vlib_log_class_data_t *c = NULL;
235   vlib_log_subclass_data_t *s;
236   vlib_log_class_data_t *tmp;
237   u32 length = 0;
238
239   vec_foreach (tmp, lm->classes)
240   {
241     if (vec_len (tmp->name) != strlen (class))
242       continue;
243     if (!memcmp (class, tmp->name, vec_len (tmp->name)))
244       {
245         c = tmp;
246         break;
247       }
248   }
249   if (!c)
250     {
251       vec_add2 (lm->classes, c, 1);
252       c->index = c - lm->classes;
253       c->name = format (0, "%s", class);
254       length = vec_len (c->name);
255     }
256
257   vec_add2 (c->subclasses, s, 1);
258   s->index = s - c->subclasses;
259   s->name = subclass ? format (0, "%s", subclass) : 0;
260   s->rate_limit = (limit == 0) ? lm->default_rate_limit : limit;
261   s->level = lm->default_log_level;
262   s->syslog_level = lm->default_syslog_log_level;
263   if (subclass)
264     length += 1 + vec_len (s->name);
265   if (length > lm->max_class_name_length)
266     lm->max_class_name_length = length;
267   return (c->index << 16) | (s->index);
268 }
269
270 vlib_log_class_t
271 vlib_log_register_class (char *class, char *subclass)
272 {
273   return vlib_log_register_class_internal (class, subclass,
274                                            0 /* default rate limit */ );
275 }
276
277 vlib_log_class_t
278 vlib_log_register_class_rate_limit (char *class, char *subclass, u32 limit)
279 {
280   return vlib_log_register_class_internal (class, subclass, limit);
281 }
282
283
284 u8 *
285 format_vlib_log_level (u8 * s, va_list * args)
286 {
287   vlib_log_level_t i = va_arg (*args, vlib_log_level_t);
288   char *t = 0;
289
290   switch (i)
291     {
292 #define _(v,uc,lc) case VLIB_LOG_LEVEL_##uc: t = #lc; break;
293       foreach_vlib_log_level
294 #undef _
295     default:
296       return format (s, "unknown");
297     }
298   return format (s, "%s", t);
299 }
300
301 static clib_error_t *
302 vlib_log_init (vlib_main_t * vm)
303 {
304   vlib_log_main_t *lm = &log_main;
305
306   gettimeofday (&lm->time_zero_timeval, 0);
307   lm->time_zero = vlib_time_now (vm);
308
309   vec_validate (lm->entries, lm->size);
310   lm->log_class = vlib_log_register_class ("log", 0);
311   return 0;
312 }
313
314 VLIB_INIT_FUNCTION (vlib_log_init);
315
316
317 static clib_error_t *
318 show_log (vlib_main_t * vm,
319           unformat_input_t * input, vlib_cli_command_t * cmd)
320 {
321   clib_error_t *error = 0;
322   vlib_log_main_t *lm = &log_main;
323   vlib_log_entry_t *e;
324   int i = last_log_entry ();
325   int count = lm->count;
326   f64 time_offset;
327
328   time_offset = (f64) lm->time_zero_timeval.tv_sec
329     + (((f64) lm->time_zero_timeval.tv_usec) * 1e-6) - lm->time_zero;
330
331   while (count--)
332     {
333       e = vec_elt_at_index (lm->entries, i);
334       vlib_cli_output (vm, "%U %-10U %-14U %v",
335                        format_time_float, 0, e->timestamp + time_offset,
336                        format_vlib_log_level, e->level,
337                        format_vlib_log_class, e->class, e->string);
338       i = (i + 1) % lm->size;
339     }
340
341   return error;
342 }
343
344 /* *INDENT-OFF* */
345 VLIB_CLI_COMMAND (cli_show_log, static) = {
346   .path = "show logging",
347   .short_help = "show logging",
348   .function = show_log,
349 };
350 /* *INDENT-ON* */
351
352 static clib_error_t *
353 show_log_config (vlib_main_t * vm,
354                  unformat_input_t * input, vlib_cli_command_t * cmd)
355 {
356   clib_error_t *error = 0;
357   vlib_log_main_t *lm = &log_main;
358   vlib_log_class_data_t *c;
359   vlib_log_subclass_data_t *sc;
360
361   vlib_cli_output (vm, "%-20s %u entries", "Buffer Size:", lm->size);
362   vlib_cli_output (vm, "Defaults:\n");
363   vlib_cli_output (vm, "%-20s %U", "  Log Level:",
364                    format_vlib_log_level, lm->default_log_level);
365   vlib_cli_output (vm, "%-20s %U", "  Syslog Log Level:",
366                    format_vlib_log_level, lm->default_syslog_log_level);
367   vlib_cli_output (vm, "%-20s %u msgs/sec", "  Rate Limit:",
368                    lm->default_rate_limit);
369   vlib_cli_output (vm, "\n");
370   vlib_cli_output (vm, "%-22s %-14s %-14s %s",
371                    "Class/Subclass", "Level", "Syslog Level", "Rate Limit");
372
373
374   u8 *defstr = format (0, "default");
375   vec_foreach (c, lm->classes)
376   {
377     vlib_cli_output (vm, "%v", c->name);
378     vec_foreach (sc, c->subclasses)
379     {
380       vlib_cli_output (vm, "  %-20v %-14U %-14U %d",
381                        sc->name ? sc->name : defstr,
382                        format_vlib_log_level, sc->level,
383                        format_vlib_log_level, sc->syslog_level,
384                        sc->rate_limit);
385     }
386   }
387   vec_free (defstr);
388
389   return error;
390 }
391
392 /* *INDENT-OFF* */
393 VLIB_CLI_COMMAND (cli_show_log_config, static) = {
394   .path = "show logging configuration",
395   .short_help = "show logging configuration",
396   .function = show_log_config,
397 };
398 /* *INDENT-ON* */
399
400 static clib_error_t *
401 clear_log (vlib_main_t * vm,
402            unformat_input_t * input, vlib_cli_command_t * cmd)
403 {
404   clib_error_t *error = 0;
405   vlib_log_main_t *lm = &log_main;
406   vlib_log_entry_t *e;
407   int i = last_log_entry ();
408   int count = lm->count;
409
410   while (count--)
411     {
412       e = vec_elt_at_index (lm->entries, i);
413       vec_free (e->string);
414       i = (i + 1) % lm->size;
415     }
416
417   lm->count = 0;
418   lm->next = 0;
419   vlib_log_info (lm->log_class, "log cleared");
420   return error;
421 }
422
423 /* *INDENT-OFF* */
424 VLIB_CLI_COMMAND (cli_clear_log, static) = {
425   .path = "clear logging",
426   .short_help = "clear logging",
427   .function = clear_log,
428 };
429 /* *INDENT-ON* */
430
431 static uword
432 unformat_vlib_log_level (unformat_input_t * input, va_list * args)
433 {
434   vlib_log_level_t *level = va_arg (*args, vlib_log_level_t *);
435   u8 *level_str = NULL;
436   uword rv = 1;
437   if (unformat (input, "%s", &level_str))
438     {
439 #define _(v, uc, lc)                                   \
440   const char __##uc[] = #lc;                           \
441   if (!strcmp ((const char *) level_str, __##uc))       \
442     {                                                  \
443       *level = VLIB_LOG_LEVEL_##uc;                 \
444       rv = 1;                                          \
445       goto done;                                       \
446     }
447       foreach_vlib_log_level;
448       rv = 0;
449 #undef _
450     }
451 done:
452   vec_free (level_str);
453   return rv;
454 }
455
456 static uword
457 unformat_vlib_log_class (unformat_input_t * input, va_list * args)
458 {
459   vlib_log_class_data_t **class = va_arg (*args, vlib_log_class_data_t **);
460   uword rv = 0;
461   u8 *class_str = NULL;
462   vlib_log_main_t *lm = &log_main;
463   if (unformat (input, "%v", &class_str))
464     {
465       vlib_log_class_data_t *cdata;
466       vec_foreach (cdata, lm->classes)
467       {
468         if (vec_is_equal (cdata->name, class_str))
469           {
470             *class = cdata;
471             rv = 1;
472             break;
473           }
474       }
475     }
476   vec_free (class_str);
477   return rv;
478 }
479
480 static clib_error_t *
481 set_log_class (vlib_main_t * vm,
482                unformat_input_t * input, vlib_cli_command_t * cmd)
483 {
484   unformat_input_t _line_input, *line_input = &_line_input;
485   clib_error_t *rv = NULL;
486   int rate_limit;
487   bool set_rate_limit = false;
488   bool set_level = false;
489   bool set_syslog_level = false;
490   vlib_log_level_t level;
491   vlib_log_level_t syslog_level;
492
493   /* Get a line of input. */
494   if (!unformat_user (input, unformat_line_input, line_input))
495     return 0;
496
497   vlib_log_class_data_t *class = NULL;
498   if (!unformat (line_input, "%U", unformat_vlib_log_class, &class))
499     {
500       return clib_error_return (0, "unknown log class `%U'",
501                                 format_unformat_error, line_input);
502     }
503   while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT)
504     {
505       if (unformat (line_input, "rate-limit %d", &rate_limit))
506         {
507           set_rate_limit = true;
508         }
509       else
510         if (unformat
511             (line_input, "level %U", unformat_vlib_log_level, &level))
512         {
513           set_level = true;
514         }
515       else
516         if (unformat
517             (line_input, "syslog-level %U", unformat_vlib_log_level,
518              &syslog_level))
519         {
520           set_syslog_level = true;
521         }
522       else
523         {
524           return clib_error_return (0, "unknown input `%U'",
525                                     format_unformat_error, line_input);
526         }
527     }
528
529   if (set_level)
530     {
531       vlib_log_subclass_data_t *subclass;
532       vec_foreach (subclass, class->subclasses)
533       {
534         subclass->level = level;
535       }
536     }
537   if (set_syslog_level)
538     {
539       vlib_log_subclass_data_t *subclass;
540       vec_foreach (subclass, class->subclasses)
541       {
542         subclass->syslog_level = syslog_level;
543       }
544     }
545   if (set_rate_limit)
546     {
547       vlib_log_subclass_data_t *subclass;
548       vec_foreach (subclass, class->subclasses)
549       {
550         subclass->rate_limit = rate_limit;
551       }
552     }
553
554   return rv;
555 }
556
557 /* *INDENT-OFF* */
558 VLIB_CLI_COMMAND (cli_set_log, static) = {
559   .path = "set logging class",
560   .short_help = "set logging class <class> [rate-limit <int>] "
561     "[level <level>] [syslog-level <level>]",
562   .function = set_log_class,
563 };
564 /* *INDENT-ON* */
565
566 static clib_error_t *
567 set_log_unth_time (vlib_main_t * vm,
568                    unformat_input_t * input, vlib_cli_command_t * cmd)
569 {
570   unformat_input_t _line_input, *line_input = &_line_input;
571   clib_error_t *rv = NULL;
572   int unthrottle_time;
573   vlib_log_main_t *lm = &log_main;
574
575   /* Get a line of input. */
576   if (!unformat_user (input, unformat_line_input, line_input))
577     return 0;
578
579   while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT)
580     {
581       if (unformat (line_input, "%d", &unthrottle_time))
582         lm->unthrottle_time = unthrottle_time;
583       else
584         return clib_error_return (0, "unknown input `%U'",
585                                   format_unformat_error, line_input);
586     }
587
588   return rv;
589 }
590
591 /* *INDENT-OFF* */
592 VLIB_CLI_COMMAND (cli_set_log_params, static) = {
593   .path = "set logging unthrottle-time",
594   .short_help = "set logging unthrottle-time <int>",
595   .function = set_log_unth_time,
596 };
597 /* *INDENT-ON* */
598
599 static clib_error_t *
600 set_log_size (vlib_main_t * vm,
601               unformat_input_t * input, vlib_cli_command_t * cmd)
602 {
603   unformat_input_t _line_input, *line_input = &_line_input;
604   clib_error_t *rv = NULL;
605   int size;
606   vlib_log_main_t *lm = &log_main;
607
608   /* Get a line of input. */
609   if (!unformat_user (input, unformat_line_input, line_input))
610     return 0;
611
612   while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT)
613     {
614       if (unformat (line_input, "%d", &size))
615         {
616           lm->size = size;
617           vec_validate (lm->entries, lm->size);
618         }
619       else
620         return clib_error_return (0, "unknown input `%U'",
621                                   format_unformat_error, line_input);
622     }
623
624   return rv;
625 }
626
627 /* *INDENT-OFF* */
628 VLIB_CLI_COMMAND (cli_set_log_size, static) = {
629   .path = "set logging size",
630   .short_help = "set logging size <int>",
631   .function = set_log_size,
632 };
633 /* *INDENT-ON* */
634
635 static uword
636 unformat_vlib_log_subclass (unformat_input_t * input, va_list * args)
637 {
638   vlib_log_class_data_t *class = va_arg (*args, vlib_log_class_data_t *);
639   vlib_log_subclass_data_t **subclass =
640     va_arg (*args, vlib_log_subclass_data_t **);
641   uword rv = 0;
642   u8 *subclass_str = NULL;
643   if (unformat (input, "%v", &subclass_str))
644     {
645       vlib_log_subclass_data_t *scdata;
646       vec_foreach (scdata, class->subclasses)
647       {
648         if (vec_is_equal (scdata->name, subclass_str))
649           {
650             rv = 1;
651             *subclass = scdata;
652             break;
653           }
654       }
655     }
656   vec_free (subclass_str);
657   return rv;
658 }
659
660 static clib_error_t *
661 test_log_class_subclass (vlib_main_t * vm,
662                          unformat_input_t * input, vlib_cli_command_t * cmd)
663 {
664   unformat_input_t _line_input, *line_input = &_line_input;
665   /* Get a line of input. */
666   if (!unformat_user (input, unformat_line_input, line_input))
667     return 0;
668
669   vlib_log_class_data_t *class = NULL;
670   vlib_log_subclass_data_t *subclass = NULL;
671   vlib_log_level_t level;
672   if (unformat (line_input, "%U", unformat_vlib_log_level, &level))
673     {
674       if (unformat (line_input, "%U", unformat_vlib_log_class, &class))
675         {
676           if (unformat
677               (line_input, "%U", unformat_vlib_log_subclass, class,
678                &subclass))
679             {
680               vlib_log (level,
681                         (class->index << 16) | (subclass->index), "%U",
682                         format_unformat_input, line_input);
683             }
684           else
685             {
686               return clib_error_return (0,
687                                         "unknown log subclass near beginning of `%U'",
688                                         format_unformat_error, line_input);
689             }
690         }
691       else
692         {
693           return clib_error_return (0,
694                                     "unknown log class near beginning of `%U'",
695                                     format_unformat_error, line_input);
696         }
697     }
698   else
699     {
700       return clib_error_return (0, "unknown log level near beginning of `%U'",
701                                 format_unformat_error, line_input);
702     }
703   return 0;
704 }
705
706 /* *INDENT-OFF* */
707 VLIB_CLI_COMMAND (cli_test_log, static) = {
708   .path = "test log",
709   .short_help = "test log <level> <class> <subclass> <message>",
710   .function = test_log_class_subclass,
711 };
712 /* *INDENT-ON* */
713
714 static clib_error_t *
715 log_config (vlib_main_t * vm, unformat_input_t * input)
716 {
717   vlib_log_main_t *lm = &log_main;
718
719   while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT)
720     {
721       if (unformat (input, "size %d", &lm->size))
722         vec_validate (lm->entries, lm->size);
723       else if (unformat (input, "unthrottle-time %d", &lm->unthrottle_time))
724         ;
725       else if (unformat (input, "default-log-level %U",
726                          unformat_vlib_log_level, &lm->default_log_level))
727         ;
728       else if (unformat (input, "default-syslog-log-level %U",
729                          unformat_vlib_log_level,
730                          &lm->default_syslog_log_level))
731         ;
732       else
733         {
734           return unformat_parse_error (input);
735         }
736     }
737
738   return 0;
739 }
740
741 VLIB_EARLY_CONFIG_FUNCTION (log_config, "logging");
742
743 /*
744  * fd.io coding-style-patch-verification: ON
745  *
746  * Local Variables:
747  * eval: (c-set-style "gnu")
748  * End:
749  */