Re: Clogger request_time formatting

[Josh Natanson <josh@natanson.net>]

Thanks.  I had some time to work on this, and I'm a little stuck.  The
changes I've made are working as expected (both new syntax & legacy)
when frozen into a test rails application. I've written a test for the
new syntax, but I'm not getting the same behavior there - it looks to
behave the same as the legacy option.  I can't see why the same code
would behave differently in an app vs. the test, and I'm having some
challenges getting useful debug out of the code in test.  I'm sure I'm
just unfamiliar with something about the gem's layout, but maybe you
have some ideas?

Here's the changes so far.  Don't mind the names, I'm planning to come
up with something better before submitting.

 $ git diff --staged | cat
diff --git a/lib/clogger.rb b/lib/clogger.rb
index be1bdce..608909d 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

@@ -91,8 +91,10 @@ private
           rv << [ OP_TIME_UTC, fmt, longest_day.strftime(fmt) ]
         when /\A\$time\{(\d+)\}\z/
           rv << [ OP_TIME, *usec_conv_pair(tok, $1.to_i) ]
+        when /\A\$request_time\{(\d+),(\d+)\}\z/
+          rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $2.to_i), $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 ]
         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..3fc9e4a 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,16 @@ class TestClogger < Test::Unit::TestCase
     assert s[-1].to_f <= 0.110
   end

+  def test_request_time_with_multiple
+    s = []
+    app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
+    cl = Clogger.new(app, :logger => s, :format => "$request_time{6,0}")
+    status, headers, body = cl.call(@req)
+    assert_nothing_raised { body.each { |x| } ; body.close }
+    assert s[-1].to_f >= 100000
+    assert s[-1].to_f <= 110000
+  end
+
   def test_insanely_long_time_format
     s = []
     app = lambda { |env| [200, [], [] ] }

On Mon, Jul 27, 2020 at 2:38 PM Eric Wong <e@yhbt.net> wrote:
>
> Josh Natanson <josh@natanson.net> wrote:
> > I'm hoping to find some time this week to work on it.  What's your
> > preferred way to review?
>
> I do everything through email.  "git format-patch" + "git send-email"
> are the recommended tools.  It's the same way git.git and the Linux
> kernel work (see Documentation/SubmittingPatches in git)
>
> https://git.kernel.org/cgit/git/git.git/tree/Documentation/SubmittingPatches
>
> (I don't care about Signed-off-by or real names, though)