Coverage Report

Created: 2026-08-08 06:29

next uncovered line (L), next uncovered region (R), next uncovered branch (B)
/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, &params, 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, &params, 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, &params, 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, &params, 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, &params, 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
}