fpm_log.c

	/* (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_scoreboard.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 int fpm_log_fd = -1;

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, "failed to open access log (%s)", wp->config->access_log);
			return -1;
		} else {
			zlog(ZLOG_DEBUG, "open access log (%s)", wp->config->access_log);
		}

		if (reopen) {
			dup2(fd, wp->log_fd);
			close(fd);
			fd = wp->log_fd;
			fpm_pctl_kill_all(SIGQUIT);
		} else {
			wp->log_fd = fd;
		}

		if (0 > fcntl(fd, F_SETFD, fcntl(fd, F_GETFD) | FD_CLOEXEC)) {
			zlog(ZLOG_WARNING, "failed to change attribute of access_log");
		}
	}

	return ret;
}
/* }}} */

/* }}} */
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 (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) /* {{{ */
{
	char *s, *b;
	char buffer[FPM_LOG_BUFFER+1];
	int token, test;
	size_t len, len2;
	struct fpm_scoreboard_proc_s proc, *proc_p;
	struct fpm_scoreboard_s *scoreboard;
	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;
	}

	now_epoch = time(NULL);

	if (!test) {
		scoreboard = fpm_scoreboard_get();
		if (!scoreboard) {
			zlog(ZLOG_WARNING, "unable to get scoreboard while preparing the access log");
			return -1;
		}
		proc_p = fpm_scoreboard_proc_acquire(NULL, -1, 0);
		if (!proc_p) {
			zlog(ZLOG_WARNING, "[pool %s] Unable to acquire shm slot while preparing the access log", scoreboard->pool);
			return -1;
		}
		proc = *proc_p;
		fpm_scoreboard_proc_release(proc_p);
	}

	token = 0;

	memset(buffer, '\0', sizeof(buffer));
	b = buffer;
	len = 0;


	s = log_format;

	while (*s != '\0') {
		/* Test is we have place for 1 more char. */
		if (len >= FPM_LOG_BUFFER) {
			zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
			len = FPM_LOG_BUFFER;
			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 = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cutime + proc.last_request_cpu.tms_cstime;
						}
					} else if (!strcasecmp(format, "user")) {
						if (!test) {
							tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_cutime;
						}
					} else if (!strcasecmp(format, "system")) {
						if (!test) {
							tms_total = proc.last_request_cpu.tms_stime + proc.last_request_cpu.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 / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.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", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.);
						}

					/* milliseconds */
					} else if (!strcasecmp(format, "milliseconds") || !strcasecmp(format, "milli") ||
						   /* mili/miliseconds are supported for backwards compatibility */
						   !strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")
					) {
						if (!test) {
							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
						}

					/* microseconds */
					} else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
						if (!test) {
							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", (unsigned long)(proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec));
						}

					} else {
						zlog(ZLOG_WARNING, "only 'seconds', 'milli', 'milliseconds', '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",  *proc.script_filename ? proc.script_filename : "-");
					}
					break;

				case 'l': /* content length */
					if (!test) {
						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length);
					}
					break;

				case 'm': /* method */
					if (!test) {
						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.request_method ? proc.request_method : "-");
					}
					break;

				case 'M': /* memory */
					/* seconds */
					if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
						if (!test) {
							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory);
						}

					/* kilobytes */
					} else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
						if (!test) {
							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024);
						}

					/* megabytes */
					} else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
						if (!test) {
							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.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", scoreboard->pool[0] ? scoreboard->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 enough 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", proc.query_string);
					}
					break;

				case 'Q': /* '?' */
					if (!test) {
						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.query_string  ? "?" : "");
					}
					break;

				case 'r': /* request URI */
					if (!test) {
						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri);
					}
					break;

				case 'R': /* remote IP address */
					if (!test) {
						const 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 = &proc.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", proc.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;
			}
			if (len >= FPM_LOG_BUFFER) {
				zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
				len = FPM_LOG_BUFFER;
				break;
			}
			continue;
		}

		if (!test) {
			// push the normal char to the output buffer
			*b = *s;
			b++;
			len++;
		}
		s++;
	}

	if (!test && strlen(buffer) > 0) {
		buffer[len] = '\n';
		zend_quiet_write(fpm_log_fd, buffer, len + 1);
	}

	return 0;
}
/* }}} */