/* Copyright (c) 2017-2018 Dovecot authors, see the included COPYING file */ #include "lib.h" #include "str.h" #include "event-filter.h" #include "lib-event-private.h" unsigned int event_filter_replace_counter = 1; static struct event_filter *global_debug_log_filter = NULL; static struct event_filter *global_debug_send_filter = NULL; static struct event_filter *global_core_log_filter = NULL; #undef e_error void e_error(struct event *event, const char *source_filename, unsigned int source_linenum, const char *fmt, ...) { struct event_log_params params = { .log_type = LOG_TYPE_ERROR, .source_filename = source_filename, .source_linenum = source_linenum, }; va_list args; va_start(args, fmt); T_BEGIN { event_logv(event, ¶ms, fmt, args); } T_END; va_end(args); } #undef e_warning void e_warning(struct event *event, const char *source_filename, unsigned int source_linenum, const char *fmt, ...) { struct event_log_params params = { .log_type = LOG_TYPE_WARNING, .source_filename = source_filename, .source_linenum = source_linenum, }; va_list args; va_start(args, fmt); T_BEGIN { event_logv(event, ¶ms, fmt, args); } T_END; va_end(args); } #undef e_info void e_info(struct event *event, const char *source_filename, unsigned int source_linenum, const char *fmt, ...) { struct event_log_params params = { .log_type = LOG_TYPE_INFO, .source_filename = source_filename, .source_linenum = source_linenum, }; va_list args; va_start(args, fmt); T_BEGIN { event_logv(event, ¶ms, fmt, args); } T_END; va_end(args); } #undef e_debug void e_debug(struct event *event, const char *source_filename, unsigned int source_linenum, const char *fmt, ...) { struct event_log_params params = { .log_type = LOG_TYPE_DEBUG, .source_filename = source_filename, .source_linenum = source_linenum, }; va_list args; va_start(args, fmt); T_BEGIN { event_logv(event, ¶ms, fmt, args); } T_END; va_end(args); } #undef e_log void e_log(struct event *event, enum log_type level, const char *source_filename, unsigned int source_linenum, const char *fmt, ...) { struct event_log_params params = { .log_type = level, .source_filename = source_filename, .source_linenum = source_linenum, }; va_list args; va_start(args, fmt); T_BEGIN { event_logv(event, ¶ms, fmt, args); } T_END; va_end(args); } struct event_get_log_message_context { const struct event_log_params *params; string_t *log_prefix; const char *message; unsigned int type_pos; bool replace_prefix:1; bool str_out_done:1; }; 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) { const struct event_log_params *params = glmctx->params; string_t *str_out = params->base_str_out; /* The message is appended once in full, rather than incremental during the recursion. */ if (glmctx->str_out_done || str_out == NULL) return; /* append the current log prefix to the string buffer */ if (params->base_str_prefix != NULL && !glmctx->replace_prefix) str_append(str_out, params->base_str_prefix); str_append_str(str_out, glmctx->log_prefix); if (glmctx->message != NULL) { /* a child event already constructed a message */ str_append(str_out, glmctx->message); } else { va_list args_copy; /* construct message from format and arguments */ VA_COPY(args_copy, args); str_vprintfa(str_out, fmt, args_copy); va_end(args_copy); } /* finished with the string buffer */ glmctx->str_out_done = TRUE; } 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) { const struct event_log_params *params = glmctx->params; const char *prefix = event->log_prefix; bool ret = FALSE; /* Reached the base event? */ if (event == params->base_event) { /* Append the message to the provided string buffer. */ event_get_log_message_str_out(glmctx, fmt, args); /* Insert the base send prefix */ if (params->base_send_prefix != NULL) { str_insert(glmctx->log_prefix, 0, params->base_send_prefix); ret = TRUE; } } /* Call the message amendment callback for this event if there is one. */ if (event->log_message_callback != NULL) { const char *in_message; /* construct the log message composed by children and arguments */ if (glmctx->message == NULL) { str_vprintfa(glmctx->log_prefix, fmt, args); in_message = str_c(glmctx->log_prefix); } else if (str_len(glmctx->log_prefix) == 0) { in_message = glmctx->message; } else { str_append(glmctx->log_prefix, glmctx->message); in_message = str_c(glmctx->log_prefix); } /* reformat the log message */ glmctx->message = event->log_message_callback( event->log_message_callback_context, glmctx->params->log_type, in_message); /* continue with a cleared prefix buffer (as prefix is now part of *message_r). */ str_truncate(glmctx->log_prefix, 0); ret = TRUE; } if (event->log_prefix_callback != NULL) { prefix = event->log_prefix_callback( event->log_prefix_callback_context); } if (event->log_prefix_replace) { /* this event replaces all parent log prefixes */ glmctx->replace_prefix = TRUE; glmctx->type_pos = (prefix == NULL ? 0 : strlen(prefix)); event_get_log_message_str_out(glmctx, fmt, args); } if (prefix != NULL) { if (event->log_prefix_replace || prefixes_dropped == 0) { str_insert(glmctx->log_prefix, 0, prefix); ret = TRUE; } else if (prefixes_dropped > 0) { prefixes_dropped--; } } if (event->parent == NULL) { event_get_log_message_str_out(glmctx, fmt, args); if (params->base_event == NULL && params->base_send_prefix != NULL && !glmctx->replace_prefix) { str_insert(glmctx->log_prefix, 0, params->base_send_prefix); ret = TRUE; } } else if (!event->log_prefix_replace && (!params->no_send || !glmctx->str_out_done)) { prefixes_dropped += event->log_prefixes_dropped; if (event_get_log_message(event->parent, glmctx, prefixes_dropped, fmt, args)) ret = TRUE; } return ret; } void event_log(struct event *event, const struct event_log_params *params, const char *fmt, ...) { va_list args; va_start(args, fmt); event_logv(event, params, fmt, args); va_end(args); } #undef event_want_log_level bool event_want_log_level(struct event *event, enum log_type level, const char *source_filename, unsigned int source_linenum) { struct failure_context ctx = { .type = LOG_TYPE_DEBUG }; if (level >= event->min_log_level) { /* Always log when level is at least this high */ return TRUE; } if (event->debug_level_checked_filter_counter == event_filter_replace_counter) { /* Log filters haven't changed since we last checked this, so we can rely on the last cached value. FIXME: this doesn't work correctly if event changes and the change affects whether the filters would match. */ return event->sending_debug_log; } event->debug_level_checked_filter_counter = event_filter_replace_counter; if (event->forced_debug) { /* Debugging is forced for this event (and its children) */ event->sending_debug_log = TRUE; } else if (global_debug_log_filter != NULL && event_filter_match_source(global_debug_log_filter, event, source_filename, source_linenum, &ctx)) { /* log_debug filter matched */ event->sending_debug_log = TRUE; } else if (global_core_log_filter != NULL && event_filter_match_source(global_core_log_filter, event, source_filename, source_linenum, &ctx)) { /* log_core_filter matched */ event->sending_debug_log = TRUE; } else { event->sending_debug_log = FALSE; } return event->sending_debug_log; } #undef event_want_level bool event_want_level(struct event *event, enum log_type level, const char *source_filename, unsigned int source_linenum) { if (event_want_log_level(event, level, source_filename, source_linenum)) return TRUE; /* see if debug send filtering matches */ if (global_debug_send_filter != NULL) { struct failure_context ctx = { .type = LOG_TYPE_DEBUG }; if (event_filter_match_source(global_debug_send_filter, event, source_filename, source_linenum, &ctx)) return TRUE; } return FALSE; } static void ATTR_FORMAT(3, 0) event_logv_params(struct event *event, const struct event_log_params *params, const char *fmt, va_list args) { struct event_get_log_message_context glmctx; struct failure_context ctx = { .type = params->log_type, }; bool abort_after_event = FALSE; i_assert(!params->no_send || params->base_str_out != NULL); if (global_core_log_filter != NULL && event_filter_match_source(global_core_log_filter, event, event->source_filename, event->source_linenum, &ctx)) abort_after_event = TRUE; i_zero(&glmctx); glmctx.params = params; glmctx.log_prefix = t_str_new(64); if (!event_get_log_message(event, &glmctx, 0, fmt, args)) { /* keep log prefix as it is */ if (params->base_str_out != NULL && !glmctx.str_out_done) { va_list args_copy; VA_COPY(args_copy, args); str_vprintfa(params->base_str_out, fmt, args_copy); va_end(args_copy); } if (!params->no_send) event_vsend(event, &ctx, fmt, args); } else if (params->no_send) { /* don't send the event */ } else if (glmctx.replace_prefix) { /* event overrides the log prefix (even if it's "") */ ctx.log_prefix = str_c(glmctx.log_prefix); ctx.log_prefix_type_pos = glmctx.type_pos; if (glmctx.message != NULL) event_send(event, &ctx, "%s", glmctx.message); else event_vsend(event, &ctx, fmt, args); } else { /* append to log prefix, but don't fully replace it */ if (glmctx.message != NULL) str_append(glmctx.log_prefix, glmctx.message); else str_vprintfa(glmctx.log_prefix, fmt, args); event_send(event, &ctx, "%s", str_c(glmctx.log_prefix)); } if (abort_after_event) abort(); } void event_logv(struct event *event, const struct event_log_params *params, const char *fmt, va_list args) { const char *orig_source_filename = event->source_filename; unsigned int orig_source_linenum = event->source_linenum; int old_errno = errno; if (params->source_filename != NULL) { event_set_source(event, params->source_filename, params->source_linenum, TRUE); } (void)event_want_log_level(event, params->log_type, event->source_filename, event->source_linenum); event_ref(event); event_logv_params(event, params, fmt, args); event_set_source(event, orig_source_filename, orig_source_linenum, TRUE); event_unref(&event); errno = old_errno; } struct event *event_set_forced_debug(struct event *event, bool force) { if (force) event->forced_debug = TRUE; event_recalculate_debug_level(event); return event; } struct event *event_unset_forced_debug(struct event *event) { event->forced_debug = FALSE; event_recalculate_debug_level(event); return event; } void event_set_global_debug_log_filter(struct event_filter *filter) { event_unset_global_debug_log_filter(); global_debug_log_filter = filter; event_filter_ref(global_debug_log_filter); event_filter_replace_counter++; } struct event_filter *event_get_global_debug_log_filter(void) { return global_debug_log_filter; } void event_unset_global_debug_log_filter(void) { event_filter_unref(&global_debug_log_filter); event_filter_replace_counter++; } void event_set_global_debug_send_filter(struct event_filter *filter) { event_unset_global_debug_send_filter(); global_debug_send_filter = filter; event_filter_ref(global_debug_send_filter); event_filter_replace_counter++; } struct event_filter *event_get_global_debug_send_filter(void) { return global_debug_send_filter; } void event_unset_global_debug_send_filter(void) { event_filter_unref(&global_debug_send_filter); event_filter_replace_counter++; } void event_set_global_core_log_filter(struct event_filter *filter) { event_unset_global_core_log_filter(); global_core_log_filter = filter; event_filter_ref(global_core_log_filter); event_filter_replace_counter++; } struct event_filter *event_get_global_core_log_filter(void) { return global_core_log_filter; } void event_unset_global_core_log_filter(void) { event_filter_unref(&global_core_log_filter); event_filter_replace_counter++; }