From: Timo Sirainen Date: Mon, 10 May 2004 16:05:09 +0000 (+0300) Subject: Write all logging through master process. Fixes problems with log rotation, X-Git-Tag: 1.1.alpha1~4106 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=316dad8277db6575354eba30d3fc7a1c0447c513;p=thirdparty%2Fdovecot%2Fcore.git 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). --HG-- branch : HEAD --- diff --git a/src/auth/main.c b/src/auth/main.c index 69c0eb8a82..67e2a4f014 100644 --- a/src/auth/main.c +++ b/src/auth/main.c @@ -41,25 +41,9 @@ static void auth_accept(void *context __attr_unused__) } } -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 --git a/src/imap/main.c b/src/imap/main.c index eae9a61e7c..8417ce1448 100644 --- a/src/imap/main.c +++ b/src/imap/main.c @@ -43,6 +43,11 @@ static void open_logfile(void) { 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 @@ int main(int argc __attr_unused__, char *argv[], char *envp[]) 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 --git a/src/lib/failures.c b/src/lib/failures.c index 64d81bb856..094613df48 100644 --- a/src/lib/failures.c +++ b/src/lib/failures.c @@ -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 @@ void i_set_failure_file(const char *path, const char *prefix) 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 --git a/src/lib/failures.h b/src/lib/failures.h index 0b0de4cd3c..cbbb89362d 100644 --- a/src/lib/failures.h +++ b/src/lib/failures.h @@ -47,6 +47,9 @@ void i_set_failure_syslog(const char *ident, int options, int facility); /* 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 --git a/src/login-common/main.c b/src/login-common/main.c index ca39d65eee..271d9126c5 100644 --- a/src/login-common/main.c +++ b/src/login-common/main.c @@ -121,25 +121,9 @@ static void auth_connect_notify(struct auth_client *client __attr_unused__, 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 @@ int main(int argc __attr_unused__, char *argv[], char *envp[]) } 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 --git a/src/master/Makefile.am b/src/master/Makefile.am index 5d1eaaa701..fbe24577f0 100644 --- a/src/master/Makefile.am +++ b/src/master/Makefile.am @@ -18,6 +18,7 @@ dovecot_LDADD = \ dovecot_SOURCES = \ auth-process.c \ + log.c \ login-process.c \ mail-process.c \ main.c \ @@ -29,6 +30,7 @@ dovecot_SOURCES = \ noinst_HEADERS = \ auth-process.h \ common.h \ + log.h \ login-process.h \ mail-process.h \ master-login-interface.h \ diff --git a/src/master/auth-process.c b/src/master/auth-process.c index 2ab2737a23..30fc950f79 100644 --- a/src/master/auth-process.c +++ b/src/master/auth-process.c @@ -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 void auth_process_destroy(struct auth_process *p) 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 @@ static pid_t create_auth_process(struct auth_process_group *group) 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"); + + if (dup2(log_fd, 2) < 0) + i_fatal("auth: dup2(stderr) failed: %m"); - child_process_init_env(group->set->parent->defaults); + 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 --git a/src/master/common.h b/src/master/common.h index afcd2c6e15..44612a691e 100644 --- a/src/master/common.h +++ b/src/master/common.h @@ -24,6 +24,7 @@ extern struct ioloop *ioloop; 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 @@ extern uid_t master_uid; #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 --git a/src/master/log.c b/src/master/log.c new file mode 100644 index 0000000000..c800695862 --- /dev/null +++ b/src/master/log.c @@ -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 --git a/src/master/log.h b/src/master/log.h new file mode 100644 index 0000000000..f8083e9234 --- /dev/null +++ b/src/master/log.h @@ -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 --git a/src/master/login-process.c b/src/master/login-process.c index 3adf77b678..cfcdb7f51d 100644 --- a/src/master/login-process.c +++ b/src/master/login-process.c @@ -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 @@ static void login_process_init_env(struct login_group *group, pid_t pid) { 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 void login_process_init_env(struct login_group *group, pid_t pid) 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 @@ static pid_t create_login_process(struct login_group *group) 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 @@ static pid_t create_login_process(struct login_group *group) 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 @@ static pid_t create_login_process(struct login_group *group) 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 --git a/src/master/mail-process.c b/src/master/mail-process.c index f21b67ab1e..ee15b971da 100644 --- a/src/master/mail-process.c +++ b/src/master/mail-process.c @@ -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 @@ int create_mail_process(struct login_group *group, int socket, 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 @@ int create_mail_process(struct login_group *group, int socket, 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 @@ int create_mail_process(struct login_group *group, int socket, /* 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 @@ int create_mail_process(struct login_group *group, int socket, 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 @@ int create_mail_process(struct login_group *group, int socket, 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 --git a/src/master/main.c b/src/master/main.c index ef28e0c809..3e5165c466 100644 --- a/src/master/main.c +++ b/src/master/main.c @@ -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 @@ int validate_str(const char *str, size_t max_len) 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 @@ static void main_init(void) (void)umask(0077); open_logfile(settings_root->defaults); + log_init(); lib_init_signals(sig_quit); @@ -412,6 +401,7 @@ static void main_deinit(void) i_error("close(null_fd) failed: %m"); hash_destroy(pids); + log_deinit(); closelog(); } diff --git a/src/master/master-settings.c b/src/master/master-settings.c index cb1a944839..804cadedb1 100644 --- a/src/master/master-settings.c +++ b/src/master/master-settings.c @@ -109,6 +109,7 @@ static struct setting_def setting_defs[] = { /* imap */ DEF(SET_INT, imap_max_line_length), + DEF(SET_STR, imap_capability), { 0, NULL, 0 } }; @@ -236,6 +237,7 @@ struct settings default_settings = { /* imap */ MEMBER(imap_max_line_length) 65536, + MEMBER(imap_capability) NULL, /* .. */ MEMBER(login_uid) 0, diff --git a/src/master/master-settings.h b/src/master/master-settings.h index 8b717c4295..a608aaa235 100644 --- a/src/master/master-settings.h +++ b/src/master/master-settings.h @@ -84,6 +84,7 @@ struct settings { /* imap */ unsigned int imap_max_line_length; + const char *imap_capability; /* .. */ uid_t login_uid; diff --git a/src/pop3/main.c b/src/pop3/main.c index 04da569d2d..b254f47880 100644 --- a/src/pop3/main.c +++ b/src/pop3/main.c @@ -33,6 +33,11 @@ static void open_logfile(void) { 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) {