Back to index

php5  5.3.10
fpm_log.c
Go to the documentation of this file.
00001 
00002        /* $Id: fpm_status.c 312262 2011-06-18 17:41:56Z felipe $ */
00003        /* (c) 2009 Jerome Loyet */
00004 
00005 #include "php.h"
00006 #include "SAPI.h"
00007 #include <stdio.h>
00008 #include <unistd.h>
00009 #include <fcntl.h>
00010 
00011 #ifdef HAVE_TIMES
00012 #include <sys/times.h>
00013 #endif
00014 
00015 #include "fpm_config.h"
00016 #include "fpm_log.h"
00017 #include "fpm_clock.h"
00018 #include "fpm_process_ctl.h"
00019 #include "fpm_signals.h"
00020 #include "fpm_scoreboard.h"
00021 #include "fastcgi.h"
00022 #include "zlog.h"
00023 
00024 #ifdef MAX_LINE_LENGTH
00025 # define FPM_LOG_BUFFER MAX_LINE_LENGTH
00026 #else
00027 # define FPM_LOG_BUFFER 1024
00028 #endif
00029 
00030 static char *fpm_log_format = NULL;
00031 static int fpm_log_fd = -1;
00032 
00033 int fpm_log_open(int reopen) /* {{{ */
00034 {
00035        struct fpm_worker_pool_s *wp;
00036        int ret = 1;
00037        
00038        int fd;
00039        for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
00040               if (!wp->config->access_log) {
00041                      continue;
00042               }
00043               ret = 0;
00044               
00045               fd = open(wp->config->access_log, O_WRONLY | O_APPEND | O_CREAT, S_IRUSR | S_IWUSR);
00046               if (0 > fd) {
00047                      zlog(ZLOG_SYSERROR, "failed to open access log (%s)", wp->config->access_log);
00048                      return -1;
00049               }
00050 
00051               if (reopen) {
00052                      dup2(fd, wp->log_fd);
00053                      close(fd);
00054                      fd = wp->log_fd;
00055                      fpm_pctl_kill_all(SIGQUIT);
00056               } else {
00057                      wp->log_fd = fd;
00058               }
00059 
00060               fcntl(fd, F_SETFD, fcntl(fd, F_GETFD) | FD_CLOEXEC);
00061        }
00062 
00063        return ret;
00064 }
00065 /* }}} */
00066 
00067 /* }}} */
00068 int fpm_log_init_child(struct fpm_worker_pool_s *wp)  /* {{{ */
00069 {
00070        if (!wp || !wp->config) {
00071               return -1;
00072        }
00073 
00074        if (wp->config->access_log && *wp->config->access_log) {
00075               if (wp->config->access_format) {
00076                      fpm_log_format = strdup(wp->config->access_format);
00077               }
00078        }
00079 
00080        if (fpm_log_fd == -1) {
00081               fpm_log_fd = wp->log_fd;
00082        }
00083 
00084 
00085        for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
00086               if (wp->log_fd > -1 && wp->log_fd != fpm_log_fd) {
00087                      close(wp->log_fd);
00088                      wp->log_fd = -1;
00089               }
00090        }
00091 
00092        return 0;
00093 }
00094 /* }}} */
00095 
00096 int fpm_log_write(char *log_format TSRMLS_DC) /* {{{ */
00097 {
00098        char *s, *b;
00099        char buffer[FPM_LOG_BUFFER];
00100        int token, test;
00101        size_t len, len2;
00102        struct fpm_scoreboard_proc_s proc, *proc_p;
00103        struct fpm_scoreboard_s *scoreboard;
00104        char tmp[129];
00105        char format[129];
00106        time_t now_epoch;
00107 #ifdef HAVE_TIMES
00108        clock_t tms_total;
00109 #endif
00110 
00111        if (!log_format && (!fpm_log_format || fpm_log_fd == -1)) {
00112               return -1;
00113        }
00114 
00115        if (!log_format) {
00116               log_format = fpm_log_format;
00117               test = 0;
00118        } else {
00119               test = 1;
00120        }
00121 
00122        now_epoch = time(NULL);
00123 
00124        if (!test) {
00125               scoreboard = fpm_scoreboard_get();
00126               if (!scoreboard) {
00127                      zlog(ZLOG_WARNING, "unable to get scoreboard while preparing the access log");
00128                      return -1;
00129               }
00130               proc_p = fpm_scoreboard_proc_acquire(NULL, -1, 0);
00131               if (!proc_p) {
00132                      zlog(ZLOG_WARNING, "[pool %s] Unable to acquire shm slot while preparing the access log", scoreboard->pool);
00133                      return -1;
00134               }
00135               proc = *proc_p;
00136               fpm_scoreboard_proc_release(proc_p);
00137        }
00138 
00139        token = 0;
00140 
00141        memset(buffer, '\0', sizeof(buffer));
00142        b = buffer;
00143        len = 0;
00144 
00145 
00146        s = log_format;
00147 
00148        while (*s != '\0') {
00149               if (len > FPM_LOG_BUFFER) {
00150                      zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
00151                      len = FPM_LOG_BUFFER - 1;
00152                      break;
00153               }
00154 
00155               if (!token && *s == '%') {
00156                      token = 1;
00157                      memset(format, '\0', sizeof(format)); /* reset format */
00158                      s++;
00159                      continue;
00160               }
00161 
00162               if (token) {
00163                      token = 0;
00164                      len2 = 0;
00165                      switch (*s) {
00166 
00167                             case '%': /* '%' */
00168                                    *b = '%';
00169                                    len2 = 1;
00170                                    break;
00171 
00172 #ifdef HAVE_TIMES
00173                             case 'C': /* %CPU */
00174                                    if (format[0] == '\0' || !strcasecmp(format, "total")) {
00175                                           if (!test) {
00176                                                  tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cutime + proc.last_request_cpu.tms_cstime;
00177                                           }
00178                                    } else if (!strcasecmp(format, "user")) {
00179                                           if (!test) {
00180                                                  tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_cutime;
00181                                           }
00182                                    } else if (!strcasecmp(format, "system")) {
00183                                           if (!test) {
00184                                                  tms_total = proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cstime;
00185                                           }
00186                                    } else {
00187                                           zlog(ZLOG_WARNING, "only 'total', 'user' or 'system' are allowed as a modifier for %%%c ('%s')", *s, format);
00188                                           return -1;
00189                                    }
00190 
00191                                    format[0] = '\0';
00192                                    if (!test) {
00193                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.2f", tms_total / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.cpu_duration.tv_usec / 1000000.) * 100.);
00194                                    }
00195                                    break;
00196 #endif
00197 
00198                             case 'd': /* duration ┬Ás */
00199                                    /* seconds */
00200                                    if (format[0] == '\0' || !strcasecmp(format, "seconds")) {
00201                                           if (!test) {
00202                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.);
00203                                           }
00204 
00205                                    /* miliseconds */
00206                                    } else if (!strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")) {
00207                                           if (!test) {
00208                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
00209                                           }
00210 
00211                                    /* microseconds */
00212                                    } else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
00213                                           if (!test) {
00214                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec);
00215                                           }
00216 
00217                                    } else {
00218                                           zlog(ZLOG_WARNING, "only 'seconds', 'mili', 'miliseconds', 'micro' or 'microseconds' are allowed as a modifier for %%%c ('%s')", *s, format);
00219                                           return -1;
00220                                    }
00221                                    format[0] = '\0';
00222                                    break;
00223 
00224                             case 'e': /* fastcgi env  */
00225                                    if (format[0] == '\0') {
00226                                           zlog(ZLOG_WARNING, "the name of the environment variable must be set between embraces for %%%c", *s);
00227                                           return -1;
00228                                    }
00229 
00230                                    if (!test) {
00231                                           char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format));
00232                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-");
00233                                    }
00234                                    format[0] = '\0';
00235                                    break;
00236 
00237                             case 'f': /* script */
00238                                    if (!test) {
00239                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s",  proc.script_filename && *proc.script_filename ? proc.script_filename : "-");
00240                                    }
00241                                    break;
00242 
00243                             case 'l': /* content length */
00244                                    if (!test) {
00245                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length);
00246                                    }
00247                                    break;
00248 
00249                             case 'm': /* method */
00250                                    if (!test) {
00251                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_method && *proc.request_method ? proc.request_method : "-");
00252                                    }
00253                                    break;
00254 
00255                             case 'M': /* memory */
00256                                    /* seconds */
00257                                    if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
00258                                           if (!test) {
00259                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory);
00260                                           }
00261 
00262                                    /* kilobytes */
00263                                    } else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
00264                                           if (!test) {
00265                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.memory / 1024);
00266                                           }
00267 
00268                                    /* megabytes */
00269                                    } else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
00270                                           if (!test) {
00271                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.memory / 1024 / 1024);
00272                                           }
00273 
00274                                    } else {
00275                                           zlog(ZLOG_WARNING, "only 'bytes', 'kilo', 'kilobytes', 'mega' or 'megabytes' are allowed as a modifier for %%%c ('%s')", *s, format);
00276                                           return -1;
00277                                    }
00278                                    format[0] = '\0';
00279                                    break;
00280 
00281                             case 'n': /* pool name */
00282                                    if (!test) {
00283                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", scoreboard->pool[0] ? scoreboard->pool : "-");
00284                                    }
00285                                    break;
00286 
00287                             case 'o': /* header output  */
00288                                    if (format[0] == '\0') {
00289                                           zlog(ZLOG_WARNING, "the name of the header must be set between embraces for %%%c", *s);
00290                                           return -1;
00291                                    }
00292                                    if (!test) {
00293                                           sapi_header_struct *h;
00294                                           zend_llist_position pos;
00295                                           sapi_headers_struct *sapi_headers = &SG(sapi_headers);
00296                                           size_t format_len = strlen(format);
00297 
00298                                           h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos);
00299                                           while (h) {
00300                                                  char *header;
00301                                                  if (!h->header_len) {
00302                                                         h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
00303                                                         continue;
00304                                                  }
00305                                                  if (!strstr(h->header, format)) {
00306                                                         h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
00307                                                         continue;
00308                                                  }
00309 
00310                                                  /* test if enought char after the header name + ': ' */
00311                                                  if (h->header_len <= format_len + 2) {
00312                                                         h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
00313                                                         continue;
00314                                                  }
00315 
00316                                                  if (h->header[format_len] != ':' || h->header[format_len + 1] != ' ') {
00317                                                         h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
00318                                                         continue;
00319                                                  }
00320 
00321                                                  header = h->header + format_len + 2;
00322                                                  len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-");
00323 
00324                                                  /* found, done */
00325                                                  break;
00326                                           }
00327                                           if (!len2) {
00328                                                  len2 = 1;
00329                                                  *b = '-';
00330                                           }
00331                                    }
00332                                    format[0] = '\0';
00333                                    break;
00334 
00335                             case 'p': /* PID */
00336                                    if (!test) {
00337                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid());
00338                                    }
00339                                    break;
00340 
00341                             case 'P': /* PID */
00342                                    if (!test) {
00343                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid());
00344                                    }
00345                                    break;
00346 
00347                             case 'q': /* query_string */
00348                                    if (!test) {
00349                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string ? proc.query_string : "");
00350                                    }
00351                                    break;
00352 
00353                             case 'Q': /* '?' */
00354                                    if (!test) {
00355                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string && *proc.query_string  ? "?" : "");
00356                                    }
00357                                    break;
00358 
00359                             case 'r': /* request URI */
00360                                    if (!test) {
00361                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri ? proc.request_uri : "-");
00362                                    }
00363                                    break;
00364 
00365                             case 'R': /* remote IP address */
00366                                    if (!test) {
00367                                           char *tmp = fcgi_get_last_client_ip();
00368                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-");
00369                                    }
00370                                    break;
00371 
00372                             case 's': /* status */
00373                                    if (!test) {
00374                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code);
00375                                    }
00376                                    break;
00377 
00378                             case 'T':
00379                             case 't': /* time */
00380                                    if (!test) {
00381                                           time_t *t;
00382                                           if (*s == 't') {
00383                                                  t = &proc.accepted_epoch;
00384                                           } else {
00385                                                  t = &now_epoch;
00386                                           }
00387                                           if (format[0] == '\0') {
00388                                                  strftime(tmp, sizeof(tmp) - 1, "%d/%b/%Y:%H:%M:%S %z", localtime(t));
00389                                           } else {
00390                                                  strftime(tmp, sizeof(tmp) - 1, format, localtime(t));
00391                                           }
00392                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp);
00393                                    }
00394                                    format[0] = '\0';
00395                                    break;
00396 
00397                             case 'u': /* remote user */
00398                                    if (!test) {
00399                                           len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.auth_user ? proc.auth_user : "-");
00400                                    }
00401                                    break;
00402 
00403                             case '{': /* complex var */
00404                                    token = 1;
00405                                    {
00406                                           char *start;
00407                                           size_t l;
00408                                           
00409                                           start = ++s;
00410 
00411                                           while (*s != '\0') {
00412                                                  if (*s == '}') {
00413                                                         l = s - start;
00414 
00415                                                         if (l >= sizeof(format) - 1) {
00416                                                                l = sizeof(format) - 1;
00417                                                         }
00418 
00419                                                         memcpy(format, start, l);
00420                                                         format[l] = '\0';
00421                                                         break;
00422                                                  }
00423                                                  s++;
00424                                           }
00425                                           if (s[1] == '\0') {
00426                                                  zlog(ZLOG_WARNING, "missing closing embrace in the access.format");
00427                                                  return -1;
00428                                           }
00429                                    }
00430                                    break;
00431 
00432                             default:
00433                                    zlog(ZLOG_WARNING, "Invalid token in the access.format (%%%c)", *s);
00434                                    return -1;
00435                      }
00436 
00437                      if (*s != '}' && format[0] != '\0') {
00438                             zlog(ZLOG_WARNING, "embrace is not allowed for modifier %%%c", *s);
00439                             return -1;
00440                      }
00441                      s++;
00442                      if (!test) {
00443                             b += len2;
00444                             len += len2;
00445                      }
00446                      continue;
00447               }
00448 
00449               if (!test) {
00450                      // push the normal char to the output buffer
00451                      *b = *s;
00452                      b++;
00453                      len++;
00454               }
00455               s++;
00456        }
00457 
00458        if (!test && strlen(buffer) > 0) {
00459               buffer[len] = '\n';
00460               write(fpm_log_fd, buffer, len + 1);
00461        }
00462 
00463        return 0;
00464 }
00465 /* }}} */