From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on dcvr.yhbt.net X-Spam-Level: X-Spam-Status: No, score=-3.0 required=3.0 tests=AWL,BAYES_00,DKIM_SIGNED, DKIM_VALID,RCVD_IN_DNSWL_NONE,SPF_HELO_NONE,SPF_NONE shortcircuit=no autolearn=ham autolearn_force=no version=3.4.2 Received: from mail-ed1-x543.google.com (mail-ed1-x543.google.com [IPv6:2a00:1450:4864:20::543]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (No client certificate requested) by dcvr.yhbt.net (Postfix) with ESMTPS id 710721F5B1 for ; Sun, 2 Aug 2020 13:44:58 +0000 (UTC) Received: by mail-ed1-x543.google.com with SMTP id c2so19558046edx.8 for ; Sun, 02 Aug 2020 06:44:58 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=natanson-net.20150623.gappssmtp.com; s=20150623; h=mime-version:from:date:message-id:subject:to:cc; bh=wBz+jEMptsbeSe/uKI+5Ma7SqRu5cgxRnMBVN+21Pjw=; b=jInqJaC7Oyi90poWv+e1sjL5JmTSFV/ccoxbzEr0MjcqeHB+bx83l33lT5vt6NyvgI CLn2SHGWMKgEv0n77v+ajYI1IiEZIEdyudML/0NNNOIIKHHZiSbkntbL6y+uTIs9Yzfl 66oPOD5CAGi+svnlu4PjgaIJw2w+CNZPe6Z7GRKsqC8v1nJPJDA/coTdVR3lC21Z05Bi ivgApIMb00DUoVuKF3p7de921CUkMHy14Zfno+DRMg+YSu7IyLzNw+l/p4bBojgpDOOP tiBi4ueJ8CoRSCxy8uBqOgcJSucn1LaxaiO0X2X1kYXUYdBX0iEWhMJYTSmJPaM6NPg1 odxg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to:cc; bh=wBz+jEMptsbeSe/uKI+5Ma7SqRu5cgxRnMBVN+21Pjw=; b=q1itYwBoatSVhvlXUORnpk50Jt05bYGkv+qNJarzsgVtFClTjCymNDBAx1FbZ8QO5B CC2dwD7CMy5P5hqtP/CZgFdvriHDobO/iJ+Fkx1vaRXvGz+E0d7RJGBE/WXMvxs+0uQL iC7p1Lbh0+wqNPEyX6ynLAzZTbyu4HghlGiEtPD2KMHMYopvbczP5N1qvVqQtHsxPOEW 4v1VwHX3bAjmSjNPELbOz9tnHfPS/oVWMYG4CS18X3cc36XdNTz5+R8AixcsEUWnp+1u VDEuYvEoAWG+UwrimfCD0EVip7nHVOupOw86aCdqqzxdRRA63haxGW3VD9z3kggrgOq7 yRYw== X-Gm-Message-State: AOAM5305CgQ7SJSiaDn3WNC7fWL/xa62gYFAkKNDiwdxl58T/8ualkub d57q9L6hTO5b3PoY2gy9Hg+J1CrMZqtSvle6OmL6Og== X-Google-Smtp-Source: ABdhPJykJL7MzZWiycFwUiXDhg5jkGDlzwkLxmxFG3CqmbVUh5g6WZLISe52SdkovvPprZiRbrlufmu93a/5KRV9amA= X-Received: by 2002:a50:d2c7:: with SMTP id q7mr7174867edg.61.1596375895948; Sun, 02 Aug 2020 06:44:55 -0700 (PDT) MIME-Version: 1.0 From: Josh Natanson Date: Sun, 2 Aug 2020 09:44:45 -0400 Message-ID: Subject: [PATCH] Added optional POWER argutment to $response_time. To: Eric Wong Cc: clogger-public@yhbt.net Content-Type: text/plain; charset="UTF-8" List-Id: This argument allows for conversion of response_time to microsecond or nanosecond, 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..7c22fd5 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 10 * $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..58c6ca3 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, [], [] ] } -- 2.20.1 (Apple Git-117)