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 /* 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, "%zu", 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, "%zu", 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 const 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 if (len >= FPM_LOG_BUFFER) {
450 zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
451 len = FPM_LOG_BUFFER;
452 break;
453 }
454 continue;
455 }
456
457 if (!test) {
458 // push the normal char to the output buffer
459 *b = *s;
460 b++;
461 len++;
462 }
463 s++;
464 }
465
466 if (!test && strlen(buffer) > 0) {
467 buffer[len] = '\n';
468 zend_quiet_write(fpm_log_fd, buffer, len + 1);
469 }
470
471 return 0;
472 }
473 /* }}} */
474
