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 166 INIT_FUNC(mod_accesslog_init) { 167 return calloc(1, sizeof(plugin_data)); 168 } 169 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 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__ 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 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 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 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 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 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 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 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 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 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 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 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); 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