xref: /PHP-5.4/sapi/fpm/fpm/fpm_log.c (revision 0549e55d)
1 
2 	/* $Id: fpm_status.c 312262 2011-06-18 17:41:56Z felipe $ */
3 	/* (c) 2009 Jerome Loyet */
4 
5 #include "php.h"
6 #include "SAPI.h"
7 #include <stdio.h>
8 #include <unistd.h>
9 #include <fcntl.h>
10 
11 #ifdef HAVE_TIMES
12 #include <sys/times.h>
13 #endif
14 
15 #include "fpm_config.h"
16 #include "fpm_log.h"
17 #include "fpm_clock.h"
18 #include "fpm_process_ctl.h"
19 #include "fpm_signals.h"
20 #include "fpm_scoreboard.h"
21 #include "fastcgi.h"
22 #include "zlog.h"
23 
24 #ifdef MAX_LINE_LENGTH
25 # define FPM_LOG_BUFFER MAX_LINE_LENGTH
26 #else
27 # define FPM_LOG_BUFFER 1024
28 #endif
29 
30 static char *fpm_log_format = NULL;
31 static int fpm_log_fd = -1;
32 
fpm_log_open(int reopen)33 int fpm_log_open(int reopen) /* {{{ */
34 {
35 	struct fpm_worker_pool_s *wp;
36 	int ret = 1;
37 
38 	int fd;
39 	for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
40 		if (!wp->config->access_log) {
41 			continue;
42 		}
43 		ret = 0;
44 
45 		fd = open(wp->config->access_log, O_WRONLY | O_APPEND | O_CREAT, S_IRUSR | S_IWUSR);
46 		if (0 > fd) {
47 			zlog(ZLOG_SYSERROR, "failed to open access log (%s)", wp->config->access_log);
48 			return -1;
49 		}
50 
51 		if (reopen) {
52 			dup2(fd, wp->log_fd);
53 			close(fd);
54 			fd = wp->log_fd;
55 			fpm_pctl_kill_all(SIGQUIT);
56 		} else {
57 			wp->log_fd = fd;
58 		}
59 
60 		if (0 > fcntl(fd, F_SETFD, fcntl(fd, F_GETFD) | FD_CLOEXEC)) {
61 			zlog(ZLOG_WARNING, "failed to change attribute of access_log");
62 		}
63 	}
64 
65 	return ret;
66 }
67 /* }}} */
68 
69 /* }}} */
fpm_log_init_child(struct fpm_worker_pool_s * wp)70 int fpm_log_init_child(struct fpm_worker_pool_s *wp)  /* {{{ */
71 {
72 	if (!wp || !wp->config) {
73 		return -1;
74 	}
75 
76 	if (wp->config->access_log && *wp->config->access_log) {
77 		if (wp->config->access_format) {
78 			fpm_log_format = strdup(wp->config->access_format);
79 		}
80 	}
81 
82 	if (fpm_log_fd == -1) {
83 		fpm_log_fd = wp->log_fd;
84 	}
85 
86 
87 	for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
88 		if (wp->log_fd > -1 && wp->log_fd != fpm_log_fd) {
89 			close(wp->log_fd);
90 			wp->log_fd = -1;
91 		}
92 	}
93 
94 	return 0;
95 }
96 /* }}} */
97 
fpm_log_write(char * log_format TSRMLS_DC)98 int fpm_log_write(char *log_format TSRMLS_DC) /* {{{ */
99 {
100 	char *s, *b;
101 	char buffer[FPM_LOG_BUFFER+1];
102 	int token, test;
103 	size_t len, len2;
104 	struct fpm_scoreboard_proc_s proc, *proc_p;
105 	struct fpm_scoreboard_s *scoreboard;
106 	char tmp[129];
107 	char format[129];
108 	time_t now_epoch;
109 #ifdef HAVE_TIMES
110 	clock_t tms_total;
111 #endif
112 
113 	if (!log_format && (!fpm_log_format || fpm_log_fd == -1)) {
114 		return -1;
115 	}
116 
117 	if (!log_format) {
118 		log_format = fpm_log_format;
119 		test = 0;
120 	} else {
121 		test = 1;
122 	}
123 
124 	now_epoch = time(NULL);
125 
126 	if (!test) {
127 		scoreboard = fpm_scoreboard_get();
128 		if (!scoreboard) {
129 			zlog(ZLOG_WARNING, "unable to get scoreboard while preparing the access log");
130 			return -1;
131 		}
132 		proc_p = fpm_scoreboard_proc_acquire(NULL, -1, 0);
133 		if (!proc_p) {
134 			zlog(ZLOG_WARNING, "[pool %s] Unable to acquire shm slot while preparing the access log", scoreboard->pool);
135 			return -1;
136 		}
137 		proc = *proc_p;
138 		fpm_scoreboard_proc_release(proc_p);
139 	}
140 
141 	token = 0;
142 
143 	memset(buffer, '\0', sizeof(buffer));
144 	b = buffer;
145 	len = 0;
146 
147 
148 	s = log_format;
149 
150 	while (*s != '\0') {
151 		/* Test is we have place for 1 more char. */
152 		if (len >= FPM_LOG_BUFFER) {
153 			zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
154 			len = FPM_LOG_BUFFER;
155 			break;
156 		}
157 
158 		if (!token && *s == '%') {
159 			token = 1;
160 			memset(format, '\0', sizeof(format)); /* reset format */
161 			s++;
162 			continue;
163 		}
164 
165 		if (token) {
166 			token = 0;
167 			len2 = 0;
168 			switch (*s) {
169 
170 				case '%': /* '%' */
171 					*b = '%';
172 					len2 = 1;
173 					break;
174 
175 #ifdef HAVE_TIMES
176 				case 'C': /* %CPU */
177 					if (format[0] == '\0' || !strcasecmp(format, "total")) {
178 						if (!test) {
179 							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;
180 						}
181 					} else if (!strcasecmp(format, "user")) {
182 						if (!test) {
183 							tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_cutime;
184 						}
185 					} else if (!strcasecmp(format, "system")) {
186 						if (!test) {
187 							tms_total = proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cstime;
188 						}
189 					} else {
190 						zlog(ZLOG_WARNING, "only 'total', 'user' or 'system' are allowed as a modifier for %%%c ('%s')", *s, format);
191 						return -1;
192 					}
193 
194 					format[0] = '\0';
195 					if (!test) {
196 						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.);
197 					}
198 					break;
199 #endif
200 
201 				case 'd': /* duration µs */
202 					/* seconds */
203 					if (format[0] == '\0' || !strcasecmp(format, "seconds")) {
204 						if (!test) {
205 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.);
206 						}
207 
208 					/* miliseconds */
209 					} else if (!strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")) {
210 						if (!test) {
211 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
212 						}
213 
214 					/* microseconds */
215 					} else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
216 						if (!test) {
217 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec);
218 						}
219 
220 					} else {
221 						zlog(ZLOG_WARNING, "only 'seconds', 'mili', 'miliseconds', 'micro' or 'microseconds' are allowed as a modifier for %%%c ('%s')", *s, format);
222 						return -1;
223 					}
224 					format[0] = '\0';
225 					break;
226 
227 				case 'e': /* fastcgi env  */
228 					if (format[0] == '\0') {
229 						zlog(ZLOG_WARNING, "the name of the environment variable must be set between embraces for %%%c", *s);
230 						return -1;
231 					}
232 
233 					if (!test) {
234 						char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format));
235 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-");
236 					}
237 					format[0] = '\0';
238 					break;
239 
240 				case 'f': /* script */
241 					if (!test) {
242 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s",  *proc.script_filename ? proc.script_filename : "-");
243 					}
244 					break;
245 
246 				case 'l': /* content length */
247 					if (!test) {
248 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length);
249 					}
250 					break;
251 
252 				case 'm': /* method */
253 					if (!test) {
254 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.request_method ? proc.request_method : "-");
255 					}
256 					break;
257 
258 				case 'M': /* memory */
259 					/* seconds */
260 					if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
261 						if (!test) {
262 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory);
263 						}
264 
265 					/* kilobytes */
266 					} else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
267 						if (!test) {
268 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.memory / 1024);
269 						}
270 
271 					/* megabytes */
272 					} else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
273 						if (!test) {
274 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.memory / 1024 / 1024);
275 						}
276 
277 					} else {
278 						zlog(ZLOG_WARNING, "only 'bytes', 'kilo', 'kilobytes', 'mega' or 'megabytes' are allowed as a modifier for %%%c ('%s')", *s, format);
279 						return -1;
280 					}
281 					format[0] = '\0';
282 					break;
283 
284 				case 'n': /* pool name */
285 					if (!test) {
286 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", scoreboard->pool[0] ? scoreboard->pool : "-");
287 					}
288 					break;
289 
290 				case 'o': /* header output  */
291 					if (format[0] == '\0') {
292 						zlog(ZLOG_WARNING, "the name of the header must be set between embraces for %%%c", *s);
293 						return -1;
294 					}
295 					if (!test) {
296 						sapi_header_struct *h;
297 						zend_llist_position pos;
298 						sapi_headers_struct *sapi_headers = &SG(sapi_headers);
299 						size_t format_len = strlen(format);
300 
301 						h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos);
302 						while (h) {
303 							char *header;
304 							if (!h->header_len) {
305 								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
306 								continue;
307 							}
308 							if (!strstr(h->header, format)) {
309 								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
310 								continue;
311 							}
312 
313 							/* test if enought char after the header name + ': ' */
314 							if (h->header_len <= format_len + 2) {
315 								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
316 								continue;
317 							}
318 
319 							if (h->header[format_len] != ':' || h->header[format_len + 1] != ' ') {
320 								h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
321 								continue;
322 							}
323 
324 							header = h->header + format_len + 2;
325 							len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-");
326 
327 							/* found, done */
328 							break;
329 						}
330 						if (!len2) {
331 							len2 = 1;
332 							*b = '-';
333 						}
334 					}
335 					format[0] = '\0';
336 					break;
337 
338 				case 'p': /* PID */
339 					if (!test) {
340 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid());
341 					}
342 					break;
343 
344 				case 'P': /* PID */
345 					if (!test) {
346 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid());
347 					}
348 					break;
349 
350 				case 'q': /* query_string */
351 					if (!test) {
352 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string);
353 					}
354 					break;
355 
356 				case 'Q': /* '?' */
357 					if (!test) {
358 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.query_string  ? "?" : "");
359 					}
360 					break;
361 
362 				case 'r': /* request URI */
363 					if (!test) {
364 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri);
365 					}
366 					break;
367 
368 				case 'R': /* remote IP address */
369 					if (!test) {
370 						char *tmp = fcgi_get_last_client_ip();
371 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-");
372 					}
373 					break;
374 
375 				case 's': /* status */
376 					if (!test) {
377 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code);
378 					}
379 					break;
380 
381 				case 'T':
382 				case 't': /* time */
383 					if (!test) {
384 						time_t *t;
385 						if (*s == 't') {
386 							t = &proc.accepted_epoch;
387 						} else {
388 							t = &now_epoch;
389 						}
390 						if (format[0] == '\0') {
391 							strftime(tmp, sizeof(tmp) - 1, "%d/%b/%Y:%H:%M:%S %z", localtime(t));
392 						} else {
393 							strftime(tmp, sizeof(tmp) - 1, format, localtime(t));
394 						}
395 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp);
396 					}
397 					format[0] = '\0';
398 					break;
399 
400 				case 'u': /* remote user */
401 					if (!test) {
402 						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.auth_user);
403 					}
404 					break;
405 
406 				case '{': /* complex var */
407 					token = 1;
408 					{
409 						char *start;
410 						size_t l;
411 
412 						start = ++s;
413 
414 						while (*s != '\0') {
415 							if (*s == '}') {
416 								l = s - start;
417 
418 								if (l >= sizeof(format) - 1) {
419 									l = sizeof(format) - 1;
420 								}
421 
422 								memcpy(format, start, l);
423 								format[l] = '\0';
424 								break;
425 							}
426 							s++;
427 						}
428 						if (s[1] == '\0') {
429 							zlog(ZLOG_WARNING, "missing closing embrace in the access.format");
430 							return -1;
431 						}
432 					}
433 					break;
434 
435 				default:
436 					zlog(ZLOG_WARNING, "Invalid token in the access.format (%%%c)", *s);
437 					return -1;
438 			}
439 
440 			if (*s != '}' && format[0] != '\0') {
441 				zlog(ZLOG_WARNING, "embrace is not allowed for modifier %%%c", *s);
442 				return -1;
443 			}
444 			s++;
445 			if (!test) {
446 				b += len2;
447 				len += len2;
448 			}
449 			continue;
450 		}
451 
452 		if (!test) {
453 			// push the normal char to the output buffer
454 			*b = *s;
455 			b++;
456 			len++;
457 		}
458 		s++;
459 	}
460 
461 	if (!test && strlen(buffer) > 0) {
462 		buffer[len] = '\n';
463 		write(fpm_log_fd, buffer, len + 1);
464 	}
465 
466 	return 0;
467 }
468 /* }}} */
469