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