/src/dovecot/src/lib/failures.c
Line | Count | Source (jump to first uncovered line) |
1 | | /* Copyright (c) 2002-2018 Dovecot authors, see the included COPYING file */ |
2 | | |
3 | | #include "lib.h" |
4 | | #include "ioloop.h" |
5 | | #include "str.h" |
6 | | #include "hostpid.h" |
7 | | #include "net.h" |
8 | | #include "process-title.h" |
9 | | #include "lib-signals.h" |
10 | | #include "backtrace-string.h" |
11 | | #include "printf-format-fix.h" |
12 | | #include "write-full.h" |
13 | | #include "time-util.h" |
14 | | #include "failures-private.h" |
15 | | |
16 | | #include <unistd.h> |
17 | | #include <fcntl.h> |
18 | | #include <syslog.h> |
19 | | #include <time.h> |
20 | | #include <poll.h> |
21 | | |
22 | 0 | #define LOG_TYPE_FLAG_PREFIX_LEN 0x40 |
23 | 0 | #define LOG_TYPE_FLAG_DISABLE_LOG_PREFIX 0x80 |
24 | | |
25 | | const char *failure_log_type_prefixes[] = { |
26 | | "Debug: ", |
27 | | "Info: ", |
28 | | "Warning: ", |
29 | | "Error: ", |
30 | | "Fatal: ", |
31 | | "Panic: " |
32 | | }; |
33 | | static_assert_array_size(failure_log_type_prefixes, LOG_TYPE_COUNT); |
34 | | |
35 | | const char *failure_log_type_names[LOG_TYPE_COUNT] = { |
36 | | "debug", "info", "warning", "error", "fatal", "panic" |
37 | | }; |
38 | | |
39 | | static int log_fd_write(int fd, const unsigned char *data, size_t len); |
40 | | |
41 | | static void error_handler_real(const struct failure_context *ctx, |
42 | | const char *format, va_list args); |
43 | | |
44 | | /* Initialize working defaults */ |
45 | | static failure_callback_t *fatal_handler ATTR_NORETURN = |
46 | | default_fatal_handler; |
47 | | static failure_callback_t *error_handler = default_error_handler; |
48 | | static failure_callback_t *info_handler = default_error_handler; |
49 | | static failure_callback_t *debug_handler = default_error_handler; |
50 | | static void (*failure_exit_callback)(int *) = NULL; |
51 | | |
52 | | static struct failure_context failure_ctx_debug = { .type = LOG_TYPE_DEBUG }; |
53 | | static struct failure_context failure_ctx_info = { .type = LOG_TYPE_INFO }; |
54 | | static struct failure_context failure_ctx_warning = { .type = LOG_TYPE_WARNING }; |
55 | | static struct failure_context failure_ctx_error = { .type = LOG_TYPE_ERROR }; |
56 | | |
57 | | static int log_fd = STDERR_FILENO, log_info_fd = STDERR_FILENO, |
58 | | log_debug_fd = STDERR_FILENO; |
59 | | static char *log_prefix = NULL; |
60 | | static char *log_stamp_format = NULL, *log_stamp_format_suffix = NULL; |
61 | | static bool failure_ignore_errors = FALSE, log_prefix_sent = FALSE; |
62 | | static bool coredump_on_error = FALSE; |
63 | | static void log_timestamp_add(const struct failure_context *ctx, string_t *str); |
64 | | static void log_prefix_add(const struct failure_context *ctx, string_t *str); |
65 | | static int i_failure_send_option_forced(const char *key, const char *value); |
66 | | static int internal_send_split(string_t *full_str, size_t prefix_len); |
67 | | |
68 | | static string_t * ATTR_FORMAT(3, 0) default_format(const struct failure_context *ctx, |
69 | | size_t *prefix_len_r ATTR_UNUSED, |
70 | | const char *format, |
71 | | va_list args) |
72 | 0 | { |
73 | 0 | string_t *str = t_str_new(256); |
74 | 0 | log_timestamp_add(ctx, str); |
75 | 0 | log_prefix_add(ctx, str); |
76 | | |
77 | | /* make sure there's no %n in there and fix %m */ |
78 | 0 | str_vprintfa(str, printf_format_fix(format), args); |
79 | 0 | return str; |
80 | 0 | } |
81 | | |
82 | | static int default_write(enum log_type type, string_t *data, size_t prefix_len ATTR_UNUSED) |
83 | 0 | { |
84 | 0 | int fd; |
85 | |
|
86 | 0 | switch (type) { |
87 | 0 | case LOG_TYPE_DEBUG: |
88 | 0 | fd = log_debug_fd; |
89 | 0 | break; |
90 | 0 | case LOG_TYPE_INFO: |
91 | 0 | fd = log_info_fd; |
92 | 0 | break; |
93 | 0 | default: |
94 | 0 | fd = log_fd; |
95 | 0 | break; |
96 | 0 | } |
97 | 0 | str_append_c(data, '\n'); |
98 | 0 | return log_fd_write(fd, str_data(data), str_len(data)); |
99 | 0 | } |
100 | | |
101 | | static void default_on_handler_failure(const struct failure_context *ctx) |
102 | 0 | { |
103 | 0 | const char *log_type = "info"; |
104 | 0 | switch (ctx->type) { |
105 | 0 | case LOG_TYPE_DEBUG: |
106 | 0 | log_type = "debug"; |
107 | | /* fall through */ |
108 | 0 | case LOG_TYPE_INFO: |
109 | | /* we failed to log to info/debug log, try to log the |
110 | | write error to error log - maybe that'll work. */ |
111 | 0 | i_fatal_status(FATAL_LOGWRITE, "write() failed to %s log: %m", |
112 | 0 | log_type); |
113 | 0 | default: |
114 | 0 | failure_exit(FATAL_LOGWRITE); |
115 | 0 | } |
116 | 0 | } |
117 | | |
118 | | static void default_post_handler(const struct failure_context *ctx) |
119 | 0 | { |
120 | 0 | if (ctx->type == LOG_TYPE_ERROR && coredump_on_error) |
121 | 0 | abort(); |
122 | 0 | } |
123 | | |
124 | | static string_t * ATTR_FORMAT(3, 0) syslog_format(const struct failure_context *ctx, |
125 | | size_t *prefix_len_r ATTR_UNUSED, |
126 | | const char *format, |
127 | | va_list args) |
128 | 0 | { |
129 | 0 | string_t *str = t_str_new(128); |
130 | 0 | if (ctx->type == LOG_TYPE_INFO) { |
131 | 0 | if (ctx->log_prefix != NULL) |
132 | 0 | str_append(str, ctx->log_prefix); |
133 | 0 | else if (log_prefix != NULL) |
134 | 0 | str_append(str, log_prefix); |
135 | 0 | } else { |
136 | 0 | log_prefix_add(ctx, str); |
137 | 0 | } |
138 | 0 | str_vprintfa(str, format, args); |
139 | 0 | return str; |
140 | 0 | } |
141 | | |
142 | | static int syslog_write(enum log_type type, string_t *data, size_t prefix_len ATTR_UNUSED) |
143 | 0 | { |
144 | 0 | int level = LOG_ERR; |
145 | |
|
146 | 0 | switch (type) { |
147 | 0 | case LOG_TYPE_DEBUG: |
148 | 0 | level = LOG_DEBUG; |
149 | 0 | break; |
150 | 0 | case LOG_TYPE_INFO: |
151 | 0 | level = LOG_INFO; |
152 | 0 | break; |
153 | 0 | case LOG_TYPE_WARNING: |
154 | 0 | level = LOG_WARNING; |
155 | 0 | break; |
156 | 0 | case LOG_TYPE_ERROR: |
157 | 0 | level = LOG_ERR; |
158 | 0 | break; |
159 | 0 | case LOG_TYPE_FATAL: |
160 | 0 | case LOG_TYPE_PANIC: |
161 | 0 | level = LOG_CRIT; |
162 | 0 | break; |
163 | 0 | case LOG_TYPE_COUNT: |
164 | 0 | case LOG_TYPE_OPTION: |
165 | 0 | i_unreached(); |
166 | 0 | } |
167 | 0 | syslog(level, "%s", str_c(data)); |
168 | 0 | return 0; |
169 | 0 | } |
170 | | |
171 | | static void syslog_on_handler_failure(const struct failure_context *ctx ATTR_UNUSED) |
172 | 0 | { |
173 | 0 | failure_exit(FATAL_LOGERROR); |
174 | 0 | } |
175 | | |
176 | | static void syslog_post_handler(const struct failure_context *ctx ATTR_UNUSED) |
177 | 0 | { |
178 | 0 | } |
179 | | |
180 | | static string_t * ATTR_FORMAT(3, 0) internal_format(const struct failure_context *ctx, |
181 | | size_t *prefix_len_r, |
182 | | const char *format, |
183 | | va_list args) |
184 | 0 | { |
185 | 0 | string_t *str; |
186 | 0 | unsigned char log_type = ctx->type + 1; |
187 | |
|
188 | 0 | if (ctx->log_prefix != NULL) { |
189 | 0 | log_type |= LOG_TYPE_FLAG_DISABLE_LOG_PREFIX; |
190 | 0 | if (ctx->log_prefix_type_pos != 0) |
191 | 0 | log_type |= LOG_TYPE_FLAG_PREFIX_LEN; |
192 | 0 | } else if (!log_prefix_sent && log_prefix != NULL) { |
193 | 0 | if (i_failure_send_option_forced("prefix", log_prefix) < 0) { |
194 | | /* Failed to write log prefix. The log message writing |
195 | | would likely fail as well, but don't even try since |
196 | | the log prefix would be wrong. */ |
197 | 0 | return NULL; |
198 | 0 | } |
199 | 0 | log_prefix_sent = TRUE; |
200 | 0 | } |
201 | | |
202 | 0 | str = t_str_new(128); |
203 | 0 | str_printfa(str, "\001%c%s ", log_type, my_pid); |
204 | 0 | if ((log_type & LOG_TYPE_FLAG_PREFIX_LEN) != 0) |
205 | 0 | str_printfa(str, "%u ", ctx->log_prefix_type_pos); |
206 | 0 | if (ctx->log_prefix != NULL) |
207 | 0 | str_append(str, ctx->log_prefix); |
208 | 0 | *prefix_len_r = str_len(str); |
209 | |
|
210 | 0 | str_vprintfa(str, format, args); |
211 | 0 | return str; |
212 | 0 | } |
213 | | |
214 | | static int internal_write(enum log_type type ATTR_UNUSED, string_t *data, size_t prefix_len) |
215 | 0 | { |
216 | 0 | if (str_len(data)+1 <= PIPE_BUF) { |
217 | 0 | str_append_c(data, '\n'); |
218 | 0 | return log_fd_write(STDERR_FILENO, |
219 | 0 | str_data(data), str_len(data)); |
220 | 0 | } |
221 | 0 | return internal_send_split(data, prefix_len); |
222 | 0 | } |
223 | | |
224 | | static void internal_on_handler_failure(const struct failure_context *ctx ATTR_UNUSED) |
225 | 0 | { |
226 | 0 | failure_exit(FATAL_LOGERROR); |
227 | 0 | } |
228 | | |
229 | | static void internal_post_handler(const struct failure_context *ctx ATTR_UNUSED) |
230 | 0 | { |
231 | 0 | } |
232 | | |
233 | | static struct failure_handler_vfuncs default_handler_vfuncs = { |
234 | | .write = &default_write, |
235 | | .format = &default_format, |
236 | | .on_handler_failure = &default_on_handler_failure, |
237 | | .post_handler = &default_post_handler |
238 | | }; |
239 | | |
240 | | static struct failure_handler_vfuncs syslog_handler_vfuncs = { |
241 | | .write = &syslog_write, |
242 | | .format = &syslog_format, |
243 | | .on_handler_failure = &syslog_on_handler_failure, |
244 | | .post_handler = &syslog_post_handler |
245 | | }; |
246 | | |
247 | | static struct failure_handler_vfuncs internal_handler_vfuncs = { |
248 | | .write = &internal_write, |
249 | | .format = &internal_format, |
250 | | .on_handler_failure = &internal_on_handler_failure, |
251 | | .post_handler = &internal_post_handler |
252 | | }; |
253 | | |
254 | | struct failure_handler_config failure_handler = { .fatal_err_reset = FATAL_LOGWRITE, |
255 | | .v = &default_handler_vfuncs }; |
256 | | |
257 | | static int common_handler(const struct failure_context *ctx, |
258 | | const char *format, va_list args) |
259 | 0 | { |
260 | 0 | static int recursed = 0; |
261 | 0 | int ret; |
262 | 0 | size_t prefix_len = 0; |
263 | |
|
264 | 0 | if (recursed >= 2) { |
265 | | /* we're being called from some signal handler or we ran |
266 | | out of memory */ |
267 | 0 | return -1; |
268 | 0 | } |
269 | 0 | recursed++; |
270 | |
|
271 | 0 | T_BEGIN { |
272 | 0 | string_t *str = failure_handler.v->format(ctx, &prefix_len, format, args); |
273 | 0 | ret = str == NULL ? -1 : |
274 | 0 | failure_handler.v->write(ctx->type, str, prefix_len); |
275 | 0 | } T_END; |
276 | | |
277 | 0 | if (ret < 0 && failure_ignore_errors) |
278 | 0 | ret = 0; |
279 | |
|
280 | 0 | recursed--; |
281 | 0 | return ret; |
282 | 0 | } |
283 | | |
284 | | static void error_handler_real(const struct failure_context *ctx, |
285 | | const char *format, va_list args) |
286 | 0 | { |
287 | 0 | if (common_handler(ctx, format, args) < 0) |
288 | 0 | failure_handler.v->on_handler_failure(ctx); |
289 | 0 | failure_handler.v->post_handler(ctx); |
290 | 0 | } |
291 | | |
292 | | static void ATTR_FORMAT(2, 0) |
293 | | i_internal_error_handler(const struct failure_context *ctx, |
294 | | const char *format, va_list args); |
295 | | |
296 | | /* kludgy .. we want to trust log_stamp_format with -Wformat-nonliteral */ |
297 | | static const char * |
298 | | get_log_stamp_format(const char *format_arg, unsigned int timestamp_usecs) |
299 | | ATTR_FORMAT_ARG(1); |
300 | | |
301 | | static const char *get_log_stamp_format(const char *format_arg ATTR_UNUSED, |
302 | | unsigned int timestamp_usecs) |
303 | 0 | { |
304 | 0 | if (log_stamp_format_suffix == NULL) |
305 | 0 | return log_stamp_format; |
306 | 0 | return t_strdup_printf("%s%06u%s", log_stamp_format, |
307 | 0 | timestamp_usecs, log_stamp_format_suffix); |
308 | 0 | } |
309 | | |
310 | | void failure_exit(int status) |
311 | 0 | { |
312 | 0 | static bool recursed = FALSE; |
313 | |
|
314 | 0 | if (failure_exit_callback != NULL && !recursed) { |
315 | 0 | recursed = TRUE; |
316 | 0 | failure_exit_callback(&status); |
317 | 0 | } |
318 | 0 | lib_exit(status); |
319 | 0 | } |
320 | | |
321 | | static void log_timestamp_add(const struct failure_context *ctx, string_t *str) |
322 | 0 | { |
323 | 0 | const struct tm *tm = ctx->timestamp; |
324 | 0 | char buf[256]; |
325 | 0 | struct timeval now; |
326 | |
|
327 | 0 | if (log_stamp_format != NULL) { |
328 | 0 | if (tm == NULL) { |
329 | 0 | i_gettimeofday(&now); |
330 | 0 | tm = localtime(&now.tv_sec); |
331 | 0 | } else { |
332 | 0 | now.tv_usec = ctx->timestamp_usecs; |
333 | 0 | } |
334 | |
|
335 | 0 | if (strftime(buf, sizeof(buf), |
336 | 0 | get_log_stamp_format("unused", now.tv_usec), tm) > 0) |
337 | 0 | str_append(str, buf); |
338 | 0 | } |
339 | 0 | } |
340 | | |
341 | | static void log_prefix_add(const struct failure_context *ctx, string_t *str) |
342 | 0 | { |
343 | 0 | if (ctx->log_prefix == NULL) { |
344 | | /* use global log prefix */ |
345 | 0 | if (log_prefix != NULL) |
346 | 0 | str_append(str, log_prefix); |
347 | 0 | str_append(str, failure_log_type_prefixes[ctx->type]); |
348 | 0 | } else if (ctx->log_prefix_type_pos == 0) { |
349 | 0 | str_append(str, ctx->log_prefix); |
350 | 0 | str_append(str, failure_log_type_prefixes[ctx->type]); |
351 | 0 | } else { |
352 | 0 | i_assert(ctx->log_prefix_type_pos <= strlen(ctx->log_prefix)); |
353 | 0 | str_append_data(str, ctx->log_prefix, ctx->log_prefix_type_pos); |
354 | 0 | str_append(str, failure_log_type_prefixes[ctx->type]); |
355 | 0 | str_append(str, ctx->log_prefix + ctx->log_prefix_type_pos); |
356 | 0 | } |
357 | 0 | } |
358 | | |
359 | | static void fd_wait_writable(int fd) |
360 | 0 | { |
361 | 0 | struct pollfd pfd = { |
362 | 0 | .fd = fd, |
363 | 0 | .events = POLLOUT | POLLERR | POLLHUP | POLLNVAL, |
364 | 0 | }; |
365 | | |
366 | | /* Use poll() instead of ioloop, because we don't want to recurse back |
367 | | to log writing in case something fails. */ |
368 | 0 | if (poll(&pfd, 1, -1) < 0 && errno != EINTR) { |
369 | | /* Unexpected error. We're already blocking on log writes, |
370 | | so we can't log it. */ |
371 | 0 | abort(); |
372 | 0 | } |
373 | 0 | } |
374 | | |
375 | | static int log_fd_write(int fd, const unsigned char *data, size_t len) |
376 | 0 | { |
377 | 0 | ssize_t ret; |
378 | 0 | unsigned int prev_signal_term_counter = signal_term_counter; |
379 | 0 | unsigned int terminal_eintr_count = 0; |
380 | 0 | const char *old_title = NULL; |
381 | 0 | bool failed = FALSE, process_title_changed = FALSE; |
382 | |
|
383 | 0 | while (!failed && |
384 | 0 | (ret = write(fd, data, len)) != (ssize_t)len) { |
385 | 0 | if (ret > 0) { |
386 | | /* some was written, continue.. */ |
387 | 0 | data += ret; |
388 | 0 | len -= ret; |
389 | 0 | continue; |
390 | 0 | } |
391 | 0 | if (ret == 0) { |
392 | | /* out of disk space? */ |
393 | 0 | errno = ENOSPC; |
394 | 0 | failed = TRUE; |
395 | 0 | break; |
396 | 0 | } |
397 | 0 | switch (errno) { |
398 | 0 | case EAGAIN: { |
399 | | /* Log fd is nonblocking - wait until we can write more. |
400 | | Indicate in process title that the process is waiting |
401 | | because it's waiting on the log. |
402 | | |
403 | | Remember that the log fd is shared across processes, |
404 | | which also means the log fd flags are shared. So if |
405 | | one process changes the O_NONBLOCK flag for a log fd, |
406 | | all the processes see the change. To avoid problems, |
407 | | we'll wait using poll() instead of changing the |
408 | | O_NONBLOCK flag. */ |
409 | 0 | if (!process_title_changed) { |
410 | 0 | const char *title; |
411 | |
|
412 | 0 | process_title_changed = TRUE; |
413 | 0 | old_title = t_strdup(process_title_get()); |
414 | 0 | if (old_title == NULL) |
415 | 0 | title = "[blocking on log write]"; |
416 | 0 | else |
417 | 0 | title = t_strdup_printf("%s - [blocking on log write]", |
418 | 0 | old_title); |
419 | 0 | process_title_set(title); |
420 | 0 | } |
421 | 0 | fd_wait_writable(fd); |
422 | 0 | break; |
423 | 0 | } |
424 | 0 | case EINTR: |
425 | 0 | if (prev_signal_term_counter == signal_term_counter) { |
426 | | /* non-terminal signal. ignore. */ |
427 | 0 | } else if (terminal_eintr_count++ == 0) { |
428 | | /* we'd rather not die in the middle of |
429 | | writing to log. try again once more */ |
430 | 0 | } else { |
431 | | /* received two terminal signals. |
432 | | someone wants us dead. */ |
433 | 0 | failed = TRUE; |
434 | 0 | break; |
435 | 0 | } |
436 | 0 | break; |
437 | 0 | default: |
438 | 0 | failed = TRUE; |
439 | 0 | break; |
440 | 0 | } |
441 | 0 | prev_signal_term_counter = signal_term_counter; |
442 | 0 | } |
443 | 0 | if (process_title_changed) |
444 | 0 | process_title_set(old_title); |
445 | 0 | return failed ? -1 : 0; |
446 | 0 | } |
447 | | |
448 | | static void ATTR_NORETURN |
449 | | default_fatal_finish(enum log_type type, int status) |
450 | 0 | { |
451 | 0 | const char *backtrace, *error; |
452 | 0 | static int recursed = 0; |
453 | |
|
454 | 0 | recursed++; |
455 | 0 | if ((type == LOG_TYPE_PANIC || status == FATAL_OUTOFMEM) && |
456 | 0 | recursed == 1) { |
457 | 0 | if (backtrace_get(&backtrace, &error) == 0) |
458 | 0 | i_error("Raw backtrace: %s", backtrace); |
459 | 0 | } |
460 | 0 | recursed--; |
461 | |
|
462 | 0 | if (type == LOG_TYPE_PANIC || getenv("CORE_ERROR") != NULL || |
463 | 0 | (status == FATAL_OUTOFMEM && getenv("CORE_OUTOFMEM") != NULL)) |
464 | 0 | abort(); |
465 | 0 | else |
466 | 0 | failure_exit(status); |
467 | 0 | } |
468 | | |
469 | | static void ATTR_NORETURN fatal_handler_real(const struct failure_context *ctx, |
470 | | const char *format, va_list args) |
471 | 0 | { |
472 | 0 | int status = ctx->exit_status; |
473 | 0 | if (common_handler(ctx, format, args) < 0 && |
474 | 0 | status == FATAL_DEFAULT) |
475 | 0 | status = failure_handler.fatal_err_reset; |
476 | 0 | default_fatal_finish(ctx->type, status); |
477 | 0 | } |
478 | | |
479 | | void default_fatal_handler(const struct failure_context *ctx, |
480 | | const char *format, va_list args) |
481 | 0 | { |
482 | 0 | failure_handler.v = &default_handler_vfuncs; |
483 | 0 | failure_handler.fatal_err_reset = FATAL_LOGWRITE; |
484 | 0 | fatal_handler_real(ctx, format, args); |
485 | 0 | } |
486 | | |
487 | | void default_error_handler(const struct failure_context *ctx, |
488 | | const char *format, va_list args) |
489 | 0 | { |
490 | 0 | failure_handler.v = &default_handler_vfuncs; |
491 | 0 | failure_handler.fatal_err_reset = FATAL_LOGWRITE; |
492 | 0 | error_handler_real(ctx, format, args); |
493 | 0 | } |
494 | | |
495 | | void i_log_type(const struct failure_context *ctx, const char *format, ...) |
496 | 0 | { |
497 | 0 | va_list args; |
498 | |
|
499 | 0 | va_start(args, format); |
500 | 0 | i_log_typev(ctx, format, args); |
501 | 0 | va_end(args); |
502 | 0 | } |
503 | | |
504 | | void i_log_typev(const struct failure_context *ctx, const char *format, |
505 | | va_list args) |
506 | 0 | { |
507 | 0 | switch (ctx->type) { |
508 | 0 | case LOG_TYPE_DEBUG: |
509 | 0 | debug_handler(ctx, format, args); |
510 | 0 | break; |
511 | 0 | case LOG_TYPE_INFO: |
512 | 0 | info_handler(ctx, format, args); |
513 | 0 | break; |
514 | 0 | default: |
515 | 0 | error_handler(ctx, format, args); |
516 | 0 | } |
517 | 0 | } |
518 | | |
519 | | void i_panic(const char *format, ...) |
520 | 0 | { |
521 | 0 | struct failure_context ctx; |
522 | 0 | va_list args; |
523 | |
|
524 | 0 | lib_set_clean_exit(TRUE); |
525 | 0 | i_zero(&ctx); |
526 | 0 | ctx.type = LOG_TYPE_PANIC; |
527 | |
|
528 | 0 | va_start(args, format); |
529 | 0 | fatal_handler(&ctx, format, args); |
530 | 0 | i_unreached(); |
531 | | /*va_end(args);*/ |
532 | 0 | } |
533 | | |
534 | | void i_fatal(const char *format, ...) |
535 | 0 | { |
536 | 0 | struct failure_context ctx; |
537 | 0 | va_list args; |
538 | |
|
539 | 0 | lib_set_clean_exit(TRUE); |
540 | 0 | i_zero(&ctx); |
541 | 0 | ctx.type = LOG_TYPE_FATAL; |
542 | 0 | ctx.exit_status = FATAL_DEFAULT; |
543 | |
|
544 | 0 | va_start(args, format); |
545 | 0 | fatal_handler(&ctx, format, args); |
546 | 0 | i_unreached(); |
547 | | /*va_end(args);*/ |
548 | 0 | } |
549 | | |
550 | | void i_fatal_status(int status, const char *format, ...) |
551 | 0 | { |
552 | 0 | struct failure_context ctx; |
553 | 0 | va_list args; |
554 | |
|
555 | 0 | lib_set_clean_exit(TRUE); |
556 | 0 | i_zero(&ctx); |
557 | 0 | ctx.type = LOG_TYPE_FATAL; |
558 | 0 | ctx.exit_status = status; |
559 | |
|
560 | 0 | va_start(args, format); |
561 | 0 | fatal_handler(&ctx, format, args); |
562 | 0 | i_unreached(); |
563 | | /*va_end(args);*/ |
564 | 0 | } |
565 | | |
566 | | void i_error(const char *format, ...) |
567 | 0 | { |
568 | 0 | int old_errno = errno; |
569 | 0 | va_list args; |
570 | |
|
571 | 0 | va_start(args, format); |
572 | 0 | error_handler(&failure_ctx_error, format, args); |
573 | 0 | va_end(args); |
574 | |
|
575 | 0 | errno = old_errno; |
576 | 0 | } |
577 | | |
578 | | void i_warning(const char *format, ...) |
579 | 0 | { |
580 | 0 | int old_errno = errno; |
581 | 0 | va_list args; |
582 | |
|
583 | 0 | va_start(args, format); |
584 | 0 | error_handler(&failure_ctx_warning, format, args); |
585 | 0 | va_end(args); |
586 | |
|
587 | 0 | errno = old_errno; |
588 | 0 | } |
589 | | |
590 | | void i_info(const char *format, ...) |
591 | 0 | { |
592 | 0 | int old_errno = errno; |
593 | 0 | va_list args; |
594 | |
|
595 | 0 | va_start(args, format); |
596 | 0 | info_handler(&failure_ctx_info, format, args); |
597 | 0 | va_end(args); |
598 | |
|
599 | 0 | errno = old_errno; |
600 | 0 | } |
601 | | |
602 | | void i_debug(const char *format, ...) |
603 | 0 | { |
604 | 0 | int old_errno = errno; |
605 | 0 | va_list args; |
606 | |
|
607 | 0 | va_start(args, format); |
608 | 0 | debug_handler(&failure_ctx_debug, format, args); |
609 | 0 | va_end(args); |
610 | |
|
611 | 0 | errno = old_errno; |
612 | 0 | } |
613 | | |
614 | | void i_set_fatal_handler(failure_callback_t *callback ATTR_NORETURN) |
615 | 0 | { |
616 | 0 | fatal_handler = callback; |
617 | 0 | } |
618 | | |
619 | | void i_set_error_handler(failure_callback_t *callback) |
620 | 0 | { |
621 | 0 | coredump_on_error = getenv("CORE_ERROR") != NULL; |
622 | 0 | error_handler = callback; |
623 | 0 | } |
624 | | |
625 | | void i_set_info_handler(failure_callback_t *callback) |
626 | 0 | { |
627 | 0 | info_handler = callback; |
628 | 0 | } |
629 | | |
630 | | void i_set_debug_handler(failure_callback_t *callback) |
631 | 0 | { |
632 | 0 | debug_handler = callback; |
633 | 0 | } |
634 | | |
635 | | void i_get_failure_handlers(failure_callback_t **fatal_callback_r, |
636 | | failure_callback_t **error_callback_r, |
637 | | failure_callback_t **info_callback_r, |
638 | | failure_callback_t **debug_callback_r) |
639 | 0 | { |
640 | 0 | *fatal_callback_r = fatal_handler; |
641 | 0 | *error_callback_r = error_handler; |
642 | 0 | *info_callback_r = info_handler; |
643 | 0 | *debug_callback_r = debug_handler; |
644 | 0 | } |
645 | | |
646 | | void i_syslog_fatal_handler(const struct failure_context *ctx, |
647 | | const char *format, va_list args) |
648 | 0 | { |
649 | 0 | failure_handler.v = &syslog_handler_vfuncs; |
650 | 0 | failure_handler.fatal_err_reset = FATAL_LOGERROR; |
651 | 0 | fatal_handler_real(ctx, format, args); |
652 | 0 | } |
653 | | |
654 | | void i_syslog_error_handler(const struct failure_context *ctx, |
655 | | const char *format, va_list args) |
656 | 0 | { |
657 | 0 | failure_handler.v = &syslog_handler_vfuncs; |
658 | 0 | failure_handler.fatal_err_reset = FATAL_LOGERROR; |
659 | 0 | error_handler_real(ctx, format, args); |
660 | 0 | } |
661 | | |
662 | | void i_set_failure_syslog(const char *ident, int options, int facility) |
663 | 0 | { |
664 | 0 | openlog(ident, options, facility); |
665 | |
|
666 | 0 | i_set_fatal_handler(i_syslog_fatal_handler); |
667 | 0 | i_set_error_handler(i_syslog_error_handler); |
668 | 0 | i_set_info_handler(i_syslog_error_handler); |
669 | 0 | i_set_debug_handler(i_syslog_error_handler); |
670 | 0 | } |
671 | | |
672 | | static void open_log_file(int *fd, const char *path) |
673 | 0 | { |
674 | 0 | const char *str; |
675 | |
|
676 | 0 | if (*fd != STDERR_FILENO) { |
677 | 0 | if (close(*fd) < 0) { |
678 | 0 | str = t_strdup_printf("close(%d) failed: %m\n", *fd); |
679 | 0 | (void)write_full(STDERR_FILENO, str, strlen(str)); |
680 | 0 | } |
681 | 0 | } |
682 | |
|
683 | 0 | if (path == NULL || strcmp(path, "/dev/stderr") == 0) |
684 | 0 | *fd = STDERR_FILENO; |
685 | 0 | else { |
686 | 0 | *fd = open(path, O_CREAT | O_APPEND | O_WRONLY, 0600); |
687 | 0 | if (*fd == -1) { |
688 | 0 | *fd = STDERR_FILENO; |
689 | 0 | str = t_strdup_printf("Can't open log file %s: %m\n", |
690 | 0 | path); |
691 | 0 | (void)write_full(STDERR_FILENO, str, strlen(str)); |
692 | 0 | if (fd == &log_fd) |
693 | 0 | failure_exit(FATAL_LOGOPEN); |
694 | 0 | else |
695 | 0 | i_fatal_status(FATAL_LOGOPEN, "%s", str); |
696 | 0 | } |
697 | 0 | fd_close_on_exec(*fd, TRUE); |
698 | 0 | } |
699 | 0 | } |
700 | | |
701 | | void i_set_failure_file(const char *path, const char *prefix) |
702 | 0 | { |
703 | 0 | i_set_failure_prefix("%s", prefix); |
704 | |
|
705 | 0 | if (log_info_fd != STDERR_FILENO && log_info_fd != log_fd) { |
706 | 0 | if (close(log_info_fd) < 0) |
707 | 0 | i_error("close(%d) failed: %m", log_info_fd); |
708 | 0 | } |
709 | |
|
710 | 0 | if (log_debug_fd != STDERR_FILENO && log_debug_fd != log_info_fd && |
711 | 0 | log_debug_fd != log_fd) { |
712 | 0 | if (close(log_debug_fd) < 0) |
713 | 0 | i_error("close(%d) failed: %m", log_debug_fd); |
714 | 0 | } |
715 | |
|
716 | 0 | open_log_file(&log_fd, path); |
717 | | /* if info/debug logs are elsewhere, i_set_info/debug_file() |
718 | | overrides these later. */ |
719 | 0 | log_info_fd = log_fd; |
720 | 0 | log_debug_fd = log_fd; |
721 | |
|
722 | 0 | i_set_fatal_handler(default_fatal_handler); |
723 | 0 | i_set_error_handler(default_error_handler); |
724 | 0 | i_set_info_handler(default_error_handler); |
725 | 0 | i_set_debug_handler(default_error_handler); |
726 | 0 | } |
727 | | |
728 | | static int i_failure_send_option_forced(const char *key, const char *value) |
729 | 0 | { |
730 | 0 | const char *str; |
731 | |
|
732 | 0 | str = t_strdup_printf("\001%c%s %s=%s\n", LOG_TYPE_OPTION+1, |
733 | 0 | my_pid, key, value); |
734 | 0 | return log_fd_write(STDERR_FILENO, (const unsigned char *)str, |
735 | 0 | strlen(str)); |
736 | 0 | } |
737 | | |
738 | | static void i_failure_send_option(const char *key, const char *value) |
739 | 0 | { |
740 | 0 | if (error_handler == i_internal_error_handler) |
741 | 0 | (void)i_failure_send_option_forced(key, value); |
742 | 0 | } |
743 | | |
744 | | void i_set_failure_prefix(const char *prefix_fmt, ...) |
745 | 0 | { |
746 | 0 | va_list args; |
747 | |
|
748 | 0 | va_start(args, prefix_fmt); |
749 | 0 | i_free(log_prefix); |
750 | 0 | log_prefix = i_strdup_vprintf(prefix_fmt, args); |
751 | 0 | va_end(args); |
752 | |
|
753 | 0 | log_prefix_sent = FALSE; |
754 | 0 | } |
755 | | |
756 | | void i_unset_failure_prefix(void) |
757 | 0 | { |
758 | 0 | i_free(log_prefix); |
759 | 0 | log_prefix = i_strdup(""); |
760 | 0 | log_prefix_sent = FALSE; |
761 | 0 | } |
762 | | |
763 | | const char *i_get_failure_prefix(void) |
764 | 0 | { |
765 | 0 | return log_prefix != NULL ? log_prefix : ""; |
766 | 0 | } |
767 | | |
768 | | static int internal_send_split(string_t *full_str, size_t prefix_len) |
769 | 0 | { |
770 | | /* This function splits the log line into PIPE_BUF sized blocks, so |
771 | | the log process doesn't see partial lines. The log prefix is |
772 | | repeated for each sent line. However, if the log prefix is |
773 | | excessively long, we're still going to send the log lines even |
774 | | if they are longer than PIPE_BUF. LINE_MIN_TEXT_LEN controls the |
775 | | minimum number of bytes we're going to send of the actual log line |
776 | | regardless of the log prefix length. (Alternative solution could be |
777 | | to just forcibly split the line to PIPE_BUF length blocks without |
778 | | repeating the log prefix for subsequent lines.) */ |
779 | 0 | #define LINE_MIN_TEXT_LEN 128 |
780 | | #if LINE_MIN_TEXT_LEN >= PIPE_BUF |
781 | | # error LINE_MIN_TEXT_LEN too large |
782 | | #endif |
783 | 0 | string_t *str; |
784 | 0 | size_t max_text_len, pos = prefix_len; |
785 | |
|
786 | 0 | str = t_str_new(PIPE_BUF); |
787 | 0 | str_append_data(str, str_data(full_str), prefix_len); |
788 | 0 | if (prefix_len < PIPE_BUF) { |
789 | 0 | max_text_len = I_MAX(PIPE_BUF - prefix_len - 1, |
790 | 0 | LINE_MIN_TEXT_LEN); |
791 | 0 | } else { |
792 | 0 | max_text_len = LINE_MIN_TEXT_LEN; |
793 | 0 | } |
794 | |
|
795 | 0 | while (pos < str_len(full_str)) { |
796 | 0 | str_truncate(str, prefix_len); |
797 | 0 | str_append_max(str, str_c(full_str) + pos, max_text_len); |
798 | 0 | str_append_c(str, '\n'); |
799 | 0 | if (log_fd_write(STDERR_FILENO, |
800 | 0 | str_data(str), str_len(str)) < 0) |
801 | 0 | return -1; |
802 | 0 | pos += max_text_len; |
803 | 0 | } |
804 | 0 | return 0; |
805 | 0 | } |
806 | | |
807 | | |
808 | | static bool line_parse_prefix(const char *line, enum log_type *log_type_r, |
809 | | bool *replace_prefix_r, bool *have_prefix_len_r) |
810 | 0 | { |
811 | 0 | if (*line != 1) |
812 | 0 | return FALSE; |
813 | | |
814 | 0 | unsigned char log_type = (line[1] & 0x3f); |
815 | 0 | if (log_type == '\0') { |
816 | 0 | i_warning("Broken log line follows (type=NUL)"); |
817 | 0 | return FALSE; |
818 | 0 | } |
819 | 0 | log_type--; |
820 | |
|
821 | 0 | if (log_type > LOG_TYPE_OPTION) { |
822 | 0 | i_warning("Broken log line follows (type=%d)", log_type); |
823 | 0 | return FALSE; |
824 | 0 | } |
825 | 0 | *log_type_r = log_type; |
826 | 0 | *replace_prefix_r = (line[1] & LOG_TYPE_FLAG_DISABLE_LOG_PREFIX) != 0; |
827 | 0 | *have_prefix_len_r = (line[1] & LOG_TYPE_FLAG_PREFIX_LEN) != 0; |
828 | 0 | return TRUE; |
829 | 0 | } |
830 | | |
831 | | void i_failure_parse_line(const char *line, struct failure_line *failure) |
832 | 0 | { |
833 | 0 | bool have_prefix_len = FALSE; |
834 | |
|
835 | 0 | i_zero(failure); |
836 | 0 | if (!line_parse_prefix(line, &failure->log_type, |
837 | 0 | &failure->disable_log_prefix, |
838 | 0 | &have_prefix_len)) { |
839 | 0 | failure->log_type = LOG_TYPE_ERROR; |
840 | 0 | failure->text = line; |
841 | 0 | return; |
842 | 0 | } |
843 | | |
844 | 0 | line += 2; |
845 | 0 | failure->text = line; |
846 | 0 | while (*line >= '0' && *line <= '9') { |
847 | 0 | failure->pid = failure->pid*10 + (*line - '0'); |
848 | 0 | line++; |
849 | 0 | } |
850 | 0 | if (*line != ' ') { |
851 | | /* some old protocol? */ |
852 | 0 | failure->pid = 0; |
853 | 0 | return; |
854 | 0 | } |
855 | 0 | line++; |
856 | |
|
857 | 0 | if (have_prefix_len) { |
858 | 0 | if (str_parse_uint(line, &failure->log_prefix_len, &line) < 0 || |
859 | 0 | line[0] != ' ') { |
860 | | /* unexpected, but ignore */ |
861 | 0 | } else { |
862 | 0 | line++; |
863 | 0 | if (failure->log_prefix_len > strlen(line)) { |
864 | | /* invalid */ |
865 | 0 | failure->log_prefix_len = 0; |
866 | 0 | } |
867 | 0 | } |
868 | 0 | } |
869 | 0 | failure->text = line; |
870 | 0 | } |
871 | | |
872 | | static void ATTR_NORETURN ATTR_FORMAT(2, 0) |
873 | | i_internal_fatal_handler(const struct failure_context *ctx, |
874 | | const char *format, va_list args) |
875 | 0 | { |
876 | 0 | failure_handler.v = &internal_handler_vfuncs; |
877 | 0 | failure_handler.fatal_err_reset = FATAL_LOGERROR; |
878 | 0 | fatal_handler_real(ctx, format, args); |
879 | | |
880 | |
|
881 | 0 | } |
882 | | |
883 | | static void |
884 | | i_internal_error_handler(const struct failure_context *ctx, |
885 | | const char *format, va_list args) |
886 | 0 | { |
887 | 0 | failure_handler.v = &internal_handler_vfuncs; |
888 | 0 | failure_handler.fatal_err_reset = FATAL_LOGERROR; |
889 | 0 | error_handler_real(ctx, format, args); |
890 | 0 | } |
891 | | |
892 | | void i_set_failure_internal(void) |
893 | 0 | { |
894 | 0 | fd_set_nonblock(STDERR_FILENO, TRUE); |
895 | 0 | i_set_fatal_handler(i_internal_fatal_handler); |
896 | 0 | i_set_error_handler(i_internal_error_handler); |
897 | 0 | i_set_info_handler(i_internal_error_handler); |
898 | 0 | i_set_debug_handler(i_internal_error_handler); |
899 | 0 | } |
900 | | |
901 | | bool i_failure_handler_is_internal(failure_callback_t *const callback) |
902 | 0 | { |
903 | 0 | return callback == i_internal_fatal_handler || |
904 | 0 | callback == i_internal_error_handler; |
905 | 0 | } |
906 | | |
907 | | void i_set_failure_ignore_errors(bool ignore) |
908 | 0 | { |
909 | 0 | failure_ignore_errors = ignore; |
910 | 0 | } |
911 | | |
912 | | void i_set_info_file(const char *path) |
913 | 0 | { |
914 | 0 | if (log_info_fd == log_fd) |
915 | 0 | log_info_fd = STDERR_FILENO; |
916 | |
|
917 | 0 | open_log_file(&log_info_fd, path); |
918 | 0 | info_handler = default_error_handler; |
919 | | /* write debug-level messages to the info_log_path, |
920 | | until i_set_debug_file() was called */ |
921 | 0 | log_debug_fd = log_info_fd; |
922 | 0 | i_set_debug_handler(default_error_handler); |
923 | 0 | } |
924 | | |
925 | | void i_set_debug_file(const char *path) |
926 | 0 | { |
927 | 0 | if (log_debug_fd == log_fd || log_debug_fd == log_info_fd) |
928 | 0 | log_debug_fd = STDERR_FILENO; |
929 | |
|
930 | 0 | open_log_file(&log_debug_fd, path); |
931 | 0 | debug_handler = default_error_handler; |
932 | 0 | } |
933 | | |
934 | | void i_set_failure_timestamp_format(const char *fmt) |
935 | 0 | { |
936 | 0 | const char *p; |
937 | |
|
938 | 0 | i_free(log_stamp_format); |
939 | 0 | i_free_and_null(log_stamp_format_suffix); |
940 | |
|
941 | 0 | p = strstr(fmt, "%{usecs}"); |
942 | 0 | if (p == NULL) |
943 | 0 | log_stamp_format = i_strdup(fmt); |
944 | 0 | else { |
945 | 0 | log_stamp_format = i_strdup_until(fmt, p); |
946 | 0 | log_stamp_format_suffix = i_strdup(p + 8); |
947 | 0 | } |
948 | 0 | } |
949 | | |
950 | | void i_set_failure_send_ip(const struct ip_addr *ip) |
951 | 0 | { |
952 | 0 | i_failure_send_option("ip", net_ip2addr(ip)); |
953 | 0 | } |
954 | | |
955 | | void i_set_failure_send_prefix(const char *prefix) |
956 | 0 | { |
957 | 0 | i_failure_send_option("prefix", prefix); |
958 | 0 | } |
959 | | |
960 | | void i_set_failure_exit_callback(void (*callback)(int *status)) |
961 | 0 | { |
962 | 0 | failure_exit_callback = callback; |
963 | 0 | } |
964 | | |
965 | | void failures_deinit(void) |
966 | 0 | { |
967 | 0 | if (log_debug_fd == log_info_fd || log_debug_fd == log_fd) |
968 | 0 | log_debug_fd = STDERR_FILENO; |
969 | |
|
970 | 0 | if (log_info_fd == log_fd) |
971 | 0 | log_info_fd = STDERR_FILENO; |
972 | |
|
973 | 0 | if (log_fd != STDERR_FILENO) { |
974 | 0 | i_close_fd(&log_fd); |
975 | 0 | log_fd = STDERR_FILENO; |
976 | 0 | } |
977 | |
|
978 | 0 | if (log_info_fd != STDERR_FILENO) { |
979 | 0 | i_close_fd(&log_info_fd); |
980 | 0 | log_info_fd = STDERR_FILENO; |
981 | 0 | } |
982 | |
|
983 | 0 | if (log_debug_fd != STDERR_FILENO) { |
984 | 0 | i_close_fd(&log_debug_fd); |
985 | 0 | log_debug_fd = STDERR_FILENO; |
986 | 0 | } |
987 | |
|
988 | 0 | i_free_and_null(log_prefix); |
989 | 0 | i_free_and_null(log_stamp_format); |
990 | 0 | i_free_and_null(log_stamp_format_suffix); |
991 | 0 | } |
992 | | |
993 | | #undef i_unreached |
994 | | void i_unreached(const char *source_filename, int source_linenum) |
995 | 0 | { |
996 | 0 | i_panic("file %s: line %d: unreached", source_filename, source_linenum); |
997 | 0 | } |