/src/dovecot/src/lib/event-log.c
Line | Count | Source |
1 | | /* Copyright (c) Dovecot authors, see top-level COPYING file */ |
2 | | |
3 | | #include "lib.h" |
4 | | #include "array.h" |
5 | | #include "str.h" |
6 | | #include "event-filter.h" |
7 | | #include "lib-event-private.h" |
8 | | |
9 | | unsigned int event_filter_replace_counter = 1; |
10 | | |
11 | | static struct event_filter *global_debug_log_filter = NULL; |
12 | | static struct event_filter *global_core_log_filter = NULL; |
13 | | static ARRAY(struct event_filter *) global_debug_send_filters; |
14 | | |
15 | | #undef e_error |
16 | | void e_error(struct event *event, |
17 | | const char *source_filename, unsigned int source_linenum, |
18 | | const char *fmt, ...) |
19 | 0 | { |
20 | 0 | if (!event_want_level(event, LOG_TYPE_ERROR)) { |
21 | 0 | event_send_abort(event); |
22 | 0 | return; |
23 | 0 | } |
24 | 0 | struct event_log_params params = { |
25 | 0 | .log_type = LOG_TYPE_ERROR, |
26 | 0 | .source_filename = source_filename, |
27 | 0 | .source_linenum = source_linenum, |
28 | 0 | }; |
29 | 0 | va_list args; |
30 | |
|
31 | 0 | va_start(args, fmt); |
32 | 0 | T_BEGIN { |
33 | 0 | event_logv(event, ¶ms, fmt, args); |
34 | 0 | } T_END; |
35 | 0 | va_end(args); |
36 | 0 | } |
37 | | |
38 | | #undef e_warning |
39 | | void e_warning(struct event *event, |
40 | | const char *source_filename, unsigned int source_linenum, |
41 | | const char *fmt, ...) |
42 | 0 | { |
43 | 0 | if (!event_want_level(event, LOG_TYPE_WARNING)) { |
44 | 0 | event_send_abort(event); |
45 | 0 | return; |
46 | 0 | } |
47 | 0 | struct event_log_params params = { |
48 | 0 | .log_type = LOG_TYPE_WARNING, |
49 | 0 | .source_filename = source_filename, |
50 | 0 | .source_linenum = source_linenum, |
51 | 0 | }; |
52 | 0 | va_list args; |
53 | |
|
54 | 0 | va_start(args, fmt); |
55 | 0 | T_BEGIN { |
56 | 0 | event_logv(event, ¶ms, fmt, args); |
57 | 0 | } T_END; |
58 | 0 | va_end(args); |
59 | 0 | } |
60 | | |
61 | | #undef e_info |
62 | | void e_info(struct event *event, |
63 | | const char *source_filename, unsigned int source_linenum, |
64 | | const char *fmt, ...) |
65 | 0 | { |
66 | 0 | if (!event_want_level(event, LOG_TYPE_INFO)) { |
67 | 0 | event_send_abort(event); |
68 | 0 | return; |
69 | 0 | } |
70 | 0 | struct event_log_params params = { |
71 | 0 | .log_type = LOG_TYPE_INFO, |
72 | 0 | .source_filename = source_filename, |
73 | 0 | .source_linenum = source_linenum, |
74 | 0 | }; |
75 | 0 | va_list args; |
76 | |
|
77 | 0 | va_start(args, fmt); |
78 | 0 | T_BEGIN { |
79 | 0 | event_logv(event, ¶ms, fmt, args); |
80 | 0 | } T_END; |
81 | 0 | va_end(args); |
82 | 0 | } |
83 | | |
84 | | #undef e_debug |
85 | | void e_debug(struct event *event, |
86 | | const char *source_filename, unsigned int source_linenum, |
87 | | const char *fmt, ...) |
88 | 0 | { |
89 | 0 | struct event_log_params params = { |
90 | 0 | .log_type = LOG_TYPE_DEBUG, |
91 | 0 | .source_filename = source_filename, |
92 | 0 | .source_linenum = source_linenum, |
93 | 0 | }; |
94 | 0 | va_list args; |
95 | |
|
96 | 0 | va_start(args, fmt); |
97 | 0 | T_BEGIN { |
98 | 0 | event_logv(event, ¶ms, fmt, args); |
99 | 0 | } T_END; |
100 | 0 | va_end(args); |
101 | 0 | } |
102 | | |
103 | | #undef e_log |
104 | | void e_log(struct event *event, enum log_type level, |
105 | | const char *source_filename, unsigned int source_linenum, |
106 | | const char *fmt, ...) |
107 | 0 | { |
108 | 0 | struct event_log_params params = { |
109 | 0 | .log_type = level, |
110 | 0 | .source_filename = source_filename, |
111 | 0 | .source_linenum = source_linenum, |
112 | 0 | }; |
113 | 0 | va_list args; |
114 | |
|
115 | 0 | va_start(args, fmt); |
116 | 0 | T_BEGIN { |
117 | 0 | event_logv(event, ¶ms, fmt, args); |
118 | 0 | } T_END; |
119 | 0 | va_end(args); |
120 | 0 | } |
121 | | |
122 | | struct event_get_log_message_context { |
123 | | const struct event_log_params *params; |
124 | | |
125 | | string_t *log_prefix; |
126 | | const char *message; |
127 | | unsigned int type_pos; |
128 | | |
129 | | bool replace_prefix:1; |
130 | | bool str_out_done:1; |
131 | | }; |
132 | | |
133 | | static inline void ATTR_FORMAT(2, 0) |
134 | | event_get_log_message_str_out(struct event_get_log_message_context *glmctx, |
135 | | const char *fmt, va_list args) |
136 | 0 | { |
137 | 0 | const struct event_log_params *params = glmctx->params; |
138 | 0 | string_t *str_out = params->base_str_out; |
139 | | |
140 | | /* The message is appended once in full, rather than incremental during |
141 | | the recursion. */ |
142 | |
|
143 | 0 | if (glmctx->str_out_done || str_out == NULL) |
144 | 0 | return; |
145 | | |
146 | | /* append the current log prefix to the string buffer */ |
147 | 0 | if (params->base_str_prefix != NULL && !glmctx->replace_prefix) |
148 | 0 | str_append(str_out, params->base_str_prefix); |
149 | 0 | str_append_str(str_out, glmctx->log_prefix); |
150 | |
|
151 | 0 | if (glmctx->message != NULL) { |
152 | | /* a child event already constructed a message */ |
153 | 0 | str_append(str_out, glmctx->message); |
154 | 0 | } else { |
155 | 0 | va_list args_copy; |
156 | | |
157 | | /* construct message from format and arguments */ |
158 | 0 | VA_COPY(args_copy, args); |
159 | 0 | str_vprintfa(str_out, fmt, args_copy); |
160 | 0 | va_end(args_copy); |
161 | 0 | } |
162 | | |
163 | | /* finished with the string buffer */ |
164 | 0 | glmctx->str_out_done = TRUE; |
165 | 0 | } |
166 | | |
167 | | static bool ATTR_FORMAT(4, 0) |
168 | | event_get_log_message(struct event *event, |
169 | | struct event_get_log_message_context *glmctx, |
170 | | unsigned int prefixes_dropped, |
171 | | const char *fmt, va_list args) |
172 | 0 | { |
173 | 0 | const struct event_log_params *params = glmctx->params; |
174 | 0 | const char *prefix = event->log_prefix; |
175 | 0 | bool ret = FALSE; |
176 | | |
177 | | /* Reached the base event? */ |
178 | 0 | if (event == params->base_event) { |
179 | | /* Append the message to the provided string buffer. */ |
180 | 0 | event_get_log_message_str_out(glmctx, fmt, args); |
181 | | /* Insert the base send prefix */ |
182 | 0 | if (params->base_send_prefix != NULL) { |
183 | 0 | str_insert(glmctx->log_prefix, 0, |
184 | 0 | params->base_send_prefix); |
185 | 0 | ret = TRUE; |
186 | 0 | } |
187 | 0 | } |
188 | | |
189 | | /* Call the message amendment callback for this event if there is one. |
190 | | */ |
191 | 0 | if (event->log_message_callback != NULL) { |
192 | 0 | const char *in_message; |
193 | | |
194 | | /* construct the log message composed by children and arguments |
195 | | */ |
196 | 0 | if (glmctx->message == NULL) { |
197 | 0 | str_vprintfa(glmctx->log_prefix, fmt, args); |
198 | 0 | in_message = str_c(glmctx->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 = str_c(glmctx->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 == str_c(glmctx->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(str_c(glmctx->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 | 69 | { |
275 | 69 | struct failure_context ctx = { .type = LOG_TYPE_DEBUG }; |
276 | | |
277 | 69 | if (event->forced_never_debug && level == LOG_TYPE_DEBUG) |
278 | 0 | return FALSE; |
279 | 69 | if (level >= event->min_log_level) { |
280 | | /* Always log when level is at least this high */ |
281 | 0 | return TRUE; |
282 | 0 | } |
283 | | |
284 | 69 | 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 | 0 | return event->sending_debug_log; |
290 | 0 | } |
291 | 69 | event->debug_level_checked_filter_counter = |
292 | 69 | event_filter_replace_counter; |
293 | | |
294 | 69 | if (event->forced_debug) { |
295 | | /* Debugging is forced for this event (and its children) */ |
296 | 0 | event->sending_debug_log = TRUE; |
297 | 69 | } else if (global_debug_log_filter != NULL && |
298 | 0 | 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 | 69 | } else if (global_core_log_filter != NULL && |
303 | 0 | 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 | 69 | } else { |
308 | 69 | event->sending_debug_log = FALSE; |
309 | 69 | } |
310 | 69 | return event->sending_debug_log; |
311 | 69 | } |
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 | 69 | { |
318 | 69 | if (event_want_log_level(event, level, source_filename, source_linenum)) |
319 | 0 | return TRUE; |
320 | | |
321 | | /* see if debug send filtering matches */ |
322 | 69 | struct event_filter *filter; |
323 | 69 | array_foreach_elem(&global_debug_send_filters, filter) { |
324 | 0 | struct failure_context ctx = { .type = LOG_TYPE_DEBUG }; |
325 | |
|
326 | 0 | if (filter != NULL && |
327 | 0 | event_filter_match_source(filter, event, |
328 | 0 | source_filename, source_linenum, |
329 | 0 | &ctx)) |
330 | 0 | return TRUE; |
331 | 0 | } |
332 | 69 | return FALSE; |
333 | 69 | } |
334 | | |
335 | | static void ATTR_FORMAT(3, 0) |
336 | | event_logv_params(struct event *event, const struct event_log_params *params, |
337 | | const char *fmt, va_list args) |
338 | 0 | { |
339 | 0 | struct event_get_log_message_context glmctx; |
340 | |
|
341 | 0 | struct failure_context ctx = { |
342 | 0 | .type = params->log_type, |
343 | 0 | }; |
344 | 0 | bool abort_after_event = FALSE; |
345 | |
|
346 | 0 | i_assert(!params->no_send || params->base_str_out != NULL); |
347 | | |
348 | 0 | if (global_core_log_filter != NULL && |
349 | 0 | event_filter_match_source(global_core_log_filter, event, |
350 | 0 | event->source_filename, |
351 | 0 | event->source_linenum, &ctx)) |
352 | 0 | abort_after_event = TRUE; |
353 | |
|
354 | 0 | i_zero(&glmctx); |
355 | 0 | glmctx.params = params; |
356 | 0 | glmctx.log_prefix = t_str_new(64); |
357 | 0 | if (!event_get_log_message(event, &glmctx, 0, fmt, args)) { |
358 | | /* keep log prefix as it is */ |
359 | 0 | if (params->base_str_out != NULL && !glmctx.str_out_done) { |
360 | 0 | va_list args_copy; |
361 | |
|
362 | 0 | VA_COPY(args_copy, args); |
363 | 0 | str_vprintfa(params->base_str_out, fmt, args_copy); |
364 | 0 | va_end(args_copy); |
365 | 0 | } |
366 | 0 | if (!params->no_send) |
367 | 0 | event_vsend(event, &ctx, fmt, args); |
368 | 0 | } else if (params->no_send) { |
369 | | /* don't send the event */ |
370 | 0 | } else if (glmctx.replace_prefix) { |
371 | | /* event overrides the log prefix (even if it's "") */ |
372 | 0 | ctx.log_prefix = str_c(glmctx.log_prefix); |
373 | 0 | ctx.log_prefix_type_pos = glmctx.type_pos; |
374 | 0 | if (glmctx.message != NULL) |
375 | 0 | event_send(event, &ctx, "%s", glmctx.message); |
376 | 0 | else |
377 | 0 | event_vsend(event, &ctx, fmt, args); |
378 | 0 | } else { |
379 | | /* append to log prefix, but don't fully replace it */ |
380 | 0 | if (glmctx.message != NULL) |
381 | 0 | str_append(glmctx.log_prefix, glmctx.message); |
382 | 0 | else |
383 | 0 | str_vprintfa(glmctx.log_prefix, fmt, args); |
384 | 0 | event_send(event, &ctx, "%s", str_c(glmctx.log_prefix)); |
385 | 0 | } |
386 | 0 | if (abort_after_event) |
387 | 0 | abort(); |
388 | 0 | } |
389 | | |
390 | | void event_logv(struct event *event, const struct event_log_params *params, |
391 | | const char *fmt, va_list args) |
392 | 0 | { |
393 | 0 | const char *orig_source_filename = event->source_filename; |
394 | 0 | unsigned int orig_source_linenum = event->source_linenum; |
395 | 0 | int old_errno = errno; |
396 | |
|
397 | 0 | if (params->source_filename != NULL) { |
398 | 0 | event_set_source(event, params->source_filename, |
399 | 0 | params->source_linenum, TRUE); |
400 | 0 | } |
401 | |
|
402 | 0 | (void)event_want_log_level(event, params->log_type, |
403 | 0 | event->source_filename, |
404 | 0 | event->source_linenum); |
405 | |
|
406 | 0 | event_ref(event); |
407 | 0 | event_logv_params(event, params, fmt, args); |
408 | 0 | event_set_source(event, orig_source_filename, |
409 | 0 | orig_source_linenum, TRUE); |
410 | 0 | event_unref(&event); |
411 | 0 | errno = old_errno; |
412 | 0 | } |
413 | | |
414 | | struct event *event_set_forced_debug(struct event *event, bool force) |
415 | 0 | { |
416 | 0 | if (force) |
417 | 0 | event->forced_debug = TRUE; |
418 | 0 | event_recalculate_debug_level(event); |
419 | 0 | return event; |
420 | 0 | } |
421 | | |
422 | | struct event *event_unset_forced_debug(struct event *event) |
423 | 0 | { |
424 | 0 | event->forced_debug = FALSE; |
425 | 0 | event_recalculate_debug_level(event); |
426 | 0 | return event; |
427 | 0 | } |
428 | | |
429 | | struct event *event_set_forced_never_debug(struct event *event, bool force) |
430 | 0 | { |
431 | 0 | event->forced_never_debug = force; |
432 | 0 | return event; |
433 | 0 | } |
434 | | |
435 | | void event_set_global_debug_log_filter(struct event_filter *filter) |
436 | 0 | { |
437 | 0 | event_unset_global_debug_log_filter(); |
438 | 0 | global_debug_log_filter = filter; |
439 | 0 | event_filter_ref(global_debug_log_filter); |
440 | 0 | event_filter_replace_counter++; |
441 | 0 | } |
442 | | |
443 | | struct event_filter *event_get_global_debug_log_filter(void) |
444 | 0 | { |
445 | 0 | return global_debug_log_filter; |
446 | 0 | } |
447 | | |
448 | | void event_unset_global_debug_log_filter(void) |
449 | 2.47k | { |
450 | 2.47k | event_filter_unref(&global_debug_log_filter); |
451 | 2.47k | event_filter_replace_counter++; |
452 | 2.47k | } |
453 | | |
454 | | struct event_filter **event_global_debug_send_filter_register(void) |
455 | 0 | { |
456 | 0 | return array_append_space(&global_debug_send_filters); |
457 | 0 | } |
458 | | |
459 | | void event_global_debug_send_filter_updated(void) |
460 | 0 | { |
461 | 0 | event_filter_replace_counter++; |
462 | 0 | } |
463 | | |
464 | | void event_set_global_core_log_filter(struct event_filter *filter) |
465 | 0 | { |
466 | 0 | event_unset_global_core_log_filter(); |
467 | 0 | global_core_log_filter = filter; |
468 | 0 | event_filter_ref(global_core_log_filter); |
469 | 0 | event_filter_replace_counter++; |
470 | 0 | } |
471 | | |
472 | | struct event_filter *event_get_global_core_log_filter(void) |
473 | 0 | { |
474 | 0 | return global_core_log_filter; |
475 | 0 | } |
476 | | |
477 | | void event_unset_global_core_log_filter(void) |
478 | 2.47k | { |
479 | 2.47k | event_filter_unref(&global_core_log_filter); |
480 | 2.47k | event_filter_replace_counter++; |
481 | 2.47k | } |
482 | | |
483 | | void event_log_init(void) |
484 | 2.47k | { |
485 | 2.47k | i_array_init(&global_debug_send_filters, 2); |
486 | 2.47k | } |
487 | | |
488 | | void event_log_deinit(void) |
489 | 2.47k | { |
490 | 2.47k | struct event_filter *filter; |
491 | 2.47k | array_foreach_elem(&global_debug_send_filters, filter) |
492 | 0 | event_filter_unref(&filter); |
493 | 2.47k | array_free(&global_debug_send_filters); |
494 | 2.47k | } |