--- embedaddon/lighttpd/src/mod_accesslog.c 2014/06/15 20:20:06 1.1.1.2 +++ embedaddon/lighttpd/src/mod_accesslog.c 2016/11/02 10:35:00 1.1.1.3 @@ -1,13 +1,11 @@ +#include "first.h" + #include "base.h" #include "log.h" #include "buffer.h" #include "plugin.h" -#include "inet_ntop_cache.h" - -#include "sys-socket.h" - #include #include @@ -43,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, @@ -58,6 +56,7 @@ typedef struct { FORMAT_BYTES_IN, FORMAT_BYTES_OUT, + FORMAT_KEEPALIVE_COUNT, FORMAT_RESPONSE_HEADER } type; } format_mapping; @@ -85,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 }, @@ -108,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 { @@ -136,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; @@ -160,16 +174,23 @@ INIT_FUNC(mod_accesslog_init) { return p; } +static void accesslog_write_all(server *srv, const buffer *filename, int fd, const void* buf, size_t count) { + if (-1 == write_all(fd, buf, count)) { + log_error_write(srv, __FILE__, __LINE__, "sbs", + "writing access log entry failed:", filename, strerror(errno)); + } +} + static void accesslog_append_escaped(buffer *dest, buffer *str) { char *ptr, *start, *end; /* replaces non-printable chars with \xHH where HH is the hex representation of the byte */ /* exceptions: " => \", \ => \\, whitespace chars => \n \t etc. */ - if (str->used == 0) return; - buffer_prepare_append(dest, str->used - 1); + if (buffer_string_is_empty(str)) return; + buffer_string_prepare_append(dest, buffer_string_length(str)); - for (ptr = start = str->ptr, end = str->ptr + str->used - 1; ptr < end; ptr++) { - char const c = *ptr; + for (ptr = start = str->ptr, end = str->ptr + buffer_string_length(str); ptr < end; ptr++) { + unsigned char const c = (unsigned char) *ptr; if (c >= ' ' && c <= '~' && c != '"' && c != '\\') { /* nothing to change, add later as one block */ } else { @@ -223,9 +244,9 @@ static void accesslog_append_escaped(buffer *dest, buf static int accesslog_parse_format(server *srv, format_fields *fields, buffer *format) { size_t i, j, k = 0, start = 0; - if (format->used == 0) return -1; + if (buffer_is_empty(format)) return -1; - for (i = 0; i < format->used - 1; i++) { + for (i = 0; i < buffer_string_length(format); i++) { switch(format->ptr[i]) { case '%': if (i > 0 && start != i) { @@ -279,6 +300,7 @@ static int accesslog_parse_format(server *srv, format_ 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++; @@ -297,11 +319,11 @@ static int accesslog_parse_format(server *srv, format_ case '{': /* go forward to } */ - for (k = i+2; k < format->used - 1; k++) { + for (k = i+2; k < buffer_string_length(format); k++) { if (format->ptr[k] == '}') break; } - if (k == format->used - 1) { + if (k == buffer_string_length(format)) { log_error_write(srv, __FILE__, __LINE__, "s", "%{ has to be terminated by a }"); return -1; } @@ -326,6 +348,7 @@ static int accesslog_parse_format(server *srv, format_ 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)); @@ -359,6 +382,7 @@ static int accesslog_parse_format(server *srv, format_ 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++; @@ -414,18 +438,17 @@ FREE_FUNC(mod_accesslog_free) { for (i = 0; i < srv->config_context->used; i++) { plugin_config *s = p->config_storage[i]; - if (!s) continue; + if (NULL == s) continue; - if (s->access_logbuffer->used) { + if (!buffer_string_is_empty(s->access_logbuffer)) { if (s->log_access_fd != -1) { - write(s->log_access_fd, s->access_logbuffer->ptr, s->access_logbuffer->used - 1); + accesslog_write_all(srv, s->access_logfile, s->log_access_fd, CONST_BUF_LEN(s->access_logbuffer)); } } 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); @@ -469,6 +492,7 @@ SETDEFAULTS_FUNC(log_access_open) { p->config_storage = calloc(1, srv->config_context->used * sizeof(plugin_config *)); for (i = 0; i < srv->config_context->used; i++) { + data_config const* config = (data_config const*)srv->config_context->data[i]; plugin_config *s; s = calloc(1, sizeof(plugin_config)); @@ -476,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); @@ -490,11 +513,11 @@ SETDEFAULTS_FUNC(log_access_open) { p->config_storage[i] = s; - if (0 != config_insert_values_global(srv, ((data_config *)srv->config_context->data[i])->value, cv)) { + if (0 != config_insert_values_global(srv, config->value, cv, i == 0 ? T_CONFIG_SCOPE_SERVER : T_CONFIG_SCOPE_CONNECTION)) { return HANDLER_ERROR; } - if (i == 0 && buffer_is_empty(s->format)) { + if (i == 0 && buffer_string_is_empty(s->format)) { /* set a default logfile string */ buffer_copy_string_len(s->format, CONST_STR_LEN("%h %V %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"")); @@ -502,8 +525,8 @@ SETDEFAULTS_FUNC(log_access_open) { /* parse */ - if (s->format->used) { - size_t j, count; + if (!buffer_is_empty(s->format)) { + size_t j, tcount = 0; s->parsed_format = calloc(1, sizeof(*(s->parsed_format))); @@ -515,25 +538,67 @@ 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_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) { + if (f->opt & ~(FORMAT_FLAG_TIME_SEC)) srv->srvconf.high_precision_timestamps = 1; + + if (buffer_string_is_empty(f->string) + || buffer_is_equal_string(f->string, CONST_STR_LEN("s")) + || buffer_is_equal_string(f->string, CONST_STR_LEN("sec"))) f->opt |= FORMAT_FLAG_TIME_SEC; + else if (buffer_is_equal_string(f->string, CONST_STR_LEN("ms")) + || buffer_is_equal_string(f->string, CONST_STR_LEN("msec"))) f->opt |= FORMAT_FLAG_TIME_MSEC; + else if (buffer_is_equal_string(f->string, CONST_STR_LEN("us")) + || buffer_is_equal_string(f->string, CONST_STR_LEN("usec"))) f->opt |= FORMAT_FLAG_TIME_USEC; + else if (buffer_is_equal_string(f->string, CONST_STR_LEN("ns")) + || buffer_is_equal_string(f->string, CONST_STR_LEN("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)*/ } } @@ -557,23 +622,15 @@ SETDEFAULTS_FUNC(log_access_open) { #endif } - s->append_tz_offset = 0; - if (buffer_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; } - if (s->access_logfile->used < 2) continue; + if (buffer_string_is_empty(s->access_logfile)) continue; + if (srv->srvconf.preflight_check) continue; + if (-1 == (s->log_access_fd = open_logfile_or_pipe(srv, s->access_logfile->ptr))) return HANDLER_ERROR; @@ -591,17 +648,17 @@ SIGHUP_FUNC(log_access_cycle) { for (i = 0; i < srv->config_context->used; i++) { plugin_config *s = p->config_storage[i]; - if (s->access_logbuffer->used) { + if (!buffer_string_is_empty(s->access_logbuffer)) { if (s->log_access_fd != -1) { - write(s->log_access_fd, s->access_logbuffer->ptr, s->access_logbuffer->used - 1); + accesslog_write_all(srv, s->access_logfile, s->log_access_fd, CONST_BUF_LEN(s->access_logbuffer)); } buffer_reset(s->access_logbuffer); } - if (s->use_syslog == 0 && - s->access_logfile->used > 1 && - s->access_logfile->ptr[0] != '|') { + if (s->use_syslog == 0 + && !buffer_string_is_empty(s->access_logfile) + && s->access_logfile->ptr[0] != '|') { if (-1 != s->log_access_fd) close(s->log_access_fd); @@ -626,13 +683,10 @@ static int mod_accesslog_patch_connection(server *srv, 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); @@ -654,12 +708,9 @@ static int mod_accesslog_patch_connection(server *srv, 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"))) { @@ -679,6 +730,7 @@ REQUESTDONE_FUNC(log_access_write) { int newts = 0; data_string *ds; + struct timespec ts = { 0, 0 }; mod_accesslog_patch_connection(srv, con, p); @@ -691,126 +743,214 @@ REQUESTDONE_FUNC(log_access_write) { b = p->conf.access_logbuffer; } - if (b->used == 0) { - buffer_copy_string_len(b, CONST_STR_LEN("")); + if (buffer_is_empty(b)) { + buffer_string_set_length(b, 0); } 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) log_clock_gettime_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) log_clock_gettime_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 */ - buffer_prepare_copy(p->conf.ts_accesslog_str, 255); -#if defined(HAVE_STRUCT_TM_GMTOFF) -# ifdef HAVE_LOCALTIME_R - localtime_r(&(srv->cur_ts), &tm); - strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, p->conf.ts_accesslog_fmt_str->ptr, &tm); -# else /* HAVE_LOCALTIME_R */ - strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, p->conf.ts_accesslog_fmt_str->ptr, localtime_r(&(srv->cur_ts))); -# endif /* HAVE_LOCALTIME_R */ - p->conf.ts_accesslog_str->used = strlen(p->conf.ts_accesslog_str->ptr) + 1; + 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 (p->conf.append_tz_offset) { - buffer_append_string_len(p->conf.ts_accesslog_str, tm.tm_gmtoff >= 0 ? "+" : "-", 1); + #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 */ - scd = abs(tm.tm_gmtoff); + buffer_string_prepare_copy(p->conf.ts_accesslog_str, 255); + + 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; /* hours */ if (hrs < 10) buffer_append_string_len(p->conf.ts_accesslog_str, CONST_STR_LEN("0")); - buffer_append_long(p->conf.ts_accesslog_str, hrs); + buffer_append_int(p->conf.ts_accesslog_str, hrs); if (min < 10) buffer_append_string_len(p->conf.ts_accesslog_str, CONST_STR_LEN("0")); - buffer_append_long(p->conf.ts_accesslog_str, min); + 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); - strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, p->conf.ts_accesslog_fmt_str->ptr, &tm); -# else /* HAVE_GMTIME_R */ - strftime(p->conf.ts_accesslog_str->ptr, p->conf.ts_accesslog_str->size - 1, p->conf.ts_accesslog_fmt_str->ptr, gmtime(&(srv->cur_ts))); -# endif /* HAVE_GMTIME_R */ - p->conf.ts_accesslog_str->used = strlen(p->conf.ts_accesslog_str->ptr) + 1; -#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); } - - 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) log_clock_gettime_realtime(&ts); + tdiff = (off_t)(ts.tv_sec - bs->tv_sec)*1000000000 + (ts.tv_nsec - bs->tv_nsec); + if (tdiff <= 0) { + /* sanity check for time moving backwards + * (daylight savings adjustment or leap seconds or ?) */ + tdiff = -1; + } else 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); + } + 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 */ buffer_append_string_len(b, CONST_STR_LEN("-")); break; case FORMAT_REMOTE_USER: - if (NULL != (ds = (data_string *)array_get_element(con->environment, "REMOTE_USER")) && ds->value->used > 1) { + if (NULL != (ds = (data_string *)array_get_element(con->environment, "REMOTE_USER")) && !buffer_string_is_empty(ds->value)) { accesslog_append_escaped(b, ds->value); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; case FORMAT_REQUEST_LINE: - if (con->request.request_line->used) { + if (!buffer_string_is_empty(con->request.request_line)) { accesslog_append_escaped(b, con->request.request_line); } break; case FORMAT_STATUS: - buffer_append_long(b, con->http_status); + buffer_append_int(b, con->http_status); break; case FORMAT_BYTES_OUT_NO_HEADER: if (con->bytes_written > 0) { - buffer_append_off_t(b, + buffer_append_int(b, con->bytes_written - con->bytes_header <= 0 ? 0 : con->bytes_written - con->bytes_header); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } 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("-")); } break; case FORMAT_FILENAME: - if (con->physical.path->used > 1) { + if (!buffer_string_is_empty(con->physical.path)) { buffer_append_string_buffer(b, con->physical.path); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); @@ -818,30 +958,27 @@ REQUESTDONE_FUNC(log_access_write) { break; case FORMAT_BYTES_OUT: if (con->bytes_written > 0) { - buffer_append_off_t(b, con->bytes_written); + buffer_append_int(b, con->bytes_written); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; case FORMAT_BYTES_IN: if (con->bytes_read > 0) { - buffer_append_off_t(b, con->bytes_read); + buffer_append_int(b, con->bytes_read); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; - case FORMAT_TIME_USED: - buffer_append_long(b, srv->cur_ts - con->request_start); - break; case FORMAT_SERVER_NAME: - if (con->server_name->used > 1) { + if (!buffer_string_is_empty(con->server_name)) { buffer_append_string_buffer(b, con->server_name); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); } break; case FORMAT_HTTP_HOST: - if (con->uri.authority->used > 1) { + if (!buffer_string_is_empty(con->uri.authority)) { accesslog_append_escaped(b, con->uri.authority); } else { buffer_append_string_len(b, CONST_STR_LEN("-")); @@ -849,7 +986,7 @@ REQUESTDONE_FUNC(log_access_write) { break; case FORMAT_REQUEST_PROTOCOL: buffer_append_string_len(b, - con->request.http_version == HTTP_VERSION_1_1 ? "HTTP/1.1" : "HTTP/1.0", 8); + con->request.http_version == HTTP_VERSION_1_1 ? "HTTP/1.1" : "HTTP/1.0", 8); break; case FORMAT_REQUEST_METHOD: buffer_append_string(b, get_http_method_name(con->request.http_method)); @@ -857,6 +994,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; @@ -869,7 +1024,7 @@ REQUESTDONE_FUNC(log_access_write) { if (colon) { buffer_append_string(b, colon+1); } else { - buffer_append_long(b, srv->srvconf.port); + buffer_append_int(b, srv->srvconf.port); } } break; @@ -880,19 +1035,48 @@ REQUESTDONE_FUNC(log_access_write) { accesslog_append_escaped(b, con->uri.path_raw); break; case FORMAT_CONNECTION_STATUS: - switch(con->keep_alive) { - case 0: buffer_append_string_len(b, CONST_STR_LEN("-")); break; - default: buffer_append_string_len(b, CONST_STR_LEN("+")); break; + if (con->state == CON_STATE_RESPONSE_END) { + if (0 == con->keep_alive) { + buffer_append_string_len(b, CONST_STR_LEN("-")); + } else { + buffer_append_string_len(b, CONST_STR_LEN("+")); + } + } else { /* CON_STATE_ERROR */ + 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; @@ -901,22 +1085,24 @@ REQUESTDONE_FUNC(log_access_write) { } } + if (p->conf.use_syslog) { /* syslog doesn't cache */ +#ifdef HAVE_SYSLOG_H + if (!buffer_string_is_empty(b)) { + /*(syslog appends a \n on its own)*/ + syslog(p->conf.syslog_level, "%s", b->ptr); + buffer_reset(b); + } +#endif + return HANDLER_GO_ON; + } + buffer_append_string_len(b, CONST_STR_LEN("\n")); - if (p->conf.use_syslog || /* syslog doesn't cache */ - (p->conf.access_logfile->used && p->conf.access_logfile->ptr[0] == '|') || /* pipes don't cache */ + if ((!buffer_string_is_empty(p->conf.access_logfile) && p->conf.access_logfile->ptr[0] == '|') || /* pipes don't cache */ newts || - b->used > BUFFER_MAX_REUSE_SIZE) { - if (p->conf.use_syslog) { -#ifdef HAVE_SYSLOG_H - if (b->used > 2) { - /* syslog appends a \n on its own */ - syslog(p->conf.syslog_level, "%*s", (int) b->used - 2, b->ptr); - } -#endif - } else if (p->conf.log_access_fd != -1) { - force_assert(b->used > 0); - write(p->conf.log_access_fd, b->ptr, b->used - 1); + buffer_string_length(b) >= BUFFER_MAX_REUSE_SIZE) { + if (p->conf.log_access_fd >= 0) { + accesslog_write_all(srv, p->conf.access_logfile, p->conf.log_access_fd, CONST_BUF_LEN(b)); } buffer_reset(b); }