From: Jérôme Loyet <fat@php.net>
Date: Thu, 23 Jun 2011 08:03:52 +0000 (+0000)
Subject: - Added custom access log (also added per request %CPU and memory mesurement)
X-Git-Tag: php-5.5.0alpha1~1886
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=8dcfa2f9169e8927c51eda9645416163c9959ef6;p=php

- Added custom access log (also added per request %CPU and memory mesurement)
---

diff --git a/sapi/fpm/config.m4 b/sapi/fpm/config.m4
index bb31d3b9b6..751f866bb2 100644
--- a/sapi/fpm/config.m4
+++ b/sapi/fpm/config.m4
@@ -340,6 +340,33 @@ AC_DEFUN([AC_FPM_LQ],
 ])
 dnl }}}
 
+AC_DEFUN([AC_FPM_SYSCONF],
+[
+	AC_MSG_CHECKING([for sysconf])
+
+	AC_TRY_COMPILE([ #include <unistd.h> ], [sysconf(_SC_CLK_TCK);], [
+		AC_DEFINE([HAVE_SYSCONF], 1, [do we have sysconf?])
+		AC_MSG_RESULT([yes])
+	], [
+		AC_MSG_RESULT([no])
+	])
+])
+dnl }}}
+
+AC_DEFUN([AC_FPM_TIMES],
+[
+	AC_MSG_CHECKING([for times])
+
+	AC_TRY_COMPILE([ #include <sys/times.h> ], [struct tms t; times(&t);], [
+		AC_DEFINE([HAVE_TIMES], 1, [do we have times?])
+		AC_MSG_RESULT([yes])
+	], [
+		AC_MSG_RESULT([no])
+	])
+])
+dnl }}}
+
+
 AC_MSG_CHECKING(for FPM build)
 if test "$PHP_FPM" != "no"; then
   AC_MSG_RESULT($PHP_FPM)
@@ -350,6 +377,8 @@ if test "$PHP_FPM" != "no"; then
   AC_FPM_TRACE
   AC_FPM_BUILTIN_ATOMIC
   AC_FPM_LQ
+	AC_FPM_SYSCONF
+	AC_FPM_TIMES
 
   PHP_ARG_WITH(fpm-user,,
   [  --with-fpm-user[=USER]  Set the user for php-fpm to run as. (default: nobody)], nobody, no)
@@ -402,6 +431,7 @@ if test "$PHP_FPM" != "no"; then
     fpm/fpm_conf.c \
     fpm/fpm_env.c \
     fpm/fpm_events.c \
+		fpm/fpm_log.c \
     fpm/fpm_main.c \
     fpm/fpm_php.c \
     fpm/fpm_php_trace.c \
diff --git a/sapi/fpm/fpm/fastcgi.c b/sapi/fpm/fpm/fastcgi.c
index a1644ed12e..00a6587214 100644
--- a/sapi/fpm/fpm/fastcgi.c
+++ b/sapi/fpm/fpm/fastcgi.c
@@ -149,6 +149,8 @@ static int is_fastcgi = 0;
 static int in_shutdown = 0;
 static in_addr_t *allowed_clients = NULL;
 
+static sa_t client_sa;
+
 #ifdef _WIN32
 
 static DWORD WINAPI fcgi_shutdown_thread(LPVOID arg)
@@ -833,7 +835,9 @@ int fcgi_accept_request(fcgi_request *req)
 					FCGI_LOCK(req->listen_socket);
 					req->fd = accept(listen_socket, (struct sockaddr *)&sa, &len);
 					FCGI_UNLOCK(req->listen_socket);
-					if (req->fd >= 0 && allowed_clients) {
+
+					client_sa = sa;
+					if (sa.sa.sa_family == AF_INET && req->fd >= 0 && allowed_clients) {
 						int n = 0;
 						int allowed = 0;
 
@@ -1118,6 +1122,14 @@ void fcgi_free_mgmt_var_cb(void * ptr)
 	pefree(*var, 1);
 }
 
+char *fcgi_get_last_client_ip() /* {{{ */
+{
+	if (client_sa.sa.sa_family == AF_UNIX) {
+		return NULL;
+	}
+	return inet_ntoa(client_sa.sa_inet.sin_addr);
+}
+/* }}} */
 /*
  * Local variables:
  * tab-width: 4
diff --git a/sapi/fpm/fpm/fastcgi.h b/sapi/fpm/fpm/fastcgi.h
index 565fd3fb1a..4129def050 100644
--- a/sapi/fpm/fpm/fastcgi.h
+++ b/sapi/fpm/fpm/fastcgi.h
@@ -135,6 +135,8 @@ int fcgi_flush(fcgi_request *req, int close);
 void fcgi_set_mgmt_var(const char * name, size_t name_len, const char * value, size_t value_len);
 void fcgi_free_mgmt_var_cb(void * ptr);
 
+char *fcgi_get_last_client_ip();
+
 /*
  * Local variables:
  * tab-width: 4
diff --git a/sapi/fpm/fpm/fpm.c b/sapi/fpm/fpm/fpm.c
index e3fa3e3bd6..f80f943910 100644
--- a/sapi/fpm/fpm/fpm.c
+++ b/sapi/fpm/fpm/fpm.c
@@ -19,6 +19,7 @@
 #include "fpm_conf.h"
 #include "fpm_worker_pool.h"
 #include "fpm_stdio.h"
+#include "fpm_log.h"
 #include "zlog.h"
 
 struct fpm_globals_s fpm_globals = {
@@ -45,8 +46,9 @@ int fpm_init(int argc, char **argv, char *config, char *prefix, int test_conf) /
 	}
 	fpm_globals.prefix = prefix;
 
-	if (0 > fpm_php_init_main()              ||
+	if (0 > fpm_php_init_main()            ||
 		0 > fpm_stdio_init_main()            ||
+		0 > fpm_log_init_main()              ||
 		0 > fpm_conf_init_main(test_conf)    ||
 		0 > fpm_unix_init_main()             ||
 		0 > fpm_pctl_init_main()             ||
diff --git a/sapi/fpm/fpm/fpm_children.c b/sapi/fpm/fpm/fpm_children.c
index 476d5523de..d8338725e4 100644
--- a/sapi/fpm/fpm/fpm_children.c
+++ b/sapi/fpm/fpm/fpm_children.c
@@ -27,6 +27,7 @@
 #include "fpm_env.h"
 #include "fpm_shm_slots.h"
 #include "fpm_status.h"
+#include "fpm_log.h"
 
 #include "zlog.h"
 
@@ -146,6 +147,7 @@ static void fpm_child_init(struct fpm_worker_pool_s *wp) /* {{{ */
 	fpm_globals.max_requests = wp->config->pm_max_requests;
 
 	if (0 > fpm_stdio_init_child(wp) ||
+		0 > fpm_log_init_child(wp) ||
 		0 > fpm_status_init_child(wp) ||
 		0 > fpm_unix_init_child(wp) ||
 		0 > fpm_signals_init_child() ||
diff --git a/sapi/fpm/fpm/fpm_conf.c b/sapi/fpm/fpm/fpm_conf.c
index a8e2d60e26..f82806644f 100644
--- a/sapi/fpm/fpm/fpm_conf.c
+++ b/sapi/fpm/fpm/fpm_conf.c
@@ -41,6 +41,7 @@
 #include "fpm_sockets.h"
 #include "fpm_shm.h"
 #include "fpm_status.h"
+#include "fpm_log.h"
 #include "zlog.h"
 
 static int fpm_conf_load_ini_file(char *filename TSRMLS_DC);
@@ -102,6 +103,8 @@ static struct ini_value_parser_s ini_fpm_pool_options[] = {
 	{ "pm.status_path", &fpm_conf_set_string, WPO(pm_status_path) },
 	{ "ping.path", &fpm_conf_set_string, WPO(ping_path) },
 	{ "ping.response", &fpm_conf_set_string, WPO(ping_response) },
+	{ "access.log", &fpm_conf_set_string, WPO(access_log) },
+	{ "access.format", &fpm_conf_set_string, WPO(access_format) },
 	{ 0, 0, 0 }
 };
 
@@ -414,6 +417,8 @@ int fpm_worker_pool_config_free(struct fpm_worker_pool_config_s *wpc) /* {{{ */
 	free(wpc->chdir);
 	free(wpc->slowlog);
 	free(wpc->prefix);
+	free(wpc->access_log);
+	free(wpc->access_format);
 
 	return 0;
 }
@@ -663,6 +668,13 @@ static int fpm_conf_process_all_pools() /* {{{ */
 			/* memset(&fpm_status.last_update, 0, sizeof(fpm_status.last_update)); */
 		}
 
+		if (wp->config->access_log && *wp->config->access_log) {
+			fpm_evaluate_full_path(&wp->config->access_log, wp, NULL, 0);
+			if (!wp->config->access_format) {
+				wp->config->access_format = strdup("%R - %u %t \"%m %r\" %s");
+			}
+		}
+
 		if (wp->config->chroot && *wp->config->chroot) {
 
 			fpm_evaluate_full_path(&wp->config->chroot, wp, NULL, 1);
@@ -770,8 +782,10 @@ int fpm_conf_write_pid() /* {{{ */
 }
 /* }}} */
 
-static int fpm_conf_post_process() /* {{{ */
+static int fpm_conf_post_process(TSRMLS_D) /* {{{ */
 {
+	struct fpm_worker_pool_s *wp;
+
 	if (fpm_global_config.pid_file) {
 		fpm_evaluate_full_path(&fpm_global_config.pid_file, NULL, PHP_LOCALSTATEDIR, 0);
 	}
@@ -786,7 +800,25 @@ static int fpm_conf_post_process() /* {{{ */
 		return -1;
 	}
 
-	return fpm_conf_process_all_pools();
+	if (0 > fpm_log_open(0)) {
+		return -1;
+	}
+
+	if (0 > fpm_conf_process_all_pools()) {
+		return -1;
+	}
+
+	for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
+		if (!wp->config->access_log || !*wp->config->access_log) {
+			continue;
+		}
+		if (0 > fpm_log_write(wp->config->access_format TSRMLS_CC)) {
+			zlog(ZLOG_ERROR, "[pool %s] wrong format for access.format '%s'", wp->config->name, wp->config->access_format);
+			return -1;
+		}
+	}
+
+	return 0;
 }
 /* }}} */
 
@@ -1147,6 +1179,8 @@ static void fpm_conf_dump() /* {{{ */
 		zlog(ZLOG_NOTICE, "\tpm.status_path = %s", STR2STR(wp->config->pm_status_path));
 		zlog(ZLOG_NOTICE, "\tping.path = %s", STR2STR(wp->config->ping_path));
 		zlog(ZLOG_NOTICE, "\tping.response = %s", STR2STR(wp->config->ping_response));
+		zlog(ZLOG_NOTICE, "\taccess.log = %s", STR2STR(wp->config->access_log));
+		zlog(ZLOG_NOTICE, "\taccess.format = %s", STR2STR(wp->config->access_format));
 		zlog(ZLOG_NOTICE, "\tcatch_workers_output = %s", BOOL2STR(wp->config->catch_workers_output));
 		zlog(ZLOG_NOTICE, "\trequest_terminate_timeout = %ds", wp->config->request_terminate_timeout);
 		zlog(ZLOG_NOTICE, "\trequest_slowlog_timeout = %ds", wp->config->request_slowlog_timeout);
@@ -1212,7 +1246,7 @@ int fpm_conf_init_main(int test_conf) /* {{{ */
 		return -1;
 	}
 
-	if (0 > fpm_conf_post_process()) {
+	if (0 > fpm_conf_post_process(TSRMLS_C)) {
 		zlog(ZLOG_ERROR, "failed to post process the configuration");
 		return -1;
 	}
diff --git a/sapi/fpm/fpm/fpm_conf.h b/sapi/fpm/fpm/fpm_conf.h
index 64b569006e..d1087641d3 100644
--- a/sapi/fpm/fpm/fpm_conf.h
+++ b/sapi/fpm/fpm/fpm_conf.h
@@ -57,6 +57,8 @@ struct fpm_worker_pool_config_s {
 	int pm_max_spare_servers;
 	char *ping_path;
 	char *ping_response;
+	char *access_log;
+	char *access_format;
 	char *listen_address;
 	int listen_backlog;
 	char *listen_owner;
diff --git a/sapi/fpm/fpm/fpm_events.c b/sapi/fpm/fpm/fpm_events.c
index 2bb4b94c00..7ba982bf75 100644
--- a/sapi/fpm/fpm/fpm_events.c
+++ b/sapi/fpm/fpm/fpm_events.c
@@ -21,6 +21,7 @@
 #include "fpm_children.h"
 #include "zlog.h"
 #include "fpm_clock.h"
+#include "fpm_log.h"
 
 #define fpm_event_set_timeout(ev, now) timeradd(&(now), &(ev)->frequency, &(ev)->timeout);
 
@@ -55,8 +56,8 @@ static void fpm_event_cleanup(int which, void *arg) /* {{{ */
 static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{{ */
 {
 	char c;
-	int res;
-	int fd = ev->fd;;
+	int res, ret;
+	int fd = ev->fd;
 
 	do {
 		do {
@@ -93,10 +94,19 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{
 			case '1' :                  /* SIGUSR1 */
 				zlog(ZLOG_DEBUG, "received SIGUSR1");
 				if (0 == fpm_stdio_open_error_log(1)) {
-					zlog(ZLOG_NOTICE, "log file re-opened");
+					zlog(ZLOG_NOTICE, "error log file re-opened");
 				} else {
-					zlog(ZLOG_ERROR, "unable to re-opened log file");
+					zlog(ZLOG_ERROR, "unable to re-opened error log file");
 				}
+
+				ret = fpm_log_open(1);
+				if (ret == 0) {
+					zlog(ZLOG_NOTICE, "access log file re-opened");
+				} else if (ret == -1) {
+					zlog(ZLOG_ERROR, "unable to re-opened access log file");
+				}
+				/* else no access log are set */
+
 				break;
 			case '2' :                  /* SIGUSR2 */
 				zlog(ZLOG_DEBUG, "received SIGUSR2");
diff --git a/sapi/fpm/fpm/fpm_log.c b/sapi/fpm/fpm/fpm_log.c
new file mode 100644
index 0000000000..243ed86764
--- /dev/null
+++ b/sapi/fpm/fpm/fpm_log.c
@@ -0,0 +1,493 @@
+
+	/* $Id: fpm_status.c 312262 2011-06-18 17:41:56Z felipe $ */
+	/* (c) 2009 Jerome Loyet */
+
+#include "php.h"
+#include "SAPI.h"
+#include <stdio.h>
+#include <unistd.h>
+#include <fcntl.h>
+
+#ifdef HAVE_TIMES
+#include <sys/times.h>
+#endif
+
+#include "fpm_config.h"
+#include "fpm_log.h"
+#include "fpm_clock.h"
+#include "fpm_process_ctl.h"
+#include "fpm_signals.h"
+#include "fpm_shm_slots.h"
+#include "fastcgi.h"
+#include "zlog.h"
+
+#ifdef MAX_LINE_LENGTH
+# define FPM_LOG_BUFFER MAX_LINE_LENGTH
+#else
+# define FPM_LOG_BUFFER 1024
+#endif
+
+static char *fpm_log_format = NULL;
+static char *fpm_log_pool = NULL;
+static int fpm_log_fd = -1;
+#ifdef HAVE_TIMES
+static float tick;
+#endif
+
+int fpm_log_open(int reopen) /* {{{ */
+{
+	struct fpm_worker_pool_s *wp;
+	int ret = 1;
+	
+	int fd;
+	for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
+		if (!wp->config->access_log) {
+			continue;
+		}
+		ret = 0;
+		
+		fd = open(wp->config->access_log, O_WRONLY | O_APPEND | O_CREAT, S_IRUSR | S_IWUSR);
+		if (0 > fd) {
+			zlog(ZLOG_SYSERROR, "open(\"%s\") failed", wp->config->access_log);
+			return -1;
+		}
+
+		if (reopen) {
+			dup2(fd, wp->log_fd);
+			close(fd);
+			fd = wp->log_fd;
+			fpm_pctl_kill_all(SIGQUIT);
+		} else {
+			wp->log_fd = fd;
+		}
+
+		fcntl(fd, F_SETFD, fcntl(fd, F_GETFD) | FD_CLOEXEC);
+	}
+
+	return ret;
+}
+/* }}} */
+
+int fpm_log_init_main() /* {{{ */
+{
+#ifdef HAVE_TIMES
+#if (defined(HAVE_SYSCONF) && defined(_SC_CLK_TCK))
+	tick = sysconf(_SC_CLK_TCK);
+#else /* _SC_CLK_TCK */
+#ifdef HZ
+	tick = HZ;
+#else /* HZ */
+	tick = 100;
+#endif /* HZ */
+#endif /* _SC_CLK_TCK */
+	zlog(ZLOG_DEBUG, "got clock tick '%.0f'", tick);
+#endif /* HAVE_TIMES */
+	return 0;
+}
+/* }}} */
+
+/* }}} */
+int fpm_log_init_child(struct fpm_worker_pool_s *wp)  /* {{{ */
+{
+	if (!wp || !wp->config) {
+		return -1;
+	}
+
+	if (wp->config->access_log && *wp->config->access_log) {
+		if (wp->config->access_format) {
+			fpm_log_format = strdup(wp->config->access_format);
+		}
+	}
+
+	if (wp->config->name) {
+		fpm_log_pool = strdup(wp->config->name);
+	}
+
+	if (fpm_log_fd == -1) {
+		fpm_log_fd = wp->log_fd;
+	}
+
+
+	for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
+		if (wp->log_fd > -1 && wp->log_fd != fpm_log_fd) {
+			close(wp->log_fd);
+			wp->log_fd = -1;
+		}
+	}
+
+	return 0;
+}
+/* }}} */
+
+int fpm_log_write(char *log_format TSRMLS_DC) /* {{{ */
+{
+	char *s, *b;
+	char buffer[FPM_LOG_BUFFER];
+	int token, test;
+	size_t len, len2;
+//	fcgi_request *request = (fcgi_request*) SG(server_context);
+	struct fpm_shm_slot_s slot, *slot_p;
+	struct timeval uptime, now;
+	char tmp[129];
+	char format[129];
+	time_t now_epoch;
+#ifdef HAVE_TIMES
+	clock_t tms_total;
+#endif
+
+	if (!log_format && (!fpm_log_format || fpm_log_fd == -1)) {
+		return -1;
+	}
+
+	if (!log_format) {
+		log_format = fpm_log_format;
+		test = 0;
+	} else {
+		test = 1;
+	}
+
+	fpm_clock_get(&now);
+	now_epoch = time(NULL);
+	if (!test) {
+		slot_p = fpm_shm_slots_acquire(0, 0);
+		if (!slot_p) {
+			zlog(ZLOG_WARNING, "Unable to acquire shm slot");
+			return -1;
+		}
+		slot = *slot_p;
+		fpm_shm_slots_release(slot_p);
+
+		timersub(&now, &slot.accepted, &uptime);
+	}
+
+	token = 0;
+
+	memset(buffer, '\0', sizeof(buffer));
+	b = buffer;
+	len = 0;
+
+
+	s = log_format;
+
+	while (*s != '\0') {
+		if (len > FPM_LOG_BUFFER) {
+			zlog(ZLOG_NOTICE, "the log buffer is full (%d). The log request has been truncated.", FPM_LOG_BUFFER);
+			len = FPM_LOG_BUFFER - 1;
+			break;
+		}
+
+		if (!token && *s == '%') {
+			token = 1;
+			memset(format, '\0', sizeof(format)); /* reset format */
+			s++;
+			continue;
+		}
+
+		if (token) {
+			token = 0;
+			len2 = 0;
+			switch (*s) {
+
+				case '%': /* '%' */
+					*b = '%';
+					len2 = 1;
+					break;
+
+#ifdef HAVE_TIMES
+				case 'C': /* %CPU */
+					if (format[0] == '\0' || !strcasecmp(format, "total")) {
+						if (!test) {
+							tms_total = 
+								(slot.cpu_finished.tms_utime + slot.cpu_finished.tms_stime + slot.cpu_finished.tms_cutime + slot.cpu_finished.tms_cstime)
+								- 
+								(slot.cpu_accepted.tms_utime + slot.cpu_accepted.tms_stime + slot.cpu_accepted.tms_cutime + slot.cpu_accepted.tms_cstime)
+								;
+						}
+					} else if (!strcasecmp(format, "user")) {
+						if (!test) {
+							tms_total = (slot.cpu_finished.tms_utime + slot.cpu_finished.tms_cutime) - (slot.cpu_accepted.tms_utime + slot.cpu_accepted.tms_cutime);
+						}
+					} else if (!strcasecmp(format, "system")) {
+						if (!test) {
+							tms_total = (slot.cpu_finished.tms_stime + slot.cpu_finished.tms_cstime) - (slot.cpu_accepted.tms_stime + slot.cpu_accepted.tms_cstime);
+						}
+					} else {
+						zlog(ZLOG_WARNING, "only 'total', 'user' or 'system' are allowed as a modifier for %%%c ('%s')", *s, format);
+						return -1;
+					}
+
+					format[0] = '\0';
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.2f", tms_total / tick / (slot.cpu_duration.tv_sec + slot.cpu_duration.tv_usec / 1000000.) * 100.);
+					}
+					break;
+#endif
+
+				case 'd': /* duration µs */
+					/* seconds */
+					if (format[0] == '\0' || !strcasecmp(format, "seconds")) {
+						if (!test) {
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", uptime.tv_sec + uptime.tv_usec / 1000000.);
+						}
+
+					/* miliseconds */
+					} else if (!strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")) {
+						if (!test) {
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", uptime.tv_sec * 1000. + uptime.tv_usec / 1000.);
+						}
+
+					/* microseconds */
+					} else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
+						if (!test) {
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", uptime.tv_sec * 1000000UL + uptime.tv_usec);
+						}
+
+					} else {
+						zlog(ZLOG_WARNING, "only 'seconds', 'mili', 'miliseconds', 'micro' or 'microseconds' are allowed as a modifier for %%%c ('%s')", *s, format);
+						return -1;
+					}
+					format[0] = '\0';
+					break;
+
+				case 'e': /* fastcgi env  */
+					if (format[0] == '\0') {
+						zlog(ZLOG_WARNING, "the name of the environment variable must be set between embraces for %%%c", *s);
+						return -1;
+					}
+
+					if (!test) {
+						char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format));
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-");
+					}
+					format[0] = '\0';
+					break;
+
+				case 'f': /* script */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s",  slot.script_filename && *slot.script_filename ? slot.script_filename : "-");
+					}
+					break;
+
+				case 'l': /* content length */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", slot.content_length);
+					}
+					break;
+
+				case 'm': /* method */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", slot.request_method && *slot.request_method ? slot.request_method : "-");
+					}
+					break;
+
+				case 'M': /* memory */
+					/* seconds */
+					if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
+						if (!test) {
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", slot.memory);
+						}
+
+					/* kilobytes */
+					} else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
+						if (!test) {
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", slot.memory / 1024);
+						}
+
+					/* megabytes */
+					} else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
+						if (!test) {
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", slot.memory / 1024 / 1024);
+						}
+
+					} else {
+						zlog(ZLOG_WARNING, "only 'bytes', 'kilo', 'kilobytes', 'mega' or 'megabytes' are allowed as a modifier for %%%c ('%s')", *s, format);
+						return -1;
+					}
+					format[0] = '\0';
+					break;
+
+				case 'n': /* pool name */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", fpm_log_pool ? fpm_log_pool : "-");
+					}
+					break;
+
+				case 'o': /* header output  */
+					if (format[0] == '\0') {
+						zlog(ZLOG_WARNING, "the name of the header must be set between embraces for %%%c", *s);
+						return -1;
+					}
+					if (!test) {
+						sapi_header_struct *h;
+						zend_llist_position pos;
+						sapi_headers_struct *sapi_headers = &SG(sapi_headers);
+						size_t format_len = strlen(format);
+
+						h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos);
+						while (h) {
+							char *header;
+							if (!h->header_len) {
+								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
+								continue;
+							}
+							if (!strstr(h->header, format)) {
+								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
+								continue;
+							}
+
+							/* test if enought char after the header name + ': ' */
+							if (h->header_len <= format_len + 2) {
+								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
+								continue;
+							}
+
+							if (h->header[format_len] != ':' || h->header[format_len + 1] != ' ') {
+								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
+								continue;
+							}
+
+							header = h->header + format_len + 2;
+							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-");
+
+							/* found, done */
+							break;
+						}
+						if (!len2) {
+							len2 = 1;
+							*b = '-';
+						}
+					}
+					format[0] = '\0';
+					break;
+
+				case 'p': /* PID */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid());
+					}
+					break;
+
+				case 'P': /* PID */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid());
+					}
+					break;
+
+				case 'q': /* query_string */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", slot.query_string ? slot.query_string : "");
+					}
+					break;
+
+				case 'Q': /* '?' */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", slot.query_string && *slot.query_string  ? "?" : "");
+					}
+					break;
+
+				case 'r': /* request URI */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", slot.request_uri ? slot.request_uri : "-");
+					}
+					break;
+
+				case 'R': /* remote IP address */
+					if (!test) {
+						char *tmp = fcgi_get_last_client_ip();
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-");
+					}
+					break;
+
+				case 's': /* status */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code);
+					}
+					break;
+
+				case 'T':
+				case 't': /* time */
+					if (!test) {
+						time_t *t;
+						if (*s == 't') {
+							t = &slot.accepted_epoch;
+						} else {
+							t = &now_epoch;
+						}
+						if (format[0] == '\0') {
+							strftime(tmp, sizeof(tmp) - 1, "%d/%b/%Y:%H:%M:%S %z", localtime(t));
+						} else {
+							strftime(tmp, sizeof(tmp) - 1, format, localtime(t));
+						}
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp);
+					}
+					format[0] = '\0';
+					break;
+
+				case 'u': /* remote user */
+					if (!test) {
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", slot.auth_user ? slot.auth_user : "-");
+					}
+					break;
+
+				case '{': /* complex var */
+					token = 1;
+					{
+						char *start;
+						size_t l;
+						
+						start = ++s;
+
+						while (*s != '\0') {
+							if (*s == '}') {
+								l = s - start;
+
+								if (l >= sizeof(format) - 1) {
+									l = sizeof(format) - 1;
+								}
+
+								memcpy(format, start, l);
+								format[l] = '\0';
+								break;
+							}
+							s++;
+						}
+						if (s[1] == '\0') {
+							zlog(ZLOG_WARNING, "missing closing embrace in the access.format");
+							return -1;
+						}
+					}
+					break;
+
+				default:
+					zlog(ZLOG_WARNING, "Invalid token in the access.format (%%%c)", *s);
+					return -1;
+			}
+
+			if (*s != '}' && format[0] != '\0') {
+				zlog(ZLOG_WARNING, "embrace is not allowed for modifier %%%c", *s);
+				return -1;
+			}
+			s++;
+			if (!test) {
+				b += len2;
+				len += len2;
+			}
+			continue;
+		}
+
+		if (!test) {
+			// push the normal char to the output buffer
+			*b = *s;
+			b++;
+			len++;
+		}
+		s++;
+	}
+
+	if (!test && strlen(buffer) > 0) {
+		buffer[len] = '\n';
+		write(fpm_log_fd, buffer, len + 1);
+	}
+
+	return 0;
+}
+/* }}} */
diff --git a/sapi/fpm/fpm/fpm_log.h b/sapi/fpm/fpm/fpm_log.h
new file mode 100644
index 0000000000..74f842646f
--- /dev/null
+++ b/sapi/fpm/fpm/fpm_log.h
@@ -0,0 +1,14 @@
+
+	/* $Id: fpm_status.h 312263 2011-06-18 17:46:16Z felipe $ */
+	/* (c) 2009 Jerome Loyet */
+
+#ifndef FPM_LOG_H
+#define FPM_LOG_H 1
+#include "fpm_worker_pool.h"
+
+int fpm_log_init_main();
+int fpm_log_init_child(struct fpm_worker_pool_s *wp);
+int fpm_log_write(char *log_format TSRMLS_DC);
+int fpm_log_open(int reopen);
+
+#endif
diff --git a/sapi/fpm/fpm/fpm_main.c b/sapi/fpm/fpm/fpm_main.c
index cd87ffc295..37c932e5b4 100644
--- a/sapi/fpm/fpm/fpm_main.c
+++ b/sapi/fpm/fpm/fpm_main.c
@@ -109,6 +109,7 @@ int __riscosify_control = __RISCOSIFY_STRICT_UNIX_SPECS;
 #include <fpm/fpm_status.h>
 #include <fpm/fpm_conf.h>
 #include <fpm/fpm_php.h>
+#include <fpm/fpm_log.h>
 
 #ifndef PHP_WIN32
 /* XXX this will need to change later when threaded fastcgi is implemented.  shane */
@@ -1905,6 +1906,9 @@ fastcgi_request_done:
 				}
 			}
 
+			fpm_request_end(TSRMLS_C);
+			fpm_log_write(NULL TSRMLS_CC);
+
 			STR_FREE(SG(request_info).path_translated);
 			SG(request_info).path_translated = NULL;
 
diff --git a/sapi/fpm/fpm/fpm_php.c b/sapi/fpm/fpm/fpm_php.c
index 384682b7e2..33b9e410e1 100644
--- a/sapi/fpm/fpm/fpm_php.c
+++ b/sapi/fpm/fpm/fpm_php.c
@@ -172,6 +172,18 @@ char *fpm_php_request_method(TSRMLS_D) /* {{{ */
 }
 /* }}} */
 
+char *fpm_php_query_string(TSRMLS_D) /* {{{ */
+{
+	return SG(request_info).query_string;
+}
+/* }}} */
+
+char *fpm_php_auth_user(TSRMLS_D) /* {{{ */
+{
+	return SG(request_info).auth_user;
+}
+/* }}} */
+
 size_t fpm_php_content_length(TSRMLS_D) /* {{{ */
 {
 	return SG(request_info).content_length;
diff --git a/sapi/fpm/fpm/fpm_php.h b/sapi/fpm/fpm/fpm_php.h
index 891e83bfce..62a47e7fd3 100644
--- a/sapi/fpm/fpm/fpm_php.h
+++ b/sapi/fpm/fpm/fpm_php.h
@@ -37,6 +37,8 @@ int fpm_php_init_child(struct fpm_worker_pool_s *wp);
 char *fpm_php_script_filename(TSRMLS_D);
 char *fpm_php_request_uri(TSRMLS_D);
 char *fpm_php_request_method(TSRMLS_D);
+char *fpm_php_query_string(TSRMLS_D);
+char *fpm_php_auth_user(TSRMLS_D);
 size_t fpm_php_content_length(TSRMLS_D);
 void fpm_php_soft_quit();
 int fpm_php_init_main();
diff --git a/sapi/fpm/fpm/fpm_process_ctl.c b/sapi/fpm/fpm/fpm_process_ctl.c
index badda14082..bd50c46c29 100644
--- a/sapi/fpm/fpm/fpm_process_ctl.c
+++ b/sapi/fpm/fpm/fpm_process_ctl.c
@@ -143,7 +143,7 @@ int fpm_pctl_kill(pid_t pid, int how) /* {{{ */
 }
 /* }}} */
 
-static void fpm_pctl_kill_all(int signo) /* {{{ */
+void fpm_pctl_kill_all(int signo) /* {{{ */
 {
 	struct fpm_worker_pool_s *wp;
 	int alive_children = 0;
diff --git a/sapi/fpm/fpm/fpm_process_ctl.h b/sapi/fpm/fpm/fpm_process_ctl.h
index 36577097cb..6bfcfd8c6b 100644
--- a/sapi/fpm/fpm/fpm_process_ctl.h
+++ b/sapi/fpm/fpm/fpm_process_ctl.h
@@ -19,6 +19,7 @@ struct fpm_child_s;
 void fpm_pctl(int new_state, int action);
 int fpm_pctl_can_spawn_children();
 int fpm_pctl_kill(pid_t pid, int how);
+void fpm_pctl_kill_all(int signo);
 void fpm_pctl_heartbeat(struct fpm_event_s *ev, short which, void *arg);
 void fpm_pctl_perform_idle_server_maintenance_heartbeat(struct fpm_event_s *ev, short which, void *arg);
 int fpm_pctl_child_exited();
diff --git a/sapi/fpm/fpm/fpm_request.c b/sapi/fpm/fpm/fpm_request.c
index 6ba9e5170c..492e76275b 100644
--- a/sapi/fpm/fpm/fpm_request.c
+++ b/sapi/fpm/fpm/fpm_request.c
@@ -1,6 +1,9 @@
 
 	/* $Id: fpm_request.c,v 1.9.2.1 2008/11/15 00:57:24 anight Exp $ */
 	/* (c) 2007,2008 Andrei Nigmatulin */
+#ifdef HAVE_TIMES
+#include <sys/times.h>
+#endif
 
 #include "fpm_config.h"
 
@@ -16,6 +19,7 @@
 #include "fpm_shm_slots.h"
 #include "fpm_status.h"
 #include "fpm_request.h"
+#include "fpm_log.h"
 
 #include "zlog.h"
 
@@ -42,6 +46,10 @@ void fpm_request_reading_headers() /* {{{ */
 	slot->request_stage = FPM_REQUEST_READING_HEADERS;
 	fpm_clock_get(&slot->tv);
 	slot->accepted = slot->tv;
+	slot->accepted_epoch = time(NULL);
+#ifdef HAVE_TIMES
+	times(&slot->cpu_accepted);
+#endif
 	fpm_shm_slots_release(slot);
 
 	fpm_status_increment_accepted_conn(fpm_status_shm);
@@ -55,6 +63,8 @@ void fpm_request_info() /* {{{ */
 	char *request_uri = fpm_php_request_uri(TSRMLS_C);
 	char *request_method = fpm_php_request_method(TSRMLS_C);
 	char *script_filename = fpm_php_script_filename(TSRMLS_C);
+	char *query_string = fpm_php_query_string(TSRMLS_C);
+	char *auth_user = fpm_php_auth_user(TSRMLS_C);
 
 	slot = fpm_shm_slots_acquire(0, 0);
 	slot->request_stage = FPM_REQUEST_INFO;
@@ -68,6 +78,14 @@ void fpm_request_info() /* {{{ */
 		strlcpy(slot->request_method, request_method, sizeof(slot->request_method));
 	}
 
+	if (query_string) {
+		strlcpy(slot->query_string, query_string, sizeof(slot->query_string));
+	}
+
+	if (auth_user) {
+		strlcpy(slot->auth_user, auth_user, sizeof(slot->auth_user));
+	}
+
 	slot->content_length = fpm_php_content_length(TSRMLS_C);
 
 	/* if cgi.fix_pathinfo is set to "1" and script cannot be found (404)
@@ -91,6 +109,22 @@ void fpm_request_executing() /* {{{ */
 }
 /* }}} */
 
+void fpm_request_end(TSRMLS_D) /* {{{ */
+{
+	struct fpm_shm_slot_s *slot;
+
+	slot = fpm_shm_slots_acquire(0, 0);
+	slot->request_stage = FPM_REQUEST_FINISHED;
+	fpm_clock_get(&slot->tv);
+#ifdef HAVE_TIMES
+	times(&slot->cpu_finished);
+	timersub(&slot->tv, &slot->accepted, &slot->cpu_duration);
+#endif
+	slot->memory = zend_memory_peak_usage(1 TSRMLS_CC);
+	fpm_shm_slots_release(slot);
+}
+/* }}} */
+
 void fpm_request_finished() /* {{{ */
 {
 	struct fpm_shm_slot_s *slot;
@@ -99,6 +133,7 @@ void fpm_request_finished() /* {{{ */
 	slot->request_stage = FPM_REQUEST_FINISHED;
 	fpm_clock_get(&slot->tv);
 	memset(&slot->accepted, 0, sizeof(slot->accepted));
+	slot->accepted_epoch = 0;
 	fpm_shm_slots_release(slot);
 }
 /* }}} */
@@ -125,7 +160,7 @@ void fpm_request_check_timed_out(struct fpm_child_s *child, struct timeval *now,
 	}
 #endif
 
-	if (slot_c.request_stage > FPM_REQUEST_ACCEPTING && slot_c.request_stage < FPM_REQUEST_FINISHED) {
+	if (slot_c.request_stage > FPM_REQUEST_ACCEPTING && slot_c.request_stage < FPM_REQUEST_END) {
 		char purified_script_filename[sizeof(slot_c.script_filename)];
 		struct timeval tv;
 
diff --git a/sapi/fpm/fpm/fpm_request.h b/sapi/fpm/fpm/fpm_request.h
index 7bc9bc8427..b3014a5f1d 100644
--- a/sapi/fpm/fpm/fpm_request.h
+++ b/sapi/fpm/fpm/fpm_request.h
@@ -9,7 +9,8 @@ void fpm_request_accepting();				/* hanging in accept() */
 void fpm_request_reading_headers();			/* start reading fastcgi request from very first byte */
 void fpm_request_info();					/* not a stage really but a point in the php code, where all request params have become known to sapi */
 void fpm_request_executing();				/* the script is executing */
-void fpm_request_finished();				/* request processed: script response have been sent to web server */
+void fpm_request_end(TSRMLS_D);				/* request ended: script response have been sent to web server */
+void fpm_request_finished();				/* request processed: cleaning current request */
 
 struct fpm_child_s;
 struct timeval;
@@ -22,6 +23,7 @@ enum fpm_request_stage_e {
 	FPM_REQUEST_READING_HEADERS,
 	FPM_REQUEST_INFO,
 	FPM_REQUEST_EXECUTING,
+	FPM_REQUEST_END,
 	FPM_REQUEST_FINISHED
 };
 
diff --git a/sapi/fpm/fpm/fpm_shm_slots.h b/sapi/fpm/fpm/fpm_shm_slots.h
index d74f176229..03303848e9 100644
--- a/sapi/fpm/fpm/fpm_shm_slots.h
+++ b/sapi/fpm/fpm/fpm_shm_slots.h
@@ -5,6 +5,10 @@
 #ifndef FPM_SHM_SLOTS_H
 #define FPM_SHM_SLOTS_H 1
 
+#ifdef HAVE_TIMES
+#include <sys/times.h>
+#endif
+
 #include "fpm_atomic.h"
 #include "fpm_worker_pool.h"
 #include "fpm_request.h"
@@ -18,11 +22,20 @@ struct fpm_shm_slot_s {
 	};
 	enum fpm_request_stage_e request_stage;
 	struct timeval accepted;
+	time_t accepted_epoch;
 	struct timeval tv;
 	char request_uri[128];
+	char query_string[512];
 	char request_method[16];
 	size_t content_length; /* used with POST only */
 	char script_filename[256];
+	char auth_user[32];
+#ifdef HAVE_TIMES
+	struct tms cpu_accepted;
+	struct tms cpu_finished;
+	struct timeval cpu_duration;
+#endif
+	size_t memory;
 };
 
 struct fpm_shm_slot_ptr_s {
diff --git a/sapi/fpm/fpm/fpm_status.c b/sapi/fpm/fpm/fpm_status.c
index 22ad159478..63f15d6e97 100644
--- a/sapi/fpm/fpm/fpm_status.c
+++ b/sapi/fpm/fpm/fpm_status.c
@@ -9,6 +9,7 @@
 #include "fpm_config.h"
 #include "fpm_status.h"
 #include "fpm_clock.h"
+#include "fpm_shm_slots.h"
 #include "zlog.h"
 
 struct fpm_shm_s *fpm_status_shm = NULL;
diff --git a/sapi/fpm/fpm/fpm_worker_pool.c b/sapi/fpm/fpm/fpm_worker_pool.c
index 53e3368fa7..e799e35026 100644
--- a/sapi/fpm/fpm/fpm_worker_pool.c
+++ b/sapi/fpm/fpm/fpm_worker_pool.c
@@ -55,6 +55,7 @@ struct fpm_worker_pool_s *fpm_worker_pool_alloc() /* {{{ */
 	fpm_array_init(&ret->slots_used, sizeof(struct fpm_shm_slot_ptr_s), 50);
 	fpm_array_init(&ret->slots_free, sizeof(struct fpm_shm_slot_ptr_s), 50);
 	ret->idle_spawn_rate = 1;
+	ret->log_fd = -1;
 	return ret;
 }
 /* }}} */
diff --git a/sapi/fpm/fpm/fpm_worker_pool.h b/sapi/fpm/fpm/fpm_worker_pool.h
index 7f240a20c2..e014255cf1 100644
--- a/sapi/fpm/fpm/fpm_worker_pool.h
+++ b/sapi/fpm/fpm/fpm_worker_pool.h
@@ -39,6 +39,7 @@ struct fpm_worker_pool_s {
 	int idle_spawn_rate;
 	int warn_max_children;
 	struct fpm_shm_s *shm_status;
+	int log_fd;
 };
 
 struct fpm_worker_pool_s *fpm_worker_pool_alloc();
diff --git a/sapi/fpm/php-fpm.conf.in b/sapi/fpm/php-fpm.conf.in
index 499eafcb66..c3b0627cd1 100644
--- a/sapi/fpm/php-fpm.conf.in
+++ b/sapi/fpm/php-fpm.conf.in
@@ -232,6 +232,65 @@ pm.max_children = 50
 ; response is formatted as text/plain with a 200 response code.
 ; Default Value: pong
 ;ping.response = pong
+
+; The access log file
+; Default: not set
+;access.log = log/$pool.access.log
+
+; The access log format.
+; The following syntax is allowed
+;  %%: the '%' character
+;  %C: %CPU used by the request
+;      it can accept the following format:
+;      - %{user}C for user CPU only
+;      - %{system}C for system CPU only
+;      - %{total}C  for user + system CPU (default)
+;  %d: time taken to serve the request
+;      it can accept the following format:
+;      - %{seconds}d (default)
+;      - %{miliseconds}d
+;      - %{mili}d
+;      - %{microseconds}d
+;      - %{micro}d
+;  %e: an environment variable (same as $_ENV or $_SERVER)
+;      it must be associated with embraces to specify the name of the env
+;      variable. Some exemples:
+;      - server specifics like: %{REQUEST_METHOD}e or %{SERVER_PROTOCOL}e
+;      - HTTP headers like: %{HTTP_HOST}e or %{HTTP_USER_AGENT}e
+;  %f: script filename
+:  %l: content-length of the request (for POST request only)
+;  %m: request method
+;  %M: peak of memory allocated by PHP
+;      it can accept the following format:
+;      - %{bytes}M (default)
+;      - %{kilobytes}M
+;      - %{kilo}M
+;      - %{megabytes}M
+;      - %{mega}M
+;  %n: pool name
+;  %o: ouput header
+;      it must be associated with embraces to specify the name of the header:
+;      - %{Content-Type}o
+;      - %{X-Powered-By}o
+;      - %{Transfert-Encoding}o
+;      - ....
+;  %p: PID of the child that serviced the request
+;  %P: PID of the parent of the child that serviced the request
+;  %q: the query string 
+;  %Q: the '?' character if query string exists
+;  %r: the request URI (without the query string, see %q and %Q)
+;  %R: remote IP address
+;  %s: status (response code)
+;  %t: server time the request was received
+;      it can accept a strftime(3) format:
+;      %d/%b/%Y:%H:%M:%S %z (default)
+;  %T: time the log has been written (the request has finished)
+;      it can accept a strftime(3) format:
+;      %d/%b/%Y:%H:%M:%S %z (default)
+;  %u: remote user
+;
+; Default: "%R - %u %t \"%m %r\" %s"
+;access.format = "%R - %u %t \"%m %r%Q%q\" %s %f %{mili}d %{kilo}M %C%%"
  
 ; The timeout for serving a single request after which the worker process will
 ; be killed. This option should be used when the 'max_execution_time' ini option