Coverage Report

Created: 2025-08-26 07:01

/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, &params, 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, &params, 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, &params, 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, &params, 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, &params, 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
}