From 81cf3b2f31a55a2caf8222c6847ca8d9c01f8eee Mon Sep 17 00:00:00 2001 From: Josh N Date: Mon, 3 Aug 2020 08:54:15 -0400 Subject: Added optional POWER argument to $response_time This argument allows for conversion of response_time to microsecond or nanosecond by multiplying by a power of 10, up to a limit of 9. Defaults to 0 so backwards compatible. --- README | 10 ++++++---- ext/clogger_ext/clogger.c | 28 ++++++++++++++++++++++++++++ lib/clogger.rb | 11 +++++++++-- lib/clogger/pure.rb | 1 + test/test_clogger.rb | 25 +++++++++++++++++++++++-- 5 files changed, 67 insertions(+), 8 deletions(-) diff --git a/README b/README index 1d1d537..a6a5db8 100644 --- a/README +++ b/README @@ -69,10 +69,12 @@ that receives a "<<" method: * $request_uri - the URI requested ($path_info?$query_string) * $request - the first line of the HTTP request ($request_method $request_uri $http_version) -* $request_time, $request_time{PRECISION} - time taken for request - (including response body iteration). PRECISION defaults to 3 - (milliseconds) if not specified but may be specified anywhere from - 0(seconds) to 6(microseconds). +* $request_time, $request_time{PRECISION}, $request_time{POWER,PRECISION} - + time taken for request (including response body iteration). PRECISION + defaults to 3 (milliseconds) if not specified but may be specified + anywhere from 0(seconds) to 6(microseconds). POWER will raise the time to + the provided power of 10, useful for converting to micro- or nanoseconds. + POWER defaults to 0 if not specified but may be specified any from 0 to 9 * $time_iso8601 - current local time in ISO 8601 format, e.g. "1970-01-01T00:00:00+00:00" * $time_local - current local time in Apache log format, diff --git a/ext/clogger_ext/clogger.c b/ext/clogger_ext/clogger.c index fdc23e3..a1f3bc4 100644 --- a/ext/clogger_ext/clogger.c +++ b/ext/clogger_ext/clogger.c @@ -374,12 +374,40 @@ static void append_ts(struct clogger *c, VALUE op, struct timespec *ts) rb_str_buf_cat(c->log_buf, buf, nr); } +#define NANO_PER_SEC (1000 * 1000 * 1000) static void append_request_time_fmt(struct clogger *c, VALUE op) { struct timespec now; + unsigned long ipow = NUM2ULONG(rb_ary_entry(op, 3)); clock_gettime(hopefully_CLOCK_MONOTONIC, &now); clock_diff(&now, &c->ts_start); + if (ipow) { + struct timespec prev; + unsigned long adj = 1; + /* + * n.b. timespec.tv_sec may not be time_t on some platforms, + * so we use a full timespec struct instead of time_t: + */ + prev.tv_sec = now.tv_sec; + do { adj *= 10; } while (--ipow); + now.tv_sec *= adj; + now.tv_nsec *= adj; + if (now.tv_nsec >= NANO_PER_SEC) { + int64_t add = now.tv_nsec / NANO_PER_SEC; + now.tv_sec += add; + now.tv_nsec %= NANO_PER_SEC; + } + if (now.tv_sec < prev.tv_sec) { /* overflowed */ + now.tv_nsec = NANO_PER_SEC - 1; + /* + * some platforms may use unsigned .tv_sec, but + * they're not worth supporting, so keep unsigned: + */ + now.tv_sec = (time_t)(sizeof(now.tv_sec) == 4 ? + INT_MAX : LONG_MAX); + } + } append_ts(c, op, &now); } diff --git a/lib/clogger.rb b/lib/clogger.rb index be1bdce..7ce2b24 100644 --- a/lib/clogger.rb +++ b/lib/clogger.rb @@ -51,7 +51,7 @@ private SCAN = /([^$]*)(\$+(?:env\{\w+(?:\.[\w\.]+)?\}| e\{[^\}]+\}| - (?:request_)?time\{\d+\}| + (?:request_)?time\{\d+(?:,\d+)?\}| time_(?:utc|local)\{[^\}]+\}| \w*))?([^$]*)/x @@ -92,7 +92,14 @@ private when /\A\$time\{(\d+)\}\z/ rv << [ OP_TIME, *usec_conv_pair(tok, $1.to_i) ] when /\A\$request_time\{(\d+)\}\z/ - rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i) ] + rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i), 0 ] + when /\A\$request_time\{(\d+),(\d+)\}\z/ + ipow = $1.to_i + prec = $2.to_i + if ipow > 9 # nanosecond precision is the highest POSIX goes + raise ArgumentError, "#{tok}: too big: #{ipow} (max=9)" + end + rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, prec), ipow ] else tok_sym = tok[1..-1].to_sym if special_code = SPECIAL_VARS[tok_sym] diff --git a/lib/clogger/pure.rb b/lib/clogger/pure.rb index fddfe79..8f1f706 100644 --- a/lib/clogger/pure.rb +++ b/lib/clogger/pure.rb @@ -166,6 +166,7 @@ private when OP_TIME_UTC; Time.now.utc.strftime(op[1]) when OP_REQUEST_TIME t = mono_now - start + t = t * (10 ** op[3]) time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2]) when OP_TIME t = Time.now diff --git a/test/test_clogger.rb b/test/test_clogger.rb index ca3bd55..b7dd4e9 100644 --- a/test/test_clogger.rb +++ b/test/test_clogger.rb @@ -167,10 +167,11 @@ class TestClogger < Test::Unit::TestCase ary = compile_format( '$remote_addr - $remote_user [$time_local] ' \ '"$request" $status $body_bytes_sent "$http_referer" ' \ - '"$http_user_agent" "$http_cookie" $request_time ' \ + '"$http_user_agent" "$http_cookie" $request_time $request_time{6,0} ' \ '$env{rack.url_scheme}' \ "\n") } + expect = [ [ Clogger::OP_REQUEST, "REMOTE_ADDR" ], [ Clogger::OP_LITERAL, " - " ], @@ -190,7 +191,9 @@ class TestClogger < Test::Unit::TestCase [ Clogger::OP_LITERAL, "\" \"" ], [ Clogger::OP_REQUEST, "HTTP_COOKIE" ], [ Clogger::OP_LITERAL, "\" " ], - [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000 ], + [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000, 0], + [ Clogger::OP_LITERAL, " " ], + [ Clogger::OP_REQUEST_TIME, '%d', 1, 6], [ Clogger::OP_LITERAL, " " ], [ Clogger::OP_REQUEST, "rack.url_scheme" ], [ Clogger::OP_LITERAL, "\n" ], @@ -721,6 +724,24 @@ class TestClogger < Test::Unit::TestCase assert s[-1].to_f <= 0.110 end + def test_request_time_with_multiplier + s = [] + app = lambda { |env| sleep(0.1) ; [302, [], [] ] } + cl = Clogger.new(app, :logger => s, :format => "$request_time{9,0}") + status, headers, body = cl.call(@req) + assert_nothing_raised { body.each { |x| } ; body.close } + assert s[-1].to_f >= 100000000 + assert s[-1].to_f <= 300000000 + end + + def test_request_time_with_invalid_multiplier + s = [] + app = lambda { |env| sleep(0.1) ; [302, [], [] ] } + assert_raise(ArgumentError) { + cl = Clogger.new(app, :logger => s, :format => "$request_time{10,0}") + } + end + def test_insanely_long_time_format s = [] app = lambda { |env| [200, [], [] ] } -- cgit v1.2.3-24-ge0c7