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