Refactore FPM logging

Author: bukka

sapi/fpm/fpm/fpm_conf.c

@@ -81,6 +81,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;
@@ -98,7 +100,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) },
@@ -154,6 +158,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
@@ -617,6 +622,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;
@@ -1193,6 +1199,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");
@@ -1266,6 +1278,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;
@@ -1607,7 +1620,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);
@@ -1670,6 +1685,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);
 

sapi/fpm/fpm/fpm_conf.h

@@ -31,6 +31,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;
@@ -86,6 +88,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;

sapi/fpm/fpm/fpm_main.c

@@ -639,21 +639,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();
 	}
 }
 /* }}} */
@@ -662,7 +656,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);
 }
 /* }}} */
 

sapi/fpm/fpm/fpm_stdio.c

@@ -15,6 +15,7 @@
 
 #include "fpm.h"
 #include "fpm_children.h"
+#include "fpm_cleanup.h"
 #include "fpm_events.h"
 #include "fpm_sockets.h"
 #include "fpm_stdio.h"
@@ -23,6 +24,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);
@@ -31,6 +38,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()");
@@ -122,21 +132,30 @@ 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;
 	} else {
 		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);
@@ -151,7 +170,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);
@@ -171,42 +189,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);
 }
 /* }}} */