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