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