/src/dovecot/src/lib/event-log.c
Line | Count | Source (jump to first uncovered line) |
1 | | /* Copyright (c) 2017-2018 Dovecot authors, see the included COPYING file */ |
2 | | |
3 | | #include "lib.h" |
4 | | #include "str.h" |
5 | | #include "event-filter.h" |
6 | | #include "lib-event-private.h" |
7 | | |
8 | | unsigned int event_filter_replace_counter = 1; |
9 | | |
10 | | static struct event_filter *global_debug_log_filter = NULL; |
11 | | static struct event_filter *global_debug_send_filter = NULL; |
12 | | static struct event_filter *global_core_log_filter = NULL; |
13 | | |
14 | | #undef e_error |
15 | | void e_error(struct event *event, |
16 | | const char *source_filename, unsigned int source_linenum, |
17 | | const char *fmt, ...) |
18 | 0 | { |
19 | 0 | if (!event_want_level(event, LOG_TYPE_ERROR)) { |
20 | 0 | event_send_abort(event); |
21 | 0 | return; |
22 | 0 | } |
23 | 0 | struct event_log_params params = { |
24 | 0 | .log_type = LOG_TYPE_ERROR, |
25 | 0 | .source_filename = source_filename, |
26 | 0 | .source_linenum = source_linenum, |
27 | 0 | }; |
28 | 0 | va_list args; |
29 | |
|
30 | 0 | va_start(args, fmt); |
31 | 0 | T_BEGIN { |
32 | 0 | event_logv(event, ¶ms, fmt, args); |
33 | 0 | } T_END; |
34 | 0 | va_end(args); |
35 | 0 | } |
36 | | |
37 | | #undef e_warning |
38 | | void e_warning(struct event *event, |
39 | | const char *source_filename, unsigned int source_linenum, |
40 | | const char *fmt, ...) |
41 | 0 | { |
42 | 0 | if (!event_want_level(event, LOG_TYPE_WARNING)) { |
43 | 0 | event_send_abort(event); |
44 | 0 | return; |
45 | 0 | } |
46 | 0 | struct event_log_params params = { |
47 | 0 | .log_type = LOG_TYPE_WARNING, |
48 | 0 | .source_filename = source_filename, |
49 | 0 | .source_linenum = source_linenum, |
50 | 0 | }; |
51 | 0 | va_list args; |
52 | |
|
53 | 0 | va_start(args, fmt); |
54 | 0 | T_BEGIN { |
55 | 0 | event_logv(event, ¶ms, fmt, args); |
56 | 0 | } T_END; |
57 | 0 | va_end(args); |
58 | 0 | } |
59 | | |
60 | | #undef e_info |
61 | | void e_info(struct event *event, |
62 | | const char *source_filename, unsigned int source_linenum, |
63 | | const char *fmt, ...) |
64 | 0 | { |
65 | 0 | if (!event_want_level(event, LOG_TYPE_INFO)) { |
66 | 0 | event_send_abort(event); |
67 | 0 | return; |
68 | 0 | } |
69 | 0 | struct event_log_params params = { |
70 | 0 | .log_type = LOG_TYPE_INFO, |
71 | 0 | .source_filename = source_filename, |
72 | 0 | .source_linenum = source_linenum, |
73 | 0 | }; |
74 | 0 | va_list args; |
75 | |
|
76 | 0 | va_start(args, fmt); |
77 | 0 | T_BEGIN { |
78 | 0 | event_logv(event, ¶ms, fmt, args); |
79 | 0 | } T_END; |
80 | 0 | va_end(args); |
81 | 0 | } |
82 | | |
83 | | #undef e_debug |
84 | | void e_debug(struct event *event, |
85 | | const char *source_filename, unsigned int source_linenum, |
86 | | const char *fmt, ...) |
87 | 0 | { |
88 | 0 | struct event_log_params params = { |
89 | 0 | .log_type = LOG_TYPE_DEBUG, |
90 | 0 | .source_filename = source_filename, |
91 | 0 | .source_linenum = source_linenum, |
92 | 0 | }; |
93 | 0 | va_list args; |
94 | |
|
95 | 0 | va_start(args, fmt); |
96 | 0 | T_BEGIN { |
97 | 0 | event_logv(event, ¶ms, fmt, args); |
98 | 0 | } T_END; |
99 | 0 | va_end(args); |
100 | 0 | } |
101 | | |
102 | | #undef e_log |
103 | | void e_log(struct event *event, enum log_type level, |
104 | | const char *source_filename, unsigned int source_linenum, |
105 | | const char *fmt, ...) |
106 | 0 | { |
107 | 0 | struct event_log_params params = { |
108 | 0 | .log_type = level, |
109 | 0 | .source_filename = source_filename, |
110 | 0 | .source_linenum = source_linenum, |
111 | 0 | }; |
112 | 0 | va_list args; |
113 | |
|
114 | 0 | va_start(args, fmt); |
115 | 0 | T_BEGIN { |
116 | 0 | event_logv(event, ¶ms, fmt, args); |
117 | 0 | } T_END; |
118 | 0 | va_end(args); |
119 | 0 | } |
120 | | |
121 | | struct event_get_log_message_context { |
122 | | const struct event_log_params *params; |
123 | | |
124 | | string_t *log_prefix; |
125 | | const char *message; |
126 | | unsigned int type_pos; |
127 | | |
128 | | bool replace_prefix:1; |
129 | | bool str_out_done:1; |
130 | | }; |
131 | | |
132 | | static inline void ATTR_FORMAT(2, 0) |
133 | | event_get_log_message_str_out(struct event_get_log_message_context *glmctx, |
134 | | const char *fmt, va_list args) |
135 | 0 | { |
136 | 0 | const struct event_log_params *params = glmctx->params; |
137 | 0 | string_t *str_out = params->base_str_out; |
138 | | |
139 | | /* The message is appended once in full, rather than incremental during |
140 | | the recursion. */ |
141 | |
|
142 | 0 | if (glmctx->str_out_done || str_out == NULL) |
143 | 0 | return; |
144 | | |
145 | | /* append the current log prefix to the string buffer */ |
146 | 0 | if (params->base_str_prefix != NULL && !glmctx->replace_prefix) |
147 | 0 | str_append(str_out, params->base_str_prefix); |
148 | 0 | str_append_str(str_out, glmctx->log_prefix); |
149 | |
|
150 | 0 | if (glmctx->message != NULL) { |
151 | | /* a child event already constructed a message */ |
152 | 0 | str_append(str_out, glmctx->message); |
153 | 0 | } else { |
154 | 0 | va_list args_copy; |
155 | | |
156 | | /* construct message from format and arguments */ |
157 | 0 | VA_COPY(args_copy, args); |
158 | 0 | str_vprintfa(str_out, fmt, args_copy); |
159 | 0 | va_end(args_copy); |
160 | 0 | } |
161 | | |
162 | | /* finished with the string buffer */ |
163 | 0 | glmctx->str_out_done = TRUE; |
164 | 0 | } |
165 | | |
166 | | static bool ATTR_FORMAT(4, 0) |
167 | | event_get_log_message(struct event *event, |
168 | | struct event_get_log_message_context *glmctx, |
169 | | unsigned int prefixes_dropped, |
170 | | const char *fmt, va_list args) |
171 | 0 | { |
172 | 0 | const struct event_log_params *params = glmctx->params; |
173 | 0 | const char *prefix = event->log_prefix; |
174 | 0 | bool ret = FALSE; |
175 | | |
176 | | /* Reached the base event? */ |
177 | 0 | if (event == params->base_event) { |
178 | | /* Append the message to the provided string buffer. */ |
179 | 0 | event_get_log_message_str_out(glmctx, fmt, args); |
180 | | /* Insert the base send prefix */ |
181 | 0 | if (params->base_send_prefix != NULL) { |
182 | 0 | str_insert(glmctx->log_prefix, 0, |
183 | 0 | params->base_send_prefix); |
184 | 0 | ret = TRUE; |
185 | 0 | } |
186 | 0 | } |
187 | | |
188 | | /* Call the message amendment callback for this event if there is one. |
189 | | */ |
190 | 0 | if (event->log_message_callback != NULL) { |
191 | 0 | const char *in_message; |
192 | | |
193 | | /* construct the log message composed by children and arguments |
194 | | */ |
195 | 0 | const char *log_prefix = str_c(glmctx->log_prefix); |
196 | 0 | if (glmctx->message == NULL) { |
197 | 0 | str_vprintfa(glmctx->log_prefix, fmt, args); |
198 | 0 | in_message = log_prefix; |
199 | 0 | } else if (str_len(glmctx->log_prefix) == 0) { |
200 | 0 | in_message = glmctx->message; |
201 | 0 | } else { |
202 | 0 | str_append(glmctx->log_prefix, glmctx->message); |
203 | 0 | in_message = log_prefix; |
204 | 0 | } |
205 | | |
206 | | /* reformat the log message */ |
207 | 0 | glmctx->message = event->log_message_callback( |
208 | 0 | event->log_message_callback_context, |
209 | 0 | glmctx->params->log_type, in_message); |
210 | 0 | if (glmctx->message == log_prefix) { |
211 | | /* The log message returned the input log_prefix |
212 | | pointer. However, it's going to become modified, so |
213 | | it needs to be duplicated. */ |
214 | 0 | glmctx->message = t_strdup(log_prefix); |
215 | 0 | } |
216 | | |
217 | | /* continue with a cleared prefix buffer (as prefix is now part |
218 | | of *message_r). */ |
219 | 0 | str_truncate(glmctx->log_prefix, 0); |
220 | 0 | ret = TRUE; |
221 | 0 | } |
222 | |
|
223 | 0 | if (event->log_prefix_callback != NULL) { |
224 | 0 | prefix = event->log_prefix_callback( |
225 | 0 | event->log_prefix_callback_context); |
226 | 0 | } |
227 | 0 | if (event->log_prefix_replace) { |
228 | | /* this event replaces all parent log prefixes */ |
229 | 0 | glmctx->replace_prefix = TRUE; |
230 | 0 | glmctx->type_pos = (prefix == NULL ? 0 : strlen(prefix)); |
231 | 0 | event_get_log_message_str_out(glmctx, fmt, args); |
232 | 0 | } |
233 | 0 | if (prefix != NULL) { |
234 | 0 | if (event->log_prefix_replace || prefixes_dropped == 0) { |
235 | 0 | str_insert(glmctx->log_prefix, 0, prefix); |
236 | 0 | ret = TRUE; |
237 | 0 | } else if (prefixes_dropped > 0) { |
238 | 0 | prefixes_dropped--; |
239 | 0 | } |
240 | 0 | } |
241 | 0 | if (event->parent == NULL) { |
242 | 0 | event_get_log_message_str_out(glmctx, fmt, args); |
243 | 0 | if (params->base_event == NULL && |
244 | 0 | params->base_send_prefix != NULL && |
245 | 0 | !glmctx->replace_prefix) { |
246 | 0 | str_insert(glmctx->log_prefix, 0, |
247 | 0 | params->base_send_prefix); |
248 | 0 | ret = TRUE; |
249 | 0 | } |
250 | 0 | } else if (!event->log_prefix_replace && |
251 | 0 | (!params->no_send || !glmctx->str_out_done)) { |
252 | 0 | prefixes_dropped += event->log_prefixes_dropped; |
253 | 0 | if (event_get_log_message(event->parent, glmctx, |
254 | 0 | prefixes_dropped, fmt, args)) |
255 | 0 | ret = TRUE; |
256 | 0 | } |
257 | 0 | return ret; |
258 | 0 | } |
259 | | |
260 | | void event_log(struct event *event, const struct event_log_params *params, |
261 | | const char *fmt, ...) |
262 | 0 | { |
263 | 0 | va_list args; |
264 | |
|
265 | 0 | va_start(args, fmt); |
266 | 0 | event_logv(event, params, fmt, args); |
267 | 0 | va_end(args); |
268 | 0 | } |
269 | | |
270 | | #undef event_want_log_level |
271 | | bool event_want_log_level(struct event *event, enum log_type level, |
272 | | const char *source_filename, |
273 | | unsigned int source_linenum) |
274 | 12 | { |
275 | 12 | struct failure_context ctx = { .type = LOG_TYPE_DEBUG }; |
276 | | |
277 | 12 | if (event->forced_never_debug && level == LOG_TYPE_DEBUG) |
278 | 0 | return FALSE; |
279 | 12 | if (level >= event->min_log_level) { |
280 | | /* Always log when level is at least this high */ |
281 | 0 | return TRUE; |
282 | 0 | } |
283 | | |
284 | 12 | if (event->debug_level_checked_filter_counter == event_filter_replace_counter) { |
285 | | /* Log filters haven't changed since we last checked this, so |
286 | | we can rely on the last cached value. FIXME: this doesn't |
287 | | work correctly if event changes and the change affects |
288 | | whether the filters would match. */ |
289 | 11 | return event->sending_debug_log; |
290 | 11 | } |
291 | 1 | event->debug_level_checked_filter_counter = |
292 | 1 | event_filter_replace_counter; |
293 | | |
294 | 1 | if (event->forced_debug) { |
295 | | /* Debugging is forced for this event (and its children) */ |
296 | 0 | event->sending_debug_log = TRUE; |
297 | 1 | } else if (global_debug_log_filter != NULL && |
298 | 1 | event_filter_match_source(global_debug_log_filter, event, |
299 | 0 | source_filename, source_linenum, &ctx)) { |
300 | | /* log_debug filter matched */ |
301 | 0 | event->sending_debug_log = TRUE; |
302 | 1 | } else if (global_core_log_filter != NULL && |
303 | 1 | event_filter_match_source(global_core_log_filter, event, |
304 | 0 | source_filename, source_linenum, &ctx)) { |
305 | | /* log_core_filter matched */ |
306 | 0 | event->sending_debug_log = TRUE; |
307 | 1 | } else { |
308 | 1 | event->sending_debug_log = FALSE; |
309 | 1 | } |
310 | 1 | return event->sending_debug_log; |
311 | 12 | } |
312 | | |
313 | | #undef event_want_level |
314 | | bool event_want_level(struct event *event, enum log_type level, |
315 | | const char *source_filename, |
316 | | unsigned int source_linenum) |
317 | 12 | { |
318 | 12 | if (event_want_log_level(event, level, source_filename, source_linenum)) |
319 | 0 | return TRUE; |
320 | | |
321 | | /* see if debug send filtering matches */ |
322 | 12 | if (global_debug_send_filter != NULL) { |
323 | 0 | struct failure_context ctx = { .type = LOG_TYPE_DEBUG }; |
324 | |
|
325 | 0 | if (event_filter_match_source(global_debug_send_filter, event, |
326 | 0 | source_filename, source_linenum, |
327 | 0 | &ctx)) |
328 | 0 | return TRUE; |
329 | 0 | } |
330 | 12 | return FALSE; |
331 | 12 | } |
332 | | |
333 | | static void ATTR_FORMAT(3, 0) |
334 | | event_logv_params(struct event *event, const struct event_log_params *params, |
335 | | const char *fmt, va_list args) |
336 | 0 | { |
337 | 0 | struct event_get_log_message_context glmctx; |
338 | |
|
339 | 0 | struct failure_context ctx = { |
340 | 0 | .type = params->log_type, |
341 | 0 | }; |
342 | 0 | bool abort_after_event = FALSE; |
343 | |
|
344 | 0 | i_assert(!params->no_send || params->base_str_out != NULL); |
345 | | |
346 | 0 | if (global_core_log_filter != NULL && |
347 | 0 | event_filter_match_source(global_core_log_filter, event, |
348 | 0 | event->source_filename, |
349 | 0 | event->source_linenum, &ctx)) |
350 | 0 | abort_after_event = TRUE; |
351 | |
|
352 | 0 | i_zero(&glmctx); |
353 | 0 | glmctx.params = params; |
354 | 0 | glmctx.log_prefix = t_str_new(64); |
355 | 0 | if (!event_get_log_message(event, &glmctx, 0, fmt, args)) { |
356 | | /* keep log prefix as it is */ |
357 | 0 | if (params->base_str_out != NULL && !glmctx.str_out_done) { |
358 | 0 | va_list args_copy; |
359 | |
|
360 | 0 | VA_COPY(args_copy, args); |
361 | 0 | str_vprintfa(params->base_str_out, fmt, args_copy); |
362 | 0 | va_end(args_copy); |
363 | 0 | } |
364 | 0 | if (!params->no_send) |
365 | 0 | event_vsend(event, &ctx, fmt, args); |
366 | 0 | } else if (params->no_send) { |
367 | | /* don't send the event */ |
368 | 0 | } else if (glmctx.replace_prefix) { |
369 | | /* event overrides the log prefix (even if it's "") */ |
370 | 0 | ctx.log_prefix = str_c(glmctx.log_prefix); |
371 | 0 | ctx.log_prefix_type_pos = glmctx.type_pos; |
372 | 0 | if (glmctx.message != NULL) |
373 | 0 | event_send(event, &ctx, "%s", glmctx.message); |
374 | 0 | else |
375 | 0 | event_vsend(event, &ctx, fmt, args); |
376 | 0 | } else { |
377 | | /* append to log prefix, but don't fully replace it */ |
378 | 0 | if (glmctx.message != NULL) |
379 | 0 | str_append(glmctx.log_prefix, glmctx.message); |
380 | 0 | else |
381 | 0 | str_vprintfa(glmctx.log_prefix, fmt, args); |
382 | 0 | event_send(event, &ctx, "%s", str_c(glmctx.log_prefix)); |
383 | 0 | } |
384 | 0 | if (abort_after_event) |
385 | 0 | abort(); |
386 | 0 | } |
387 | | |
388 | | void event_logv(struct event *event, const struct event_log_params *params, |
389 | | const char *fmt, va_list args) |
390 | 0 | { |
391 | 0 | const char *orig_source_filename = event->source_filename; |
392 | 0 | unsigned int orig_source_linenum = event->source_linenum; |
393 | 0 | int old_errno = errno; |
394 | |
|
395 | 0 | if (params->source_filename != NULL) { |
396 | 0 | event_set_source(event, params->source_filename, |
397 | 0 | params->source_linenum, TRUE); |
398 | 0 | } |
399 | |
|
400 | 0 | (void)event_want_log_level(event, params->log_type, |
401 | 0 | event->source_filename, |
402 | 0 | event->source_linenum); |
403 | |
|
404 | 0 | event_ref(event); |
405 | 0 | event_logv_params(event, params, fmt, args); |
406 | 0 | event_set_source(event, orig_source_filename, |
407 | 0 | orig_source_linenum, TRUE); |
408 | 0 | event_unref(&event); |
409 | 0 | errno = old_errno; |
410 | 0 | } |
411 | | |
412 | | struct event *event_set_forced_debug(struct event *event, bool force) |
413 | 0 | { |
414 | 0 | if (force) |
415 | 0 | event->forced_debug = TRUE; |
416 | 0 | event_recalculate_debug_level(event); |
417 | 0 | return event; |
418 | 0 | } |
419 | | |
420 | | struct event *event_unset_forced_debug(struct event *event) |
421 | 0 | { |
422 | 0 | event->forced_debug = FALSE; |
423 | 0 | event_recalculate_debug_level(event); |
424 | 0 | return event; |
425 | 0 | } |
426 | | |
427 | | struct event *event_set_forced_never_debug(struct event *event, bool force) |
428 | 0 | { |
429 | 0 | event->forced_never_debug = force; |
430 | 0 | return event; |
431 | 0 | } |
432 | | |
433 | | void event_set_global_debug_log_filter(struct event_filter *filter) |
434 | 0 | { |
435 | 0 | event_unset_global_debug_log_filter(); |
436 | 0 | global_debug_log_filter = filter; |
437 | 0 | event_filter_ref(global_debug_log_filter); |
438 | 0 | event_filter_replace_counter++; |
439 | 0 | } |
440 | | |
441 | | struct event_filter *event_get_global_debug_log_filter(void) |
442 | 0 | { |
443 | 0 | return global_debug_log_filter; |
444 | 0 | } |
445 | | |
446 | | void event_unset_global_debug_log_filter(void) |
447 | 0 | { |
448 | 0 | event_filter_unref(&global_debug_log_filter); |
449 | 0 | event_filter_replace_counter++; |
450 | 0 | } |
451 | | |
452 | | void event_set_global_debug_send_filter(struct event_filter *filter) |
453 | 0 | { |
454 | 0 | event_unset_global_debug_send_filter(); |
455 | 0 | global_debug_send_filter = filter; |
456 | 0 | event_filter_ref(global_debug_send_filter); |
457 | 0 | event_filter_replace_counter++; |
458 | 0 | } |
459 | | |
460 | | struct event_filter *event_get_global_debug_send_filter(void) |
461 | 0 | { |
462 | 0 | return global_debug_send_filter; |
463 | 0 | } |
464 | | |
465 | | void event_unset_global_debug_send_filter(void) |
466 | 0 | { |
467 | 0 | event_filter_unref(&global_debug_send_filter); |
468 | 0 | event_filter_replace_counter++; |
469 | 0 | } |
470 | | |
471 | | void event_set_global_core_log_filter(struct event_filter *filter) |
472 | 0 | { |
473 | 0 | event_unset_global_core_log_filter(); |
474 | 0 | global_core_log_filter = filter; |
475 | 0 | event_filter_ref(global_core_log_filter); |
476 | 0 | event_filter_replace_counter++; |
477 | 0 | } |
478 | | |
479 | | struct event_filter *event_get_global_core_log_filter(void) |
480 | 0 | { |
481 | 0 | return global_core_log_filter; |
482 | 0 | } |
483 | | |
484 | | void event_unset_global_core_log_filter(void) |
485 | 0 | { |
486 | 0 | event_filter_unref(&global_core_log_filter); |
487 | 0 | event_filter_replace_counter++; |
488 | 0 | } |