php/archived-php-src
1
0
Fork 0
mirror of https://github.com/php/php-src.git synced 2026-03-24 00:02:20 +01:00
Code Issues Packages Projects Releases Wiki Activity

Refactore FPM logging

Browse Source
This commit is contained in:
Jakub Zelenka
2018-06-14 18:14:33 +01:00
parent 2a78006adb
commit 3e5afbf0a8
22 changed files with 1474 additions and 92 deletions
Download Patch File Download Diff File Expand all files Collapse all files

16
sapi/fpm/fpm/fpm_conf.c
View File

@@ -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);

3
sapi/fpm/fpm/fpm_conf.h
View File

@@ -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;

20
sapi/fpm/fpm/fpm_main.c
View File

@@ -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);
}
/* }}} */

69
sapi/fpm/fpm/fpm_stdio.c
View File

@@ -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);
}
/* }}} */

751
sapi/fpm/fpm/zlog.c
View File

@@ -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) /* {{{ */
{
int old_value = zlog_limit;
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;
}
}
/* }}} */
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;
char buf[MAX_LINE_LENGTH];
const size_t buf_size = MAX_LINE_LENGTH;
size_t len = 0;
int truncated = 0;
int saved_errno;
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);
}
if ((flags & ZLOG_LEVEL_MASK) < zlog_level) {
return;
}
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;
}
/* }}} */

77
sapi/fpm/fpm/zlog.h
View File

@@ -5,16 +5,26 @@
#define ZLOG_H 1
#include <stdarg.h>
#include <sys/types.h>
#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

18
sapi/fpm/php-fpm.conf.in
View File

@@ -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'.

47
sapi/fpm/tests/log-bm-limit-1024-msg-80.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Buffered message output log with limit 1024 and msg 80
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1024
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
error_log(str_repeat('e', 80));
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->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--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

47
sapi/fpm/tests/log-bm-limit-2048-msg-4000.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Buffered message output log with limit 2048 and msg 4000
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 2048
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
error_log(str_repeat('t', 4000));
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->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--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

47
sapi/fpm/tests/log-bwd-limit-1050-msg-2048.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Buffered worker output decorated log with limit 1050 with 2048 msg
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1050
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
decorate_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 2048) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1050, 2048);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

46
sapi/fpm/tests/log-bwd-limit-1050-msg-2900.phpt Normal file
View File

@@ -0,0 +1,46 @@
--TEST--
FPM: Buffered worker output decorated log with limit 1050 with 2900 msg
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1050
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 2900) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1050, 2900);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

42
sapi/fpm/tests/log-bwd-limit-64-too-low-error.phpt Normal file
View File

@@ -0,0 +1,42 @@
--TEST--
FPM: Buffered worker output decorated log with limit 64 fails because it is too low
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 64
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 2048) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogError('log_limit must be greater than 512');
$tester->close(true);
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

46
sapi/fpm/tests/log-bwd-limit-8000-msg-4096.phpt Normal file
View File

@@ -0,0 +1,46 @@
--TEST--
FPM: Buffered worker output decorated log with limit 8000 with 4096 msg
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 8000
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 4096) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 8000, 4096);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

46
sapi/fpm/tests/log-bwd-msg-with-nl.phpt Normal file
View File

@@ -0,0 +1,46 @@
--TEST--
FPM: Buffered worker output decorated log with msg containing new lines
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', "msg 1\nmsg 2\nmsg 3");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->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--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

47
sapi/fpm/tests/log-bwp-limit-1024-msg-120.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Buffered worker output plain log with limit 1024 and msg 120
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1024
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
decorate_workers_output = no
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 120) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1024, 120, false);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

47
sapi/fpm/tests/log-bwp-limit-1500-msg-3300.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Buffered worker output plain log with limit 1500 and msg 3300
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1500
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
decorate_workers_output = no
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 3300) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1500, 3300, false);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

47
sapi/fpm/tests/log-dwd-limit-1050-msg-2048.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Direct worker output decorated log with limit 1050 with 2048 msg
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1050
log_buffering = no
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
decorate_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 2048) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1050, 2048);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

46
sapi/fpm/tests/log-dwd-limit-1050-msg-2900.phpt Normal file
View File

@@ -0,0 +1,46 @@
--TEST--
FPM: Direct worker output decorated log with limit 1050 with 2900 msg
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1050
log_buffering = no
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 2900) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1050, 2900);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

46
sapi/fpm/tests/log-dwd-limit-8000-msg-4096.phpt Normal file
View File

@@ -0,0 +1,46 @@
--TEST--
FPM: Direct worker output decorated log with limit 8000 with 4096 msg
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 8000
log_buffering = no
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 4096) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 8000, 4096);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

47
sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt Normal file
View File

@@ -0,0 +1,47 @@
--TEST--
FPM: Direct worker output plain log with limit 1000 and msg 2000
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1000
log_buffering = no
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
decorate_workers_output = no
EOT;
$code = <<<EOT
<?php
file_put_contents('php://stderr', str_repeat('a', 2000) . "\n");
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectLogMessage('a', 1000, 2000, false);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>

4
sapi/fpm/tests/logtool.inc
View File

@@ -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) {

7
sapi/fpm/www.conf.in
View File

@@ -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