]>
Commit | Line | Data |
---|---|---|
064af421 | 1 | /* |
4958e3ee | 2 | * Copyright (c) 2008, 2009, 2010, 2011, 2012, 2013 Nicira, Inc. |
064af421 | 3 | * |
a14bc59f BP |
4 | * Licensed under the Apache License, Version 2.0 (the "License"); |
5 | * you may not use this file except in compliance with the License. | |
6 | * You may obtain a copy of the License at: | |
064af421 | 7 | * |
a14bc59f BP |
8 | * http://www.apache.org/licenses/LICENSE-2.0 |
9 | * | |
10 | * Unless required by applicable law or agreed to in writing, software | |
11 | * distributed under the License is distributed on an "AS IS" BASIS, | |
12 | * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | |
13 | * See the License for the specific language governing permissions and | |
14 | * limitations under the License. | |
064af421 BP |
15 | */ |
16 | ||
17 | #include <config.h> | |
18 | #include "vlog.h" | |
19 | #include <assert.h> | |
20 | #include <ctype.h> | |
21 | #include <errno.h> | |
9eb94563 | 22 | #include <fcntl.h> |
064af421 BP |
23 | #include <stdarg.h> |
24 | #include <stdlib.h> | |
25 | #include <string.h> | |
68cb8aaf | 26 | #include <sys/stat.h> |
064af421 BP |
27 | #include <sys/types.h> |
28 | #include <syslog.h> | |
29 | #include <time.h> | |
30 | #include <unistd.h> | |
4958e3ee | 31 | #include "coverage.h" |
064af421 BP |
32 | #include "dirs.h" |
33 | #include "dynamic-string.h" | |
cbb13e8e | 34 | #include "ofpbuf.h" |
064af421 | 35 | #include "sat-math.h" |
8628b0b7 | 36 | #include "svec.h" |
064af421 BP |
37 | #include "timeval.h" |
38 | #include "unixctl.h" | |
39 | #include "util.h" | |
cbb13e8e | 40 | #include "worker.h" |
064af421 | 41 | |
d98e6007 | 42 | VLOG_DEFINE_THIS_MODULE(vlog); |
064af421 | 43 | |
4958e3ee BP |
44 | COVERAGE_DEFINE(vlog_recursive); |
45 | ||
46 | /* ovs_assert() logs the assertion message, so using ovs_assert() in this | |
47 | * source file could cause recursion. */ | |
48 | #undef ovs_assert | |
49 | #define ovs_assert use_assert_instead_of_ovs_assert_in_this_module | |
50 | ||
064af421 | 51 | /* Name for each logging level. */ |
4b5f1d2c | 52 | static const char *const level_names[VLL_N_LEVELS] = { |
064af421 BP |
53 | #define VLOG_LEVEL(NAME, SYSLOG_LEVEL) #NAME, |
54 | VLOG_LEVELS | |
55 | #undef VLOG_LEVEL | |
56 | }; | |
57 | ||
58 | /* Syslog value for each logging level. */ | |
4b5f1d2c | 59 | static const int syslog_levels[VLL_N_LEVELS] = { |
064af421 BP |
60 | #define VLOG_LEVEL(NAME, SYSLOG_LEVEL) SYSLOG_LEVEL, |
61 | VLOG_LEVELS | |
62 | #undef VLOG_LEVEL | |
63 | }; | |
64 | ||
480ce8ab BP |
65 | /* The log modules. */ |
66 | #if USE_LINKER_SECTIONS | |
67 | extern struct vlog_module *__start_vlog_modules[]; | |
68 | extern struct vlog_module *__stop_vlog_modules[]; | |
69 | #define vlog_modules __start_vlog_modules | |
70 | #define n_vlog_modules (__stop_vlog_modules - __start_vlog_modules) | |
71 | #else | |
72 | #define VLOG_MODULE VLOG_DEFINE_MODULE__ | |
73 | #include "vlog-modules.def" | |
74 | #undef VLOG_MODULE | |
75 | ||
76 | struct vlog_module *vlog_modules[] = { | |
77 | #define VLOG_MODULE(NAME) &VLM_##NAME, | |
064af421 BP |
78 | #include "vlog-modules.def" |
79 | #undef VLOG_MODULE | |
80 | }; | |
480ce8ab BP |
81 | #define n_vlog_modules ARRAY_SIZE(vlog_modules) |
82 | #endif | |
064af421 BP |
83 | |
84 | /* Information about each facility. */ | |
85 | struct facility { | |
86 | const char *name; /* Name. */ | |
87 | char *pattern; /* Current pattern. */ | |
88 | bool default_pattern; /* Whether current pattern is the default. */ | |
89 | }; | |
90 | static struct facility facilities[VLF_N_FACILITIES] = { | |
91 | #define VLOG_FACILITY(NAME, PATTERN) {#NAME, PATTERN, true}, | |
92 | VLOG_FACILITIES | |
93 | #undef VLOG_FACILITY | |
94 | }; | |
95 | ||
064af421 BP |
96 | /* VLF_FILE configuration. */ |
97 | static char *log_file_name; | |
9eb94563 | 98 | static int log_fd = -1; |
064af421 | 99 | |
1e8cf0f7 BP |
100 | /* vlog initialized? */ |
101 | static bool vlog_inited; | |
102 | ||
480ce8ab | 103 | static void format_log_message(const struct vlog_module *, enum vlog_level, |
064af421 BP |
104 | enum vlog_facility, unsigned int msg_num, |
105 | const char *message, va_list, struct ds *) | |
106 | PRINTF_FORMAT(5, 0); | |
cbb13e8e BP |
107 | static void vlog_write_file(struct ds *); |
108 | static void vlog_update_async_log_fd(void); | |
064af421 BP |
109 | |
110 | /* Searches the 'n_names' in 'names'. Returns the index of a match for | |
111 | * 'target', or 'n_names' if no name matches. */ | |
112 | static size_t | |
4b5f1d2c | 113 | search_name_array(const char *target, const char *const *names, size_t n_names) |
064af421 BP |
114 | { |
115 | size_t i; | |
116 | ||
117 | for (i = 0; i < n_names; i++) { | |
118 | assert(names[i]); | |
119 | if (!strcasecmp(names[i], target)) { | |
120 | break; | |
121 | } | |
122 | } | |
123 | return i; | |
124 | } | |
125 | ||
126 | /* Returns the name for logging level 'level'. */ | |
127 | const char * | |
128 | vlog_get_level_name(enum vlog_level level) | |
129 | { | |
130 | assert(level < VLL_N_LEVELS); | |
131 | return level_names[level]; | |
132 | } | |
133 | ||
134 | /* Returns the logging level with the given 'name', or VLL_N_LEVELS if 'name' | |
135 | * is not the name of a logging level. */ | |
136 | enum vlog_level | |
d295e8e9 | 137 | vlog_get_level_val(const char *name) |
064af421 BP |
138 | { |
139 | return search_name_array(name, level_names, ARRAY_SIZE(level_names)); | |
140 | } | |
141 | ||
142 | /* Returns the name for logging facility 'facility'. */ | |
143 | const char * | |
d295e8e9 | 144 | vlog_get_facility_name(enum vlog_facility facility) |
064af421 BP |
145 | { |
146 | assert(facility < VLF_N_FACILITIES); | |
147 | return facilities[facility].name; | |
148 | } | |
149 | ||
150 | /* Returns the logging facility named 'name', or VLF_N_FACILITIES if 'name' is | |
151 | * not the name of a logging facility. */ | |
152 | enum vlog_facility | |
d295e8e9 | 153 | vlog_get_facility_val(const char *name) |
064af421 BP |
154 | { |
155 | size_t i; | |
156 | ||
157 | for (i = 0; i < VLF_N_FACILITIES; i++) { | |
158 | if (!strcasecmp(facilities[i].name, name)) { | |
159 | break; | |
160 | } | |
161 | } | |
162 | return i; | |
163 | } | |
164 | ||
165 | /* Returns the name for logging module 'module'. */ | |
480ce8ab BP |
166 | const char * |
167 | vlog_get_module_name(const struct vlog_module *module) | |
064af421 | 168 | { |
480ce8ab | 169 | return module->name; |
064af421 BP |
170 | } |
171 | ||
480ce8ab BP |
172 | /* Returns the logging module named 'name', or NULL if 'name' is not the name |
173 | * of a logging module. */ | |
174 | struct vlog_module * | |
175 | vlog_module_from_name(const char *name) | |
064af421 | 176 | { |
480ce8ab BP |
177 | struct vlog_module **mp; |
178 | ||
179 | for (mp = vlog_modules; mp < &vlog_modules[n_vlog_modules]; mp++) { | |
180 | if (!strcasecmp(name, (*mp)->name)) { | |
181 | return *mp; | |
182 | } | |
183 | } | |
184 | return NULL; | |
064af421 BP |
185 | } |
186 | ||
187 | /* Returns the current logging level for the given 'module' and 'facility'. */ | |
188 | enum vlog_level | |
d295e8e9 | 189 | vlog_get_level(const struct vlog_module *module, enum vlog_facility facility) |
064af421 | 190 | { |
064af421 | 191 | assert(facility < VLF_N_FACILITIES); |
480ce8ab | 192 | return module->levels[facility]; |
064af421 BP |
193 | } |
194 | ||
195 | static void | |
480ce8ab | 196 | update_min_level(struct vlog_module *module) |
064af421 | 197 | { |
064af421 BP |
198 | enum vlog_facility facility; |
199 | ||
c1a543a8 | 200 | module->min_level = VLL_OFF; |
064af421 | 201 | for (facility = 0; facility < VLF_N_FACILITIES; facility++) { |
9eb94563 | 202 | if (log_fd >= 0 || facility != VLF_FILE) { |
480ce8ab | 203 | enum vlog_level level = module->levels[facility]; |
56cee53b | 204 | if (level > module->min_level) { |
480ce8ab BP |
205 | module->min_level = level; |
206 | } | |
064af421 BP |
207 | } |
208 | } | |
064af421 BP |
209 | } |
210 | ||
211 | static void | |
480ce8ab | 212 | set_facility_level(enum vlog_facility facility, struct vlog_module *module, |
064af421 BP |
213 | enum vlog_level level) |
214 | { | |
215 | assert(facility >= 0 && facility < VLF_N_FACILITIES); | |
216 | assert(level < VLL_N_LEVELS); | |
217 | ||
480ce8ab BP |
218 | if (!module) { |
219 | struct vlog_module **mp; | |
220 | ||
221 | for (mp = vlog_modules; mp < &vlog_modules[n_vlog_modules]; mp++) { | |
222 | (*mp)->levels[facility] = level; | |
223 | update_min_level(*mp); | |
064af421 BP |
224 | } |
225 | } else { | |
480ce8ab | 226 | module->levels[facility] = level; |
064af421 BP |
227 | update_min_level(module); |
228 | } | |
229 | } | |
230 | ||
480ce8ab BP |
231 | /* Sets the logging level for the given 'module' and 'facility' to 'level'. A |
232 | * null 'module' or a 'facility' of VLF_ANY_FACILITY is treated as a wildcard | |
233 | * across all modules or facilities, respectively. */ | |
064af421 | 234 | void |
480ce8ab | 235 | vlog_set_levels(struct vlog_module *module, enum vlog_facility facility, |
d295e8e9 | 236 | enum vlog_level level) |
064af421 BP |
237 | { |
238 | assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY); | |
239 | if (facility == VLF_ANY_FACILITY) { | |
240 | for (facility = 0; facility < VLF_N_FACILITIES; facility++) { | |
241 | set_facility_level(facility, module, level); | |
242 | } | |
243 | } else { | |
244 | set_facility_level(facility, module, level); | |
245 | } | |
246 | } | |
247 | ||
248 | static void | |
d295e8e9 | 249 | do_set_pattern(enum vlog_facility facility, const char *pattern) |
064af421 BP |
250 | { |
251 | struct facility *f = &facilities[facility]; | |
252 | if (!f->default_pattern) { | |
253 | free(f->pattern); | |
254 | } else { | |
255 | f->default_pattern = false; | |
256 | } | |
257 | f->pattern = xstrdup(pattern); | |
258 | } | |
259 | ||
260 | /* Sets the pattern for the given 'facility' to 'pattern'. */ | |
261 | void | |
262 | vlog_set_pattern(enum vlog_facility facility, const char *pattern) | |
263 | { | |
264 | assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY); | |
265 | if (facility == VLF_ANY_FACILITY) { | |
266 | for (facility = 0; facility < VLF_N_FACILITIES; facility++) { | |
267 | do_set_pattern(facility, pattern); | |
268 | } | |
269 | } else { | |
270 | do_set_pattern(facility, pattern); | |
271 | } | |
272 | } | |
273 | ||
274 | /* Returns the name of the log file used by VLF_FILE, or a null pointer if no | |
275 | * log file has been set. (A non-null return value does not assert that the | |
276 | * named log file is in use: if vlog_set_log_file() or vlog_reopen_log_file() | |
277 | * fails, it still sets the log file name.) */ | |
278 | const char * | |
279 | vlog_get_log_file(void) | |
280 | { | |
281 | return log_file_name; | |
282 | } | |
283 | ||
284 | /* Sets the name of the log file used by VLF_FILE to 'file_name', or to the | |
285 | * default file name if 'file_name' is null. Returns 0 if successful, | |
286 | * otherwise a positive errno value. */ | |
287 | int | |
288 | vlog_set_log_file(const char *file_name) | |
289 | { | |
290 | char *old_log_file_name; | |
480ce8ab | 291 | struct vlog_module **mp; |
064af421 BP |
292 | int error; |
293 | ||
294 | /* Close old log file. */ | |
9eb94563 | 295 | if (log_fd >= 0) { |
064af421 | 296 | VLOG_INFO("closing log file"); |
9eb94563 BP |
297 | close(log_fd); |
298 | log_fd = -1; | |
064af421 BP |
299 | } |
300 | ||
301 | /* Update log file name and free old name. The ordering is important | |
302 | * because 'file_name' might be 'log_file_name' or some suffix of it. */ | |
303 | old_log_file_name = log_file_name; | |
304 | log_file_name = (file_name | |
305 | ? xstrdup(file_name) | |
b43c6fe2 | 306 | : xasprintf("%s/%s.log", ovs_logdir(), program_name)); |
064af421 BP |
307 | free(old_log_file_name); |
308 | file_name = NULL; /* Might have been freed. */ | |
309 | ||
310 | /* Open new log file and update min_levels[] to reflect whether we actually | |
311 | * have a log_file. */ | |
9eb94563 | 312 | log_fd = open(log_file_name, O_WRONLY | O_CREAT | O_APPEND, 0666); |
cbb13e8e BP |
313 | if (log_fd >= 0) { |
314 | vlog_update_async_log_fd(); | |
315 | } | |
480ce8ab BP |
316 | for (mp = vlog_modules; mp < &vlog_modules[n_vlog_modules]; mp++) { |
317 | update_min_level(*mp); | |
064af421 BP |
318 | } |
319 | ||
320 | /* Log success or failure. */ | |
9eb94563 | 321 | if (log_fd < 0) { |
064af421 BP |
322 | VLOG_WARN("failed to open %s for logging: %s", |
323 | log_file_name, strerror(errno)); | |
324 | error = errno; | |
325 | } else { | |
326 | VLOG_INFO("opened log file %s", log_file_name); | |
327 | error = 0; | |
328 | } | |
329 | ||
330 | return error; | |
331 | } | |
332 | ||
333 | /* Closes and then attempts to re-open the current log file. (This is useful | |
334 | * just after log rotation, to ensure that the new log file starts being used.) | |
335 | * Returns 0 if successful, otherwise a positive errno value. */ | |
336 | int | |
337 | vlog_reopen_log_file(void) | |
338 | { | |
68cb8aaf BP |
339 | struct stat old, new; |
340 | ||
341 | /* Skip re-opening if there's nothing to reopen. */ | |
342 | if (!log_file_name) { | |
343 | return 0; | |
344 | } | |
345 | ||
346 | /* Skip re-opening if it would be a no-op because the old and new files are | |
347 | * the same. (This avoids writing "closing log file" followed immediately | |
348 | * by "opened log file".) */ | |
9eb94563 BP |
349 | if (log_fd >= 0 |
350 | && !fstat(log_fd, &old) | |
68cb8aaf BP |
351 | && !stat(log_file_name, &new) |
352 | && old.st_dev == new.st_dev | |
353 | && old.st_ino == new.st_ino) { | |
354 | return 0; | |
355 | } | |
356 | ||
357 | return vlog_set_log_file(log_file_name); | |
064af421 BP |
358 | } |
359 | ||
2a3e30b2 BP |
360 | /* Set debugging levels. Returns null if successful, otherwise an error |
361 | * message that the caller must free(). */ | |
064af421 BP |
362 | char * |
363 | vlog_set_levels_from_string(const char *s_) | |
364 | { | |
064af421 | 365 | char *s = xstrdup(s_); |
2a3e30b2 BP |
366 | char *save_ptr = NULL; |
367 | char *msg = NULL; | |
368 | char *word; | |
064af421 | 369 | |
2a3e30b2 BP |
370 | word = strtok_r(s, " ,:\t", &save_ptr); |
371 | if (word && !strcasecmp(word, "PATTERN")) { | |
372 | enum vlog_facility facility; | |
064af421 | 373 | |
2a3e30b2 BP |
374 | word = strtok_r(NULL, " ,:\t", &save_ptr); |
375 | if (!word) { | |
376 | msg = xstrdup("missing facility"); | |
377 | goto exit; | |
064af421 BP |
378 | } |
379 | ||
2a3e30b2 BP |
380 | facility = (!strcasecmp(word, "ANY") |
381 | ? VLF_ANY_FACILITY | |
382 | : vlog_get_facility_val(word)); | |
383 | if (facility == VLF_N_FACILITIES) { | |
384 | msg = xasprintf("unknown facility \"%s\"", word); | |
385 | goto exit; | |
386 | } | |
387 | vlog_set_pattern(facility, save_ptr); | |
388 | } else { | |
389 | struct vlog_module *module = NULL; | |
390 | enum vlog_level level = VLL_N_LEVELS; | |
391 | enum vlog_facility facility = VLF_N_FACILITIES; | |
392 | ||
393 | for (; word != NULL; word = strtok_r(NULL, " ,:\t", &save_ptr)) { | |
394 | if (!strcasecmp(word, "ANY")) { | |
395 | continue; | |
396 | } else if (vlog_get_facility_val(word) != VLF_N_FACILITIES) { | |
397 | if (facility != VLF_N_FACILITIES) { | |
398 | msg = xstrdup("cannot specify multiple facilities"); | |
399 | goto exit; | |
064af421 | 400 | } |
2a3e30b2 BP |
401 | facility = vlog_get_facility_val(word); |
402 | } else if (vlog_get_level_val(word) != VLL_N_LEVELS) { | |
403 | if (level != VLL_N_LEVELS) { | |
404 | msg = xstrdup("cannot specify multiple levels"); | |
405 | goto exit; | |
406 | } | |
407 | level = vlog_get_level_val(word); | |
408 | } else if (vlog_module_from_name(word)) { | |
409 | if (module) { | |
410 | msg = xstrdup("cannot specify multiple modules"); | |
411 | goto exit; | |
412 | } | |
413 | module = vlog_module_from_name(word); | |
414 | } else { | |
415 | msg = xasprintf("no facility, level, or module \"%s\"", word); | |
416 | goto exit; | |
064af421 | 417 | } |
2a3e30b2 | 418 | } |
064af421 | 419 | |
2a3e30b2 BP |
420 | if (facility == VLF_N_FACILITIES) { |
421 | facility = VLF_ANY_FACILITY; | |
422 | } | |
423 | if (level == VLL_N_LEVELS) { | |
424 | level = VLL_DBG; | |
064af421 | 425 | } |
2a3e30b2 | 426 | vlog_set_levels(module, facility, level); |
064af421 | 427 | } |
2a3e30b2 BP |
428 | |
429 | exit: | |
064af421 | 430 | free(s); |
2a3e30b2 | 431 | return msg; |
064af421 BP |
432 | } |
433 | ||
316bd0f8 BP |
434 | /* Set debugging levels. Abort with an error message if 's' is invalid. */ |
435 | void | |
436 | vlog_set_levels_from_string_assert(const char *s) | |
437 | { | |
438 | char *error = vlog_set_levels_from_string(s); | |
439 | if (error) { | |
440 | ovs_fatal(0, "%s", error); | |
441 | } | |
442 | } | |
443 | ||
064af421 BP |
444 | /* If 'arg' is null, configure maximum verbosity. Otherwise, sets |
445 | * configuration according to 'arg' (see vlog_set_levels_from_string()). */ | |
446 | void | |
447 | vlog_set_verbosity(const char *arg) | |
448 | { | |
449 | if (arg) { | |
450 | char *msg = vlog_set_levels_from_string(arg); | |
451 | if (msg) { | |
452 | ovs_fatal(0, "processing \"%s\": %s", arg, msg); | |
453 | } | |
454 | } else { | |
480ce8ab | 455 | vlog_set_levels(NULL, VLF_ANY_FACILITY, VLL_DBG); |
064af421 BP |
456 | } |
457 | } | |
458 | ||
459 | static void | |
0e15264f BP |
460 | vlog_unixctl_set(struct unixctl_conn *conn, int argc, const char *argv[], |
461 | void *aux OVS_UNUSED) | |
064af421 | 462 | { |
0e15264f BP |
463 | int i; |
464 | ||
465 | for (i = 1; i < argc; i++) { | |
466 | char *msg = vlog_set_levels_from_string(argv[i]); | |
467 | if (msg) { | |
bde9f75d | 468 | unixctl_command_reply_error(conn, msg); |
0e15264f BP |
469 | free(msg); |
470 | return; | |
471 | } | |
472 | } | |
bde9f75d | 473 | unixctl_command_reply(conn, NULL); |
064af421 BP |
474 | } |
475 | ||
476 | static void | |
0e15264f BP |
477 | vlog_unixctl_list(struct unixctl_conn *conn, int argc OVS_UNUSED, |
478 | const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED) | |
064af421 BP |
479 | { |
480 | char *msg = vlog_get_levels(); | |
bde9f75d | 481 | unixctl_command_reply(conn, msg); |
064af421 BP |
482 | free(msg); |
483 | } | |
484 | ||
485 | static void | |
0e15264f BP |
486 | vlog_unixctl_reopen(struct unixctl_conn *conn, int argc OVS_UNUSED, |
487 | const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED) | |
064af421 BP |
488 | { |
489 | if (log_file_name) { | |
490 | int error = vlog_reopen_log_file(); | |
491 | if (error) { | |
bde9f75d | 492 | unixctl_command_reply_error(conn, strerror(errno)); |
064af421 | 493 | } else { |
bde9f75d | 494 | unixctl_command_reply(conn, NULL); |
064af421 BP |
495 | } |
496 | } else { | |
bde9f75d | 497 | unixctl_command_reply_error(conn, "Logging to file not configured"); |
064af421 BP |
498 | } |
499 | } | |
500 | ||
4958e3ee BP |
501 | static void |
502 | set_all_rate_limits(bool enable) | |
503 | { | |
504 | struct vlog_module **mp; | |
505 | ||
506 | for (mp = vlog_modules; mp < &vlog_modules[n_vlog_modules]; mp++) { | |
507 | (*mp)->honor_rate_limits = enable; | |
508 | } | |
509 | } | |
510 | ||
511 | static void | |
512 | set_rate_limits(struct unixctl_conn *conn, int argc, | |
513 | const char *argv[], bool enable) | |
514 | { | |
515 | if (argc > 1) { | |
516 | int i; | |
517 | ||
518 | for (i = 1; i < argc; i++) { | |
519 | if (!strcasecmp(argv[i], "ANY")) { | |
520 | set_all_rate_limits(enable); | |
521 | } else { | |
522 | struct vlog_module *module = vlog_module_from_name(argv[i]); | |
523 | if (!module) { | |
524 | unixctl_command_reply_error(conn, "unknown module"); | |
525 | return; | |
526 | } | |
527 | module->honor_rate_limits = enable; | |
528 | } | |
529 | } | |
530 | } else { | |
531 | set_all_rate_limits(enable); | |
532 | } | |
533 | unixctl_command_reply(conn, NULL); | |
534 | } | |
535 | ||
536 | static void | |
537 | vlog_enable_rate_limit(struct unixctl_conn *conn, int argc, | |
538 | const char *argv[], void *aux OVS_UNUSED) | |
539 | { | |
540 | set_rate_limits(conn, argc, argv, true); | |
541 | } | |
542 | ||
543 | static void | |
544 | vlog_disable_rate_limit(struct unixctl_conn *conn, int argc, | |
545 | const char *argv[], void *aux OVS_UNUSED) | |
546 | { | |
547 | set_rate_limits(conn, argc, argv, false); | |
548 | } | |
549 | ||
df5d2ed9 BP |
550 | /* Initializes the logging subsystem and registers its unixctl server |
551 | * commands. */ | |
064af421 | 552 | void |
d295e8e9 | 553 | vlog_init(void) |
064af421 | 554 | { |
487657b2 | 555 | static char *program_name_copy; |
064af421 BP |
556 | time_t now; |
557 | ||
1e8cf0f7 BP |
558 | if (vlog_inited) { |
559 | return; | |
560 | } | |
561 | vlog_inited = true; | |
562 | ||
487657b2 BP |
563 | /* openlog() is allowed to keep the pointer passed in, without making a |
564 | * copy. The daemonize code sometimes frees and replaces 'program_name', | |
565 | * so make a private copy just for openlog(). (We keep a pointer to the | |
566 | * private copy to suppress memory leak warnings in case openlog() does | |
567 | * make its own copy.) */ | |
568 | program_name_copy = program_name ? xstrdup(program_name) : NULL; | |
569 | openlog(program_name_copy, LOG_NDELAY, LOG_DAEMON); | |
064af421 | 570 | |
c73814a3 | 571 | now = time_wall(); |
064af421 BP |
572 | if (now < 0) { |
573 | struct tm tm; | |
574 | char s[128]; | |
575 | ||
3123c8fd BP |
576 | gmtime_r(&now, &tm); |
577 | strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S", &tm); | |
064af421 BP |
578 | VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now); |
579 | } | |
580 | ||
0e15264f | 581 | unixctl_command_register( |
2a3e30b2 | 582 | "vlog/set", "{spec | PATTERN:facility:pattern}", |
0e15264f BP |
583 | 1, INT_MAX, vlog_unixctl_set, NULL); |
584 | unixctl_command_register("vlog/list", "", 0, 0, vlog_unixctl_list, NULL); | |
4958e3ee BP |
585 | unixctl_command_register("vlog/enable-rate-limit", "[module]...", |
586 | 0, INT_MAX, vlog_enable_rate_limit, NULL); | |
587 | unixctl_command_register("vlog/disable-rate-limit", "[module]...", | |
588 | 0, INT_MAX, vlog_disable_rate_limit, NULL); | |
0e15264f BP |
589 | unixctl_command_register("vlog/reopen", "", 0, 0, |
590 | vlog_unixctl_reopen, NULL); | |
064af421 BP |
591 | } |
592 | ||
593 | /* Closes the logging subsystem. */ | |
594 | void | |
d295e8e9 | 595 | vlog_exit(void) |
064af421 | 596 | { |
1e8cf0f7 BP |
597 | if (vlog_inited) { |
598 | closelog(); | |
599 | vlog_inited = false; | |
600 | } | |
064af421 BP |
601 | } |
602 | ||
603 | /* Print the current logging level for each module. */ | |
604 | char * | |
605 | vlog_get_levels(void) | |
606 | { | |
607 | struct ds s = DS_EMPTY_INITIALIZER; | |
480ce8ab | 608 | struct vlog_module **mp; |
8628b0b7 JP |
609 | struct svec lines = SVEC_EMPTY_INITIALIZER; |
610 | char *line; | |
611 | size_t i; | |
064af421 BP |
612 | |
613 | ds_put_format(&s, " console syslog file\n"); | |
614 | ds_put_format(&s, " ------- ------ ------\n"); | |
615 | ||
480ce8ab | 616 | for (mp = vlog_modules; mp < &vlog_modules[n_vlog_modules]; mp++) { |
4958e3ee BP |
617 | struct ds line; |
618 | ||
619 | ds_init(&line); | |
620 | ds_put_format(&line, "%-16s %4s %4s %4s", | |
621 | vlog_get_module_name(*mp), | |
622 | vlog_get_level_name(vlog_get_level(*mp, VLF_CONSOLE)), | |
623 | vlog_get_level_name(vlog_get_level(*mp, VLF_SYSLOG)), | |
624 | vlog_get_level_name(vlog_get_level(*mp, VLF_FILE))); | |
625 | if (!(*mp)->honor_rate_limits) { | |
626 | ds_put_cstr(&line, " (rate limiting disabled)"); | |
627 | } | |
628 | ds_put_char(&line, '\n'); | |
629 | ||
630 | svec_add_nocopy(&lines, ds_steal_cstr(&line)); | |
8628b0b7 JP |
631 | } |
632 | ||
633 | svec_sort(&lines); | |
634 | SVEC_FOR_EACH (i, line, &lines) { | |
635 | ds_put_cstr(&s, line); | |
064af421 | 636 | } |
8628b0b7 | 637 | svec_destroy(&lines); |
064af421 BP |
638 | |
639 | return ds_cstr(&s); | |
640 | } | |
641 | ||
642 | /* Returns true if a log message emitted for the given 'module' and 'level' | |
643 | * would cause some log output, false if that module and level are completely | |
644 | * disabled. */ | |
645 | bool | |
480ce8ab | 646 | vlog_is_enabled(const struct vlog_module *module, enum vlog_level level) |
064af421 | 647 | { |
480ce8ab | 648 | return module->min_level >= level; |
064af421 BP |
649 | } |
650 | ||
651 | static const char * | |
652 | fetch_braces(const char *p, const char *def, char *out, size_t out_size) | |
653 | { | |
654 | if (*p == '{') { | |
655 | size_t n = strcspn(p + 1, "}"); | |
656 | size_t n_copy = MIN(n, out_size - 1); | |
657 | memcpy(out, p + 1, n_copy); | |
658 | out[n_copy] = '\0'; | |
659 | p += n + 2; | |
660 | } else { | |
661 | ovs_strlcpy(out, def, out_size); | |
662 | } | |
663 | return p; | |
664 | } | |
665 | ||
666 | static void | |
480ce8ab | 667 | format_log_message(const struct vlog_module *module, enum vlog_level level, |
064af421 BP |
668 | enum vlog_facility facility, unsigned int msg_num, |
669 | const char *message, va_list args_, struct ds *s) | |
670 | { | |
671 | char tmp[128]; | |
672 | va_list args; | |
673 | const char *p; | |
674 | ||
675 | ds_clear(s); | |
676 | for (p = facilities[facility].pattern; *p != '\0'; ) { | |
677 | enum { LEFT, RIGHT } justify = RIGHT; | |
678 | int pad = '0'; | |
679 | size_t length, field, used; | |
680 | ||
681 | if (*p != '%') { | |
682 | ds_put_char(s, *p++); | |
683 | continue; | |
684 | } | |
685 | ||
686 | p++; | |
687 | if (*p == '-') { | |
688 | justify = LEFT; | |
689 | p++; | |
690 | } | |
691 | if (*p == '0') { | |
692 | pad = '0'; | |
693 | p++; | |
694 | } | |
695 | field = 0; | |
be2c418b | 696 | while (isdigit((unsigned char)*p)) { |
064af421 BP |
697 | field = (field * 10) + (*p - '0'); |
698 | p++; | |
699 | } | |
700 | ||
701 | length = s->length; | |
702 | switch (*p++) { | |
703 | case 'A': | |
704 | ds_put_cstr(s, program_name); | |
705 | break; | |
706 | case 'c': | |
707 | p = fetch_braces(p, "", tmp, sizeof tmp); | |
708 | ds_put_cstr(s, vlog_get_module_name(module)); | |
709 | break; | |
710 | case 'd': | |
711 | p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp); | |
b5d29991 GS |
712 | ds_put_strftime(s, tmp, false); |
713 | break; | |
714 | case 'D': | |
715 | p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp); | |
716 | ds_put_strftime(s, tmp, true); | |
064af421 BP |
717 | break; |
718 | case 'm': | |
719 | /* Format user-supplied log message and trim trailing new-lines. */ | |
720 | length = s->length; | |
721 | va_copy(args, args_); | |
722 | ds_put_format_valist(s, message, args); | |
723 | va_end(args); | |
724 | while (s->length > length && s->string[s->length - 1] == '\n') { | |
725 | s->length--; | |
726 | } | |
727 | break; | |
728 | case 'N': | |
729 | ds_put_format(s, "%u", msg_num); | |
730 | break; | |
731 | case 'n': | |
732 | ds_put_char(s, '\n'); | |
733 | break; | |
734 | case 'p': | |
735 | ds_put_cstr(s, vlog_get_level_name(level)); | |
736 | break; | |
737 | case 'P': | |
738 | ds_put_format(s, "%ld", (long int) getpid()); | |
739 | break; | |
740 | case 'r': | |
4ae90ff9 | 741 | ds_put_format(s, "%lld", time_msec() - time_boot_msec()); |
064af421 | 742 | break; |
781dee08 BP |
743 | case 't': |
744 | ds_put_cstr(s, subprogram_name[0] ? subprogram_name : "main"); | |
745 | break; | |
746 | case 'T': | |
747 | if (subprogram_name[0]) { | |
748 | ds_put_format(s, "(%s)", subprogram_name); | |
749 | } | |
750 | break; | |
064af421 BP |
751 | default: |
752 | ds_put_char(s, p[-1]); | |
753 | break; | |
754 | } | |
755 | used = s->length - length; | |
756 | if (used < field) { | |
757 | size_t n_pad = field - used; | |
758 | if (justify == RIGHT) { | |
759 | ds_put_uninit(s, n_pad); | |
760 | memmove(&s->string[length + n_pad], &s->string[length], used); | |
761 | memset(&s->string[length], pad, n_pad); | |
762 | } else { | |
763 | ds_put_char_multiple(s, pad, n_pad); | |
764 | } | |
765 | } | |
766 | } | |
767 | } | |
768 | ||
769 | /* Writes 'message' to the log at the given 'level' and as coming from the | |
770 | * given 'module'. | |
771 | * | |
772 | * Guaranteed to preserve errno. */ | |
773 | void | |
480ce8ab | 774 | vlog_valist(const struct vlog_module *module, enum vlog_level level, |
064af421 BP |
775 | const char *message, va_list args) |
776 | { | |
480ce8ab BP |
777 | bool log_to_console = module->levels[VLF_CONSOLE] >= level; |
778 | bool log_to_syslog = module->levels[VLF_SYSLOG] >= level; | |
9eb94563 | 779 | bool log_to_file = module->levels[VLF_FILE] >= level && log_fd >= 0; |
064af421 BP |
780 | if (log_to_console || log_to_syslog || log_to_file) { |
781 | int save_errno = errno; | |
782 | static unsigned int msg_num; | |
783 | struct ds s; | |
784 | ||
1e8cf0f7 BP |
785 | vlog_init(); |
786 | ||
064af421 BP |
787 | ds_init(&s); |
788 | ds_reserve(&s, 1024); | |
789 | msg_num++; | |
790 | ||
791 | if (log_to_console) { | |
792 | format_log_message(module, level, VLF_CONSOLE, msg_num, | |
793 | message, args, &s); | |
794 | ds_put_char(&s, '\n'); | |
795 | fputs(ds_cstr(&s), stderr); | |
796 | } | |
797 | ||
798 | if (log_to_syslog) { | |
799 | int syslog_level = syslog_levels[level]; | |
800 | char *save_ptr = NULL; | |
801 | char *line; | |
802 | ||
803 | format_log_message(module, level, VLF_SYSLOG, msg_num, | |
804 | message, args, &s); | |
805 | for (line = strtok_r(s.string, "\n", &save_ptr); line; | |
806 | line = strtok_r(NULL, "\n", &save_ptr)) { | |
807 | syslog(syslog_level, "%s", line); | |
808 | } | |
809 | } | |
810 | ||
811 | if (log_to_file) { | |
812 | format_log_message(module, level, VLF_FILE, msg_num, | |
813 | message, args, &s); | |
814 | ds_put_char(&s, '\n'); | |
cbb13e8e | 815 | vlog_write_file(&s); |
064af421 BP |
816 | } |
817 | ||
818 | ds_destroy(&s); | |
819 | errno = save_errno; | |
820 | } | |
821 | } | |
822 | ||
823 | void | |
480ce8ab BP |
824 | vlog(const struct vlog_module *module, enum vlog_level level, |
825 | const char *message, ...) | |
064af421 BP |
826 | { |
827 | va_list args; | |
828 | ||
829 | va_start(args, message); | |
830 | vlog_valist(module, level, message, args); | |
831 | va_end(args); | |
832 | } | |
833 | ||
d41d4b71 BP |
834 | /* Logs 'message' to 'module' at maximum verbosity, then exits with a failure |
835 | * exit code. Always writes the message to stderr, even if the console | |
836 | * facility is disabled. | |
837 | * | |
838 | * Choose this function instead of vlog_abort_valist() if the daemon monitoring | |
839 | * facility shouldn't automatically restart the current daemon. */ | |
279c9e03 | 840 | void |
c1a543a8 | 841 | vlog_fatal_valist(const struct vlog_module *module_, |
279c9e03 BP |
842 | const char *message, va_list args) |
843 | { | |
ebc56baa | 844 | struct vlog_module *module = CONST_CAST(struct vlog_module *, module_); |
279c9e03 BP |
845 | |
846 | /* Don't log this message to the console to avoid redundancy with the | |
847 | * message written by the later ovs_fatal_valist(). */ | |
c1a543a8 | 848 | module->levels[VLF_CONSOLE] = VLL_OFF; |
279c9e03 | 849 | |
c1a543a8 | 850 | vlog_valist(module, VLL_EMER, message, args); |
279c9e03 BP |
851 | ovs_fatal_valist(0, message, args); |
852 | } | |
853 | ||
d41d4b71 BP |
854 | /* Logs 'message' to 'module' at maximum verbosity, then exits with a failure |
855 | * exit code. Always writes the message to stderr, even if the console | |
856 | * facility is disabled. | |
857 | * | |
858 | * Choose this function instead of vlog_abort() if the daemon monitoring | |
859 | * facility shouldn't automatically restart the current daemon. */ | |
279c9e03 | 860 | void |
c1a543a8 | 861 | vlog_fatal(const struct vlog_module *module, const char *message, ...) |
279c9e03 BP |
862 | { |
863 | va_list args; | |
864 | ||
865 | va_start(args, message); | |
c1a543a8 | 866 | vlog_fatal_valist(module, message, args); |
279c9e03 BP |
867 | va_end(args); |
868 | } | |
869 | ||
d41d4b71 BP |
870 | /* Logs 'message' to 'module' at maximum verbosity, then calls abort(). Always |
871 | * writes the message to stderr, even if the console facility is disabled. | |
872 | * | |
873 | * Choose this function instead of vlog_fatal_valist() if the daemon monitoring | |
874 | * facility should automatically restart the current daemon. */ | |
875 | void | |
876 | vlog_abort_valist(const struct vlog_module *module_, | |
877 | const char *message, va_list args) | |
878 | { | |
879 | struct vlog_module *module = (struct vlog_module *) module_; | |
880 | ||
881 | /* Don't log this message to the console to avoid redundancy with the | |
882 | * message written by the later ovs_abort_valist(). */ | |
883 | module->levels[VLF_CONSOLE] = VLL_OFF; | |
884 | ||
885 | vlog_valist(module, VLL_EMER, message, args); | |
886 | ovs_abort_valist(0, message, args); | |
887 | } | |
888 | ||
889 | /* Logs 'message' to 'module' at maximum verbosity, then calls abort(). Always | |
890 | * writes the message to stderr, even if the console facility is disabled. | |
891 | * | |
892 | * Choose this function instead of vlog_fatal() if the daemon monitoring | |
893 | * facility should automatically restart the current daemon. */ | |
894 | void | |
895 | vlog_abort(const struct vlog_module *module, const char *message, ...) | |
896 | { | |
897 | va_list args; | |
898 | ||
899 | va_start(args, message); | |
900 | vlog_abort_valist(module, message, args); | |
901 | va_end(args); | |
902 | } | |
903 | ||
064af421 | 904 | bool |
480ce8ab | 905 | vlog_should_drop(const struct vlog_module *module, enum vlog_level level, |
064af421 BP |
906 | struct vlog_rate_limit *rl) |
907 | { | |
4958e3ee BP |
908 | if (!module->honor_rate_limits) { |
909 | return false; | |
910 | } | |
911 | ||
064af421 BP |
912 | if (!vlog_is_enabled(module, level)) { |
913 | return true; | |
914 | } | |
915 | ||
648f4f1f | 916 | if (!token_bucket_withdraw(&rl->token_bucket, VLOG_MSG_TOKENS)) { |
064af421 | 917 | time_t now = time_now(); |
648f4f1f BP |
918 | if (!rl->n_dropped) { |
919 | rl->first_dropped = now; | |
064af421 | 920 | } |
648f4f1f BP |
921 | rl->last_dropped = now; |
922 | rl->n_dropped++; | |
923 | return true; | |
064af421 | 924 | } |
064af421 BP |
925 | |
926 | if (rl->n_dropped) { | |
e2eed6a7 BP |
927 | time_t now = time_now(); |
928 | unsigned int first_dropped_elapsed = now - rl->first_dropped; | |
929 | unsigned int last_dropped_elapsed = now - rl->last_dropped; | |
930 | ||
064af421 | 931 | vlog(module, level, |
e2eed6a7 BP |
932 | "Dropped %u log messages in last %u seconds (most recently, " |
933 | "%u seconds ago) due to excessive rate", | |
934 | rl->n_dropped, first_dropped_elapsed, last_dropped_elapsed); | |
935 | ||
064af421 BP |
936 | rl->n_dropped = 0; |
937 | } | |
938 | return false; | |
939 | } | |
940 | ||
941 | void | |
480ce8ab | 942 | vlog_rate_limit(const struct vlog_module *module, enum vlog_level level, |
064af421 BP |
943 | struct vlog_rate_limit *rl, const char *message, ...) |
944 | { | |
945 | if (!vlog_should_drop(module, level, rl)) { | |
946 | va_list args; | |
947 | ||
948 | va_start(args, message); | |
949 | vlog_valist(module, level, message, args); | |
950 | va_end(args); | |
951 | } | |
952 | } | |
953 | ||
954 | void | |
d295e8e9 | 955 | vlog_usage(void) |
064af421 BP |
956 | { |
957 | printf("\nLogging options:\n" | |
2a3e30b2 | 958 | " -v, --verbose=[SPEC] set logging levels\n" |
064af421 BP |
959 | " -v, --verbose set maximum verbosity level\n" |
960 | " --log-file[=FILE] enable logging to specified FILE\n" | |
961 | " (default: %s/%s.log)\n", | |
b43c6fe2 | 962 | ovs_logdir(), program_name); |
064af421 | 963 | } |
cbb13e8e BP |
964 | \f |
965 | static bool vlog_async_inited = false; | |
966 | ||
967 | static worker_request_func vlog_async_write_request_cb; | |
968 | ||
969 | static void | |
970 | vlog_write_file(struct ds *s) | |
971 | { | |
972 | if (worker_is_running()) { | |
4958e3ee BP |
973 | static bool in_worker_request = false; |
974 | if (!in_worker_request) { | |
975 | in_worker_request = true; | |
976 | ||
977 | worker_request(s->string, s->length, | |
978 | &log_fd, vlog_async_inited ? 0 : 1, | |
979 | vlog_async_write_request_cb, NULL, NULL); | |
980 | vlog_async_inited = true; | |
981 | ||
982 | in_worker_request = false; | |
983 | return; | |
984 | } else { | |
985 | /* We've been entered recursively. This can happen if | |
986 | * worker_request(), or a function that it calls, tries to log | |
987 | * something. We can't call worker_request() recursively, so fall | |
988 | * back to writing the log file directly. */ | |
989 | COVERAGE_INC(vlog_recursive); | |
990 | } | |
cbb13e8e | 991 | } |
4958e3ee | 992 | ignore(write(log_fd, s->string, s->length)); |
cbb13e8e BP |
993 | } |
994 | ||
995 | static void | |
996 | vlog_update_async_log_fd(void) | |
997 | { | |
998 | if (worker_is_running()) { | |
999 | worker_request(NULL, 0, &log_fd, 1, vlog_async_write_request_cb, | |
1000 | NULL, NULL); | |
1001 | vlog_async_inited = true; | |
1002 | } | |
1003 | } | |
1004 | ||
1005 | static void | |
1006 | vlog_async_write_request_cb(struct ofpbuf *request, | |
1007 | const int *fd, size_t n_fds) | |
1008 | { | |
1009 | if (n_fds > 0) { | |
1010 | if (log_fd >= 0) { | |
1011 | close(log_fd); | |
1012 | } | |
1013 | log_fd = *fd; | |
1014 | } | |
1015 | ||
1016 | if (request->size > 0) { | |
171c54d7 | 1017 | ignore(write(log_fd, request->data, request->size)); |
cbb13e8e BP |
1018 | } |
1019 | } |