# HG changeset patch # User Timo Sirainen # Date 1084205109 -10800 # Node ID c7c19f5071c366f6e959c6737a557d2fe3d5ce5f # Parent 8f0e6d4572393b551f1f12e8e08a04dde376e403 Write all logging through master process. Fixes problems with log rotation, chrooting, etc. Master process also allows max. 10 log messages per second per child process, it then begins throttling them (eventually making the child process start blocking on stderr). diff -r 8f0e6d457239 -r c7c19f5071c3 src/auth/main.c --- a/src/auth/main.c Mon May 10 18:12:38 2004 +0300 +++ b/src/auth/main.c Mon May 10 19:05:09 2004 +0300 @@ -41,25 +41,9 @@ } } -static void open_logfile(void) -{ - if (getenv("USE_SYSLOG") != NULL) - i_set_failure_syslog("dovecot-auth", LOG_NDELAY, LOG_MAIL); - else { - /* log to file or stderr */ - i_set_failure_file(getenv("LOGFILE"), "dovecot-auth"); - } - - if (getenv("INFOLOGFILE") != NULL) - i_set_info_file(getenv("INFOLOGFILE")); - - i_set_failure_timestamp_format(getenv("LOGSTAMP")); -} - static void drop_privileges(void) { - /* Log file or syslog opening probably requires roots */ - open_logfile(); + i_set_failure_internal(); /* Open /dev/urandom before chrooting */ random_init(); diff -r 8f0e6d457239 -r c7c19f5071c3 src/imap/main.c --- a/src/imap/main.c Mon May 10 18:12:38 2004 +0300 +++ b/src/imap/main.c Mon May 10 19:05:09 2004 +0300 @@ -43,6 +43,11 @@ { const char *user; + if (getenv("LOG_TO_MASTER") != NULL) { + i_set_failure_internal(); + return; + } + user = getenv("USER"); if (user == NULL) { if (IS_STANDALONE()) @@ -169,6 +174,10 @@ lib_init(); drop_privileges(); + {int i; + for (i = 0; i < 30; i++) + i_warning("%d", i);} + process_title_init(argv, envp); ioloop = io_loop_create(system_pool); diff -r 8f0e6d457239 -r c7c19f5071c3 src/lib/failures.c --- a/src/lib/failures.c Mon May 10 18:12:38 2004 +0300 +++ b/src/lib/failures.c Mon May 10 19:05:09 2004 +0300 @@ -1,6 +1,8 @@ /* Copyright (c) 2002-2003 Timo Sirainen */ #include "lib.h" +#include "str.h" +#include "write-full.h" #include "fd-close-on-exec.h" #include "printf-upper-bound.h" @@ -342,6 +344,65 @@ log_info_fd = log_fd; } +static int internal_handler(char log_type, const char *format, va_list args) +{ + string_t *str; + int ret; + + t_push(); + str = t_str_new(512); + str_append_c(str, 1); + str_append_c(str, log_type); + str_vprintfa(str, format, args); + str_append_c(str, '\n'); + ret = write_full(2, str_data(str), str_len(str)); + t_pop(); + + return ret; +} + +static void i_internal_panic_handler(const char *fmt, va_list args) + __attr_noreturn__; +static void i_internal_panic_handler(const char *fmt, va_list args) +{ + (void)internal_handler('F', fmt, args); + abort(); +} + +static void i_internal_fatal_handler(int status, const char *fmt, va_list args) + __attr_noreturn__; +static void i_internal_fatal_handler(int status, const char *fmt, va_list args) +{ + if (internal_handler('F', fmt, args) < 0 && status == FATAL_DEFAULT) + status = FATAL_LOGERROR; + exit(status); +} + +static void i_internal_error_handler(const char *fmt, va_list args) +{ + if (internal_handler('E', fmt, args) < 0) + exit(FATAL_LOGERROR); +} + +static void i_internal_warning_handler(const char *fmt, va_list args) +{ + (void)internal_handler('W', fmt, args); +} + +static void i_internal_info_handler(const char *fmt, va_list args) +{ + (void)internal_handler('I', fmt, args); +} + +void i_set_failure_internal(void) +{ + i_set_panic_handler(i_internal_panic_handler); + i_set_fatal_handler(i_internal_fatal_handler); + i_set_error_handler(i_internal_error_handler); + i_set_warning_handler(i_internal_warning_handler); + i_set_info_handler(i_internal_info_handler); +} + void i_set_info_file(const char *path) { if (log_info_fd == log_fd) diff -r 8f0e6d457239 -r c7c19f5071c3 src/lib/failures.h --- a/src/lib/failures.h Mon May 10 18:12:38 2004 +0300 +++ b/src/lib/failures.h Mon May 10 19:05:09 2004 +0300 @@ -47,6 +47,9 @@ /* Send failures to specified log file instead of stderr. */ void i_set_failure_file(const char *path, const char *prefix); +/* Send errors to stderr using internal error protocol. */ +void i_set_failure_internal(void); + /* Send informational messages to specified log file. i_set_failure_*() functions modify the info file too, so call this function after them. */ void i_set_info_file(const char *path); diff -r 8f0e6d457239 -r c7c19f5071c3 src/login-common/main.c --- a/src/login-common/main.c Mon May 10 18:12:38 2004 +0300 +++ b/src/login-common/main.c Mon May 10 19:05:09 2004 +0300 @@ -121,25 +121,9 @@ clients_notify_auth_connected(); } -static void open_logfile(const char *name) +static void drop_privileges() { - if (getenv("USE_SYSLOG") != NULL) - i_set_failure_syslog(name, LOG_NDELAY, LOG_MAIL); - else { - /* log to file or stderr */ - i_set_failure_file(getenv("LOGFILE"), name); - } - - if (getenv("INFOLOGFILE") != NULL) - i_set_info_file(getenv("INFOLOGFILE")); - - i_set_failure_timestamp_format(getenv("LOGSTAMP")); -} - -static void drop_privileges(const char *name) -{ - /* Log file or syslog opening probably requires roots */ - open_logfile(name); + i_set_failure_internal(); /* Initialize SSL proxy so it can read certificate and private key file. */ @@ -259,7 +243,7 @@ } name = strrchr(argv[0], '/'); - drop_privileges(name == NULL ? argv[0] : name+1); + drop_privileges(); process_title_init(argv, envp); ioloop = io_loop_create(system_pool); diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/Makefile.am --- a/src/master/Makefile.am Mon May 10 18:12:38 2004 +0300 +++ b/src/master/Makefile.am Mon May 10 19:05:09 2004 +0300 @@ -18,6 +18,7 @@ dovecot_SOURCES = \ auth-process.c \ + log.c \ login-process.c \ mail-process.c \ main.c \ @@ -29,6 +30,7 @@ noinst_HEADERS = \ auth-process.h \ common.h \ + log.h \ login-process.h \ mail-process.h \ master-login-interface.h \ diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/auth-process.c --- a/src/master/auth-process.c Mon May 10 18:12:38 2004 +0300 +++ b/src/master/auth-process.c Mon May 10 19:05:09 2004 +0300 @@ -10,6 +10,7 @@ #include "restrict-access.h" #include "restrict-process-size.h" #include "auth-process.h" +#include "log.h" #include #include @@ -252,20 +253,30 @@ static pid_t create_auth_process(struct auth_process_group *group) { static char *argv[] = { NULL, NULL }; + const char *prefix; pid_t pid; - int fd[2], i; + int fd[2], log_fd, i; /* create communication to process with a socket pair */ - if (socketpair(AF_UNIX, SOCK_STREAM, 0, fd) == -1) { + if (socketpair(AF_UNIX, SOCK_STREAM, 0, fd) < 0) { i_error("socketpair() failed: %m"); return -1; } - pid = fork(); + prefix = t_strdup_printf("auth(%s): ", group->set->name); + log_fd = log_create_pipe(prefix); + if (log_fd < 0) + pid = -1; + else { + pid = fork(); + if (pid < 0) + i_error("fork() failed: %m"); + } + if (pid < 0) { (void)close(fd[0]); (void)close(fd[1]); - i_error("fork() failed: %m"); + (void)close(log_fd); return -1; } @@ -275,28 +286,31 @@ fd_close_on_exec(fd[0], TRUE); auth_process_new(pid, fd[0], group); (void)close(fd[1]); + (void)close(log_fd); return pid; } /* move master communication handle to 0 */ if (dup2(fd[1], 0) < 0) - i_fatal("login: dup2(0) failed: %m"); + i_fatal("auth: dup2(stdin) failed: %m"); (void)close(fd[0]); (void)close(fd[1]); - /* set stdout to /dev/null, so anything written into it gets ignored. - leave stderr alone, we might want to use it for logging. */ + /* set stdout to /dev/null, so anything written into it gets ignored. */ if (dup2(null_fd, 1) < 0) - i_fatal("login: dup2(1) failed: %m"); + i_fatal("auth: dup2(stdout) failed: %m"); - child_process_init_env(group->set->parent->defaults); + if (dup2(log_fd, 2) < 0) + i_fatal("auth: dup2(stderr) failed: %m"); + + child_process_init_env(); /* move login communication handle to 3. do it last so we can be sure it's not closed afterwards. */ if (group->listen_fd != 3) { if (dup2(group->listen_fd, 3) < 0) - i_fatal("login: dup2() failed: %m"); + i_fatal("auth: dup2() failed: %m"); } for (i = 0; i <= 3; i++) diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/common.h --- a/src/master/common.h Mon May 10 18:12:38 2004 +0300 +++ b/src/master/common.h Mon May 10 19:05:09 2004 +0300 @@ -24,6 +24,7 @@ extern struct hash_table *pids; extern int null_fd, inetd_login_fd; extern uid_t master_uid; +extern const char *process_names[]; #define IS_INETD() \ (inetd_login_fd != -1) @@ -38,7 +39,7 @@ #define PID_REMOVE_PROCESS_TYPE(pid) \ hash_remove(pids, POINTER_CAST(pid)) -void child_process_init_env(struct settings *set); +void child_process_init_env(void); /* misc */ #define VALIDATE_STR(str) \ diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/log.c --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/src/master/log.c Mon May 10 19:05:09 2004 +0300 @@ -0,0 +1,251 @@ +/* Copyright (C) 2002 Timo Sirainen */ + +#include "common.h" +#include "ioloop.h" +#include "istream.h" +#include "fd-close-on-exec.h" +#include "log.h" + +#include + +#define MAX_LOG_MESSAGS_PER_SEC 10 + +struct log_io { + struct log_io *prev, *next; + struct io *io; + struct istream *stream; + + time_t log_stamp; + unsigned int log_counter; + + char *prefix; + char next_log_type; + unsigned int throttle_msg:1; +}; + +static struct log_io *log_ios; +static struct timeout *to; +static unsigned int throttle_count; + +static int log_it(struct log_io *log_io, const char *line, int continues); +static void log_read(void *context); +static void log_io_free(struct log_io *log_io); +static void log_throttle_timeout(void *context); + +static int log_write_pending(struct log_io *log_io) +{ + const char *line; + + if (log_io->log_stamp != ioloop_time) { + log_io->log_stamp = ioloop_time; + log_io->log_counter = 0; + } + + while ((line = i_stream_next_line(log_io->stream)) != NULL) { + if (!log_it(log_io, line, FALSE)) + return FALSE; + } + + return TRUE; +} + +static void log_throttle(struct log_io *log_io) +{ + if (!log_io->throttle_msg) { + log_io->throttle_msg = TRUE; + log_it(log_io, "Sending log messages too fast, throttling..", + FALSE); + } + + if (log_io->io != NULL) { + io_remove(log_io->io); + log_io->io = NULL; + } + + if (to == NULL) + to = timeout_add(1000, log_throttle_timeout, NULL); + throttle_count++; +} + +static void log_unthrottle(struct log_io *log_io) +{ + if (log_io->io != NULL) + return; + + if (--throttle_count == 0 && to != NULL) { + timeout_remove(to); + to = NULL; + } + log_io->io = io_add(i_stream_get_fd(log_io->stream), + IO_READ, log_read, log_io); +} + +static int log_it(struct log_io *log_io, const char *line, int continues) +{ + if (log_io->next_log_type == '\0') { + if (line[0] == 1 && line[1] != '\0') { + /* our internal protocol. + \001 + log_type */ + log_io->next_log_type = line[1]; + line += 2; + } else { + log_io->next_log_type = 'E'; + } + } + + t_push(); + switch (log_io->next_log_type) { + case 'I': + i_info("%s%s", log_io->prefix, line); + break; + case 'W': + i_warning("%s%s", log_io->prefix, line); + break; + default: + i_error("%s%s", log_io->prefix, line); + break; + } + t_pop(); + + if (!continues) + log_io->next_log_type = '\0'; + + if (++log_io->log_counter > MAX_LOG_MESSAGS_PER_SEC) { + log_throttle(log_io); + return 0; + } + return 1; +} + +static void log_read(void *context) +{ + struct log_io *log_io = context; + const unsigned char *data; + const char *line; + size_t size; + int ret; + + if (!log_write_pending(log_io)) + return; + + ret = i_stream_read(log_io->stream); + if (ret < 0) { + if (ret == -1) { + /* closed */ + log_io_free(log_io); + return; + } + + /* buffer full. treat it as one line */ + data = i_stream_get_data(log_io->stream, &size); + line = t_strndup(data, size); + i_stream_skip(log_io->stream, size); + + if (!log_it(log_io, line, TRUE)) + return; + } + + if (!log_write_pending(log_io)) + return; + + if (log_io->log_counter < MAX_LOG_MESSAGS_PER_SEC) + log_unthrottle(log_io); +} + +int log_create_pipe(const char *prefix) +{ + struct log_io *log_io; + int fd[2]; + + if (pipe(fd) < 0) { + i_error("pipe() failed: %m"); + return -1; + } + + fd_close_on_exec(fd[0], TRUE); + fd_close_on_exec(fd[1], TRUE); + + log_io = i_new(struct log_io, 1); + log_io->prefix = i_strdup(prefix); + log_io->stream = i_stream_create_file(fd[0], default_pool, 1024, TRUE); + + throttle_count++; + log_unthrottle(log_io); + + if (log_ios != NULL) + log_ios->prev = log_io; + log_io->next = log_ios; + log_ios = log_io; + + return fd[1]; +} + +static void log_io_free(struct log_io *log_io) +{ + const unsigned char *data; + size_t size; + + /* if there was something in buffer, write it */ + data = i_stream_get_data(log_io->stream, &size); + if (size != 0) { + t_push(); + log_it(log_io, t_strndup(data, size), TRUE); + t_pop(); + } + + if (log_io == log_ios) + log_ios = log_io->next; + else + log_io->prev->next = log_io->next; + if (log_io->next != NULL) + log_io->next->prev = log_io->prev; + + if (log_io->io != NULL) + io_remove(log_io->io); + else + throttle_count--; + i_stream_unref(log_io->stream); + i_free(log_io->prefix); + i_free(log_io); +} + +static void log_throttle_timeout(void *context __attr_unused__) +{ + struct log_io *log, *next; + unsigned int left = throttle_count; + + i_assert(left > 0); + + for (log = log_ios; log != NULL; log = next) { + next = log->next; + + if (log->io == NULL) { + if (log_write_pending(log)) + log_unthrottle(log); + + if (--left == 0) + break; + } + } +} + +void log_init(void) +{ + log_ios = NULL; + throttle_count = 0; + to = NULL; +} + +void log_deinit(void) +{ + struct log_io *next; + + while (log_ios != NULL) { + next = log_ios->next; + log_io_free(log_ios); + log_ios = next; + } + + if (to != NULL) + timeout_remove(to); +} diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/log.h --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/src/master/log.h Mon May 10 19:05:09 2004 +0300 @@ -0,0 +1,8 @@ +#ifndef __LOG_H +#define __LOG_H + +int log_create_pipe(const char *prefix); +void log_init(void); +void log_deinit(void); + +#endif diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/login-process.c --- a/src/master/login-process.c Mon May 10 18:12:38 2004 +0300 +++ b/src/master/login-process.c Mon May 10 19:05:09 2004 +0300 @@ -13,6 +13,7 @@ #include "auth-process.h" #include "mail-process.h" #include "master-login-interface.h" +#include "log.h" #include #include @@ -370,7 +371,7 @@ { struct settings *set = group->set; - child_process_init_env(set); + child_process_init_env(); /* setup access environment - needs to be done after clean_child_process() since it clears environment */ @@ -421,8 +422,9 @@ static pid_t create_login_process(struct login_group *group) { static const char *argv[] = { NULL, NULL }; + const char *prefix; pid_t pid; - int fd[2]; + int fd[2], log_fd; if (group->set->login_process_per_connection && group->processes - group->listening_processes >= @@ -435,16 +437,26 @@ i_fatal("Login process must not run as root"); /* create communication to process with a socket pair */ - if (socketpair(AF_UNIX, SOCK_STREAM, 0, fd) == -1) { + if (socketpair(AF_UNIX, SOCK_STREAM, 0, fd) < 0) { i_error("socketpair() failed: %m"); return -1; } - pid = fork(); + prefix = t_strdup_printf("%s-login: ", + process_names[group->process_type]); + log_fd = log_create_pipe(prefix); + if (log_fd < 0) + pid = -1; + else { + pid = fork(); + if (pid < 0) + i_error("fork() failed: %m"); + } + if (pid < 0) { (void)close(fd[0]); (void)close(fd[1]); - i_error("fork() failed: %m"); + (void)close(log_fd); return -1; } @@ -454,6 +466,7 @@ fd_close_on_exec(fd[0], TRUE); (void)login_process_new(group, pid, fd[0]); (void)close(fd[1]); + (void)close(log_fd); return pid; } @@ -472,6 +485,10 @@ i_fatal("login: dup2(master) failed: %m"); fd_close_on_exec(LOGIN_MASTER_SOCKET_FD, FALSE); + if (dup2(log_fd, 2) < 0) + i_fatal("login: dup2(stderr) failed: %m"); + fd_close_on_exec(2, FALSE); + (void)close(fd[0]); (void)close(fd[1]); diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/mail-process.c --- a/src/master/mail-process.c Mon May 10 18:12:38 2004 +0300 +++ b/src/master/mail-process.c Mon May 10 19:05:09 2004 +0300 @@ -10,6 +10,7 @@ #include "var-expand.h" #include "mail-process.h" #include "login-process.h" +#include "log.h" #include #include @@ -152,10 +153,10 @@ const char *argv[4]; struct settings *set = group->set; const char *addr, *mail, *user, *chroot_dir, *home_dir, *full_home_dir; - const char *executable, *p; + const char *executable, *p, *prefix; char title[1024]; pid_t pid; - int i, err, ret; + int i, err, ret, log_fd; // FIXME: per-group if (mail_process_count == set->max_mail_processes) { @@ -178,9 +179,14 @@ return FALSE; } + prefix = t_strdup_printf("%s(%s): ", process_names[group->process_type], + data + reply->virtual_user_idx); + log_fd = log_create_pipe(prefix); + pid = fork(); if (pid < 0) { i_error("fork() failed: %m"); + (void)close(log_fd); return FALSE; } @@ -188,10 +194,11 @@ /* master */ mail_process_count++; PID_ADD_PROCESS_TYPE(pid, group->process_type); + (void)close(log_fd); return TRUE; } - child_process_init_env(set); + child_process_init_env(); /* move the client socket into stdin and stdout fds */ fd_close_on_exec(socket, FALSE); @@ -199,6 +206,8 @@ i_fatal("mail: dup2(stdin) failed: %m"); if (dup2(socket, 1) < 0) i_fatal("mail: dup2(stdout) failed: %m"); + if (dup2(log_fd, 2) < 0) + i_fatal("mail: dup2(stderr) failed: %m"); if (close(socket) < 0) i_error("mail: close(mail client) failed: %m"); @@ -256,6 +265,8 @@ set->mail_max_keyword_length)); env_put(t_strdup_printf("IMAP_MAX_LINE_LENGTH=%u", set->imap_max_line_length)); + env_put(t_strconcat("IMAP_CAPABILITY=", + set->imap_capability, NULL)); if (set->mail_save_crlf) env_put("MAIL_SAVE_CRLF=1"); diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/main.c --- a/src/master/main.c Mon May 10 18:12:38 2004 +0300 +++ b/src/master/main.c Mon May 10 19:05:09 2004 +0300 @@ -11,6 +11,7 @@ #include "login-process.h" #include "mail-process.h" #include "ssl-init.h" +#include "log.h" #include #include @@ -49,26 +50,13 @@ return FALSE; } -void child_process_init_env(struct settings *set) +void child_process_init_env(void) { /* remove all environment, we don't need them */ env_clean(); - /* set the failure log */ - if (set->log_path == NULL) - env_put("USE_SYSLOG=1"); - else - env_put(t_strconcat("LOGFILE=", set->log_path, NULL)); - - if (set->info_log_path != NULL) { - env_put(t_strconcat("INFOLOGFILE=", - set->info_log_path, NULL)); - } - - if (set->log_timestamp != NULL) { - env_put(t_strconcat("LOGSTAMP=", - set->log_timestamp, NULL)); - } + /* we'll log through master process */ + env_put("LOG_TO_MASTER=1"); } static void sig_quit(int signo __attr_unused__) @@ -383,6 +371,7 @@ (void)umask(0077); open_logfile(settings_root->defaults); + log_init(); lib_init_signals(sig_quit); @@ -412,6 +401,7 @@ i_error("close(null_fd) failed: %m"); hash_destroy(pids); + log_deinit(); closelog(); } diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/master-settings.c --- a/src/master/master-settings.c Mon May 10 18:12:38 2004 +0300 +++ b/src/master/master-settings.c Mon May 10 19:05:09 2004 +0300 @@ -109,6 +109,7 @@ /* imap */ DEF(SET_INT, imap_max_line_length), + DEF(SET_STR, imap_capability), { 0, NULL, 0 } }; @@ -236,6 +237,7 @@ /* imap */ MEMBER(imap_max_line_length) 65536, + MEMBER(imap_capability) NULL, /* .. */ MEMBER(login_uid) 0, diff -r 8f0e6d457239 -r c7c19f5071c3 src/master/master-settings.h --- a/src/master/master-settings.h Mon May 10 18:12:38 2004 +0300 +++ b/src/master/master-settings.h Mon May 10 19:05:09 2004 +0300 @@ -84,6 +84,7 @@ /* imap */ unsigned int imap_max_line_length; + const char *imap_capability; /* .. */ uid_t login_uid; diff -r 8f0e6d457239 -r c7c19f5071c3 src/pop3/main.c --- a/src/pop3/main.c Mon May 10 18:12:38 2004 +0300 +++ b/src/pop3/main.c Mon May 10 19:05:09 2004 +0300 @@ -33,6 +33,11 @@ { const char *user; + if (getenv("LOG_TO_MASTER") != NULL) { + i_set_failure_internal(); + return; + } + user = getenv("USER"); if (user == NULL) user = "??"; if (strlen(user) >= sizeof(log_prefix)-6) {