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