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