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