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
fpm_log_open(int reopen)31 int fpm_log_open(int reopen) /* {{{ */
32 {
33 struct fpm_worker_pool_s *wp;
34 int ret = 1;
35
36 int fd;
37 for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
38 if (!wp->config->access_log) {
39 continue;
40 }
41 ret = 0;
42
43 fd = open(wp->config->access_log, O_WRONLY | O_APPEND | O_CREAT, S_IRUSR | S_IWUSR);
44 if (0 > fd) {
45 zlog(ZLOG_SYSERROR, "failed to open access log (%s)", wp->config->access_log);
46 return -1;
47 } else {
48 zlog(ZLOG_DEBUG, "open access log (%s)", wp->config->access_log);
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)98 int fpm_log_write(char *log_format) /* {{{ */
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 /* milliseconds */
209 } else if (!strcasecmp(format, "milliseconds") || !strcasecmp(format, "milli") ||
210 /* mili/miliseconds are supported for backwards compatibility */
211 !strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")
212 ) {
213 if (!test) {
214 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
215 }
216
217 /* microseconds */
218 } else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
219 if (!test) {
220 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", (unsigned long)(proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec));
221 }
222
223 } else {
224 zlog(ZLOG_WARNING, "only 'seconds', 'milli', 'milliseconds', 'micro' or 'microseconds' are allowed as a modifier for %%%c ('%s')", *s, format);
225 return -1;
226 }
227 format[0] = '\0';
228 break;
229
230 case 'e': /* fastcgi env */
231 if (format[0] == '\0') {
232 zlog(ZLOG_WARNING, "the name of the environment variable must be set between embraces for %%%c", *s);
233 return -1;
234 }
235
236 if (!test) {
237 char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format));
238 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-");
239 }
240 format[0] = '\0';
241 break;
242
243 case 'f': /* script */
244 if (!test) {
245 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.script_filename ? proc.script_filename : "-");
246 }
247 break;
248
249 case 'l': /* content length */
250 if (!test) {
251 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length);
252 }
253 break;
254
255 case 'm': /* method */
256 if (!test) {
257 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.request_method ? proc.request_method : "-");
258 }
259 break;
260
261 case 'M': /* memory */
262 /* seconds */
263 if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
264 if (!test) {
265 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory);
266 }
267
268 /* kilobytes */
269 } else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
270 if (!test) {
271 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024);
272 }
273
274 /* megabytes */
275 } else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
276 if (!test) {
277 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024 / 1024);
278 }
279
280 } else {
281 zlog(ZLOG_WARNING, "only 'bytes', 'kilo', 'kilobytes', 'mega' or 'megabytes' are allowed as a modifier for %%%c ('%s')", *s, format);
282 return -1;
283 }
284 format[0] = '\0';
285 break;
286
287 case 'n': /* pool name */
288 if (!test) {
289 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", scoreboard->pool[0] ? scoreboard->pool : "-");
290 }
291 break;
292
293 case 'o': /* header output */
294 if (format[0] == '\0') {
295 zlog(ZLOG_WARNING, "the name of the header must be set between embraces for %%%c", *s);
296 return -1;
297 }
298 if (!test) {
299 sapi_header_struct *h;
300 zend_llist_position pos;
301 sapi_headers_struct *sapi_headers = &SG(sapi_headers);
302 size_t format_len = strlen(format);
303
304 h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos);
305 while (h) {
306 char *header;
307 if (!h->header_len) {
308 h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
309 continue;
310 }
311 if (!strstr(h->header, format)) {
312 h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
313 continue;
314 }
315
316 /* test if enough char after the header name + ': ' */
317 if (h->header_len <= format_len + 2) {
318 h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
319 continue;
320 }
321
322 if (h->header[format_len] != ':' || h->header[format_len + 1] != ' ') {
323 h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
324 continue;
325 }
326
327 header = h->header + format_len + 2;
328 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-");
329
330 /* found, done */
331 break;
332 }
333 if (!len2) {
334 len2 = 1;
335 *b = '-';
336 }
337 }
338 format[0] = '\0';
339 break;
340
341 case 'p': /* PID */
342 if (!test) {
343 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid());
344 }
345 break;
346
347 case 'P': /* PID */
348 if (!test) {
349 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid());
350 }
351 break;
352
353 case 'q': /* query_string */
354 if (!test) {
355 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string);
356 }
357 break;
358
359 case 'Q': /* '?' */
360 if (!test) {
361 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.query_string ? "?" : "");
362 }
363 break;
364
365 case 'r': /* request URI */
366 if (!test) {
367 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri);
368 }
369 break;
370
371 case 'R': /* remote IP address */
372 if (!test) {
373 const char *tmp = fcgi_get_last_client_ip();
374 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-");
375 }
376 break;
377
378 case 's': /* status */
379 if (!test) {
380 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code);
381 }
382 break;
383
384 case 'T':
385 case 't': /* time */
386 if (!test) {
387 time_t *t;
388 if (*s == 't') {
389 t = &proc.accepted_epoch;
390 } else {
391 t = &now_epoch;
392 }
393 if (format[0] == '\0') {
394 strftime(tmp, sizeof(tmp) - 1, "%d/%b/%Y:%H:%M:%S %z", localtime(t));
395 } else {
396 strftime(tmp, sizeof(tmp) - 1, format, localtime(t));
397 }
398 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp);
399 }
400 format[0] = '\0';
401 break;
402
403 case 'u': /* remote user */
404 if (!test) {
405 len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.auth_user);
406 }
407 break;
408
409 case '{': /* complex var */
410 token = 1;
411 {
412 char *start;
413 size_t l;
414
415 start = ++s;
416
417 while (*s != '\0') {
418 if (*s == '}') {
419 l = s - start;
420
421 if (l >= sizeof(format) - 1) {
422 l = sizeof(format) - 1;
423 }
424
425 memcpy(format, start, l);
426 format[l] = '\0';
427 break;
428 }
429 s++;
430 }
431 if (s[1] == '\0') {
432 zlog(ZLOG_WARNING, "missing closing embrace in the access.format");
433 return -1;
434 }
435 }
436 break;
437
438 default:
439 zlog(ZLOG_WARNING, "Invalid token in the access.format (%%%c)", *s);
440 return -1;
441 }
442
443 if (*s != '}' && format[0] != '\0') {
444 zlog(ZLOG_WARNING, "embrace is not allowed for modifier %%%c", *s);
445 return -1;
446 }
447 s++;
448 if (!test) {
449 b += len2;
450 len += len2;
451 }
452 if (len >= FPM_LOG_BUFFER) {
453 zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
454 len = FPM_LOG_BUFFER;
455 break;
456 }
457 continue;
458 }
459
460 if (!test) {
461 // push the normal char to the output buffer
462 *b = *s;
463 b++;
464 len++;
465 }
466 s++;
467 }
468
469 if (!test && strlen(buffer) > 0) {
470 buffer[len] = '\n';
471 zend_quiet_write(fpm_log_fd, buffer, len + 1);
472 }
473
474 return 0;
475 }
476 /* }}} */
477
