From 3e5afbf0a80317216d98c6e5c0dd2eb54f34e438 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Thu, 14 Jun 2018 18:14:33 +0100 Subject: [PATCH] Refactore FPM logging --- sapi/fpm/fpm/fpm_conf.c | 16 + sapi/fpm/fpm/fpm_conf.h | 3 + sapi/fpm/fpm/fpm_main.c | 20 +- sapi/fpm/fpm/fpm_stdio.c | 69 +- sapi/fpm/fpm/zlog.c | 747 +++++++++++++++++- sapi/fpm/fpm/zlog.h | 77 +- sapi/fpm/php-fpm.conf.in | 18 + sapi/fpm/tests/log-bm-limit-1024-msg-80.phpt | 47 ++ .../fpm/tests/log-bm-limit-2048-msg-4000.phpt | 47 ++ .../tests/log-bwd-limit-1050-msg-2048.phpt | 47 ++ .../tests/log-bwd-limit-1050-msg-2900.phpt | 46 ++ .../tests/log-bwd-limit-64-too-low-error.phpt | 42 + .../tests/log-bwd-limit-8000-msg-4096.phpt | 46 ++ sapi/fpm/tests/log-bwd-msg-with-nl.phpt | 46 ++ .../fpm/tests/log-bwp-limit-1024-msg-120.phpt | 47 ++ .../tests/log-bwp-limit-1500-msg-3300.phpt | 47 ++ .../tests/log-dwd-limit-1050-msg-2048.phpt | 47 ++ .../tests/log-dwd-limit-1050-msg-2900.phpt | 46 ++ .../tests/log-dwd-limit-8000-msg-4096.phpt | 46 ++ .../tests/log-dwp-limit-1000-msg-2000.phpt | 47 ++ sapi/fpm/tests/logtool.inc | 4 +- sapi/fpm/www.conf.in | 7 + 22 files changed, 1472 insertions(+), 90 deletions(-) create mode 100644 sapi/fpm/tests/log-bm-limit-1024-msg-80.phpt create mode 100644 sapi/fpm/tests/log-bm-limit-2048-msg-4000.phpt create mode 100644 sapi/fpm/tests/log-bwd-limit-1050-msg-2048.phpt create mode 100644 sapi/fpm/tests/log-bwd-limit-1050-msg-2900.phpt create mode 100644 sapi/fpm/tests/log-bwd-limit-64-too-low-error.phpt create mode 100644 sapi/fpm/tests/log-bwd-limit-8000-msg-4096.phpt create mode 100644 sapi/fpm/tests/log-bwd-msg-with-nl.phpt create mode 100644 sapi/fpm/tests/log-bwp-limit-1024-msg-120.phpt create mode 100644 sapi/fpm/tests/log-bwp-limit-1500-msg-3300.phpt create mode 100644 sapi/fpm/tests/log-dwd-limit-1050-msg-2048.phpt create mode 100644 sapi/fpm/tests/log-dwd-limit-1050-msg-2900.phpt create mode 100644 sapi/fpm/tests/log-dwd-limit-8000-msg-4096.phpt create mode 100644 sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt diff --git a/sapi/fpm/fpm/fpm_conf.c b/sapi/fpm/fpm/fpm_conf.c index ffa4afe0f5467..b5998d961e90d 100644 --- a/sapi/fpm/fpm/fpm_conf.c +++ b/sapi/fpm/fpm/fpm_conf.c @@ -80,6 +80,8 @@ struct fpm_global_config_s fpm_global_config = { .systemd_watchdog = 0, .systemd_interval = -1, /* -1 means not set */ #endif + .log_buffering = ZLOG_DEFAULT_BUFFERING, + .log_limit = ZLOG_DEFAULT_LIMIT }; static struct fpm_worker_pool_s *current_wp = NULL; static int ini_recursion = 0; @@ -97,7 +99,9 @@ static struct ini_value_parser_s ini_fpm_global_options[] = { { "syslog.ident", &fpm_conf_set_string, GO(syslog_ident) }, { "syslog.facility", &fpm_conf_set_syslog_facility, GO(syslog_facility) }, #endif + { "log_buffering", &fpm_conf_set_boolean, GO(log_buffering) }, { "log_level", &fpm_conf_set_log_level, GO(log_level) }, + { "log_limit", &fpm_conf_set_integer, GO(log_limit) }, { "emergency_restart_threshold", &fpm_conf_set_integer, GO(emergency_restart_threshold) }, { "emergency_restart_interval", &fpm_conf_set_time, GO(emergency_restart_interval) }, { "process_control_timeout", &fpm_conf_set_time, GO(process_control_timeout) }, @@ -153,6 +157,7 @@ static struct ini_value_parser_s ini_fpm_pool_options[] = { { "chroot", &fpm_conf_set_string, WPO(chroot) }, { "chdir", &fpm_conf_set_string, WPO(chdir) }, { "catch_workers_output", &fpm_conf_set_boolean, WPO(catch_workers_output) }, + { "decorate_workers_output", &fpm_conf_set_boolean, WPO(decorate_workers_output) }, { "clear_env", &fpm_conf_set_boolean, WPO(clear_env) }, { "security.limit_extensions", &fpm_conf_set_string, WPO(security_limit_extensions) }, #ifdef HAVE_APPARMOR @@ -616,6 +621,7 @@ static void *fpm_worker_pool_config_alloc() /* {{{ */ wp->config->process_priority = 64; /* 64 means unset */ wp->config->process_dumpable = 0; wp->config->clear_env = 1; + wp->config->decorate_workers_output = 1; if (!fpm_worker_all_pools) { fpm_worker_all_pools = wp; @@ -1192,6 +1198,12 @@ static int fpm_conf_post_process(int force_daemon) /* {{{ */ fpm_globals.log_level = fpm_global_config.log_level; zlog_set_level(fpm_globals.log_level); + if (fpm_global_config.log_limit < ZLOG_MIN_LIMIT) { + zlog(ZLOG_ERROR, "log_limit must be greater than %d", ZLOG_MIN_LIMIT); + return -1; + } + zlog_set_limit(fpm_global_config.log_limit); + zlog_set_buffering(fpm_global_config.log_buffering); if (fpm_global_config.process_max < 0) { zlog(ZLOG_ERROR, "process_max can't be negative"); @@ -1265,6 +1277,7 @@ static void fpm_conf_cleanup(int which, void *arg) /* {{{ */ free(fpm_global_config.events_mechanism); fpm_global_config.pid_file = 0; fpm_global_config.error_log = 0; + fpm_global_config.log_limit = ZLOG_DEFAULT_LIMIT; #ifdef HAVE_SYSLOG_H free(fpm_global_config.syslog_ident); fpm_global_config.syslog_ident = 0; @@ -1606,7 +1619,9 @@ static void fpm_conf_dump() /* {{{ */ zlog(ZLOG_NOTICE, "\tsyslog.ident = %s", STR2STR(fpm_global_config.syslog_ident)); zlog(ZLOG_NOTICE, "\tsyslog.facility = %d", fpm_global_config.syslog_facility); /* FIXME: convert to string */ #endif + zlog(ZLOG_NOTICE, "\tlog_buffering = %s", BOOL2STR(fpm_global_config.log_buffering)); zlog(ZLOG_NOTICE, "\tlog_level = %s", zlog_get_level_name(fpm_globals.log_level)); + zlog(ZLOG_NOTICE, "\tlog_limit = %d", fpm_global_config.log_limit); zlog(ZLOG_NOTICE, "\temergency_restart_interval = %ds", fpm_global_config.emergency_restart_interval); zlog(ZLOG_NOTICE, "\temergency_restart_threshold = %d", fpm_global_config.emergency_restart_threshold); zlog(ZLOG_NOTICE, "\tprocess_control_timeout = %ds", fpm_global_config.process_control_timeout); @@ -1669,6 +1684,7 @@ static void fpm_conf_dump() /* {{{ */ zlog(ZLOG_NOTICE, "\tchroot = %s", STR2STR(wp->config->chroot)); zlog(ZLOG_NOTICE, "\tchdir = %s", STR2STR(wp->config->chdir)); zlog(ZLOG_NOTICE, "\tcatch_workers_output = %s", BOOL2STR(wp->config->catch_workers_output)); + zlog(ZLOG_NOTICE, "\tdecorate_workers_output = %s", BOOL2STR(wp->config->decorate_workers_output)); zlog(ZLOG_NOTICE, "\tclear_env = %s", BOOL2STR(wp->config->clear_env)); zlog(ZLOG_NOTICE, "\tsecurity.limit_extensions = %s", wp->config->security_limit_extensions); diff --git a/sapi/fpm/fpm/fpm_conf.h b/sapi/fpm/fpm/fpm_conf.h index 4f79cb21cdee3..8491888aa764f 100644 --- a/sapi/fpm/fpm/fpm_conf.h +++ b/sapi/fpm/fpm/fpm_conf.h @@ -30,6 +30,8 @@ struct fpm_global_config_s { int syslog_facility; #endif int log_level; + int log_limit; + int log_buffering; int emergency_restart_threshold; int emergency_restart_interval; int process_control_timeout; @@ -85,6 +87,7 @@ struct fpm_worker_pool_config_s { char *chroot; char *chdir; int catch_workers_output; + int decorate_workers_output; int clear_env; char *security_limit_extensions; struct key_value_s *env; diff --git a/sapi/fpm/fpm/fpm_main.c b/sapi/fpm/fpm/fpm_main.c index 673ae447b45f9..49acb79c684fb 100644 --- a/sapi/fpm/fpm/fpm_main.c +++ b/sapi/fpm/fpm/fpm_main.c @@ -637,21 +637,15 @@ void sapi_cgi_log_fastcgi(int level, char *message, size_t len) fcgi_request *request = (fcgi_request*) SG(server_context); - /* ensure we want: - * - to log (fastcgi.logging in php.ini) + /* message is written to FCGI_STDERR if following conditions are met: + * - logging is enabled (fastcgi.logging in php.ini) * - we are currently dealing with a request * - the message is not empty + * - the fcgi_write did not fail */ - if (CGIG(fcgi_logging) && request && message && len > 0) { - ssize_t ret; - char *buf = malloc(len + 2); - memcpy(buf, message, len); - memcpy(buf + len, "\n", sizeof("\n")); - ret = fcgi_write(request, FCGI_STDERR, buf, len + 1); - free(buf); - if (ret < 0) { - php_handle_aborted_connection(); - } + if (CGIG(fcgi_logging) && request && message && len > 0 + && fcgi_write(request, FCGI_STDERR, message, len) < 0) { + php_handle_aborted_connection(); } } /* }}} */ @@ -660,7 +654,7 @@ void sapi_cgi_log_fastcgi(int level, char *message, size_t len) */ static void sapi_cgi_log_message(char *message, int syslog_type_int) { - zlog(ZLOG_NOTICE, "PHP message: %s", message); + zlog_msg(ZLOG_NOTICE, "PHP message: ", message); } /* }}} */ diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 88c05b60af56c..380f9644bd368 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -14,6 +14,7 @@ #include "fpm.h" #include "fpm_children.h" +#include "fpm_cleanup.h" #include "fpm_events.h" #include "fpm_sockets.h" #include "fpm_stdio.h" @@ -22,6 +23,12 @@ static int fd_stdout[2]; static int fd_stderr[2]; +static void fpm_stdio_cleanup(int which, void *arg) /* {{{ */ +{ + zlog_cleanup(); +} +/* }}} */ + int fpm_stdio_init_main() /* {{{ */ { int fd = open("/dev/null", O_RDWR); @@ -30,6 +37,9 @@ int fpm_stdio_init_main() /* {{{ */ zlog(ZLOG_SYSERROR, "failed to init stdio: open(\"/dev/null\")"); return -1; } + if (0 > fpm_cleanup_add(FPM_CLEANUP_PARENT, fpm_stdio_cleanup, 0)) { + return -1; + } if (0 > dup2(fd, STDIN_FILENO) || 0 > dup2(fd, STDOUT_FILENO)) { zlog(ZLOG_SYSERROR, "failed to init stdio: dup2()"); @@ -115,14 +125,15 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) int is_stdout; struct fpm_event_s *event; int fifo_in = 1, fifo_out = 1; - int is_last_message = 0; int in_buf = 0; int res; + struct zlog_stream stream; if (!arg) { return; } child = (struct fpm_child_s *)arg; + is_stdout = (fd == child->fd_stdout); if (is_stdout) { event = &child->ev_stdout; @@ -130,6 +141,14 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) event = &child->ev_stderr; } + zlog_stream_init_ex(&stream, ZLOG_WARNING, STDERR_FILENO); + zlog_stream_set_decorating(&stream, child->wp->config->decorate_workers_output); + zlog_stream_set_wrapping(&stream, ZLOG_TRUE); + zlog_stream_set_msg_prefix(&stream, "[pool %s] child %d said into %s: ", + child->wp->config->name, (int) child->pid, is_stdout ? "stdout" : "stderr"); + zlog_stream_set_msg_suffix(&stream, NULL, ", pipe is closed"); + zlog_stream_set_msg_quoting(&stream, ZLOG_TRUE); + while (fifo_in || fifo_out) { if (fifo_in) { res = read(fd, buf + in_buf, max_buf_size - 1 - in_buf); @@ -144,7 +163,6 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) } fpm_event_del(event); - is_last_message = 1; if (is_stdout) { close(child->fd_stdout); @@ -164,42 +182,27 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) fifo_out = 0; } else { char *nl; - int should_print = 0; - buf[in_buf] = '\0'; - /* FIXME: there might be binary data */ - - /* we should print if no more space in the buffer */ - if (in_buf == max_buf_size - 1) { - should_print = 1; - } - - /* we should print if no more data to come */ - if (!fifo_in) { - should_print = 1; - } - - nl = strchr(buf, '\n'); - if (nl || should_print) { - - if (nl) { - *nl = '\0'; - } - - zlog(ZLOG_WARNING, "[pool %s] child %d said into %s: \"%s\"%s", child->wp->config->name, - (int) child->pid, is_stdout ? "stdout" : "stderr", buf, is_last_message ? ", pipe is closed" : ""); - - if (nl) { - int out_buf = 1 + nl - buf; - memmove(buf, buf + out_buf, in_buf - out_buf); - in_buf -= out_buf; - } else { - in_buf = 0; - } + nl = memchr(buf, '\n', in_buf); + if (nl) { + /* we should print each new line int the new message */ + int out_len = nl - buf; + zlog_stream_str(&stream, buf, out_len); + zlog_stream_finish(&stream); + /* skip new line */ + out_len++; + /* move data in the buffer */ + memmove(buf, buf + out_len, in_buf - out_len); + in_buf -= out_len; + } else if (in_buf == max_buf_size - 1 || !fifo_in) { + /* we should print if no more space in the buffer or no more data to come */ + zlog_stream_str(&stream, buf, in_buf); + in_buf = 0; } } } } + zlog_stream_close(&stream); } /* }}} */ diff --git a/sapi/fpm/fpm/zlog.c b/sapi/fpm/fpm/zlog.c index 3df8822fdbc93..cea0325897f03 100644 --- a/sapi/fpm/fpm/zlog.c +++ b/sapi/fpm/fpm/zlog.c @@ -17,10 +17,19 @@ #include "fpm.h" #include "zend_portability.h" -#define MAX_LINE_LENGTH 1024 +/* buffer is used for fmt result and it should never be over 2048 */ +#define MAX_BUF_LENGTH 2048 + +/* maximal length for wrapping prefix */ +#define MAX_WRAPPING_PREFIX_LENGTH 512 + +#define EXTRA_SPACE_FOR_PREFIX 128 static int zlog_fd = -1; static int zlog_level = ZLOG_NOTICE; +static int zlog_limit = ZLOG_DEFAULT_LIMIT; +static zlog_bool zlog_buffering = ZLOG_DEFAULT_BUFFERING; +static struct zlog_stream_buffer zlog_buffer = {NULL, 0}; static int launched = 0; static void (*external_logger)(int, char *, size_t) = NULL; @@ -60,16 +69,19 @@ const char *zlog_get_level_name(int log_level) /* {{{ */ } /* }}} */ -void zlog_set_launched(void) { +void zlog_set_launched(void) /* {{{ */ +{ launched = 1; } +/* }}} */ size_t zlog_print_time(struct timeval *tv, char *timebuf, size_t timebuf_len) /* {{{ */ { struct tm t; size_t len; - len = strftime(timebuf, timebuf_len, "[%d-%b-%Y %H:%M:%S", localtime_r((const time_t *) &tv->tv_sec, &t)); + len = strftime(timebuf, timebuf_len, "[%d-%b-%Y %H:%M:%S", + localtime_r((const time_t *) &tv->tv_sec, &t)); if (zlog_level == ZLOG_DEBUG) { len += snprintf(timebuf + len, timebuf_len - len, ".%06d", (int) tv->tv_usec); } @@ -98,39 +110,70 @@ int zlog_set_level(int new_value) /* {{{ */ } /* }}} */ -void vzlog(const char *function, int line, int flags, const char *fmt, va_list args) /* {{{ */ +int zlog_set_limit(int new_value) /* {{{ */ { - struct timeval tv; - char buf[MAX_LINE_LENGTH]; - const size_t buf_size = MAX_LINE_LENGTH; - size_t len = 0; - int truncated = 0; - int saved_errno; + int old_value = zlog_limit; - if (external_logger) { - va_list ap; - va_copy(ap, args); - len = vsnprintf(buf, buf_size, fmt, ap); - va_end(ap); - if (len >= buf_size) { - memcpy(buf + buf_size - sizeof("..."), "...", sizeof("...") - 1); - len = buf_size - 1; - } - external_logger(flags & ZLOG_LEVEL_MASK, buf, len); - len = 0; - memset(buf, '\0', buf_size); + zlog_limit = new_value; + return old_value; +} +/* }}} */ + +int zlog_set_buffering(zlog_bool buffering) /* {{{ */ +{ + int old_value = zlog_buffering; + + zlog_buffering = buffering; + return old_value; +} +/* }}} */ + +void zlog_cleanup() /* {{{ */ +{ + if (zlog_buffer.data) { + free(zlog_buffer.data); + zlog_buffer.data = NULL; + zlog_buffer.size = 0; } +} +/* }}} */ - if ((flags & ZLOG_LEVEL_MASK) < zlog_level) { - return; +static inline size_t zlog_truncate_buf(char *buf, size_t buf_size, size_t space_left) /* {{{ */ +{ + memcpy(buf + buf_size - sizeof("...") + 1 - space_left, "...", sizeof("...") - 1); + return buf_size - space_left; +} +/* }}} */ + +static inline void zlog_external( + int flags, char *buf, size_t buf_size, const char *fmt, va_list args) /* {{{ */ +{ + va_list ap; + size_t len; + + va_copy(ap, args); + len = vsnprintf(buf, buf_size, fmt, ap); + va_end(ap); + + if (len >= buf_size) { + len = zlog_truncate_buf(buf, buf_size, 0); } + external_logger(flags & ZLOG_LEVEL_MASK, buf, len); +} +/* }}} */ + +static size_t zlog_buf_prefix( + const char *function, int line, int flags, + char *buf, size_t buf_size, int use_syslog) /* {{{ */ +{ + struct timeval tv; + size_t len = 0; - saved_errno = errno; #ifdef HAVE_SYSLOG_H - if (zlog_fd == ZLOG_SYSLOG /* && !fpm_globals.is_child */) { - len = 0; + if (use_syslog /* && !fpm_globals.is_child */) { if (zlog_level == ZLOG_DEBUG) { - len += snprintf(buf, buf_size, "[%s] %s(), line %d: ", level_names[flags & ZLOG_LEVEL_MASK], function, line); + len += snprintf(buf, buf_size, "[%s] %s(), line %d: ", + level_names[flags & ZLOG_LEVEL_MASK], function, line); } else { len += snprintf(buf, buf_size, "[%s] ", level_names[flags & ZLOG_LEVEL_MASK]); } @@ -143,20 +186,44 @@ void vzlog(const char *function, int line, int flags, const char *fmt, va_list a } if (zlog_level == ZLOG_DEBUG) { if (!fpm_globals.is_child) { - len += snprintf(buf + len, buf_size - len, "%s: pid %d, %s(), line %d: ", level_names[flags & ZLOG_LEVEL_MASK], getpid(), function, line); + len += snprintf(buf + len, buf_size - len, "%s: pid %d, %s(), line %d: ", + level_names[flags & ZLOG_LEVEL_MASK], getpid(), function, line); } else { - len += snprintf(buf + len, buf_size - len, "%s: %s(), line %d: ", level_names[flags & ZLOG_LEVEL_MASK], function, line); + len += snprintf(buf + len, buf_size - len, "%s: %s(), line %d: ", + level_names[flags & ZLOG_LEVEL_MASK], function, line); } } else { - len += snprintf(buf + len, buf_size - len, "%s: ", level_names[flags & ZLOG_LEVEL_MASK]); + len += snprintf(buf + len, buf_size - len, "%s: ", + level_names[flags & ZLOG_LEVEL_MASK]); } } - if (len > buf_size - 1) { - truncated = 1; + return len; +} +/* }}} */ + +void vzlog(const char *function, int line, int flags, const char *fmt, va_list args) /* {{{ */ +{ + char buf[MAX_BUF_LENGTH]; + size_t buf_size = MAX_BUF_LENGTH; + size_t len = 0; + int truncated = 0; + int saved_errno; + + if (external_logger) { + zlog_external(flags, buf, buf_size, fmt, args); } - if (!truncated) { + if ((flags & ZLOG_LEVEL_MASK) < zlog_level) { + return; + } + + saved_errno = errno; + len = zlog_buf_prefix(function, line, flags, buf, buf_size, zlog_fd == ZLOG_SYSLOG); + + if (len > buf_size - 1) { + truncated = 1; + } else { len += vsnprintf(buf + len, buf_size - len, fmt, args); if (len >= buf_size) { truncated = 1; @@ -165,16 +232,16 @@ void vzlog(const char *function, int line, int flags, const char *fmt, va_list a if (!truncated) { if (flags & ZLOG_HAVE_ERRNO) { - len += snprintf(buf + len, buf_size - len, ": %s (%d)", strerror(saved_errno), saved_errno); - if (len >= buf_size) { + len += snprintf(buf + len, buf_size - len, + ": %s (%d)", strerror(saved_errno), saved_errno); + if (len >= zlog_limit) { truncated = 1; } } } if (truncated) { - memcpy(buf + buf_size - sizeof("..."), "...", sizeof("...") - 1); - len = buf_size - 1; + len = zlog_truncate_buf(buf, zlog_limit < buf_size ? zlog_limit : buf_size, 1); } #ifdef HAVE_SYSLOG_H @@ -189,16 +256,616 @@ void vzlog(const char *function, int line, int flags, const char *fmt, va_list a zend_quiet_write(zlog_fd > -1 ? zlog_fd : STDERR_FILENO, buf, len); } - if (zlog_fd != STDERR_FILENO && zlog_fd != -1 && !launched && (flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE) { + if (zlog_fd != STDERR_FILENO && zlog_fd != -1 && + !launched && (flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE) { zend_quiet_write(STDERR_FILENO, buf, len); } } /* }}} */ -void zlog_ex(const char *function, int line, int flags, const char *fmt, ...) /* {{{ */ { +void zlog_ex(const char *function, int line, int flags, const char *fmt, ...) /* {{{ */ +{ va_list args; va_start(args, fmt); vzlog(function, line, flags, fmt, args); va_end(args); } /* }}} */ + +/* predefine stream init that is used by zlog_msg_ex */ +static inline void zlog_stream_init_internal( + struct zlog_stream *stream, int flags, size_t capacity, int fd); + +void zlog_msg_ex(const char *function, int line, int flags, + const char *prefix, const char *msg) /* {{{ */ +{ + struct zlog_stream stream; + size_t prefix_len = strlen(prefix); + size_t msg_len = strlen(msg); + + zlog_stream_init_internal(&stream, flags, msg_len + prefix_len, 0); + zlog_stream_prefix_ex(&stream, function, line); + zlog_stream_str(&stream, prefix, prefix_len); + zlog_stream_str(&stream, msg, msg_len); + zlog_stream_finish(&stream); + zlog_stream_destroy(&stream); +} +/* }}} */ + +/* STREAM OPS */ + +static zlog_bool zlog_stream_buf_alloc_ex(struct zlog_stream *stream, size_t needed) /* {{{ */ +{ + char *buf; + size_t size = stream->buf.size ?: stream->buf_init_size; + + if (stream->buf.data) { + size = MIN(zlog_limit, MAX(size * 2, needed)); + buf = realloc(stream->buf.data, size); + } else { + size = MIN(zlog_limit, MAX(size, needed)); + if (stream->shared_buffer && zlog_buffer.data) { + if (zlog_buffer.size < size) { + buf = realloc(stream->buf.data, size); + } else { + buf = zlog_buffer.data; + size = zlog_buffer.size; + } + } else { + buf = malloc(size); + } + } + + if (buf == NULL) { + return 0; + } + + stream->buf.data = buf; + stream->buf.size = size; + if (stream->shared_buffer) { + zlog_buffer.data = buf; + zlog_buffer.size = size; + } + + return 1; +} +/* }}} */ + +inline static zlog_bool zlog_stream_buf_alloc(struct zlog_stream *stream) /* {{{ */ +{ + /* if there is enough space in the buffer, we do not need to reallocate */ + if (stream->buf.data && stream->buf.size >= MIN(zlog_limit, stream->buf_init_size)) { + return 1; + } + return zlog_stream_buf_alloc_ex(stream, 0); +} +/* }}} */ + +static inline ssize_t zlog_stream_direct_write_ex( + struct zlog_stream *stream, const char *buf, size_t len, + const char *append, size_t append_len) /* {{{ */ +{ + if (stream->use_fd) { + zend_quiet_write(stream->fd, buf, len); + if (append_len > 0) { + zend_quiet_write(stream->fd, append, append_len); + } + } + + if (stream->use_stderr) { + zend_quiet_write(STDERR_FILENO, buf, len); + if (append_len > 0) { + zend_quiet_write(STDERR_FILENO, append, append_len); + } + } + + return len; +} +/* }}} */ + +static ssize_t zlog_stream_direct_write( + struct zlog_stream *stream, const char *buf, size_t len) /* {{{ */ +{ + return zlog_stream_direct_write_ex(stream, buf, len, NULL, 0); +} +/* }}} */ + +static inline ssize_t zlog_stream_unbuffered_write( + struct zlog_stream *stream, const char *buf, size_t len) /* {{{ */ +{ + const char *append; + size_t append_len = 0, required_len, reserved_len; + ssize_t written; + + if (stream->len == 0) { + stream->len = zlog_stream_prefix_ex(stream, stream->function, stream->line); + } + + /* msg_suffix_len and msg_quote are used only for wrapping */ + reserved_len = stream->len + stream->msg_suffix_len + stream->msg_quote; + required_len = reserved_len + len; + if (required_len >= zlog_limit) { + if (stream->wrap) { + size_t available_len; + if (required_len == zlog_limit) { + append = NULL; + append_len = 0; + } else { + append = "\n"; + append_len = 1; + } + available_len = zlog_limit - reserved_len - 1; + zlog_stream_direct_write(stream, buf, available_len); + if (append != NULL) { + if (stream->msg_quote) { + zlog_stream_direct_write(stream, "\"", 1); + } + if (stream->msg_suffix) { + zlog_stream_direct_write(stream, stream->msg_suffix, stream->msg_suffix_len); + } + zlog_stream_direct_write(stream, append, append_len); + } + stream->len = 0; + written = zlog_stream_unbuffered_write( + stream, buf + available_len, len - available_len); + if (written > 0) { + return available_len + written; + } + + return written; + } + /* this would be used in case of an option for disabling wrapping in direct write */ + stream->full = 1; + if (required_len == zlog_limit) { + append = NULL; + } else { + append = "..."; + append_len = sizeof(append) - 1; + len = zlog_limit - stream->len - append_len; + } + } + + written = zlog_stream_direct_write_ex(stream, buf, len, append, append_len); + if (written > 0) { + /* currently written will be always len as the write is blocking + * - this should be address if we change to non-blocking write */ + stream->len += written; + } + + return written; +} +/* }}} */ + +static inline ssize_t zlog_stream_buf_copy_cstr( + struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */ +{ + if (stream->buf.size - stream->len <= str_len && !zlog_stream_buf_alloc_ex(stream, str_len)) { + return -1; + } + + memcpy(stream->buf.data + stream->len, str, str_len); + stream->len += str_len; + + return str_len; +} +/* }}} */ + +static inline ssize_t zlog_stream_buf_copy_char(struct zlog_stream *stream, char c) /* {{{ */ +{ + if (stream->buf.size - stream->len < 1 && !zlog_stream_buf_alloc_ex(stream, 1)) { + return -1; + } + + stream->buf.data[stream->len++] = c; + + return 1; +} +/* }}} */ + +static ssize_t zlog_stream_buf_flush(struct zlog_stream *stream) /* {{{ */ +{ + ssize_t written; + +#ifdef HAVE_SYSLOG_H + if (stream->use_syslog) { + zlog_stream_buf_copy_char(stream, '\0'); + php_syslog(syslog_priorities[zlog_level], "%s", stream->buf.data); + --stream->len; + } +#endif + + if (external_logger != NULL) { + external_logger(stream->flags & ZLOG_LEVEL_MASK, + stream->buf.data + stream->prefix_len, stream->len - stream->prefix_len); + } + zlog_stream_buf_copy_char(stream, '\n'); + written = zlog_stream_direct_write(stream, stream->buf.data, stream->len); + stream->len = 0; + + return written; +} +/* }}} */ + +static ssize_t zlog_stream_buf_append( + struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */ +{ + int over_limit = 0; + size_t available_len, required_len, reserved_len; + + if (stream->len == 0) { + stream->len = zlog_stream_prefix_ex(stream, stream->function, stream->line); + } + + /* msg_suffix_len and msg_quote are used only for wrapping */ + reserved_len = stream->len + stream->msg_suffix_len + stream->msg_quote; + required_len = reserved_len + str_len; + if (required_len >= zlog_limit) { + over_limit = 1; + available_len = zlog_limit - reserved_len - 1; + } else { + available_len = str_len; + } + + if (zlog_stream_buf_copy_cstr(stream, str, available_len) < 0) { + return -1; + } + + if (!over_limit) { + return available_len; + } + + if (stream->wrap) { + if (stream->msg_quote) { + zlog_stream_buf_copy_char(stream, '"'); + } + if (stream->msg_suffix != NULL) { + zlog_stream_buf_copy_cstr(stream, stream->msg_suffix, stream->msg_suffix_len); + } + zlog_stream_buf_flush(stream); + zlog_stream_prefix_ex(stream, stream->function, stream->line); + return available_len + zlog_stream_buf_append( + stream, str + available_len, str_len - available_len); + } + + stream->len = zlog_truncate_buf(stream->buf.data, stream->len, 0); + stream->full = 1; + return available_len; +} +/* }}} */ + +static inline void zlog_stream_init_internal( + struct zlog_stream *stream, int flags, size_t capacity, int fd) /* {{{ */ +{ + if (fd == 0) { + fd = zlog_fd; + } + + memset(stream, 0, sizeof(struct zlog_stream)); + stream->flags = flags; + stream->use_syslog = fd == ZLOG_SYSLOG; + stream->use_fd = fd > 0; + stream->use_buffer = zlog_buffering || external_logger != NULL || stream->use_syslog; + stream->buf_init_size = capacity; + stream->use_stderr = fd < 0 || + ( + fd != STDERR_FILENO && fd != STDOUT_FILENO && !launched && + (flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE + ); + stream->prefix_buffer = (flags & ZLOG_LEVEL_MASK) >= zlog_level && + (stream->use_fd || stream->use_stderr || stream->use_syslog); + stream->fd = fd > -1 ? fd : STDERR_FILENO; + stream->shared_buffer = external_logger == NULL; +} +/* }}} */ + +void zlog_stream_init(struct zlog_stream *stream, int flags) /* {{{ */ +{ + zlog_stream_init_internal(stream, flags, 1024, 0); +} +/* }}} */ + +void zlog_stream_init_ex(struct zlog_stream *stream, int flags, int fd) /* {{{ */ +{ + zlog_stream_init_internal(stream, flags, 1024, fd); + stream->wrap = 1; +} +/* }}} */ + +void zlog_stream_set_decorating(struct zlog_stream *stream, zlog_bool decorate) /* {{{ */ +{ + if (decorate) { + stream->decorate = 1; + } else { + stream->decorate = 0; + stream->msg_quote = 0; + stream->prefix_buffer = 0; + } +} +/* }}} */ + +void zlog_stream_set_wrapping(struct zlog_stream *stream, zlog_bool wrap) /* {{{ */ +{ + stream->wrap = wrap ? 1 : 0; +} +/* }}} */ + +void zlog_stream_set_msg_quoting(struct zlog_stream *stream, zlog_bool quote) /* {{{ */ +{ + stream->msg_quote = quote && stream->decorate ? 1 : 0; +} +/* }}} */ + +ssize_t zlog_stream_set_msg_prefix(struct zlog_stream *stream, const char *fmt, ...) /* {{{ */ +{ + char buf[MAX_WRAPPING_PREFIX_LENGTH]; + size_t len; + va_list args; + + if (!stream->decorate) { + return -1; + } + + va_start(args, fmt); + len = vsnprintf(buf, MAX_WRAPPING_PREFIX_LENGTH - 1, fmt, args); + va_end(args); + + stream->msg_prefix = malloc(len + 1); + if (stream->msg_prefix == NULL) { + return -1; + } + memcpy(stream->msg_prefix, buf, len); + stream->msg_prefix[len] = 0; + stream->msg_prefix_len = len; + + return len; +} +/* }}} */ + +ssize_t zlog_stream_set_msg_suffix( + struct zlog_stream *stream, const char *suffix, const char *final_suffix) /* {{{ */ +{ + size_t len; + if (!stream->wrap || !stream->decorate) { + return -1; + } + + if (suffix != NULL && final_suffix != NULL) { + stream->msg_suffix_len = strlen(suffix); + stream->msg_final_suffix_len = strlen(final_suffix); + len = stream->msg_suffix_len + stream->msg_final_suffix_len + 2; + stream->msg_suffix = malloc(len); + if (stream->msg_suffix == NULL) { + return -1; + } + stream->msg_final_suffix = stream->msg_suffix + stream->msg_suffix_len + 1; + memcpy(stream->msg_suffix, suffix, stream->msg_suffix_len + 1); + memcpy(stream->msg_final_suffix, final_suffix, stream->msg_final_suffix_len + 1); + return len; + } + if (suffix != NULL) { + stream->msg_suffix_len = len = strlen(suffix); + stream->msg_suffix = malloc(len); + if (stream->msg_suffix == NULL) { + return -1; + } + memcpy(stream->msg_suffix, suffix, stream->msg_suffix_len + 1); + return len; + } + if (final_suffix != NULL) { + stream->msg_final_suffix_len = len = strlen(final_suffix); + stream->msg_final_suffix = malloc(len + 1); + if (stream->msg_final_suffix == NULL) { + return -1; + } + memcpy(stream->msg_final_suffix, final_suffix, stream->msg_final_suffix_len + 1); + return len; + } + + return 0; +} +/* }}} */ + +ssize_t zlog_stream_prefix_ex(struct zlog_stream *stream, const char *function, int line) /* {{{ */ +{ + size_t len; + + if (!stream->prefix_buffer) { + return 0; + } + if (stream->wrap && stream->function == NULL) { + stream->function = function; + stream->line = line; + } + + if (stream->use_buffer) { + if (!zlog_stream_buf_alloc(stream)) { + return -1; + } + len = zlog_buf_prefix( + function, line, stream->flags, + stream->buf.data, stream->buf.size, stream->use_syslog); + stream->len = stream->prefix_len = len; + if (stream->msg_prefix != NULL) { + zlog_stream_buf_copy_cstr(stream, stream->msg_prefix, stream->msg_prefix_len); + } + if (stream->msg_quote) { + zlog_stream_buf_copy_char(stream, '"'); + } + return stream->len; + } else { + char sbuf[1024]; + ssize_t written; + len = zlog_buf_prefix(function, line, stream->flags, sbuf, 1024, stream->use_syslog); + written = zlog_stream_direct_write(stream, sbuf, len); + if (stream->msg_prefix != NULL) { + written += zlog_stream_direct_write( + stream, stream->msg_prefix, stream->msg_prefix_len); + } + if (stream->msg_quote) { + written += zlog_stream_direct_write(stream, "\"", 1); + } + return written; + } +} +/* }}} */ + +ssize_t zlog_stream_vformat(struct zlog_stream *stream, const char *fmt, va_list args) /* {{{ */ +{ + char sbuf[1024]; + size_t len; + + len = vsnprintf(sbuf, 1024, fmt, args); + + return zlog_stream_str(stream, sbuf, len); +} +/* }}} */ + +ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...) /* {{{ */ +{ + ssize_t len; + + va_list args; + va_start(args, fmt); + len = zlog_stream_vformat(stream, fmt, args); + va_end(args); + + return len; +} +/* }}} */ + +ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */ +{ + /* reset stream if it is finished */ + if (stream->finished) { + stream->finished = 0; + stream->len = 0; + stream->full = 0; + } else if (stream->full) { + /* do not write anything if the stream is full */ + return 0; + } + + if (stream->use_buffer) { + return zlog_stream_buf_append(stream, str, str_len); + } + + return zlog_stream_unbuffered_write(stream, str, str_len); +} +/* }}} */ + +static inline void zlog_stream_finish_buffer_suffix(struct zlog_stream *stream) /* {{{ */ +{ + if (stream->msg_quote) { + zlog_stream_buf_copy_char(stream, '"'); + } + if (stream->msg_suffix != NULL) { + zlog_stream_buf_copy_cstr(stream, stream->msg_suffix, stream->msg_suffix_len); + } + if (stream->msg_final_suffix != NULL) { + if (stream->len + stream->msg_final_suffix_len >= zlog_limit) { + zlog_bool quoting = stream->msg_quote; + size_t final_suffix_wrap = stream->len + stream->msg_final_suffix_len + 1 - zlog_limit; + zlog_stream_buf_copy_cstr( + stream, stream->msg_final_suffix, + stream->msg_final_suffix_len - final_suffix_wrap); + zlog_stream_buf_copy_char(stream, '\n'); + zlog_stream_buf_flush(stream); + stream->msg_quote = 0; + zlog_stream_prefix_ex(stream, stream->function, stream->line); + stream->msg_quote = quoting; + zlog_stream_buf_copy_cstr( + stream, + stream->msg_final_suffix + (stream->msg_final_suffix_len - final_suffix_wrap), + final_suffix_wrap); + zlog_stream_buf_copy_char(stream, '\n'); + } else { + zlog_stream_buf_copy_cstr( + stream, stream->msg_final_suffix, stream->msg_final_suffix_len); + } + } +} +/* }}} */ + +static inline void zlog_stream_finish_direct_suffix(struct zlog_stream *stream) /* {{{ */ +{ + if (stream->msg_quote) { + zlog_stream_direct_write(stream, "\"", 1); + ++stream->len; + } + if (stream->msg_suffix != NULL) { + /* we should always have space for wrap suffix so we don't have to check it */ + zlog_stream_direct_write(stream, stream->msg_suffix, stream->msg_suffix_len); + stream->len += stream->msg_suffix_len; + } + if (stream->msg_final_suffix != NULL) { + if (stream->len + stream->msg_final_suffix_len >= zlog_limit) { + zlog_bool quoting = stream->msg_quote; + size_t final_suffix_wrap = stream->len + stream->msg_final_suffix_len + 1 - zlog_limit; + zlog_stream_direct_write_ex( + stream, stream->msg_final_suffix, + stream->msg_final_suffix_len - final_suffix_wrap, "\n", 1); + stream->msg_quote = 0; + zlog_stream_prefix_ex(stream, stream->function, stream->line); + stream->msg_quote = quoting; + zlog_stream_direct_write_ex( + stream, + stream->msg_final_suffix + (stream->msg_final_suffix_len - final_suffix_wrap), + final_suffix_wrap, "\n", 1); + } else { + zlog_stream_direct_write_ex( + stream, stream->msg_final_suffix, stream->msg_final_suffix_len, "\n", 1); + } + } else { + zlog_stream_direct_write(stream, "\n", 1); + } +} +/* }}} */ + +zlog_bool zlog_stream_finish(struct zlog_stream *stream) /* {{{ */ +{ + if (stream->finished || stream->len == 0) { + return ZLOG_TRUE; + } + + if (stream->use_buffer) { + if (stream->decorate) { + zlog_stream_finish_buffer_suffix(stream); + } + zlog_stream_buf_flush(stream); + } else { + if (stream->decorate) { + zlog_stream_finish_direct_suffix(stream); + } else { + zlog_stream_direct_write(stream, "\n", 1); + } + } + stream->finished = 1; + + return ZLOG_TRUE; +} +/* }}} */ + +void zlog_stream_destroy(struct zlog_stream *stream) /* {{{ */ +{ + if (!stream->shared_buffer && stream->buf.data != NULL) { + free(stream->buf.data); + } + if (stream->msg_prefix != NULL) { + free(stream->msg_prefix); + } + if (stream->msg_suffix != NULL) { + free(stream->msg_suffix); + } else if (stream->msg_final_suffix != NULL) { + free(stream->msg_final_suffix); + } +} +/* }}} */ + +zlog_bool zlog_stream_close(struct zlog_stream *stream) /* {{{ */ +{ + zlog_bool finished = zlog_stream_finish(stream); + zlog_stream_destroy(stream); + + return finished; +} +/* }}} */ diff --git a/sapi/fpm/fpm/zlog.h b/sapi/fpm/fpm/zlog.h index e6c6b55b51a0c..ce977020b4b2d 100644 --- a/sapi/fpm/fpm/zlog.h +++ b/sapi/fpm/fpm/zlog.h @@ -5,16 +5,26 @@ #define ZLOG_H 1 #include +#include #define zlog(flags,...) zlog_ex(__func__, __LINE__, flags, __VA_ARGS__) +#define zlog_msg(flags, prefix, msg) zlog_msg_ex(__func__, __LINE__, flags, prefix, msg) struct timeval; +typedef unsigned char zlog_bool; + +#define ZLOG_TRUE 1 +#define ZLOG_FALSE 0 + void zlog_set_external_logger(void (*logger)(int, char *, size_t)); int zlog_set_fd(int new_fd); int zlog_set_level(int new_value); +int zlog_set_limit(int new_value); +int zlog_set_buffering(zlog_bool buffering); const char *zlog_get_level_name(int log_level); void zlog_set_launched(void); +void zlog_cleanup(); size_t zlog_print_time(struct timeval *tv, char *timebuf, size_t timebuf_len); @@ -22,6 +32,9 @@ void vzlog(const char *function, int line, int flags, const char *fmt, va_list a void zlog_ex(const char *function, int line, int flags, const char *fmt, ...) __attribute__ ((format(printf,4,5))); +void zlog_msg_ex(const char *function, int line, int flags, + const char *prefix, const char *msg); + #ifdef HAVE_SYSLOG_H extern const int syslog_priorities[]; #endif @@ -41,8 +54,68 @@ enum { #define ZLOG_SYSERROR (ZLOG_ERROR | ZLOG_HAVE_ERRNO) -#ifdef HAVE_SYSLOG_H #define ZLOG_SYSLOG -2 -#endif + +/* STREAM */ + +struct zlog_stream_buffer { + char *data; + size_t size; +}; + +struct zlog_stream { + int flags; + unsigned int use_syslog:1; + unsigned int use_fd:1; + unsigned int use_buffer:1; + unsigned int use_stderr:1; + unsigned int prefix_buffer:1; + unsigned int finished:1; + unsigned int full:1; + unsigned int wrap:1; + unsigned int msg_quote:1; + unsigned int decorate:1; + unsigned int shared_buffer:1; + int fd; + int line; + const char *function; + struct zlog_stream_buffer buf; + size_t len; + size_t buf_init_size; + size_t prefix_len; + char *msg_prefix; + size_t msg_prefix_len; + char *msg_suffix; + size_t msg_suffix_len; + char *msg_final_suffix; + size_t msg_final_suffix_len; +}; + +void zlog_stream_init(struct zlog_stream *stream, int flags); +void zlog_stream_init_ex(struct zlog_stream *stream, int flags, int fd); +void zlog_stream_set_decorating(struct zlog_stream *stream, zlog_bool decorate); +void zlog_stream_set_wrapping(struct zlog_stream *stream, zlog_bool wrap); +void zlog_stream_set_msg_quoting(struct zlog_stream *stream, zlog_bool quote); +ssize_t zlog_stream_set_msg_prefix(struct zlog_stream *stream, const char *fmt, ...) + __attribute__ ((format(printf,2,3))); +ssize_t zlog_stream_set_msg_suffix( + struct zlog_stream *stream, const char *suffix, const char *final_suffix); +#define zlog_stream_prefix(stream) \ + zlog_stream_prefix_ex(stream, __func__, __LINE__) +ssize_t zlog_stream_prefix_ex(struct zlog_stream *stream, const char *function, int line); +ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...) + __attribute__ ((format(printf,2,3))); +ssize_t zlog_stream_vformat(struct zlog_stream *stream, const char *fmt, va_list args); +ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len); +zlog_bool zlog_stream_finish(struct zlog_stream *stream); +void zlog_stream_destroy(struct zlog_stream *stream); +zlog_bool zlog_stream_close(struct zlog_stream *stream); + +/* default log limit */ +#define ZLOG_DEFAULT_LIMIT 1024 +/* minimum log limit */ +#define ZLOG_MIN_LIMIT 512 +/* default log buffering */ +#define ZLOG_DEFAULT_BUFFERING 1 #endif diff --git a/sapi/fpm/php-fpm.conf.in b/sapi/fpm/php-fpm.conf.in index 56c18e862a176..7f21aaa9606a1 100644 --- a/sapi/fpm/php-fpm.conf.in +++ b/sapi/fpm/php-fpm.conf.in @@ -41,6 +41,24 @@ ; Default Value: notice ;log_level = notice +; Log limit on number of characters in the single line (log entry). If the +; line is over the limit, it is wrapped on multiple lines. The limit is for +; all logged characters including message prefix and suffix if present. However +; the new line character does not count into it as it is present only when +; logging to a file descriptor. It means the new line character is not present +; when logging to syslog. +; Default Value: 1024 +;log_limit = 4096 + +; Log buffering specifies if the log line is buffered which means that the +; line is written in a single write operation. If the value is false, then the +; data is written directly into the file descriptor. It is an experimental +; option that can potentionaly improve logging performance and memory usage +; for some heavy logging scenarios. This option is ignored if logging to syslog +; as it has to be always buffered. +; Default value: yes +;log_buffering = no + ; If this number of child processes exit with SIGSEGV or SIGBUS within the time ; interval set by emergency_restart_interval then FPM will restart. A value ; of '0' means 'Off'. diff --git a/sapi/fpm/tests/log-bm-limit-1024-msg-80.phpt b/sapi/fpm/tests/log-bm-limit-1024-msg-80.phpt new file mode 100644 index 0000000000000..940d0df6e9abd --- /dev/null +++ b/sapi/fpm/tests/log-bm-limit-1024-msg-80.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Buffered message output log with limit 1024 and msg 80 +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectFastCGIErrorMessage('e', 1050, 80); +$tester->expectLogMessage('NOTICE: PHP message: ' . str_repeat('e', 80), 1050); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bm-limit-2048-msg-4000.phpt b/sapi/fpm/tests/log-bm-limit-2048-msg-4000.phpt new file mode 100644 index 0000000000000..5354671ee2a70 --- /dev/null +++ b/sapi/fpm/tests/log-bm-limit-2048-msg-4000.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Buffered message output log with limit 2048 and msg 4000 +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectFastCGIErrorMessage('t', 2048, 4000); +$tester->expectLogMessage('NOTICE: PHP message: ' . str_repeat('t', 2023) . '...', 2048); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bwd-limit-1050-msg-2048.phpt b/sapi/fpm/tests/log-bwd-limit-1050-msg-2048.phpt new file mode 100644 index 0000000000000..65524287459dd --- /dev/null +++ b/sapi/fpm/tests/log-bwd-limit-1050-msg-2048.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Buffered worker output decorated log with limit 1050 with 2048 msg +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1050, 2048); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bwd-limit-1050-msg-2900.phpt b/sapi/fpm/tests/log-bwd-limit-1050-msg-2900.phpt new file mode 100644 index 0000000000000..c528804292737 --- /dev/null +++ b/sapi/fpm/tests/log-bwd-limit-1050-msg-2900.phpt @@ -0,0 +1,46 @@ +--TEST-- +FPM: Buffered worker output decorated log with limit 1050 with 2900 msg +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1050, 2900); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bwd-limit-64-too-low-error.phpt b/sapi/fpm/tests/log-bwd-limit-64-too-low-error.phpt new file mode 100644 index 0000000000000..2259ecb1493cd --- /dev/null +++ b/sapi/fpm/tests/log-bwd-limit-64-too-low-error.phpt @@ -0,0 +1,42 @@ +--TEST-- +FPM: Buffered worker output decorated log with limit 64 fails because it is too low +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogError('log_limit must be greater than 512'); +$tester->close(true); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bwd-limit-8000-msg-4096.phpt b/sapi/fpm/tests/log-bwd-limit-8000-msg-4096.phpt new file mode 100644 index 0000000000000..fc8fbe1fe8ea1 --- /dev/null +++ b/sapi/fpm/tests/log-bwd-limit-8000-msg-4096.phpt @@ -0,0 +1,46 @@ +--TEST-- +FPM: Buffered worker output decorated log with limit 8000 with 4096 msg +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 8000, 4096); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bwd-msg-with-nl.phpt b/sapi/fpm/tests/log-bwd-msg-with-nl.phpt new file mode 100644 index 0000000000000..99385400b964d --- /dev/null +++ b/sapi/fpm/tests/log-bwd-msg-with-nl.phpt @@ -0,0 +1,46 @@ +--TEST-- +FPM: Buffered worker output decorated log with msg containing new lines +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogLine('msg 1'); +$tester->expectLogLine('msg 2'); +$tester->expectLogLine('msg 3'); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + \ No newline at end of file diff --git a/sapi/fpm/tests/log-bwp-limit-1024-msg-120.phpt b/sapi/fpm/tests/log-bwp-limit-1024-msg-120.phpt new file mode 100644 index 0000000000000..5a62285eda9dd --- /dev/null +++ b/sapi/fpm/tests/log-bwp-limit-1024-msg-120.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Buffered worker output plain log with limit 1024 and msg 120 +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1024, 120, false); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-bwp-limit-1500-msg-3300.phpt b/sapi/fpm/tests/log-bwp-limit-1500-msg-3300.phpt new file mode 100644 index 0000000000000..10674935cce9a --- /dev/null +++ b/sapi/fpm/tests/log-bwp-limit-1500-msg-3300.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Buffered worker output plain log with limit 1500 and msg 3300 +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1500, 3300, false); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-dwd-limit-1050-msg-2048.phpt b/sapi/fpm/tests/log-dwd-limit-1050-msg-2048.phpt new file mode 100644 index 0000000000000..5162206cdd03f --- /dev/null +++ b/sapi/fpm/tests/log-dwd-limit-1050-msg-2048.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Direct worker output decorated log with limit 1050 with 2048 msg +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1050, 2048); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-dwd-limit-1050-msg-2900.phpt b/sapi/fpm/tests/log-dwd-limit-1050-msg-2900.phpt new file mode 100644 index 0000000000000..fe08be6d3cbad --- /dev/null +++ b/sapi/fpm/tests/log-dwd-limit-1050-msg-2900.phpt @@ -0,0 +1,46 @@ +--TEST-- +FPM: Direct worker output decorated log with limit 1050 with 2900 msg +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1050, 2900); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-dwd-limit-8000-msg-4096.phpt b/sapi/fpm/tests/log-dwd-limit-8000-msg-4096.phpt new file mode 100644 index 0000000000000..351473fc2cfa8 --- /dev/null +++ b/sapi/fpm/tests/log-dwd-limit-8000-msg-4096.phpt @@ -0,0 +1,46 @@ +--TEST-- +FPM: Direct worker output decorated log with limit 8000 with 4096 msg +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 8000, 4096); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt b/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt new file mode 100644 index 0000000000000..61cb92331ebb4 --- /dev/null +++ b/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt @@ -0,0 +1,47 @@ +--TEST-- +FPM: Direct worker output plain log with limit 1000 and msg 2000 +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$tester->expectLogMessage('a', 1000, 2000, false); +$tester->close(); + +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/logtool.inc b/sapi/fpm/tests/logtool.inc index 219c6fedbb8fd..1cbef50a1ab87 100644 --- a/sapi/fpm/tests/logtool.inc +++ b/sapi/fpm/tests/logtool.inc @@ -90,7 +90,7 @@ class LogTool return $this->error("Unexpected truncated message: {$line}"); } - if ($lineLen === $this->limit) { + if ($lineLen === $this->limit - strlen('NOTICE: ') - 1) { if (!isset($matches[2])) { return $this->error("The truncated line is not ended with '...'"); } @@ -205,7 +205,7 @@ class LogTool if ($rem !== $outLen) { return $this->error("Printed more than the message len"); } - if ($finalSuffix === null || $finalSuffix === "") { + if ($finalSuffix === null) { return false; } if ($finalSuffix === false) { diff --git a/sapi/fpm/www.conf.in b/sapi/fpm/www.conf.in index ccfdbd9e872fd..a6227264ea48b 100644 --- a/sapi/fpm/www.conf.in +++ b/sapi/fpm/www.conf.in @@ -371,6 +371,13 @@ pm.max_spare_servers = 3 ; Default Value: no ;catch_workers_output = yes +; Decorate worker output with prefix and suffix containing information about +; the child that writes to the log and if stdout or stderr is used as well as +; log level and time. This options is used only if catch_workers_output is yes. +; Settings to "no" will output data as written to the stdout or stderr. +; Default value: yes +;decorate_workers_output = no + ; Clear environment in FPM workers ; Prevents arbitrary environment variables from reaching FPM worker processes ; by clearing the environment in workers before env vars specified in this