]> granicus.if.org Git - php/commitdiff
- Added custom access log (also added per request %CPU and memory mesurement)
authorJérôme Loyet <fat@php.net>
Thu, 23 Jun 2011 08:03:52 +0000 (08:03 +0000)
committerJérôme Loyet <fat@php.net>
Thu, 23 Jun 2011 08:03:52 +0000 (08:03 +0000)
22 files changed:
sapi/fpm/config.m4
sapi/fpm/fpm/fastcgi.c
sapi/fpm/fpm/fastcgi.h
sapi/fpm/fpm/fpm.c
sapi/fpm/fpm/fpm_children.c
sapi/fpm/fpm/fpm_conf.c
sapi/fpm/fpm/fpm_conf.h
sapi/fpm/fpm/fpm_events.c
sapi/fpm/fpm/fpm_log.c [new file with mode: 0644]
sapi/fpm/fpm/fpm_log.h [new file with mode: 0644]
sapi/fpm/fpm/fpm_main.c
sapi/fpm/fpm/fpm_php.c
sapi/fpm/fpm/fpm_php.h
sapi/fpm/fpm/fpm_process_ctl.c
sapi/fpm/fpm/fpm_process_ctl.h
sapi/fpm/fpm/fpm_request.c
sapi/fpm/fpm/fpm_request.h
sapi/fpm/fpm/fpm_shm_slots.h
sapi/fpm/fpm/fpm_status.c
sapi/fpm/fpm/fpm_worker_pool.c
sapi/fpm/fpm/fpm_worker_pool.h
sapi/fpm/php-fpm.conf.in

index bb31d3b9b61c35822e4426329f5a3a3c959ae2e4..751f866bb2955c6efffe72f84deccb22edd3aa0c 100644 (file)
@@ -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 \
index a1644ed12e7db786d78a6630dd30e24f4c952d37..00a658721425cbe8406c42f8c4ab8881d33784fa 100644 (file)
@@ -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
index 565fd3fb1a5fcf04ff991986b43c50dbb60ff30e..4129def0502a9cde9c3de518a2755d0f33d3c488 100644 (file)
@@ -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
index e3fa3e3bd694b3192821f06db6e5368dc9f737a3..f80f943910664395ccd8e836adc6cf4372a61005 100644 (file)
@@ -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()             ||
index 476d5523deac518390d6c5898a3381ef66b1713d..d8338725e48c91b00dd55449a16641abd3e490ff 100644 (file)
@@ -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() ||
index a8e2d60e26ec038339ac9c0c415e6c6e84acf2bc..f82806644fd3cc4971bd6df30228cb5ea8d242cc 100644 (file)
@@ -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;
        }
index 64b569006efb438a69e85f577957abd9b8624175..d1087641d38e9faac9a89bfbc7affe19d537bfb4 100644 (file)
@@ -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;
index 2bb4b94c00d57eb8cfe783e2edb1dc0eace4f50c..7ba982bf75c7f6fe552ba0c68fa44e3b3ddb6f2f 100644 (file)
@@ -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 (file)
index 0000000..243ed86
--- /dev/null
@@ -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 (file)
index 0000000..74f8426
--- /dev/null
@@ -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
index cd87ffc29559e267f3c97b8ab8c2d10371cb1c3e..37c932e5b48104da908c3c825c91d5703af21c2e 100644 (file)
@@ -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;
 
index 384682b7e222755b03c9b87303df08bf208a7b32..33b9e410e1fff71d1b374e7b593a6e69f7d893c9 100644 (file)
@@ -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;
index 891e83bfce97c6738753e0029deb16e41bb96672..62a47e7fd37b3698eb520c2239062fcf6c86efe0 100644 (file)
@@ -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();
index badda1408237b1a01bf1f13e2acb873de508044b..bd50c46c297f1bec33b728b70a99038ee944e30e 100644 (file)
@@ -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;
index 36577097cbddc529ed47d76fcbc5ad5de6bb21eb..6bfcfd8c6beb1cfc0dd5c7e834e6cd27801ccc70 100644 (file)
@@ -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();
index 6ba9e5170ca6c72640fade048ca0000bbf441d3f..492e76275be12ba8aeadd8bb08d978a23a079e7f 100644 (file)
@@ -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;
 
index 7bc9bc84270aafa3ea9ff9fb14cacbbf5fd54c36..b3014a5f1dcb0c5240c2dfee3ffdd9e8615f156a 100644 (file)
@@ -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
 };
 
index d74f1762292c009df693de22eeb155114b752f86..03303848e92a7ba544ffc0b242f0a96ce88f9608 100644 (file)
@@ -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 {
index 22ad15947834660b27a77783c5e1819ca83e9cd1..63f15d6e971c7236667c1f72fa0b18070d2c452e 100644 (file)
@@ -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;
index 53e3368fa764305d8e31743df7f4b13fce521836..e799e3502637391594783251b1a24517732f7a12 100644 (file)
@@ -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;
 }
 /* }}} */
index 7f240a20c28464102265c2436ac0a5f9e89d3813..e014255cf148fcaa60e8c44f6f9102f4cde291e9 100644 (file)
@@ -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();
index 499eafcb6689e8be3adff32c00ab58089646e05e..c3b0627cd103dd286405ca032f077135071f1f4f 100644 (file)
@@ -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