From 5e76b284df750e6c4196c4e24ff55be9271763f6 Mon Sep 17 00:00:00 2001 From: Glenn Strauss Date: Tue, 12 Jul 2016 20:41:53 -0400 Subject: [PATCH] [mod_accesslog] %a %A %C %D %k %{}t %{}T (fixes #1145, fixes #1415, fixes #2081) add support for additional commonly-used accesslog format flags x-ref: "mod_accesslog cookie field support %{VARNAME}C" https://redmine.lighttpd.net/issues/1145 "access_log : %D time used in ms (not supported)" https://redmine.lighttpd.net/issues/1415 "%{format}t support" https://redmine.lighttpd.net/issues/2081 --- src/base.h | 5 +- src/configfile.c | 1 + src/connections.c | 11 +- src/mod_accesslog.c | 345 ++++++++++++++++++++++++++++++++------------ src/server.c | 4 + 5 files changed, 269 insertions(+), 97 deletions(-) diff --git a/src/base.h b/src/base.h index 77bc44ed..e5db2e31 100644 --- a/src/base.h +++ b/src/base.h @@ -256,6 +256,7 @@ typedef struct { buffer *dirlist_encoding; buffer *errorfile_prefix; + unsigned short high_precision_timestamps; unsigned short max_keep_alive_requests; unsigned short max_keep_alive_idle; unsigned short max_read_idle; @@ -393,8 +394,7 @@ typedef struct { time_t connection_start; time_t request_start; - - struct timeval start_tv; + struct timespec request_start_hp; size_t request_count; /* number of requests handled in this connection */ size_t loops_per_request; /* to catch endless loops in a single request @@ -561,6 +561,7 @@ typedef struct { unsigned short http_header_strict; unsigned short http_host_strict; unsigned short http_host_normalize; + unsigned short high_precision_timestamps; } server_config; typedef struct server_socket { diff --git a/src/configfile.c b/src/configfile.c index 476c0e93..d845adc1 100644 --- a/src/configfile.c +++ b/src/configfile.c @@ -438,6 +438,7 @@ int config_setup_connection(server *srv, connection *con) { PATCH(allow_http11); PATCH(mimetypes); PATCH(document_root); + PATCH(high_precision_timestamps); PATCH(max_keep_alive_requests); PATCH(max_keep_alive_idle); PATCH(max_read_idle); diff --git a/src/connections.c b/src/connections.c index d2a6da18..e73a667e 100644 --- a/src/connections.c +++ b/src/connections.c @@ -689,7 +689,11 @@ static int connection_handle_read_state(server *srv, connection *con) { /* update request_start timestamp when first byte of * next request is received on a keep-alive connection */ - if (con->request_count > 1 && is_request_start) con->request_start = srv->cur_ts; + if (con->request_count > 1 && is_request_start) { + con->request_start = srv->cur_ts; + if (con->conf.high_precision_timestamps) + clock_gettime(CLOCK_REALTIME, &con->request_start_hp); + } /* if there is a \r\n\r\n in the chunkqueue * @@ -932,9 +936,6 @@ connection *connection_accepted(server *srv, server_socket *srv_socket, sock_add con->fd = cnt; con->fde_ndx = -1; -#if 0 - gettimeofday(&(con->start_tv), NULL); -#endif fdevent_register(srv->ev, con->fd, connection_handle_fdevent, con); connection_set_state(srv, con, CON_STATE_REQUEST_START); @@ -998,6 +999,8 @@ int connection_state_machine(server *srv, connection *con) { con->request_start = srv->cur_ts; con->read_idle_ts = srv->cur_ts; + if (con->conf.high_precision_timestamps) + clock_gettime(CLOCK_REALTIME, &con->request_start_hp); con->request_count++; con->loops_per_request = 0; diff --git a/src/mod_accesslog.c b/src/mod_accesslog.c index 45039ce0..043defb7 100644 --- a/src/mod_accesslog.c +++ b/src/mod_accesslog.c @@ -6,10 +6,6 @@ #include "plugin.h" -#include "inet_ntop_cache.h" - -#include "sys-socket.h" - #include #include @@ -45,7 +41,7 @@ typedef struct { FORMAT_REMOTE_ADDR, FORMAT_LOCAL_ADDR, FORMAT_COOKIE, - FORMAT_TIME_USED_MS, + FORMAT_TIME_USED_US, FORMAT_ENV, FORMAT_FILENAME, FORMAT_REQUEST_PROTOCOL, @@ -60,6 +56,7 @@ typedef struct { FORMAT_BYTES_IN, FORMAT_BYTES_OUT, + FORMAT_KEEPALIVE_COUNT, FORMAT_RESPONSE_HEADER } type; } format_mapping; @@ -87,10 +84,11 @@ static const format_mapping fmap[] = { 'A', FORMAT_LOCAL_ADDR }, { 'B', FORMAT_BYTES_OUT_NO_HEADER }, { 'C', FORMAT_COOKIE }, - { 'D', FORMAT_TIME_USED_MS }, + { 'D', FORMAT_TIME_USED_US }, { 'e', FORMAT_ENV }, { 'f', FORMAT_FILENAME }, { 'H', FORMAT_REQUEST_PROTOCOL }, + { 'k', FORMAT_KEEPALIVE_COUNT }, { 'm', FORMAT_REQUEST_METHOD }, { 'n', FORMAT_UNSUPPORTED }, /* we have no notes */ { 'p', FORMAT_SERVER_PORT }, @@ -110,11 +108,27 @@ static const format_mapping fmap[] = }; +enum e_optflags_time { + /* format string is passed to strftime unless other format optflags set + * (besides FORMAT_FLAG_TIME_BEGIN or FORMAT_FLAG_TIME_END) */ + FORMAT_FLAG_TIME_END = 0x00,/* use request end time (default) */ + FORMAT_FLAG_TIME_BEGIN = 0x01,/* use request start time */ + FORMAT_FLAG_TIME_SEC = 0x02,/* request time as num sec since epoch */ + FORMAT_FLAG_TIME_MSEC = 0x04,/* request time as num msec since epoch */ + FORMAT_FLAG_TIME_USEC = 0x08,/* request time as num usec since epoch */ + FORMAT_FLAG_TIME_NSEC = 0x10,/* request time as num nsec since epoch */ + FORMAT_FLAG_TIME_MSEC_FRAC = 0x20,/* request time msec fraction */ + FORMAT_FLAG_TIME_USEC_FRAC = 0x40,/* request time usec fraction */ + FORMAT_FLAG_TIME_NSEC_FRAC = 0x80 /* request time nsec fraction */ +}; + + typedef struct { enum { FIELD_UNSET, FIELD_STRING, FIELD_FORMAT } type; buffer *string; int field; + int opt; } format_field; typedef struct { @@ -138,8 +152,6 @@ typedef struct { time_t *last_generated_accesslog_ts_ptr; buffer *ts_accesslog_str; - buffer *ts_accesslog_fmt_str; - unsigned short append_tz_offset; format_fields *parsed_format; } plugin_config; @@ -288,6 +300,7 @@ static int accesslog_parse_format(server *srv, format_fields *fields, buffer *fo fields->ptr[fields->used]->type = FIELD_FORMAT; fields->ptr[fields->used]->field = fmap[j].type; fields->ptr[fields->used]->string = NULL; + fields->ptr[fields->used]->opt = 0; fields->used++; @@ -335,6 +348,7 @@ static int accesslog_parse_format(server *srv, format_fields *fields, buffer *fo fields->ptr[fields->used]->type = FIELD_FORMAT; fields->ptr[fields->used]->field = fmap[j].type; fields->ptr[fields->used]->string = buffer_init(); + fields->ptr[fields->used]->opt = 0; buffer_copy_string_len(fields->ptr[fields->used]->string, format->ptr + i + 2, k - (i + 2)); @@ -368,6 +382,7 @@ static int accesslog_parse_format(server *srv, format_fields *fields, buffer *fo fields->ptr[fields->used]->type = FIELD_FORMAT; fields->ptr[fields->used]->field = fmap[j].type; fields->ptr[fields->used]->string = NULL; + fields->ptr[fields->used]->opt = 0; fields->used++; @@ -434,7 +449,6 @@ FREE_FUNC(mod_accesslog_free) { if (s->log_access_fd != -1) close(s->log_access_fd); buffer_free(s->ts_accesslog_str); - buffer_free(s->ts_accesslog_fmt_str); buffer_free(s->access_logbuffer); buffer_free(s->format); buffer_free(s->access_logfile); @@ -486,7 +500,6 @@ SETDEFAULTS_FUNC(log_access_open) { s->format = buffer_init(); s->access_logbuffer = buffer_init(); s->ts_accesslog_str = buffer_init(); - s->ts_accesslog_fmt_str = buffer_init(); s->log_access_fd = -1; s->last_generated_accesslog_ts = 0; s->last_generated_accesslog_ts_ptr = &(s->last_generated_accesslog_ts); @@ -513,7 +526,7 @@ SETDEFAULTS_FUNC(log_access_open) { /* parse */ if (!buffer_is_empty(s->format)) { - size_t j, count; + size_t j, tcount = 0; s->parsed_format = calloc(1, sizeof(*(s->parsed_format))); @@ -525,25 +538,65 @@ SETDEFAULTS_FUNC(log_access_open) { return HANDLER_ERROR; } - /* make sure they didn't try to send the timestamp in twice... - * also, save the format string in a different variable (this - * will save a few conditionals later) - */ - count = 0; - for (j = 0; j < s->parsed_format->used; j++) { - if (FIELD_FORMAT == s->parsed_format->ptr[j]->type) { - if (FORMAT_TIMESTAMP == s->parsed_format->ptr[j]->field) { - if (!buffer_string_is_empty(s->parsed_format->ptr[j]->string)) { - buffer_copy_string(s->ts_accesslog_fmt_str, s->parsed_format->ptr[j]->string->ptr); + for (j = 0; j < s->parsed_format->used; ++j) { + format_field * const f = s->parsed_format->ptr[j]; + if (FIELD_FORMAT != f->type) continue; + if (FORMAT_TIMESTAMP == f->field) { + if (!buffer_string_is_empty(f->string)) { + const char *ptr = f->string->ptr; + if (0 == strncmp(ptr, "begin:", sizeof("begin:")-1)) { + f->opt |= FORMAT_FLAG_TIME_BEGIN; + ptr += sizeof("begin:")-1; + } else if (0 == strncmp(ptr, "end:", sizeof("end:")-1)) { + f->opt |= FORMAT_FLAG_TIME_END; + ptr += sizeof("end:")-1; } - - if (++count > 1) { + if (0 == strcmp(ptr, "sec")) f->opt |= FORMAT_FLAG_TIME_SEC; + else if (0 == strcmp(ptr, "msec")) f->opt |= FORMAT_FLAG_TIME_MSEC; + else if (0 == strcmp(ptr, "usec")) f->opt |= FORMAT_FLAG_TIME_USEC; + else if (0 == strcmp(ptr, "nsec")) f->opt |= FORMAT_FLAG_TIME_NSEC; + else if (0 == strcmp(ptr, "msec_frac")) f->opt |= FORMAT_FLAG_TIME_MSEC_FRAC; + else if (0 == strcmp(ptr, "usec_frac")) f->opt |= FORMAT_FLAG_TIME_USEC_FRAC; + else if (0 == strcmp(ptr, "nsec_frac")) f->opt |= FORMAT_FLAG_TIME_NSEC_FRAC; + else if (NULL == strchr(ptr, '%')) { log_error_write(srv, __FILE__, __LINE__, "sb", - "you may not use the timestamp twice in the same access log:", s->format); + "constant string for time format (misspelled token? or missing '%'):", s->format); return HANDLER_ERROR; } } + + /* make sure they didn't try to send the timestamp in twice + * (would invalidate s->ts_accesslog_str cache of timestamp str) */ + if (!(f->opt & ~(FORMAT_FLAG_TIME_BEGIN|FORMAT_FLAG_TIME_END|FORMAT_FLAG_TIME_SEC)) && ++tcount > 1) { + log_error_write(srv, __FILE__, __LINE__, "sb", + "you may not use strftime timestamp format %{}t twice in the same access log:", s->format); + + return HANDLER_ERROR; + } + + if (f->opt & FORMAT_FLAG_TIME_BEGIN) srv->srvconf.high_precision_timestamps = 1; + } else if (FORMAT_TIME_USED_US == f->field) { + f->opt |= FORMAT_FLAG_TIME_USEC; + srv->srvconf.high_precision_timestamps = 1; + } else if (FORMAT_TIME_USED == f->field) { + const char * const ptr = f->string->ptr; + + if (f->opt & ~(FORMAT_FLAG_TIME_SEC)) srv->srvconf.high_precision_timestamps = 1; + + if (buffer_string_is_empty(f->string) + || 0 == strcmp(ptr, "s") || 0 == strcmp(ptr, "sec")) f->opt |= FORMAT_FLAG_TIME_SEC; + else if (0 == strcmp(ptr, "ms") || 0 == strcmp(ptr, "msec")) f->opt |= FORMAT_FLAG_TIME_MSEC; + else if (0 == strcmp(ptr, "us") || 0 == strcmp(ptr, "usec")) f->opt |= FORMAT_FLAG_TIME_USEC; + else if (0 == strcmp(ptr, "ns") || 0 == strcmp(ptr, "nsec")) f->opt |= FORMAT_FLAG_TIME_NSEC; + else { + log_error_write(srv, __FILE__, __LINE__, "sb", + "invalid time unit in %{UNIT}T:", s->format); + + return HANDLER_ERROR; + } + } else if (FORMAT_COOKIE == f->field) { + if (buffer_string_is_empty(f->string)) f->type = FIELD_STRING; /*(blank)*/ } } @@ -567,16 +620,6 @@ SETDEFAULTS_FUNC(log_access_open) { #endif } - s->append_tz_offset = 0; - if (buffer_string_is_empty(s->ts_accesslog_fmt_str)) { -#if defined(HAVE_STRUCT_TM_GMTOFF) - BUFFER_COPY_STRING_CONST(s->ts_accesslog_fmt_str, "[%d/%b/%Y:%H:%M:%S "); - s->append_tz_offset = 1; -#else - BUFFER_COPY_STRING_CONST(s->ts_accesslog_fmt_str, "[%d/%b/%Y:%H:%M:%S +0000]"); -#endif - } - if (s->use_syslog) { /* ignore the next checks */ continue; @@ -638,13 +681,10 @@ static int mod_accesslog_patch_connection(server *srv, connection *con, plugin_d plugin_config *s = p->config_storage[0]; PATCH(access_logfile); - PATCH(format); PATCH(log_access_fd); PATCH(last_generated_accesslog_ts_ptr); PATCH(access_logbuffer); PATCH(ts_accesslog_str); - PATCH(ts_accesslog_fmt_str); - PATCH(append_tz_offset); PATCH(parsed_format); PATCH(use_syslog); PATCH(syslog_level); @@ -666,12 +706,9 @@ static int mod_accesslog_patch_connection(server *srv, connection *con, plugin_d PATCH(log_access_fd); PATCH(access_logbuffer); } else if (buffer_is_equal_string(du->key, CONST_STR_LEN("accesslog.format"))) { - PATCH(format); PATCH(parsed_format); PATCH(last_generated_accesslog_ts_ptr); PATCH(ts_accesslog_str); - PATCH(ts_accesslog_fmt_str); - PATCH(append_tz_offset); } else if (buffer_is_equal_string(du->key, CONST_STR_LEN("accesslog.use-syslog"))) { PATCH(use_syslog); } else if (buffer_is_equal_string(du->key, CONST_STR_LEN("accesslog.syslog-level"))) { @@ -691,6 +728,7 @@ REQUESTDONE_FUNC(log_access_write) { int newts = 0; data_string *ds; + struct timespec ts = { 0, 0 }; mod_accesslog_patch_connection(srv, con, p); @@ -708,34 +746,111 @@ REQUESTDONE_FUNC(log_access_write) { } for (j = 0; j < p->conf.parsed_format->used; j++) { - switch(p->conf.parsed_format->ptr[j]->type) { + const format_field * const f = p->conf.parsed_format->ptr[j]; + switch(f->type) { case FIELD_STRING: - buffer_append_string_buffer(b, p->conf.parsed_format->ptr[j]->string); + buffer_append_string_buffer(b, f->string); break; case FIELD_FORMAT: - switch(p->conf.parsed_format->ptr[j]->field) { + switch(f->field) { case FORMAT_TIMESTAMP: - /* cache the generated timestamp */ - if (srv->cur_ts != *(p->conf.last_generated_accesslog_ts_ptr)) { + if (f->opt & ~(FORMAT_FLAG_TIME_BEGIN|FORMAT_FLAG_TIME_END)) { + if (f->opt & FORMAT_FLAG_TIME_SEC) { + time_t t = (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) ? srv->cur_ts : con->request_start; + buffer_append_int(b, (intmax_t)t); + } else if (f->opt & (FORMAT_FLAG_TIME_MSEC|FORMAT_FLAG_TIME_USEC|FORMAT_FLAG_TIME_NSEC)) { + off_t t; /*(expected to be 64-bit since large file support enabled)*/ + long ns; + if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) { + if (0 == ts.tv_sec) clock_gettime(CLOCK_REALTIME, &ts); + t = (off_t)ts.tv_sec; + ns = ts.tv_nsec; + } else { + t = (off_t)con->request_start_hp.tv_sec; + ns = con->request_start_hp.tv_nsec; + } + if (f->opt & FORMAT_FLAG_TIME_MSEC) { + t *= 1000; + t += (ns + 999999) / 1000000; /* ceil */ + } else if (f->opt & FORMAT_FLAG_TIME_USEC) { + t *= 1000000; + t += (ns + 999) / 1000; /* ceil */ + } else {/*(f->opt & FORMAT_FLAG_TIME_NSEC)*/ + t *= 1000000000; + t += ns; + } + buffer_append_int(b, (intmax_t)t); + } else { /*(FORMAT_FLAG_TIME_MSEC_FRAC|FORMAT_FLAG_TIME_USEC_FRAC|FORMAT_FLAG_TIME_NSEC_FRAC)*/ + long ns; + char *ptr; + if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) { + if (0 == ts.tv_sec) clock_gettime(CLOCK_REALTIME, &ts); + ns = ts.tv_nsec; + } else { + ns = con->request_start_hp.tv_nsec; + } + /*assert(t < 1000000000);*/ + if (f->opt & FORMAT_FLAG_TIME_MSEC_FRAC) { + ns += 999999; /* ceil */ + ns /= 1000000; + buffer_append_string_len(b, CONST_STR_LEN("000")); + } else if (f->opt & FORMAT_FLAG_TIME_USEC_FRAC) { + ns += 999; /* ceil */ + ns /= 1000; + buffer_append_string_len(b, CONST_STR_LEN("000000")); + } else {/*(f->opt & FORMAT_FLAG_TIME_NSEC_FRAC)*/ + buffer_append_string_len(b, CONST_STR_LEN("000000000")); + } + for (ptr = b->ptr + buffer_string_length(b); ns > 0; ns /= 10) + *--ptr = (ns % 10) + '0'; + } + } else if (!(f->opt & FORMAT_FLAG_TIME_BEGIN) && srv->cur_ts == *(p->conf.last_generated_accesslog_ts_ptr)) { + buffer_append_string_buffer(b, p->conf.ts_accesslog_str); + } else { + /* cache the generated timestamp (only if ! FORMAT_FLAG_TIME_BEGIN) */ + struct tm *tmptr; + time_t t; + #if defined(HAVE_STRUCT_TM_GMTOFF) + # ifdef HAVE_LOCALTIME_R struct tm tm; -#if defined(HAVE_STRUCT_TM_GMTOFF) - long scd, hrs, min; -#endif + # endif /* HAVE_LOCALTIME_R */ + #else /* HAVE_STRUCT_TM_GMTOFF */ + # ifdef HAVE_GMTIME_R + struct tm tm; + # endif /* HAVE_GMTIME_R */ + #endif /* HAVE_STRUCT_TM_GMTOFF */ + + if (!(f->opt & FORMAT_FLAG_TIME_BEGIN)) { + t = *(p->conf.last_generated_accesslog_ts_ptr) = srv->cur_ts; + newts = 1; + } else { + t = con->request_start; + } + + #if defined(HAVE_STRUCT_TM_GMTOFF) + # ifdef HAVE_LOCALTIME_R + tmptr = localtime_r(&t, &tm); + # else /* HAVE_LOCALTIME_R */ + tmptr = localtime(&t); + # endif /* HAVE_LOCALTIME_R */ + #else /* HAVE_STRUCT_TM_GMTOFF */ + # ifdef HAVE_GMTIME_R + tmptr = gmtime_r(&t, &tm); + # else /* HAVE_GMTIME_R */ + tmptr = gmtime(&t); + # endif /* HAVE_GMTIME_R */ + #endif /* HAVE_STRUCT_TM_GMTOFF */ buffer_string_prepare_copy(p->conf.ts_accesslog_str, 255); -#if defined(HAVE_STRUCT_TM_GMTOFF) -# ifdef HAVE_LOCALTIME_R - localtime_r(&(srv->cur_ts), &tm); - buffer_append_strftime(p->conf.ts_accesslog_str, p->conf.ts_accesslog_fmt_str->ptr, &tm); -# else /* HAVE_LOCALTIME_R */ - buffer_append_strftime(p->conf.ts_accesslog_str, p->conf.ts_accesslog_fmt_str->ptr, localtime(&(srv->cur_ts))); -# endif /* HAVE_LOCALTIME_R */ - - if (p->conf.append_tz_offset) { - buffer_append_string_len(p->conf.ts_accesslog_str, tm.tm_gmtoff >= 0 ? "+" : "-", 1); - - scd = labs(tm.tm_gmtoff); + + if (buffer_string_is_empty(f->string)) { + #if defined(HAVE_STRUCT_TM_GMTOFF) + long scd, hrs, min; + buffer_append_strftime(p->conf.ts_accesslog_str, "[%d/%b/%Y:%H:%M:%S ", tmptr); + buffer_append_string_len(p->conf.ts_accesslog_str, tmptr->tm_gmtoff >= 0 ? "+" : "-", 1); + + scd = labs(tmptr->tm_gmtoff); hrs = scd / 3600; min = (scd % 3600) / 60; @@ -746,29 +861,38 @@ REQUESTDONE_FUNC(log_access_write) { if (min < 10) buffer_append_string_len(p->conf.ts_accesslog_str, CONST_STR_LEN("0")); buffer_append_int(p->conf.ts_accesslog_str, min); buffer_append_string_len(p->conf.ts_accesslog_str, CONST_STR_LEN("]")); + #else + buffer_append_strftime(p->conf.ts_accesslog_str, "[%d/%b/%Y:%H:%M:%S +0000]", tmptr); + #endif /* HAVE_STRUCT_TM_GMTOFF */ + } else { + buffer_append_strftime(p->conf.ts_accesslog_str, f->string->ptr, tmptr); } -#else /* HAVE_STRUCT_TM_GMTOFF */ -# ifdef HAVE_GMTIME_R - gmtime_r(&(srv->cur_ts), &tm); - buffer_append_strftime(p->conf.ts_accesslog_str, p->conf.ts_accesslog_fmt_str->ptr, &tm); -# else /* HAVE_GMTIME_R */ - buffer_append_strftime(p->conf.ts_accesslog_str, p->conf.ts_accesslog_fmt_str->ptr, gmtime(&(srv->cur_ts))); -# endif /* HAVE_GMTIME_R */ -#endif /* HAVE_STRUCT_TM_GMTOFF */ - *(p->conf.last_generated_accesslog_ts_ptr) = srv->cur_ts; - newts = 1; + buffer_append_string_buffer(b, p->conf.ts_accesslog_str); + } + break; + case FORMAT_TIME_USED: + case FORMAT_TIME_USED_US: + if (f->opt & FORMAT_FLAG_TIME_SEC) { + buffer_append_int(b, srv->cur_ts - con->request_start); + } else { + const struct timespec * const bs = &con->request_start_hp; + off_t tdiff; /*(expected to be 64-bit since large file support enabled)*/ + if (0 == ts.tv_sec) clock_gettime(CLOCK_REALTIME, &ts); + tdiff = (off_t)(ts.tv_sec - bs->tv_sec)*1000000000 + (ts.tv_nsec - bs->tv_nsec); + if (f->opt & FORMAT_FLAG_TIME_MSEC) { + tdiff += 999999; /* ceil */ + tdiff /= 1000000; + } else if (f->opt & FORMAT_FLAG_TIME_USEC) { + tdiff += 999; /* ceil */ + tdiff /= 1000; + } /* else (f->opt & FORMAT_FLAG_TIME_NSEC) */ + buffer_append_int(b, (intmax_t)tdiff); } - - buffer_append_string_buffer(b, p->conf.ts_accesslog_str); - break; + case FORMAT_REMOTE_ADDR: case FORMAT_REMOTE_HOST: - - /* handle inet_ntop cache */ - - buffer_append_string(b, inet_ntop_cache_get_ip(srv, &(con->dst_addr))); - + buffer_append_string_buffer(b, con->dst_addr_buf); break; case FORMAT_REMOTE_IDENT: /* ident */ @@ -799,21 +923,21 @@ REQUESTDONE_FUNC(log_access_write) { } break; case FORMAT_HEADER: - if (NULL != (ds = (data_string *)array_get_element(con->request.headers, p->conf.parsed_format->ptr[j]->string->ptr))) { + if (NULL != (ds = (data_string *)array_get_element(con->request.headers, f->string->ptr))) { accesslog_append_escaped(b, ds->value); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; case FORMAT_RESPONSE_HEADER: - if (NULL != (ds = (data_string *)array_get_element(con->response.headers, p->conf.parsed_format->ptr[j]->string->ptr))) { + if (NULL != (ds = (data_string *)array_get_element(con->response.headers, f->string->ptr))) { accesslog_append_escaped(b, ds->value); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; case FORMAT_ENV: - if (NULL != (ds = (data_string *)array_get_element(con->environment, p->conf.parsed_format->ptr[j]->string->ptr))) { + if (NULL != (ds = (data_string *)array_get_element(con->environment, f->string->ptr))) { accesslog_append_escaped(b, ds->value); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); @@ -840,9 +964,6 @@ REQUESTDONE_FUNC(log_access_write) { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; - case FORMAT_TIME_USED: - buffer_append_int(b, srv->cur_ts - con->request_start); - break; case FORMAT_SERVER_NAME: if (!buffer_string_is_empty(con->server_name)) { buffer_append_string_buffer(b, con->server_name); @@ -867,6 +988,24 @@ REQUESTDONE_FUNC(log_access_write) { case FORMAT_PERCENT: buffer_append_string_len(b, CONST_STR_LEN("%")); break; + case FORMAT_LOCAL_ADDR: + { + /* (perf: not using getsockname() and inet_ntop_cache_get_ip()) + * (still useful if admin has configured explicit listen IPs) */ + const char *colon; + buffer *srvtoken = con->srv_socket->srv_token; + if (srvtoken->ptr[0] == '[') { + colon = strstr(srvtoken->ptr, "]:"); + } else { + colon = strchr(srvtoken->ptr, ':'); + } + if (colon) { + buffer_append_string_len(b, srvtoken->ptr, (size_t)(colon - srvtoken->ptr)); + } else { + buffer_append_string_buffer(b, srvtoken); + } + } + break; case FORMAT_SERVER_PORT: { const char *colon; @@ -900,14 +1039,38 @@ REQUESTDONE_FUNC(log_access_write) { buffer_append_string_len(b, CONST_STR_LEN("X")); } break; + case FORMAT_KEEPALIVE_COUNT: + if (con->request_count > 1) { + buffer_append_int(b, (intmax_t)(con->request_count-1)); + } else { + buffer_append_string_len(b, CONST_STR_LEN("0")); + } + break; + case FORMAT_COOKIE: + if (NULL != (ds = (data_string *)array_get_element(con->request.headers, "Cookie"))) { + char *str = ds->value->ptr; + size_t len = buffer_string_length(f->string); + do { + while (*str == ' ' || *str == '\t') ++str; + if (0 == strncmp(str, f->string->ptr, len) && str[len] == '=') { + char *v = str+len+1; + buffer *bstr; + for (str = v; *str != '\0' && *str != ';'; ++str) ; + if (str == v) break; + do { --str; } while (str > v && (*str == ' ' || *str == '\t')); + bstr = buffer_init(); + buffer_copy_string_len(bstr, v, str - v + 1); + accesslog_append_escaped(b, bstr); + buffer_free(bstr); + break; + } else { + do { ++str; } while (*str != ' ' && *str != '\t' && *str != '\0'); + } + while (*str == ' ' || *str == '\t') ++str; + } while (*str++ == ';'); + } + break; default: - /* - { 'a', FORMAT_REMOTE_ADDR }, - { 'A', FORMAT_LOCAL_ADDR }, - { 'C', FORMAT_COOKIE }, - { 'D', FORMAT_TIME_USED_MS }, - */ - break; } break; diff --git a/src/server.c b/src/server.c index a55c315c..ddab20e5 100644 --- a/src/server.c +++ b/src/server.c @@ -280,6 +280,7 @@ static server *server_init(void) { srv->srvconf.http_header_strict = 1; srv->srvconf.http_host_strict = 1; /*(implies http_host_normalize)*/ srv->srvconf.http_host_normalize = 0; + srv->srvconf.high_precision_timestamps = 0; /* use syslog */ srv->errorlog_fd = STDERR_FILENO; @@ -1272,6 +1273,9 @@ int main (int argc, char **argv) { return -1; } + /* settings might be enabled during module config set defaults */ + srv->config_storage[0]->high_precision_timestamps = srv->srvconf.high_precision_timestamps; + /* dump unused config-keys */ for (i = 0; i < srv->config_context->used; i++) { array *config = ((data_config *)srv->config_context->data[i])->value;