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=BAYES_00,DKIM_SIGNED, DKIM_VALID,HEADER_FROM_DIFFERENT_DOMAINS,RCVD_IN_DNSWL_NONE, RCVD_IN_MSPIKE_H2,SPF_HELO_PASS,SPF_PASS shortcircuit=no autolearn=ham autolearn_force=no version=3.4.2 Received: from NAM02-SN1-obe.outbound.protection.outlook.com (mail-eopbgr770079.outbound.protection.outlook.com [40.107.77.79]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dcvr.yhbt.net (Postfix) with ESMTPS id E015F1F5AE; Mon, 3 Aug 2020 12:54:38 +0000 (UTC) ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=JfOEf1mIYYAtfUa/l+Skbbu31ybsL4Bhb3iNVCw4Bx1Z0FHbWS9FvT4VtdbFViabkL7D67zVltOCzB3MOjcd+tqcOMfjT6aWh/EFrU94HIfCin+zb9/YCFor+eawdwSYtMia4nu/2MrkM4zNIimXUc6pmIEil7bJtSJNt0Xec4TB0C5Y465gz6Y5CpxriT5+SHQ18ImbfSqDmfetJarSa1vMQOMV5f8u5wpD56ScoLfEfIWe3EZHi3/j7wuidUsbcmQNviBJw7sy6js52HOlllCErAFJaUPd9xUV9A2j3w7nQ+RGGR4xpWD6Nr0RjL+j8MJAU+sCzreE49hl8PjNDQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=microsoft.com; s=arcselector9901; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=yWHhYFbkqHBaoNIsnASVhKXuQiRE2nYn9rSAIqNsttc=; b=EawPS6LSvBt8a9uu6kglibO1OWy4vvaBOBXQgIIrGQtCyhc2eaxCS7s//C+DTvmPezntyP76avh3HA+YmYXYtDdpdgVK+j0A+V1t/xMF6K/StGNxbfzrYJTwzv4KxL704v6VUV0cLXRxUeMHElBASGyda4Kp1rG8ZUklMri4Cn7ZzUsEHJQiOhLf57T0apnriVJE8dp3qAYAuWTGH0ePmSX15BTzIa4OH93qvnuermrD/eylYHYxEvUVZXJ47kMoJF32SKePV7+TvGVUMO1aQdF0w1baXVKpJTRAc2fB/ew20e/mw4LdaL4zepJnEyniGEn98y+6m+gZ22V10FhHOw== ARC-Authentication-Results: i=1; mx.microsoft.com 1; spf=softfail (sender ip is 144.212.100.42) smtp.rcpttodomain=yhbt.net smtp.mailfrom=mathworks.com; dmarc=none action=none header.from=natanson.net; dkim=none (message not signed); arc=none DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mathworks.onmicrosoft.com; s=selector2-mathworks-onmicrosoft-com; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=yWHhYFbkqHBaoNIsnASVhKXuQiRE2nYn9rSAIqNsttc=; b=lhYqErf8ULWVLwTOcmoZLeekyz+N5++EgUtWqmShrh249cTAzLFYWLjq/riF2meZdCkKukHnQMA8y1uJ4wvfka/nSV5XUT3EAw/wq2XkbpMxVuXGn2DyZWDJgBeB9MW17O3uJMECJrNSJ/Vfk0SPgc7AHqpKmbbHWePNsZRPVqY= Received: from BN6PR10CA0021.namprd10.prod.outlook.com (2603:10b6:405:1::31) by CY4PR05MB3157.namprd05.prod.outlook.com (2603:10b6:903:f6::13) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.3261.12; Mon, 3 Aug 2020 12:54:36 +0000 Received: from BN8NAM12FT059.eop-nam12.prod.protection.outlook.com (2603:10b6:405:1:cafe::52) by BN6PR10CA0021.outlook.office365.com (2603:10b6:405:1::31) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.3239.17 via Frontend Transport; Mon, 3 Aug 2020 12:54:36 +0000 X-MS-Exchange-Authentication-Results: spf=softfail (sender IP is 144.212.100.42) smtp.mailfrom=mathworks.com; yhbt.net; dkim=none (message not signed) header.d=none;yhbt.net; dmarc=none action=none header.from=natanson.net; Received-SPF: SoftFail (protection.outlook.com: domain of transitioning mathworks.com discourages use of 144.212.100.42 as permitted sender) Received: from exedge.mathworks.com (144.212.100.42) by BN8NAM12FT059.mail.protection.outlook.com (10.13.183.55) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.3261.10 via Frontend Transport; Mon, 3 Aug 2020 12:54:36 +0000 Received: from ex16-01-ah.mathworks.com (172.31.80.219) by ex16edge-00-ah.mathworks.com (172.31.187.33) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.1979.3; Mon, 3 Aug 2020 08:54:13 -0400 Received: from ex16-00-ah.mathworks.com (172.31.39.22) by ex16-01-ah.mathworks.com (172.31.80.219) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.1979.3; Mon, 3 Aug 2020 08:54:35 -0400 Received: from mail-vif.mathworks.com (144.212.95.101) by ex16-00-ah.mathworks.com (172.31.39.22) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.1979.3 via Frontend Transport; Mon, 3 Aug 2020 08:54:35 -0400 Received: from ah-joshn-mac.mathworks.com (ah-joshn-mac.dhcp.mathworks.com [172.28.155.190]) by mail-vif.mathworks.com (8.14.7/8.14.7) with ESMTP id 073CsZfh017177; Mon, 3 Aug 2020 08:54:35 -0400 Received: by ah-joshn-mac.mathworks.com (Postfix, from userid 974) id 6A4DB145F0A4; Mon, 3 Aug 2020 08:54:34 -0400 (EDT) From: Josh N To: CC: Josh N , Subject: [PATCH] Added optional POWER argument to $response_time Date: Mon, 3 Aug 2020 08:54:15 -0400 Message-ID: <20200803125415.83393-1-josh@natanson.net> X-Mailer: git-send-email 2.20.1 (Apple Git-117) MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Content-Type: text/plain X-EOPAttributedMessage: 0 X-MS-PublicTrafficType: Email X-MS-Office365-Filtering-Correlation-Id: 0d9a9ab5-eeac-457c-cd10-08d837ac6059 X-MS-TrafficTypeDiagnostic: CY4PR05MB3157: X-Microsoft-Antispam-PRVS: X-MS-Oob-TLC-OOBClassifiers: OLM:2887; X-MS-Exchange-SenderADCheck: 2 X-Microsoft-Antispam: BCL:0; X-Microsoft-Antispam-Message-Info: kQPwHYZKnZIw9PpAxzcf2Um9fpElVgBCyIN8aX6hxyw4B3WblVXqISI3+Txyg0rKDdL1bHdRbcTXlJYs7X8E2FlCrVI1BP8jBjrqkMaDURwa11+kbdeR8Dra0zgMtWw1HhJoz1x/4L3GqLmF5Rnz6h8N6z7F/eGXhlHAMkqqf4aBzn2dlLWjfKAQn8o6UoVsvH+Piw1Cr4ejxbIHiEJ6r5gi5jFTeEWtaOpGCQpEI/TJzLOFG2lSoZbhChi7I0J0XbClBEp9VqMCvV53ialRhDYFSuC8qSXJzr+SMYvwhdBuS7y8T8ETbqVbJkKFRlKOUzIaNHsIATc6ovt33KGEWc8L6Ds5E1Mye5FnEefJa9IA6Eqzbt1yeHt4+YHsWOH9fZ82hI386lHaX/RcteQRX+/FLRB5o8hmFYenVtjIlos= X-Forefront-Antispam-Report: CIP:144.212.100.42;CTRY:US;LANG:en;SCL:1;SRV:;IPV:NLI;SFV:NSPM;H:exedge.mathworks.com;PTR:airwatch-dmz-ah.mathworks.com;CAT:NONE;SFTY:;SFS:(4636009)(136003)(346002)(376002)(39850400004)(396003)(46966005)(82310400002)(83170400001)(6666004)(83380400001)(316002)(8936002)(5660300002)(42186006)(70586007)(42882007)(8676002)(26005)(2906002)(186003)(4326008)(1076003)(36756003)(6916009)(2616005)(6266002)(336012)(47076004)(54906003)(356005)(70206006)(82740400003)(478600001)(7636003)(781001);DIR:OUT;SFP:1101; X-OriginatorOrg: mathworks.com X-MS-Exchange-CrossTenant-OriginalArrivalTime: 03 Aug 2020 12:54:36.2266 (UTC) X-MS-Exchange-CrossTenant-Network-Message-Id: 0d9a9ab5-eeac-457c-cd10-08d837ac6059 X-MS-Exchange-CrossTenant-Id: 99dd3a11-4348-4468-9bdd-e5072b1dc1e6 X-MS-Exchange-CrossTenant-OriginalAttributedTenantConnectingIp: TenantId=99dd3a11-4348-4468-9bdd-e5072b1dc1e6;Ip=[144.212.100.42];Helo=[exedge.mathworks.com] X-MS-Exchange-CrossTenant-AuthSource: BN8NAM12FT059.eop-nam12.prod.protection.outlook.com X-MS-Exchange-CrossTenant-AuthAs: Anonymous X-MS-Exchange-CrossTenant-FromEntityHeader: HybridOnPrem X-MS-Exchange-Transport-CrossTenantHeadersStamped: CY4PR05MB3157 List-Id: 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..27ff553 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..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)