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