1 #include "first.h"
2
3 #include "sys-time.h"
4
5 #include "base.h"
6 #include "fdevent.h"
7 #include "fdlog.h"
8 #include "log.h"
9 #include "buffer.h"
10 #include "http_header.h"
11 #include "sock_addr.h"
12
13 #include "plugin.h"
14
15 #include <sys/types.h>
16 #include <sys/stat.h>
17
18 #include <stdlib.h>
19 #include <string.h>
20 #include <fcntl.h>
21 #include <unistd.h>
22
23 #ifdef HAVE_SYSLOG_H
24 # include <syslog.h>
25 #endif
26
27 typedef struct {
28 char key;
29 enum {
30 FORMAT_UNSET,
31 FORMAT_UNSUPPORTED,
32 FORMAT_PERCENT,
33 FORMAT_REMOTE_HOST,
34 FORMAT_REMOTE_IDENT,
35 FORMAT_REMOTE_USER,
36 FORMAT_TIMESTAMP,
37 FORMAT_REQUEST_LINE,
38 FORMAT_STATUS,
39 FORMAT_BYTES_OUT_NO_HEADER,
40 FORMAT_HEADER,
41
42 FORMAT_REMOTE_ADDR,
43 FORMAT_LOCAL_ADDR,
44 FORMAT_COOKIE,
45 FORMAT_TIME_USED_US,
46 FORMAT_ENV,
47 FORMAT_FILENAME,
48 FORMAT_REQUEST_PROTOCOL,
49 FORMAT_REQUEST_METHOD,
50 FORMAT_SERVER_PORT,
51 FORMAT_QUERY_STRING,
52 FORMAT_TIME_USED,
53 FORMAT_URL,
54 FORMAT_SERVER_NAME,
55 FORMAT_HTTP_HOST,
56 FORMAT_CONNECTION_STATUS,
57 FORMAT_BYTES_IN,
58 FORMAT_BYTES_OUT,
59
60 FORMAT_KEEPALIVE_COUNT,
61 FORMAT_RESPONSE_HEADER,
62 FORMAT_NOTE
63 } type;
64 } format_mapping;
65
66 /**
67 *
68 *
69 * "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\""
70 *
71 */
72
73 static const format_mapping fmap[] =
74 {
75 { '%', FORMAT_PERCENT },
76 { 'h', FORMAT_REMOTE_HOST },
77 { 'l', FORMAT_REMOTE_IDENT },
78 { 'u', FORMAT_REMOTE_USER },
79 { 't', FORMAT_TIMESTAMP },
80 { 'r', FORMAT_REQUEST_LINE },
81 { 's', FORMAT_STATUS },
82 { 'b', FORMAT_BYTES_OUT_NO_HEADER },
83 { 'i', FORMAT_HEADER },
84
85 { 'a', FORMAT_REMOTE_ADDR },
86 { 'A', FORMAT_LOCAL_ADDR },
87 { 'B', FORMAT_BYTES_OUT_NO_HEADER },
88 { 'C', FORMAT_COOKIE },
89 { 'D', FORMAT_TIME_USED_US },
90 { 'e', FORMAT_ENV },
91 { 'f', FORMAT_FILENAME },
92 { 'H', FORMAT_REQUEST_PROTOCOL },
93 { 'k', FORMAT_KEEPALIVE_COUNT },
94 { 'm', FORMAT_REQUEST_METHOD },
95 { 'n', FORMAT_NOTE },
96 { 'p', FORMAT_SERVER_PORT },
97 { 'P', FORMAT_UNSUPPORTED }, /* we are only one process */
98 { 'q', FORMAT_QUERY_STRING },
99 { 'T', FORMAT_TIME_USED },
100 { 'U', FORMAT_URL }, /* w/o querystring */
101 { 'v', FORMAT_SERVER_NAME },
102 { 'V', FORMAT_HTTP_HOST },
103 { 'X', FORMAT_CONNECTION_STATUS },
104 { 'I', FORMAT_BYTES_IN },
105 { 'O', FORMAT_BYTES_OUT },
106
107 { 'o', FORMAT_RESPONSE_HEADER },
108
109 { '\0', FORMAT_UNSET }
110 };
111
112
113 enum e_optflags_time {
114 /* format string is passed to strftime unless other format optflags set
115 * (besides FORMAT_FLAG_TIME_BEGIN or FORMAT_FLAG_TIME_END) */
116 FORMAT_FLAG_TIME_END = 0x00,/* use request end time (default) */
117 FORMAT_FLAG_TIME_BEGIN = 0x01,/* use request start time */
118 FORMAT_FLAG_TIME_SEC = 0x02,/* request time as num sec since epoch */
119 FORMAT_FLAG_TIME_MSEC = 0x04,/* request time as num msec since epoch */
120 FORMAT_FLAG_TIME_USEC = 0x08,/* request time as num usec since epoch */
121 FORMAT_FLAG_TIME_NSEC = 0x10,/* request time as num nsec since epoch */
122 FORMAT_FLAG_TIME_MSEC_FRAC = 0x20,/* request time msec fraction */
123 FORMAT_FLAG_TIME_USEC_FRAC = 0x40,/* request time usec fraction */
124 FORMAT_FLAG_TIME_NSEC_FRAC = 0x80 /* request time nsec fraction */
125 };
126
127 enum e_optflags_port {
128 FORMAT_FLAG_PORT_LOCAL = 0x01,/* (default) */
129 FORMAT_FLAG_PORT_REMOTE = 0x02
130 };
131
132
133 typedef struct {
134 enum { FIELD_UNSET, FIELD_STRING, FIELD_FORMAT } type;
135 int field;
136 int opt;
137 buffer string;
138 } format_field;
139
140 typedef struct {
141 unix_time64_t last_generated_accesslog_ts;
142 buffer ts_accesslog_str;
143 #if defined(__STDC_VERSION__) && __STDC_VERSION__-0 >= 199901L /* C99 */
144 format_field ptr[]; /* C99 VLA */
145 #else
146 format_field ptr[1];
147 #endif
148 } format_fields;
149
150 typedef struct {
151 fdlog_st *fdlog;
152 char use_syslog; /* syslog has global buffer */
153 unsigned short syslog_level;
154
155 format_fields *parsed_format;
156 } plugin_config;
157
158 typedef struct {
159 PLUGIN_DATA;
160 plugin_config defaults;
161 plugin_config conf;
162
163 format_fields *default_format;/* allocated if default format */
164 } plugin_data;
165
INIT_FUNC(mod_accesslog_init)166 INIT_FUNC(mod_accesslog_init) {
167 return calloc(1, sizeof(plugin_data));
168 }
169
accesslog_append_escaped_str(buffer * const dest,const char * const str,const size_t len)170 static void accesslog_append_escaped_str(buffer * const dest, const char * const str, const size_t len) {
171 const char *ptr, *start, *end;
172
173 /* replaces non-printable chars with \xHH where HH is the hex representation of the byte */
174 /* exceptions: " => \", \ => \\, whitespace chars => \n \t etc. */
175 if (0 == len) return;
176 buffer_string_prepare_append(dest, len);
177
178 for (ptr = start = str, end = str+len; ptr < end; ++ptr) {
179 unsigned char const c = *(const unsigned char *)ptr;
180 if (c >= ' ' && c <= '~' && c != '"' && c != '\\') {
181 /* nothing to change, add later as one block */
182 } else {
183 /* copy previous part */
184 if (start < ptr) {
185 buffer_append_string_len(dest, start, ptr - start);
186 }
187 start = ptr + 1;
188
189 const char *h2;
190 switch (c) {
191 case '"': h2 = "\\\""; break;
192 case '\\': h2 = "\\\\"; break;
193 case '\b': h2 = "\\b"; break;
194 case '\n': h2 = "\\n"; break;
195 case '\r': h2 = "\\r"; break;
196 case '\t': h2 = "\\t"; break;
197 case '\v': h2 = "\\v"; break;
198 default: {
199 /* non printable char => \xHH */
200 char hh[5] = {'\\','x',0,0,0};
201 char h = c >> 4;
202 hh[2] = (h > 9) ? (h - 10 + 'A') : (h + '0');
203 h = c & 0xFF;
204 hh[3] = (h > 9) ? (h - 10 + 'A') : (h + '0');
205 buffer_append_string_len(dest, hh, 4);
206 continue;
207 }
208 }
209 buffer_append_string_len(dest, h2, 2);
210 }
211 }
212
213 if (start < end) {
214 buffer_append_string_len(dest, start, end - start);
215 }
216 }
217
accesslog_append_escaped(buffer * dest,const buffer * str)218 static void accesslog_append_escaped(buffer *dest, const buffer *str) {
219 accesslog_append_escaped_str(dest, BUF_PTR_LEN(str));
220 }
221
222 __attribute_cold__
accesslog_parse_format_err(log_error_st * errh,const char * file,unsigned int line,format_field * f,const char * msg)223 static format_fields * accesslog_parse_format_err(log_error_st *errh, const char *file, unsigned int line, format_field *f, const char *msg) {
224 log_error(errh, file, line, "%s", msg);
225 for (; f->type != FIELD_UNSET; ++f) free(f->string.ptr);
226 return NULL;
227 }
228
accesslog_parse_format(const char * const format,const size_t flen,log_error_st * const errh)229 static format_fields * accesslog_parse_format(const char * const format, const size_t flen, log_error_st * const errh) {
230 /* common log format (the default) results in 18 elements,
231 * so 127 should be enough except for obscene custom usage */
232 size_t i, j, k = 0, start = 0;
233 uint32_t used = 0;
234 const uint32_t sz = 127;/* (sz+1 must match fptr[] num elts below) */
235 format_field *f;
236 format_field fptr[128]; /* (128 elements takes 4k on stack in 64-bit) */
237 memset(fptr, 0, sizeof(fptr));
238 if (0 != FIELD_UNSET) return NULL;
239
240 if (0 == flen) return NULL;
241
242 for (i = 0; i < flen; ++i) {
243 if (format[i] != '%') continue;
244
245 if (i > 0 && start != i) {
246 /* copy the string before this % */
247 if (used == sz)
248 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
249 "too many fields (>= 127) in accesslog.format");
250
251 f = fptr+used;
252 f->type = FIELD_STRING;
253 memset(&f->string, 0, sizeof(buffer));
254 buffer_copy_string_len(&f->string, format + start, i - start);
255
256 ++used;
257 }
258
259 /* we need a new field */
260 if (used == sz)
261 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
262 "too many fields (>= 127) in accesslog.format");
263
264 /* search for the terminating command */
265 switch (format[i+1]) {
266 case '>':
267 case '<':
268 /* after the } has to be a character */
269 if (format[i+2] == '\0') {
270 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
271 "%< and %> have to be followed by a format-specifier");
272 }
273
274
275 for (j = 0; fmap[j].key != '\0'; j++) {
276 if (fmap[j].key != format[i+2]) continue;
277
278 /* found key */
279
280 f = fptr+used;
281 f->type = FIELD_FORMAT;
282 f->field = fmap[j].type;
283 f->opt = 0;
284 f->string.ptr = NULL;
285
286 ++used;
287
288 break;
289 }
290
291 if (fmap[j].key == '\0') {
292 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
293 "%< and %> have to be followed by a valid format-specifier");
294 }
295
296 start = i + 3;
297 i = start - 1; /* skip the string */
298
299 break;
300 case '{':
301 /* go forward to } */
302
303 for (k = i+2; k < flen; ++k) {
304 if (format[k] == '}') break;
305 }
306
307 if (k == flen) {
308 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
309 "%{ has to be terminated by a }");
310 }
311
312 /* after the } has to be a character */
313 if (format[k+1] == '\0') {
314 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
315 "%{...} has to be followed by a format-specifier");
316 }
317
318 if (k == i + 2) {
319 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
320 "%{...} has to contain a string");
321 }
322
323 for (j = 0; fmap[j].key != '\0'; j++) {
324 if (fmap[j].key != format[k+1]) continue;
325
326 /* found key */
327
328 f = fptr+used;
329 f->type = FIELD_FORMAT;
330 f->field = fmap[j].type;
331 f->opt = 0;
332 memset(&f->string, 0, sizeof(buffer));
333 buffer_copy_string_len(&f->string, format + i + 2, k - (i + 2));
334
335 ++used;
336
337 break;
338 }
339
340 if (fmap[j].key == '\0') {
341 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
342 "%{...} has to be followed by a valid format-specifier");
343 }
344
345 start = k + 2;
346 i = start - 1; /* skip the string */
347
348 break;
349 default:
350 /* after the % has to be a character */
351 if (format[i+1] == '\0') {
352 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
353 "% has to be followed by a format-specifier");
354 }
355
356 for (j = 0; fmap[j].key != '\0'; j++) {
357 if (fmap[j].key != format[i+1]) continue;
358
359 /* found key */
360
361 f = fptr+used;
362 f->type = FIELD_FORMAT;
363 f->field = fmap[j].type;
364 f->string.ptr = NULL;
365 f->opt = 0;
366
367 ++used;
368
369 break;
370 }
371
372 if (fmap[j].key == '\0') {
373 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
374 "% has to be followed by a valid format-specifier");
375 }
376
377 start = i + 2;
378 i = start - 1; /* skip the string */
379
380 break;
381 }
382 }
383
384 if (start < i) {
385 /* copy the string */
386 if (used == sz)
387 return accesslog_parse_format_err(errh, __FILE__, __LINE__, fptr,
388 "too many fields (>= 127) in accesslog.format");
389
390 f = fptr+used;
391 f->type = FIELD_STRING;
392 memset(&f->string, 0, sizeof(buffer));
393 buffer_copy_string_len(&f->string, format + start, i - start);
394
395 ++used;
396 }
397
398 format_fields * const fields =
399 malloc(sizeof(format_fields) + ((used+1) * sizeof(format_field)));
400 force_assert(fields);
401 memset(fields, 0, sizeof(format_fields));
402 memcpy(fields->ptr, fptr, (used+1) * sizeof(format_field));
403 return fields;
404 }
405
mod_accesslog_free_format_fields(format_fields * const ff)406 static void mod_accesslog_free_format_fields(format_fields * const ff) {
407 for (format_field *f = ff->ptr; f->type != FIELD_UNSET; ++f)
408 free(f->string.ptr);
409 free(ff->ts_accesslog_str.ptr);
410 free(ff);
411 }
412
FREE_FUNC(mod_accesslog_free)413 FREE_FUNC(mod_accesslog_free) {
414 plugin_data * const p = p_d;
415 if (NULL == p->cvlist) return;
416 /* (init i to 0 if global context; to 1 to skip empty global context) */
417 for (int i = !p->cvlist[0].v.u2[1], used = p->nconfig; i < used; ++i) {
418 config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
419 for (; -1 != cpv->k_id; ++cpv) {
420 if (cpv->vtype != T_CONFIG_LOCAL || NULL == cpv->v.v) continue;
421 switch (cpv->k_id) {
422 case 0: /* accesslog.filename */
423 /*(handled by fdlog_closeall())*/
424 break;
425 case 1: /* accesslog.format */
426 mod_accesslog_free_format_fields(cpv->v.v);
427 break;
428 default:
429 break;
430 }
431 }
432 }
433
434 if (NULL != p->default_format) {
435 mod_accesslog_free_format_fields(p->default_format);
436 }
437 }
438
mod_accesslog_merge_config_cpv(plugin_config * const pconf,const config_plugin_value_t * const cpv)439 static void mod_accesslog_merge_config_cpv(plugin_config * const pconf, const config_plugin_value_t * const cpv) {
440 switch (cpv->k_id) { /* index into static config_plugin_keys_t cpk[] */
441 case 0:{/* accesslog.filename */
442 if (cpv->vtype != T_CONFIG_LOCAL) break;
443 pconf->fdlog = cpv->v.v;
444 break;
445 }
446 case 1:{/* accesslog.format */
447 if (cpv->vtype != T_CONFIG_LOCAL) break;
448 pconf->parsed_format = cpv->v.v;
449 break;
450 }
451 case 2: /* accesslog.use-syslog */
452 pconf->use_syslog = (int)cpv->v.u;
453 break;
454 case 3: /* accesslog.syslog-level */
455 pconf->syslog_level = cpv->v.shrt;
456 break;
457 default:/* should not happen */
458 return;
459 }
460 }
461
mod_accesslog_merge_config(plugin_config * const pconf,const config_plugin_value_t * cpv)462 static void mod_accesslog_merge_config(plugin_config * const pconf, const config_plugin_value_t *cpv) {
463 do {
464 mod_accesslog_merge_config_cpv(pconf, cpv);
465 } while ((++cpv)->k_id != -1);
466 }
467
mod_accesslog_patch_config(request_st * const r,plugin_data * const p)468 static void mod_accesslog_patch_config(request_st * const r, plugin_data * const p) {
469 memcpy(&p->conf, &p->defaults, sizeof(plugin_config));
470 for (int i = 1, used = p->nconfig; i < used; ++i) {
471 if (config_check_cond(r, (uint32_t)p->cvlist[i].k_id))
472 mod_accesslog_merge_config(&p->conf, p->cvlist + p->cvlist[i].v.u2[0]);
473 }
474 }
475
476 static format_fields * mod_accesslog_process_format(const char * const format, const size_t flen, server * const srv);
477
SETDEFAULTS_FUNC(mod_accesslog_set_defaults)478 SETDEFAULTS_FUNC(mod_accesslog_set_defaults) {
479 static const config_plugin_keys_t cpk[] = {
480 { CONST_STR_LEN("accesslog.filename"),
481 T_CONFIG_STRING,
482 T_CONFIG_SCOPE_CONNECTION }
483 ,{ CONST_STR_LEN("accesslog.format"),
484 T_CONFIG_STRING,
485 T_CONFIG_SCOPE_CONNECTION }
486 ,{ CONST_STR_LEN("accesslog.use-syslog"),
487 T_CONFIG_BOOL,
488 T_CONFIG_SCOPE_CONNECTION }
489 ,{ CONST_STR_LEN("accesslog.syslog-level"),
490 T_CONFIG_SHORT,
491 T_CONFIG_SCOPE_CONNECTION }
492 ,{ NULL, 0,
493 T_CONFIG_UNSET,
494 T_CONFIG_SCOPE_UNSET }
495 };
496
497 plugin_data * const p = p_d;
498 if (!config_plugin_values_init(srv, p, cpk, "mod_accesslog"))
499 return HANDLER_ERROR;
500
501 /* process and validate config directives
502 * (init i to 0 if global context; to 1 to skip empty global context) */
503 for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) {
504 config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
505 int use_syslog = 0;
506 config_plugin_value_t *cpvfile = NULL;
507 for (; -1 != cpv->k_id; ++cpv) {
508 switch (cpv->k_id) {
509 case 0: /* accesslog.filename */
510 if (!buffer_is_blank(cpv->v.b))
511 cpvfile = cpv;
512 else {
513 cpv->v.v = NULL;
514 cpv->vtype = T_CONFIG_LOCAL;
515 }
516 break;
517 case 1: /* accesslog.format */
518 if (NULL != strchr(cpv->v.b->ptr, '\\')) {
519 /* process basic backslash-escapes in format string */
520 buffer *b;
521 *(const buffer **)&b = cpv->v.b;
522 char *t = b->ptr;
523 for (char *s = t; *s; ++s) {
524 if (s[0] != '\\') { *t++ = *s; continue; }
525 if (s[1] == '\0') continue; /*(ignore dangling '\\')*/
526 switch (*++s) {
527 case 'a': *t++ = '\a'; break; /* bell */
528 case 'b': *t++ = '\b'; break; /* backspace */
529 case 'f': *t++ = '\f'; break; /* form feed */
530 case 'n': *t++ = '\n'; break; /* newline */
531 case 'r': *t++ = '\r'; break; /* carriage return */
532 case 't': *t++ = '\t'; break; /* horizontal tab */
533 case 'v': *t++ = '\v'; break; /* vertical tab */
534 /*case '"':*/
535 /*case '\\':*/
536 default: *t++ = *s; break; /*(use literal char)*/
537 }
538 }
539 buffer_truncate(b, (size_t)(t - b->ptr));
540 }
541 cpv->v.v =
542 mod_accesslog_process_format(BUF_PTR_LEN(cpv->v.b), srv);
543 if (NULL == cpv->v.v) return HANDLER_ERROR;
544 cpv->vtype = T_CONFIG_LOCAL;
545 break;
546 case 2: /* accesslog.use-syslog */
547 use_syslog = (int)cpv->v.u;
548 break;
549 case 3: /* accesslog.syslog-level */
550 break;
551 default:/* should not happen */
552 break;
553 }
554 }
555
556 if (srv->srvconf.preflight_check) continue;
557
558 if (use_syslog) continue; /* ignore the next checks */
559 cpv = cpvfile; /* accesslog.filename handled after preflight_check */
560 if (NULL == cpv) continue;
561 const char * const fn = cpv->v.b->ptr;
562 cpv->v.v = fdlog_open(fn);
563 cpv->vtype = T_CONFIG_LOCAL;
564 if (NULL == cpv->v.v) {
565 log_perror(srv->errh, __FILE__, __LINE__,
566 "opening log '%s' failed", fn);
567 return HANDLER_ERROR;
568 }
569 }
570
571 p->defaults.syslog_level = LOG_INFO;
572
573 /* initialize p->defaults from global config context */
574 if (p->nconfig > 0 && p->cvlist->v.u2[1]) {
575 const config_plugin_value_t *cpv = p->cvlist + p->cvlist->v.u2[0];
576 if (-1 != cpv->k_id)
577 mod_accesslog_merge_config(&p->defaults, cpv);
578 }
579
580 if (NULL == p->defaults.parsed_format) {
581 /* (set default format even if p->use_syslog since
582 * some other condition might enable logfile) */
583 static const char fmt[] =
584 "%h %V %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"";
585 p->defaults.parsed_format = p->default_format =
586 mod_accesslog_process_format(CONST_STR_LEN(fmt), srv);
587 if (NULL == p->default_format) return HANDLER_ERROR;
588 }
589
590 return HANDLER_GO_ON;
591 }
592
mod_accesslog_process_format(const char * const format,const size_t flen,server * const srv)593 static format_fields * mod_accesslog_process_format(const char * const format, const size_t flen, server * const srv) {
594 format_fields * const parsed_format =
595 accesslog_parse_format(format, flen, srv->errh);
596 if (NULL == parsed_format) {
597 log_error(srv->errh, __FILE__, __LINE__,
598 "parsing accesslog-definition failed: %s", format);
599 return NULL;
600 }
601
602 uint32_t tcount = 0;
603 for (format_field *f = parsed_format->ptr; f->type != FIELD_UNSET; ++f) {
604 const buffer * const fstr = &f->string;
605 if (FIELD_FORMAT != f->type) continue;
606 if (FORMAT_TIMESTAMP == f->field) {
607 if (!buffer_is_blank(fstr)) {
608 const char *ptr = fstr->ptr;
609 if (0 == strncmp(ptr, "begin:", sizeof("begin:")-1)) {
610 f->opt |= FORMAT_FLAG_TIME_BEGIN;
611 ptr += sizeof("begin:")-1;
612 } else if (0 == strncmp(ptr, "end:", sizeof("end:")-1)) {
613 f->opt |= FORMAT_FLAG_TIME_END;
614 ptr += sizeof("end:")-1;
615 }
616 if (0 == strcmp(ptr, "sec")) f->opt |= FORMAT_FLAG_TIME_SEC;
617 else if (0 == strcmp(ptr, "msec")) f->opt |= FORMAT_FLAG_TIME_MSEC;
618 else if (0 == strcmp(ptr, "usec")) f->opt |= FORMAT_FLAG_TIME_USEC;
619 else if (0 == strcmp(ptr, "nsec")) f->opt |= FORMAT_FLAG_TIME_NSEC;
620 else if (0 == strcmp(ptr, "msec_frac")) f->opt |= FORMAT_FLAG_TIME_MSEC_FRAC;
621 else if (0 == strcmp(ptr, "usec_frac")) f->opt |= FORMAT_FLAG_TIME_USEC_FRAC;
622 else if (0 == strcmp(ptr, "nsec_frac")) f->opt |= FORMAT_FLAG_TIME_NSEC_FRAC;
623 else if (NULL == strchr(ptr, '%')) {
624 log_error(srv->errh, __FILE__, __LINE__,
625 "constant string for time format (misspelled token? or missing '%%'): %s", format);
626 mod_accesslog_free_format_fields(parsed_format);
627 return NULL;
628 }
629 }
630
631 /* make sure they didn't try to send the timestamp in twice
632 * (would invalidate pconf->parsed_format.ts_accesslog_str cache of timestamp str) */
633 if (!(f->opt & ~(FORMAT_FLAG_TIME_BEGIN|FORMAT_FLAG_TIME_END|FORMAT_FLAG_TIME_SEC)) && ++tcount > 1) {
634 log_error(srv->errh, __FILE__, __LINE__,
635 "you may not use strftime timestamp format %%{}t twice in the same access log: %s", format);
636 mod_accesslog_free_format_fields(parsed_format);
637 return NULL;
638 }
639
640 if (f->opt & FORMAT_FLAG_TIME_BEGIN) srv->srvconf.high_precision_timestamps = 1;
641 } else if (FORMAT_TIME_USED_US == f->field) {
642 f->opt |= FORMAT_FLAG_TIME_USEC;
643 srv->srvconf.high_precision_timestamps = 1;
644 } else if (FORMAT_TIME_USED == f->field) {
645 if (buffer_is_blank(fstr)
646 || buffer_is_equal_string(fstr, CONST_STR_LEN("s"))
647 || buffer_is_equal_string(fstr, CONST_STR_LEN("sec"))) f->opt |= FORMAT_FLAG_TIME_SEC;
648 else if (buffer_is_equal_string(fstr, CONST_STR_LEN("ms"))
649 || buffer_is_equal_string(fstr, CONST_STR_LEN("msec"))) f->opt |= FORMAT_FLAG_TIME_MSEC;
650 else if (buffer_is_equal_string(fstr, CONST_STR_LEN("us"))
651 || buffer_is_equal_string(fstr, CONST_STR_LEN("usec"))) f->opt |= FORMAT_FLAG_TIME_USEC;
652 else if (buffer_is_equal_string(fstr, CONST_STR_LEN("ns"))
653 || buffer_is_equal_string(fstr, CONST_STR_LEN("nsec"))) f->opt |= FORMAT_FLAG_TIME_NSEC;
654 else {
655 log_error(srv->errh, __FILE__, __LINE__,
656 "invalid time unit in %%{UNIT}T: %s", format);
657 mod_accesslog_free_format_fields(parsed_format);
658 return NULL;
659 }
660
661 if (f->opt & ~(FORMAT_FLAG_TIME_SEC)) srv->srvconf.high_precision_timestamps = 1;
662 } else if (FORMAT_COOKIE == f->field) {
663 if (buffer_is_blank(fstr)) f->type = FIELD_STRING; /*(blank)*/
664 } else if (FORMAT_SERVER_PORT == f->field) {
665 if (buffer_is_blank(fstr))
666 f->opt |= FORMAT_FLAG_PORT_LOCAL;
667 else if (buffer_is_equal_string(fstr, CONST_STR_LEN("canonical")))
668 f->opt |= FORMAT_FLAG_PORT_LOCAL;
669 else if (buffer_is_equal_string(fstr, CONST_STR_LEN("local")))
670 f->opt |= FORMAT_FLAG_PORT_LOCAL;
671 else if (buffer_is_equal_string(fstr, CONST_STR_LEN("remote")))
672 f->opt |= FORMAT_FLAG_PORT_REMOTE;
673 else {
674 log_error(srv->errh, __FILE__, __LINE__,
675 "invalid format %%{canonical,local,remote}p: %s", format);
676 mod_accesslog_free_format_fields(parsed_format);
677 return NULL;
678 }
679 } else if (FORMAT_HEADER == f->field
680 || FORMAT_RESPONSE_HEADER == f->field) {
681 f->opt = http_header_hkey_get(BUF_PTR_LEN(fstr));
682 }
683 }
684
685 return parsed_format;
686 }
687
TRIGGER_FUNC(log_access_periodic_flush)688 TRIGGER_FUNC(log_access_periodic_flush) {
689 UNUSED(p_d);
690 /* flush buffered access logs every 4 seconds */
691 if (0 == (log_monotonic_secs & 3)) fdlog_files_flush(srv->errh, 0);
692 return HANDLER_GO_ON;
693 }
694
log_access_record(const request_st * const r,buffer * const b,format_fields * const parsed_format)695 static int log_access_record (const request_st * const r, buffer * const b, format_fields * const parsed_format) {
696 const connection * const con = r->con;
697 const buffer *vb;
698 unix_timespec64_t ts = { 0, 0 };
699 int flush = 0;
700
701 for (const format_field *f = parsed_format->ptr; f->type != FIELD_UNSET; ++f) {
702 switch(f->type) {
703 case FIELD_STRING:
704 buffer_append_string_buffer(b, &f->string);
705 break;
706 case FIELD_FORMAT:
707 switch(f->field) {
708 case FORMAT_TIMESTAMP:
709
710 if (f->opt & ~(FORMAT_FLAG_TIME_BEGIN|FORMAT_FLAG_TIME_END)) {
711 if (f->opt & FORMAT_FLAG_TIME_SEC) {
712 unix_time64_t t = (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) ? log_epoch_secs : r->start_hp.tv_sec;
713 buffer_append_int(b, (intmax_t)t);
714 } else if (f->opt & (FORMAT_FLAG_TIME_MSEC|FORMAT_FLAG_TIME_USEC|FORMAT_FLAG_TIME_NSEC)) {
715 unix_time64_t t;
716 long ns;
717 if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) {
718 if (0 == ts.tv_sec) log_clock_gettime_realtime(&ts);
719 t = ts.tv_sec;
720 ns = ts.tv_nsec;
721 } else {
722 t = r->start_hp.tv_sec;
723 ns = r->start_hp.tv_nsec;
724 }
725 if (f->opt & FORMAT_FLAG_TIME_MSEC) {
726 t *= 1000;
727 t += (ns + 999999) / 1000000; /* ceil */
728 } else if (f->opt & FORMAT_FLAG_TIME_USEC) {
729 t *= 1000000;
730 t += (ns + 999) / 1000; /* ceil */
731 } else {/*(f->opt & FORMAT_FLAG_TIME_NSEC)*/
732 t *= 1000000000;
733 t += ns;
734 }
735 buffer_append_int(b, (intmax_t)t);
736 } else { /*(FORMAT_FLAG_TIME_MSEC_FRAC|FORMAT_FLAG_TIME_USEC_FRAC|FORMAT_FLAG_TIME_NSEC_FRAC)*/
737 long ns;
738 char *ptr;
739 if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) {
740 if (0 == ts.tv_sec) log_clock_gettime_realtime(&ts);
741 ns = ts.tv_nsec;
742 } else {
743 ns = r->start_hp.tv_nsec;
744 }
745 /*assert(t < 1000000000);*/
746 if (f->opt & FORMAT_FLAG_TIME_MSEC_FRAC) {
747 ns += 999999; /* ceil */
748 ns /= 1000000;
749 buffer_append_string_len(b, CONST_STR_LEN("000"));
750 } else if (f->opt & FORMAT_FLAG_TIME_USEC_FRAC) {
751 ns += 999; /* ceil */
752 ns /= 1000;
753 buffer_append_string_len(b, CONST_STR_LEN("000000"));
754 } else {/*(f->opt & FORMAT_FLAG_TIME_NSEC_FRAC)*/
755 buffer_append_string_len(b, CONST_STR_LEN("000000000"));
756 }
757 ptr = b->ptr + buffer_clen(b);
758 for (long x; ns > 0; ns = x)
759 *--ptr += (ns - (x = ns/10) * 10); /* ns % 10 */
760 }
761 } else {
762 buffer * const ts_accesslog_str = &parsed_format->ts_accesslog_str;
763 /* cache the generated timestamp (only if ! FORMAT_FLAG_TIME_BEGIN) */
764 unix_time64_t t;
765 struct tm tm;
766
767 if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) {
768 const unix_time64_t cur_ts = log_epoch_secs;
769 if (parsed_format->last_generated_accesslog_ts == cur_ts) {
770 buffer_append_string_buffer(b, ts_accesslog_str);
771 break;
772 }
773 t = parsed_format->last_generated_accesslog_ts = cur_ts;
774 flush = 1;
775 } else {
776 t = r->start_hp.tv_sec;
777 }
778
779 const char *fmt = buffer_is_blank(&f->string)
780 ? NULL
781 : f->string.ptr;
782 buffer_clear(ts_accesslog_str);
783 #if defined(HAVE_STRUCT_TM_GMTOFF)
784 buffer_append_strftime(ts_accesslog_str,
785 fmt ? fmt : "[%d/%b/%Y:%T %z]",
786 localtime64_r(&t, &tm));
787 #else /* HAVE_STRUCT_TM_GMTOFF */
788 buffer_append_strftime(ts_accesslog_str,
789 fmt ? fmt : "[%d/%b/%Y:%T +0000]",
790 gmtime64_r(&t, &tm));
791 #endif /* HAVE_STRUCT_TM_GMTOFF */
792 buffer_append_string_buffer(b, ts_accesslog_str);
793 }
794 break;
795 case FORMAT_TIME_USED:
796 case FORMAT_TIME_USED_US:
797 if (f->opt & FORMAT_FLAG_TIME_SEC) {
798 buffer_append_int(b, log_epoch_secs - r->start_hp.tv_sec);
799 } else {
800 const unix_timespec64_t * const bs = &r->start_hp;
801 off_t tdiff; /*(expected to be 64-bit since large file support enabled)*/
802 if (0 == ts.tv_sec) log_clock_gettime_realtime(&ts);
803 tdiff = (off_t)(ts.tv_sec - bs->tv_sec)*1000000000 + (ts.tv_nsec - bs->tv_nsec);
804 if (tdiff <= 0) {
805 /* sanity check for time moving backwards
806 * (daylight savings adjustment or leap seconds or ?) */
807 tdiff = -1;
808 } else if (f->opt & FORMAT_FLAG_TIME_MSEC) {
809 tdiff += 999999; /* ceil */
810 tdiff /= 1000000;
811 } else if (f->opt & FORMAT_FLAG_TIME_USEC) {
812 tdiff += 999; /* ceil */
813 tdiff /= 1000;
814 } /* else (f->opt & FORMAT_FLAG_TIME_NSEC) */
815 buffer_append_int(b, (intmax_t)tdiff);
816 }
817 break;
818 case FORMAT_REMOTE_ADDR:
819 case FORMAT_REMOTE_HOST:
820 buffer_append_string_buffer(b, &con->dst_addr_buf);
821 break;
822 case FORMAT_REMOTE_IDENT:
823 /* ident */
824 buffer_append_string_len(b, CONST_STR_LEN("-"));
825 break;
826 case FORMAT_REMOTE_USER:
827 if (NULL != (vb = http_header_env_get(r, CONST_STR_LEN("REMOTE_USER")))) {
828 accesslog_append_escaped(b, vb);
829 } else {
830 buffer_append_string_len(b, CONST_STR_LEN("-"));
831 }
832 break;
833 case FORMAT_REQUEST_LINE:
834 /*(attempt to reconstruct request line)*/
835 http_method_append(b, r->http_method);
836 buffer_append_string_len(b, CONST_STR_LEN(" "));
837 accesslog_append_escaped(b, &r->target_orig);
838 buffer_append_string_len(b, CONST_STR_LEN(" "));
839 http_version_append(b, r->http_version);
840 break;
841 case FORMAT_STATUS:
842 buffer_append_int(b, r->http_status);
843 break;
844
845 case FORMAT_BYTES_OUT_NO_HEADER:
846 {
847 off_t bytes = r->http_version <= HTTP_VERSION_1_1
848 ? con->bytes_written - r->bytes_written_ckpt
849 : r->write_queue.bytes_out;
850 if (bytes > 0) {
851 bytes -= (off_t)r->resp_header_len;
852 buffer_append_int(b, bytes > 0 ? bytes : 0);
853 } else {
854 buffer_append_string_len(b, CONST_STR_LEN("-"));
855 }
856 break;
857 }
858 case FORMAT_HEADER:
859 if (NULL != (vb = http_header_request_get(r, f->opt, BUF_PTR_LEN(&f->string)))) {
860 accesslog_append_escaped(b, vb);
861 } else {
862 buffer_append_string_len(b, CONST_STR_LEN("-"));
863 }
864 break;
865 case FORMAT_RESPONSE_HEADER:
866 if (NULL != (vb = http_header_response_get(r, f->opt, BUF_PTR_LEN(&f->string)))) {
867 accesslog_append_escaped(b, vb);
868 } else {
869 buffer_append_string_len(b, CONST_STR_LEN("-"));
870 }
871 break;
872 case FORMAT_ENV:
873 case FORMAT_NOTE:
874 if (NULL != (vb = http_header_env_get(r, BUF_PTR_LEN(&f->string)))) {
875 accesslog_append_escaped(b, vb);
876 } else {
877 buffer_append_string_len(b, CONST_STR_LEN("-"));
878 }
879 break;
880 case FORMAT_FILENAME:
881 if (!buffer_is_blank(&r->physical.path)) {
882 buffer_append_string_buffer(b, &r->physical.path);
883 } else {
884 buffer_append_string_len(b, CONST_STR_LEN("-"));
885 }
886 break;
887 case FORMAT_BYTES_OUT:
888 {
889 off_t bytes = r->http_version <= HTTP_VERSION_1_1
890 ? con->bytes_written - r->bytes_written_ckpt
891 : r->write_queue.bytes_out;
892 if (bytes > 0) {
893 buffer_append_int(b, bytes);
894 } else {
895 buffer_append_string_len(b, CONST_STR_LEN("-"));
896 }
897 break;
898 }
899 case FORMAT_BYTES_IN:
900 {
901 off_t bytes = r->http_version <= HTTP_VERSION_1_1
902 ? con->bytes_read - r->bytes_read_ckpt
903 : r->read_queue.bytes_in + (off_t)r->rqst_header_len;
904 if (bytes > 0) {
905 buffer_append_int(b, bytes);
906 } else {
907 buffer_append_string_len(b, CONST_STR_LEN("-"));
908 }
909 break;
910 }
911 case FORMAT_SERVER_NAME:
912 if (!buffer_is_blank(r->server_name)) {
913 buffer_append_string_buffer(b, r->server_name);
914 } else {
915 buffer_append_string_len(b, CONST_STR_LEN("-"));
916 }
917 break;
918 case FORMAT_HTTP_HOST:
919 if (!buffer_is_blank(&r->uri.authority)) {
920 accesslog_append_escaped(b, &r->uri.authority);
921 } else {
922 buffer_append_string_len(b, CONST_STR_LEN("-"));
923 }
924 break;
925 case FORMAT_REQUEST_PROTOCOL:
926 http_version_append(b, r->http_version);
927 break;
928 case FORMAT_REQUEST_METHOD:
929 http_method_append(b, r->http_method);
930 break;
931 case FORMAT_PERCENT:
932 buffer_append_string_len(b, CONST_STR_LEN("%"));
933 break;
934 case FORMAT_LOCAL_ADDR:
935 {
936 /* (perf: not using getsockname() and
937 * sock_addr_cache_inet_ntop_copy_buffer())
938 * (still useful if admin has configured explicit listen IPs) */
939 const server_socket * const srv_sock = con->srv_socket;
940 buffer_append_string_len(b, srv_sock->srv_token->ptr,
941 srv_sock->srv_token_colon);
942 }
943 break;
944 case FORMAT_SERVER_PORT:
945 if (f->opt & FORMAT_FLAG_PORT_REMOTE) {
946 buffer_append_int(b, sock_addr_get_port(&con->dst_addr));
947 } else { /* if (f->opt & FORMAT_FLAG_PORT_LOCAL) *//*(default)*/
948 const server_socket * const srv_sock = con->srv_socket;
949 const buffer * const srv_token = srv_sock->srv_token;
950 const size_t tlen = buffer_clen(srv_token);
951 size_t colon = srv_sock->srv_token_colon;
952 if (colon < tlen) /*(colon != tlen)*/
953 buffer_append_string_len(b, srv_token->ptr+colon+1,
954 tlen - (colon+1));
955 }
956 break;
957 case FORMAT_QUERY_STRING:
958 accesslog_append_escaped(b, &r->uri.query);
959 break;
960 case FORMAT_URL:
961 {
962 const uint32_t len = buffer_clen(&r->target);
963 const char * const qmark = memchr(r->target.ptr, '?', len);
964 accesslog_append_escaped_str(b, r->target.ptr, qmark ? (uint32_t)(qmark - r->target.ptr) : len);
965 }
966 break;
967 case FORMAT_CONNECTION_STATUS:
968 if (r->state == CON_STATE_RESPONSE_END) {
969 if (r->keep_alive <= 0) {
970 buffer_append_string_len(b, CONST_STR_LEN("-"));
971 } else {
972 buffer_append_string_len(b, CONST_STR_LEN("+"));
973 }
974 } else { /* CON_STATE_ERROR */
975 buffer_append_string_len(b, CONST_STR_LEN("X"));
976 }
977 break;
978 case FORMAT_KEEPALIVE_COUNT:
979 if (con->request_count > 1) {
980 buffer_append_int(b, (intmax_t)(con->request_count-1));
981 } else {
982 buffer_append_string_len(b, CONST_STR_LEN("0"));
983 }
984 break;
985 case FORMAT_COOKIE:
986 if (NULL != (vb = http_header_request_get(r, HTTP_HEADER_COOKIE, CONST_STR_LEN("Cookie")))) {
987 char *str = vb->ptr;
988 size_t len = buffer_clen(&f->string);
989 do {
990 while (*str == ' ' || *str == '\t') ++str;
991 if (0 == strncmp(str, f->string.ptr, len) && str[len] == '=') {
992 char *v = str+len+1;
993 for (str = v; *str != '\0' && *str != ';'; ++str) ;
994 if (str == v) break;
995 do { --str; } while (str > v && (*str == ' ' || *str == '\t'));
996 accesslog_append_escaped_str(b, v, str - v + 1);
997 break;
998 } else {
999 while (*str != ';' && *str != ' ' && *str != '\t' && *str != '\0') ++str;
1000 }
1001 while (*str == ' ' || *str == '\t') ++str;
1002 } while (*str++ == ';');
1003 }
1004 break;
1005 default:
1006 break;
1007 }
1008 break;
1009 default:
1010 break;
1011 }
1012 }
1013
1014 return flush;
1015 }
1016
REQUESTDONE_FUNC(log_access_write)1017 REQUESTDONE_FUNC(log_access_write) {
1018 plugin_data * const p = p_d;
1019 mod_accesslog_patch_config(r, p);
1020 fdlog_st * const fdlog = p->conf.fdlog;
1021
1022 /* No output device, nothing to do */
1023 if (!p->conf.use_syslog && !fdlog) return HANDLER_GO_ON;
1024
1025 buffer * const b = (p->conf.use_syslog || fdlog->mode == FDLOG_PIPE)
1026 ? (buffer_clear(r->tmp_buf), r->tmp_buf)
1027 : &fdlog->b;
1028
1029 const int flush = log_access_record(r, b, p->conf.parsed_format);
1030
1031 #ifdef HAVE_SYSLOG_H
1032 if (p->conf.use_syslog) {
1033 if (!buffer_is_blank(b))
1034 syslog(p->conf.syslog_level, "%s", b->ptr);
1035 return HANDLER_GO_ON;
1036 }
1037 #endif
1038
1039 buffer_append_string_len(b, CONST_STR_LEN("\n"));
1040
1041 if (flush || fdlog->mode == FDLOG_PIPE || buffer_clen(b) >= 8192) {
1042 const ssize_t wr = write_all(fdlog->fd, BUF_PTR_LEN(b));
1043 buffer_clear(b); /*(clear buffer, even on error)*/
1044 if (-1 == wr)
1045 log_perror(r->conf.errh, __FILE__, __LINE__,
1046 "error flushing log %s", fdlog->fn);
1047 }
1048
1049 return HANDLER_GO_ON;
1050 }
1051
1052
1053 int mod_accesslog_plugin_init(plugin *p);
mod_accesslog_plugin_init(plugin * p)1054 int mod_accesslog_plugin_init(plugin *p) {
1055 p->version = LIGHTTPD_VERSION_ID;
1056 p->name = "accesslog";
1057
1058 p->init = mod_accesslog_init;
1059 p->set_defaults= mod_accesslog_set_defaults;
1060 p->cleanup = mod_accesslog_free;
1061
1062 p->handle_request_done = log_access_write;
1063 p->handle_trigger = log_access_periodic_flush;
1064
1065 return 0;
1066 }
1067