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 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 malloc(sizeof(format_fields) + ((used+1) * sizeof(format_field))); 272 force_assert(fields); 273 memset(fields, 0, sizeof(format_fields)); 274 memcpy(fields->ptr, fptr, (used+1) * sizeof(format_field)); 275 return fields; 276 } 277 278 static void mod_accesslog_free_format_fields(format_fields * const ff) { 279 for (format_field *f = ff->ptr; f->field != FORMAT_UNSET; ++f) 280 free(f->string.ptr); 281 free(ff->ts_accesslog_str.ptr); 282 free(ff); 283 } 284 285 FREE_FUNC(mod_accesslog_free) { 286 plugin_data * const p = p_d; 287 if (NULL == p->cvlist) return; 288 /* (init i to 0 if global context; to 1 to skip empty global context) */ 289 for (int i = !p->cvlist[0].v.u2[1], used = p->nconfig; i < used; ++i) { 290 config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0]; 291 for (; -1 != cpv->k_id; ++cpv) { 292 if (cpv->vtype != T_CONFIG_LOCAL || NULL == cpv->v.v) continue; 293 switch (cpv->k_id) { 294 case 0: /* accesslog.filename */ 295 /*(handled by fdlog_closeall())*/ 296 break; 297 case 1: /* accesslog.format */ 298 mod_accesslog_free_format_fields(cpv->v.v); 299 break; 300 default: 301 break; 302 } 303 } 304 } 305 306 if (NULL != p->default_format) { 307 mod_accesslog_free_format_fields(p->default_format); 308 } 309 } 310 311 static void mod_accesslog_merge_config_cpv(plugin_config * const pconf, const config_plugin_value_t * const cpv) { 312 switch (cpv->k_id) { /* index into static config_plugin_keys_t cpk[] */ 313 case 0:{/* accesslog.filename */ 314 if (cpv->vtype != T_CONFIG_LOCAL) break; 315 pconf->fdlog = cpv->v.v; 316 break; 317 } 318 case 1:{/* accesslog.format */ 319 if (cpv->vtype != T_CONFIG_LOCAL) break; 320 pconf->parsed_format = cpv->v.v; 321 break; 322 } 323 case 2: /* accesslog.use-syslog */ 324 pconf->use_syslog = (int)cpv->v.u; 325 break; 326 case 3: /* accesslog.syslog-level */ 327 pconf->syslog_level = cpv->v.shrt; 328 break; 329 case 4: /* accesslog.escaping */ 330 if (cpv->vtype != T_CONFIG_LOCAL) break; 331 pconf->escaping = (int)cpv->v.u; 332 break; 333 default:/* should not happen */ 334 return; 335 } 336 } 337 338 static void mod_accesslog_merge_config(plugin_config * const pconf, const config_plugin_value_t *cpv) { 339 do { 340 mod_accesslog_merge_config_cpv(pconf, cpv); 341 } while ((++cpv)->k_id != -1); 342 } 343 344 static void mod_accesslog_patch_config(request_st * const r, plugin_data * const p) { 345 memcpy(&p->conf, &p->defaults, sizeof(plugin_config)); 346 for (int i = 1, used = p->nconfig; i < used; ++i) { 347 if (config_check_cond(r, (uint32_t)p->cvlist[i].k_id)) 348 mod_accesslog_merge_config(&p->conf, p->cvlist + p->cvlist[i].v.u2[0]); 349 } 350 } 351 352 static format_fields * mod_accesslog_process_format(const char * const format, const uint32_t flen, server * const srv); 353 354 SETDEFAULTS_FUNC(mod_accesslog_set_defaults) { 355 static const config_plugin_keys_t cpk[] = { 356 { CONST_STR_LEN("accesslog.filename"), 357 T_CONFIG_STRING, 358 T_CONFIG_SCOPE_CONNECTION } 359 ,{ CONST_STR_LEN("accesslog.format"), 360 T_CONFIG_STRING, 361 T_CONFIG_SCOPE_CONNECTION } 362 ,{ CONST_STR_LEN("accesslog.use-syslog"), 363 T_CONFIG_BOOL, 364 T_CONFIG_SCOPE_CONNECTION } 365 ,{ CONST_STR_LEN("accesslog.syslog-level"), 366 T_CONFIG_SHORT, 367 T_CONFIG_SCOPE_CONNECTION } 368 ,{ CONST_STR_LEN("accesslog.escaping"), 369 T_CONFIG_STRING, 370 T_CONFIG_SCOPE_CONNECTION } 371 ,{ NULL, 0, 372 T_CONFIG_UNSET, 373 T_CONFIG_SCOPE_UNSET } 374 }; 375 376 plugin_data * const p = p_d; 377 if (!config_plugin_values_init(srv, p, cpk, "mod_accesslog")) 378 return HANDLER_ERROR; 379 380 /* process and validate config directives 381 * (init i to 0 if global context; to 1 to skip empty global context) */ 382 for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) { 383 config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0]; 384 int use_syslog = 0; 385 config_plugin_value_t *cpvfile = NULL; 386 for (; -1 != cpv->k_id; ++cpv) { 387 switch (cpv->k_id) { 388 case 0: /* accesslog.filename */ 389 if (!buffer_is_blank(cpv->v.b)) 390 cpvfile = cpv; 391 else { 392 cpv->v.v = NULL; 393 cpv->vtype = T_CONFIG_LOCAL; 394 } 395 break; 396 case 1: /* accesslog.format */ 397 if (NULL != strchr(cpv->v.b->ptr, '\\')) { 398 /* process basic backslash-escapes in format string */ 399 buffer *b; 400 *(const buffer **)&b = cpv->v.b; 401 char *t = b->ptr; 402 for (char *s = t; *s; ++s) { 403 if (s[0] != '\\') { *t++ = *s; continue; } 404 if (s[1] == '\0') continue; /*(ignore dangling '\\')*/ 405 switch (*++s) { 406 case 'a': *t++ = '\a'; break; /* bell */ 407 case 'b': *t++ = '\b'; break; /* backspace */ 408 case 'f': *t++ = '\f'; break; /* form feed */ 409 case 'n': *t++ = '\n'; break; /* newline */ 410 case 'r': *t++ = '\r'; break; /* carriage return */ 411 case 't': *t++ = '\t'; break; /* horizontal tab */ 412 case 'v': *t++ = '\v'; break; /* vertical tab */ 413 /*case '"':*/ 414 /*case '\\':*/ 415 default: *t++ = *s; break; /*(use literal char)*/ 416 } 417 } 418 buffer_truncate(b, (size_t)(t - b->ptr)); 419 } 420 cpv->v.v = 421 mod_accesslog_process_format(BUF_PTR_LEN(cpv->v.b), srv); 422 if (NULL == cpv->v.v) return HANDLER_ERROR; 423 cpv->vtype = T_CONFIG_LOCAL; 424 break; 425 case 2: /* accesslog.use-syslog */ 426 use_syslog = (int)cpv->v.u; 427 break; 428 case 3: /* accesslog.syslog-level */ 429 break; 430 case 4: /* accesslog.escaping */ 431 /* quick parse: 0 == "default", 1 == "json" */ 432 cpv->v.u = (0 == strcmp(cpv->v.b->ptr, "json")) 433 ? BS_ESCAPE_JSON 434 : BS_ESCAPE_DEFAULT; 435 cpv->vtype = T_CONFIG_LOCAL; 436 break; 437 default:/* should not happen */ 438 break; 439 } 440 } 441 442 if (srv->srvconf.preflight_check) continue; 443 444 if (use_syslog) continue; /* ignore the next checks */ 445 cpv = cpvfile; /* accesslog.filename handled after preflight_check */ 446 if (NULL == cpv) continue; 447 const char * const fn = cpv->v.b->ptr; 448 cpv->v.v = fdlog_open(fn); 449 cpv->vtype = T_CONFIG_LOCAL; 450 if (NULL == cpv->v.v) { 451 log_perror(srv->errh, __FILE__, __LINE__, 452 "opening log '%s' failed", fn); 453 return HANDLER_ERROR; 454 } 455 } 456 457 p->defaults.syslog_level = LOG_INFO; 458 459 /* initialize p->defaults from global config context */ 460 if (p->nconfig > 0 && p->cvlist->v.u2[1]) { 461 const config_plugin_value_t *cpv = p->cvlist + p->cvlist->v.u2[0]; 462 if (-1 != cpv->k_id) 463 mod_accesslog_merge_config(&p->defaults, cpv); 464 } 465 466 if (NULL == p->defaults.parsed_format) { 467 /* (set default format even if p->use_syslog since 468 * some other condition might enable logfile) */ 469 static const char fmt[] = 470 "%h %V %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\""; 471 p->defaults.parsed_format = p->default_format = 472 mod_accesslog_process_format(CONST_STR_LEN(fmt), srv); 473 if (NULL == p->default_format) return HANDLER_ERROR; 474 } 475 476 return HANDLER_GO_ON; 477 } 478 479 static format_fields * mod_accesslog_process_format(const char * const format, const uint32_t flen, server * const srv) { 480 format_fields * const parsed_format = 481 accesslog_parse_format(format, flen, srv->errh); 482 if (NULL == parsed_format) { 483 log_error(srv->errh, __FILE__, __LINE__, 484 "parsing accesslog-definition failed: %s", format); 485 return NULL; 486 } 487 488 uint32_t tcount = 0; 489 for (format_field *f = parsed_format->ptr; f->field != FORMAT_UNSET; ++f) { 490 buffer * const fstr = &f->string; 491 if (FORMAT_LITERAL == f->field) continue; 492 if (FORMAT_TIMESTAMP == f->field) { 493 if (!buffer_is_blank(fstr)) { 494 const char * const ptr = fstr->ptr; 495 uint32_t len = buffer_clen(fstr); 496 if (0 == strncmp(ptr, "begin:", sizeof("begin:")-1)) { 497 f->opt |= FORMAT_FLAG_TIME_BEGIN; 498 memmove(fstr->ptr, fstr->ptr+6, len-6); /*"begin:"*/ 499 buffer_truncate(fstr, len-6); 500 } else if (0 == strncmp(ptr, "end:", sizeof("end:")-1)) { 501 f->opt |= FORMAT_FLAG_TIME_END; 502 memmove(fstr->ptr, fstr->ptr+4, len-4); /*"end:"*/ 503 buffer_truncate(fstr, len-4); 504 } 505 if (0 == strcmp(ptr, "sec")) f->opt |= FORMAT_FLAG_TIME_SEC; 506 else if (0 == strcmp(ptr, "msec")) f->opt |= FORMAT_FLAG_TIME_MSEC; 507 else if (0 == strcmp(ptr, "usec")) f->opt |= FORMAT_FLAG_TIME_USEC; 508 else if (0 == strcmp(ptr, "nsec")) f->opt |= FORMAT_FLAG_TIME_NSEC; 509 else if (0 == strcmp(ptr, "msec_frac")) f->opt |= FORMAT_FLAG_TIME_MSEC_FRAC; 510 else if (0 == strcmp(ptr, "usec_frac")) f->opt |= FORMAT_FLAG_TIME_USEC_FRAC; 511 else if (0 == strcmp(ptr, "nsec_frac")) f->opt |= FORMAT_FLAG_TIME_NSEC_FRAC; 512 else if (NULL == strchr(ptr, '%')) { 513 log_error(srv->errh, __FILE__, __LINE__, 514 "constant string for time format (misspelled token? or missing '%%'): %s", format); 515 mod_accesslog_free_format_fields(parsed_format); 516 return NULL; 517 } 518 } 519 520 /* make sure they didn't try to send the timestamp in twice 521 * (would invalidate pconf->parsed_format.ts_accesslog_str cache of timestamp str) */ 522 if (!(f->opt & ~(FORMAT_FLAG_TIME_BEGIN|FORMAT_FLAG_TIME_END|FORMAT_FLAG_TIME_SEC)) && ++tcount > 1) { 523 log_error(srv->errh, __FILE__, __LINE__, 524 "you may not use strftime timestamp format %%{}t twice in the same access log: %s", format); 525 mod_accesslog_free_format_fields(parsed_format); 526 return NULL; 527 } 528 529 if (f->opt & FORMAT_FLAG_TIME_BEGIN) srv->srvconf.high_precision_timestamps = 1; 530 } else if (FORMAT_TIME_USED_US == f->field) { 531 f->opt |= FORMAT_FLAG_TIME_USEC; 532 f->field = FORMAT_TIME_USED; 533 srv->srvconf.high_precision_timestamps = 1; 534 } else if (FORMAT_TIME_USED == f->field) { 535 const char * const ptr = fstr->ptr; 536 if (buffer_is_blank(fstr) 537 || 0 == strcmp(ptr, "s") 538 || 0 == strcmp(ptr, "sec")) f->opt |= FORMAT_FLAG_TIME_SEC; 539 else if (0 == strcmp(ptr, "ms") 540 || 0 == strcmp(ptr, "msec")) f->opt |= FORMAT_FLAG_TIME_MSEC; 541 else if (0 == strcmp(ptr, "us") 542 || 0 == strcmp(ptr, "usec")) f->opt |= FORMAT_FLAG_TIME_USEC; 543 else if (0 == strcmp(ptr, "ns") 544 || 0 == strcmp(ptr, "nsec")) f->opt |= FORMAT_FLAG_TIME_NSEC; 545 else { 546 log_error(srv->errh, __FILE__, __LINE__, 547 "invalid time unit in %%{UNIT}T: %s", format); 548 mod_accesslog_free_format_fields(parsed_format); 549 return NULL; 550 } 551 552 if (f->opt & ~(FORMAT_FLAG_TIME_SEC)) srv->srvconf.high_precision_timestamps = 1; 553 } else if (FORMAT_COOKIE == f->field) { 554 if (buffer_is_blank(fstr)) f->field = FORMAT_LITERAL; /*(blank)*/ 555 } else if (FORMAT_SERVER_PORT == f->field) { 556 const char * const ptr = fstr->ptr; 557 if (buffer_is_blank(fstr)) 558 f->opt |= FORMAT_FLAG_PORT_LOCAL; 559 else if (0 == strcmp(ptr, "canonical")) 560 f->opt |= FORMAT_FLAG_PORT_LOCAL; 561 else if (0 == strcmp(ptr, "local")) 562 f->opt |= FORMAT_FLAG_PORT_LOCAL; 563 else if (0 == strcmp(ptr, "remote")) 564 f->opt |= FORMAT_FLAG_PORT_REMOTE; 565 else { 566 log_error(srv->errh, __FILE__, __LINE__, 567 "invalid format %%{canonical,local,remote}p: %s", format); 568 mod_accesslog_free_format_fields(parsed_format); 569 return NULL; 570 } 571 } else if (FORMAT_HEADER == f->field 572 || FORMAT_RESPONSE_HEADER == f->field) { 573 f->opt = http_header_hkey_get(BUF_PTR_LEN(fstr)); 574 } else if (FORMAT_REMOTE_HOST == f->field) { 575 f->field = FORMAT_REMOTE_ADDR; 576 } else if (FORMAT_REMOTE_USER == f->field) { 577 f->field = FORMAT_ENV; 578 buffer_copy_string_len(fstr, CONST_STR_LEN("REMOTE_USER")); 579 } else if (FORMAT_NOTE == f->field) { 580 f->field = FORMAT_ENV; 581 } 582 } 583 584 return parsed_format; 585 } 586 587 TRIGGER_FUNC(log_access_periodic_flush) { 588 UNUSED(p_d); 589 /* flush buffered access logs every 4 seconds */ 590 if (0 == (log_monotonic_secs & 3)) fdlog_files_flush(srv->errh, 0); 591 return HANDLER_GO_ON; 592 } 593 594 static void 595 accesslog_append_buffer (buffer * const restrict dest, 596 const buffer * const restrict b, esc_fn_t esc_fn) 597 { 598 if (!buffer_string_is_empty(b)) 599 esc_fn(dest, BUF_PTR_LEN(b)); 600 else 601 buffer_append_char(dest, '-'); 602 } 603 604 static void 605 accesslog_append_bytes (buffer * const dest, off_t bytes, const uint32_t adj) 606 { 607 if (bytes > 0) 608 buffer_append_int(dest, (bytes -= (off_t)adj) > 0 ? bytes : 0); 609 else 610 buffer_append_char(dest, '-'); 611 } 612 613 __attribute_cold__ 614 __attribute_noinline__ 615 static void 616 accesslog_append_cookie (buffer * const restrict dest, 617 const request_st * const restrict r, 618 const buffer * const restrict name, 619 esc_fn_t esc_fn) 620 { 621 const buffer * const vb = 622 http_header_request_get(r, HTTP_HEADER_COOKIE, CONST_STR_LEN("Cookie")); 623 if (NULL == vb) return; 624 625 char *str = vb->ptr; 626 size_t len = buffer_clen(name); 627 do { 628 while (*str == ' ' || *str == '\t') ++str; 629 if (0 == strncmp(str, name->ptr, len) && str[len] == '=') { 630 char *v = str+len+1; 631 for (str = v; *str != '\0' && *str != ';'; ++str) ; 632 if (str == v) break; 633 do { --str; } while (str > v && (*str == ' ' || *str == '\t')); 634 esc_fn(dest, v, str - v + 1); 635 break; 636 } 637 else { 638 while (*str != ';' && *str != ' ' && *str != '\t' && *str != '\0') 639 ++str; 640 } 641 while (*str == ' ' || *str == '\t') ++str; 642 } while (*str++ == ';'); 643 } 644 645 static int 646 accesslog_append_time (buffer * const b, const request_st * const r, 647 const format_field * const f, 648 unix_timespec64_t * const ts, 649 format_fields * const parsed_format) 650 { 651 int flush = 0; 652 if (f->field == FORMAT_TIMESTAMP) { 653 if (f->opt & ~(FORMAT_FLAG_TIME_BEGIN|FORMAT_FLAG_TIME_END)) { 654 if (f->opt & FORMAT_FLAG_TIME_SEC) { 655 unix_time64_t t = (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) ? log_epoch_secs : r->start_hp.tv_sec; 656 buffer_append_int(b, (intmax_t)t); 657 } else if (f->opt & (FORMAT_FLAG_TIME_MSEC|FORMAT_FLAG_TIME_USEC|FORMAT_FLAG_TIME_NSEC)) { 658 unix_time64_t t; 659 long ns; 660 if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) { 661 if (0 == ts->tv_sec) log_clock_gettime_realtime(ts); 662 t = ts->tv_sec; 663 ns = ts->tv_nsec; 664 } else { 665 t = r->start_hp.tv_sec; 666 ns = r->start_hp.tv_nsec; 667 } 668 if (f->opt & FORMAT_FLAG_TIME_MSEC) { 669 t *= 1000; 670 t += (ns + 999999) / 1000000; /* ceil */ 671 } else if (f->opt & FORMAT_FLAG_TIME_USEC) { 672 t *= 1000000; 673 t += (ns + 999) / 1000; /* ceil */ 674 } else {/*(f->opt & FORMAT_FLAG_TIME_NSEC)*/ 675 t *= 1000000000; 676 t += ns; 677 } 678 buffer_append_int(b, (intmax_t)t); 679 } else { /*(FORMAT_FLAG_TIME_MSEC_FRAC|FORMAT_FLAG_TIME_USEC_FRAC|FORMAT_FLAG_TIME_NSEC_FRAC)*/ 680 long ns; 681 char *ptr; 682 if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) { 683 if (0 == ts->tv_sec) log_clock_gettime_realtime(ts); 684 ns = ts->tv_nsec; 685 } else { 686 ns = r->start_hp.tv_nsec; 687 } 688 /*assert(t < 1000000000);*/ 689 if (f->opt & FORMAT_FLAG_TIME_MSEC_FRAC) { 690 ns += 999999; /* ceil */ 691 ns /= 1000000; 692 buffer_append_string_len(b, CONST_STR_LEN("000")); 693 } else if (f->opt & FORMAT_FLAG_TIME_USEC_FRAC) { 694 ns += 999; /* ceil */ 695 ns /= 1000; 696 buffer_append_string_len(b, CONST_STR_LEN("000000")); 697 } else {/*(f->opt & FORMAT_FLAG_TIME_NSEC_FRAC)*/ 698 buffer_append_string_len(b, CONST_STR_LEN("000000000")); 699 } 700 ptr = b->ptr + buffer_clen(b); 701 for (long x; ns > 0; ns = x) 702 *--ptr += (ns - (x = ns/10) * 10); /* ns % 10 */ 703 } 704 } else { 705 buffer * const ts_accesslog_str = &parsed_format->ts_accesslog_str; 706 /* cache the generated timestamp (only if ! FORMAT_FLAG_TIME_BEGIN) */ 707 unix_time64_t t; 708 struct tm tm; 709 710 if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) { 711 const unix_time64_t cur_ts = log_epoch_secs; 712 if (parsed_format->last_generated_accesslog_ts == cur_ts) { 713 buffer_append_string_buffer(b, ts_accesslog_str); 714 return 0; /* flush == 0 */ 715 } 716 t = parsed_format->last_generated_accesslog_ts = cur_ts; 717 flush = 1; 718 } else { 719 t = r->start_hp.tv_sec; 720 } 721 722 const char *fmt = buffer_is_blank(&f->string) 723 ? NULL 724 : f->string.ptr; 725 buffer_clear(ts_accesslog_str); 726 #if defined(HAVE_STRUCT_TM_GMTOFF) 727 buffer_append_strftime(ts_accesslog_str, 728 fmt ? fmt : "[%d/%b/%Y:%T %z]", 729 localtime64_r(&t, &tm)); 730 #else /* HAVE_STRUCT_TM_GMTOFF */ 731 buffer_append_strftime(ts_accesslog_str, 732 fmt ? fmt : "[%d/%b/%Y:%T +0000]", 733 gmtime64_r(&t, &tm)); 734 #endif /* HAVE_STRUCT_TM_GMTOFF */ 735 buffer_append_string_buffer(b, ts_accesslog_str); 736 } 737 } 738 else { /* FORMAT_TIME_USED or FORMAT_TIME_USED_US */ 739 if (f->opt & FORMAT_FLAG_TIME_SEC) { 740 buffer_append_int(b, log_epoch_secs - r->start_hp.tv_sec); 741 } else { 742 const unix_timespec64_t * const bs = &r->start_hp; 743 off_t tdiff; /*(expected to be 64-bit since large file support enabled)*/ 744 if (0 == ts->tv_sec) log_clock_gettime_realtime(ts); 745 tdiff = (off_t)(ts->tv_sec - bs->tv_sec)*1000000000 + (ts->tv_nsec - bs->tv_nsec); 746 if (tdiff <= 0) { 747 /* sanity check for time moving backwards 748 * (daylight savings adjustment or leap seconds or ?) */ 749 tdiff = -1; 750 } else if (f->opt & FORMAT_FLAG_TIME_MSEC) { 751 tdiff += 999999; /* ceil */ 752 tdiff /= 1000000; 753 } else if (f->opt & FORMAT_FLAG_TIME_USEC) { 754 tdiff += 999; /* ceil */ 755 tdiff /= 1000; 756 } /* else (f->opt & FORMAT_FLAG_TIME_NSEC) */ 757 buffer_append_int(b, (intmax_t)tdiff); 758 } 759 } 760 return flush; 761 } 762 763 __attribute_cold__ 764 __attribute_noinline__ 765 static void 766 log_access_record_cold (buffer * const b, const request_st * const r, 767 const format_field * const f, esc_fn_t esc_fn) 768 { 769 connection * const con = r->con; 770 switch (f->field) { 771 case FORMAT_SERVER_PORT: 772 if (f->opt & FORMAT_FLAG_PORT_REMOTE) { 773 buffer_append_int(b, sock_addr_get_port(&con->dst_addr)); 774 break; 775 } 776 /* else if (f->opt & FORMAT_FLAG_PORT_LOCAL) *//*(default)*/ 777 __attribute_fallthrough__ 778 case FORMAT_LOCAL_ADDR: 779 { 780 const server_socket * const srv_sock = con->srv_socket; 781 const buffer * const srv_token = srv_sock->srv_token; 782 const uint32_t colon = srv_sock->srv_token_colon; 783 if (f->field == FORMAT_LOCAL_ADDR) 784 /* (perf: not using getsockname() and 785 * sock_addr_cache_inet_ntop_copy_buffer()) 786 * (still useful if admin has configured explicit listen IPs) */ 787 buffer_append_string_len(b, srv_token->ptr, colon); 788 else { /* FORMAT_SERVER_PORT */ 789 const uint32_t tlen = buffer_clen(srv_token); 790 if (colon < tlen) /*(colon != tlen)*/ 791 buffer_append_string_len(b, srv_token->ptr+colon+1, 792 tlen - (colon+1)); 793 } 794 } 795 break; 796 case FORMAT_KEEPALIVE_COUNT: 797 if (con->request_count > 1) 798 buffer_append_int(b, (intmax_t)(con->request_count-1)); 799 else 800 buffer_append_char(b, '0'); 801 break; 802 case FORMAT_URL: 803 { 804 const uint32_t len = buffer_clen(&r->target); 805 const char * const qmark = memchr(r->target.ptr, '?', len); 806 esc_fn(b, r->target.ptr, 807 qmark ? (uint32_t)(qmark - r->target.ptr) : len); 808 } 809 break; 810 case FORMAT_QUERY_STRING: 811 esc_fn(b, BUF_PTR_LEN(&r->uri.query)); 812 break; 813 case FORMAT_FILENAME: 814 accesslog_append_buffer(b, &r->physical.path, esc_fn); 815 break; 816 case FORMAT_CONNECTION_STATUS: 817 buffer_append_char(b, (r->state == CON_STATE_RESPONSE_END) 818 ? r->keep_alive <= 0 ? '-' : '+' 819 : 'X'); /* CON_STATE_ERROR */ 820 break; 821 #if 0 /*(parsed and replaced at startup)*/ 822 case FORMAT_REMOTE_IDENT: 823 /* ident */ 824 buffer_append_char(b, '-'); 825 break; 826 #endif 827 #if 0 /*(parsed and replaced at startup)*/ 828 case FORMAT_PERCENT: 829 buffer_append_char(b, '%'); 830 break; 831 #endif 832 default: 833 break; 834 } 835 } 836 837 static int log_access_record (const request_st * const r, buffer * const b, format_fields * const parsed_format, esc_fn_t esc) { 838 const buffer *vb; 839 unix_timespec64_t ts = { 0, 0 }; 840 int flush = 0; 841 842 for (const format_field *f = parsed_format->ptr; f->field != FORMAT_UNSET; ++f) { 843 switch(f->field) { 844 case FORMAT_LITERAL: 845 buffer_append_string_buffer(b, &f->string); 846 break; 847 case FORMAT_HEADER: 848 vb = http_header_request_get(r, f->opt, BUF_PTR_LEN(&f->string)); 849 accesslog_append_buffer(b, vb, esc); 850 break; 851 case FORMAT_RESPONSE_HEADER: 852 vb = http_header_response_get(r, f->opt, BUF_PTR_LEN(&f->string)); 853 accesslog_append_buffer(b, vb, esc); 854 break; 855 #if 0 /*(parsed and redirected at startup to FORMAT_ENV "REMOTE_USER")*/ 856 case FORMAT_REMOTE_USER: 857 vb = http_header_env_get(r, CONST_STR_LEN("REMOTE_USER")); 858 accesslog_append_buffer(b, vb, esc); 859 break; 860 #endif 861 #if 0 /*(parsed and redirected at startup to FORMAT_ENV)*/ 862 /*case FORMAT_NOTE:*/ 863 #endif 864 case FORMAT_ENV: 865 vb = http_header_env_get(r, BUF_PTR_LEN(&f->string)); 866 accesslog_append_buffer(b, vb, esc); 867 break; 868 case FORMAT_TIMESTAMP: 869 #if 0 /*(parsed and redirected at startup to FORMAT_TIME_USED)*/ 870 case FORMAT_TIME_USED_US: 871 #endif 872 case FORMAT_TIME_USED: 873 flush |= accesslog_append_time(b, r, f, &ts, parsed_format); 874 break; 875 #if 0 /*(parsed and redirected at startup to FORMAT_REMOTE_ADDR)*/ 876 /*case FORMAT_REMOTE_HOST:*/ 877 #endif 878 case FORMAT_REMOTE_ADDR: 879 buffer_append_string_buffer(b, &r->con->dst_addr_buf); 880 break; 881 case FORMAT_HTTP_HOST: 882 accesslog_append_buffer(b, &r->uri.authority, esc); 883 break; 884 case FORMAT_REQUEST_LINE: 885 /*(attempt to reconstruct request line)*/ 886 http_method_append(b, r->http_method); 887 buffer_append_char(b, ' '); 888 esc(b, BUF_PTR_LEN(&r->target_orig)); 889 buffer_append_char(b, ' '); 890 http_version_append(b, r->http_version); 891 break; 892 case FORMAT_STATUS: 893 buffer_append_int(b, r->http_status); 894 break; 895 case FORMAT_BYTES_OUT_NO_HEADER: 896 accesslog_append_bytes(b, http_request_stats_bytes_out(r), 897 r->resp_header_len); 898 break; 899 case FORMAT_BYTES_OUT: 900 accesslog_append_bytes(b, http_request_stats_bytes_out(r), 0); 901 break; 902 case FORMAT_BYTES_IN: 903 accesslog_append_bytes(b, http_request_stats_bytes_in(r), 0); 904 break; 905 case FORMAT_SERVER_NAME: 906 accesslog_append_buffer(b, r->server_name, esc); 907 break; 908 case FORMAT_REQUEST_PROTOCOL: 909 http_version_append(b, r->http_version); 910 break; 911 case FORMAT_REQUEST_METHOD: 912 http_method_append(b, r->http_method); 913 break; 914 case FORMAT_COOKIE: 915 accesslog_append_cookie(b, r, &f->string, esc); 916 break; 917 default: 918 log_access_record_cold(b, r, f, esc); 919 break; 920 } 921 } 922 923 return flush; 924 } 925 926 REQUESTDONE_FUNC(log_access_write) { 927 plugin_data * const p = p_d; 928 mod_accesslog_patch_config(r, p); 929 fdlog_st * const fdlog = p->conf.fdlog; 930 931 /* No output device, nothing to do */ 932 if (!p->conf.use_syslog && !fdlog) return HANDLER_GO_ON; 933 934 buffer * const b = (p->conf.use_syslog || fdlog->mode == FDLOG_PIPE) 935 ? (buffer_clear(r->tmp_buf), r->tmp_buf) 936 : &fdlog->b; 937 938 esc_fn_t * const esc_fn = !p->conf.escaping 939 ? buffer_append_bs_escaped 940 : buffer_append_bs_escaped_json; 941 const int flush = 942 log_access_record(r, b, p->conf.parsed_format, esc_fn); 943 944 #ifdef HAVE_SYSLOG_H 945 if (p->conf.use_syslog) { 946 if (!buffer_is_blank(b)) 947 syslog(p->conf.syslog_level, "%s", b->ptr); 948 return HANDLER_GO_ON; 949 } 950 #endif 951 952 buffer_append_char(b, '\n'); 953 954 if (flush || fdlog->mode == FDLOG_PIPE || buffer_clen(b) >= 8192) { 955 const ssize_t wr = write_all(fdlog->fd, BUF_PTR_LEN(b)); 956 buffer_clear(b); /*(clear buffer, even on error)*/ 957 if (-1 == wr) 958 log_perror(r->conf.errh, __FILE__, __LINE__, 959 "error flushing log %s", fdlog->fn); 960 } 961 962 return HANDLER_GO_ON; 963 } 964 965 966 __attribute_cold__ 967 int mod_accesslog_plugin_init(plugin *p); 968 int mod_accesslog_plugin_init(plugin *p) { 969 p->version = LIGHTTPD_VERSION_ID; 970 p->name = "accesslog"; 971 972 p->init = mod_accesslog_init; 973 p->set_defaults= mod_accesslog_set_defaults; 974 p->cleanup = mod_accesslog_free; 975 976 p->handle_request_done = log_access_write; 977 p->handle_trigger = log_access_periodic_flush; 978 979 return 0; 980 } 981