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