Clogger request_time formatting

Clogger request_time formatting

[Josh Natanson]

Hi,

I'm looking to use clogger for some access logging, and I need to
match a legacy format within my organization.  I've managed to
recreate everything I need to, with one exception.  $request_time
looks like it returns seconds, and I need to display microseconds.  I
see that precision is supported, but I haven't been able to figure out
a way to change the actual format.

My questions are: Is there a way to do this that I'm not aware of?  If
not, could it be added?  I can try to take a crack at it if you think
it's a good idea.

Thanks a lot,

- Josh

Re: Clogger request_time formatting

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> Hi,
> 
> I'm looking to use clogger for some access logging, and I need to
> match a legacy format within my organization.  I've managed to
> recreate everything I need to, with one exception.  $request_time
> looks like it returns seconds, and I need to display microseconds.  I
> see that precision is supported, but I haven't been able to figure out
> a way to change the actual format.
> 
> My questions are: Is there a way to do this that I'm not aware of?  If
> not, could it be added?  I can try to take a crack at it if you think
> it's a good idea.

Hi Josh, does $request_time{6} work?

From the README:

    * $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).

Or is the "." component not desirable?

I suppose something like $request_time{6,0} could be added
(Multiply by 10**6, PRECISION=0)

Re: Clogger request_time formatting

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> > Or is the "." component not desirable?
> 
> Exactly, my requirements require actual microseconds, not just that precision.

OK.

Btw, please keep clogger-public@yhbt.net Cc-ed for public
archival purposes.   Most people reading these emails are not
subscribed via SMTP, but rather via NNTP/Atom/HTML/IMAP/git;
so we have no idea how many people read this inbox.

> > I suppose something like $request_time{6,0} could be added
> > (Multiply by 10**6, PRECISION=0)
> 
> I think that would do the trick, but probably wouldn't be backwards
> compatible with people already using $request_time{6,0}?  Maybe a
> second optional {}, like $request_time{0}{6}?  Or a separate token
> altogether, $request_time_micro, but that could be less flexible.

There shouldn't be any incompatibility, since it currently
accepts only matching /\A\$request_time\{(\d+)\}\z/.  Thus "{6,0}"
is rejected by current versions.

Re: Clogger request_time formatting

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> Hi,
> 
> I'm looking to use clogger for some access logging, and I need to
> match a legacy format within my organization.  I've managed to
> recreate everything I need to, with one exception.  $request_time
> looks like it returns seconds, and I need to display microseconds.  I
> see that precision is supported, but I haven't been able to figure out
> a way to change the actual format.
> 
> My questions are: Is there a way to do this that I'm not aware of?  If
> not, could it be added?  I can try to take a crack at it if you think
> it's a good idea.

Ping.  Were you going to work on a patch for this?
I'd be happy to help you review at some point.

cf.
https://yhbt.net/clogger-public/CAPdx2szjqUuFjUtrgoeXXwmz0HzfdnWe+2h2Sp_ywDkTDVL0-g@mail.gmail.com/t/

Thanks.

Re: Clogger request_time formatting

[Josh Natanson]

I'm hoping to find some time this week to work on it.  What's your
preferred way to review?

Thanks,

- Josh

On Sun, Jul 26, 2020 at 12:46 AM Eric Wong <e@yhbt.net> wrote:
>
> Josh Natanson <josh@natanson.net> wrote:
> > Hi,
> >
> > I'm looking to use clogger for some access logging, and I need to
> > match a legacy format within my organization.  I've managed to
> > recreate everything I need to, with one exception.  $request_time
> > looks like it returns seconds, and I need to display microseconds.  I
> > see that precision is supported, but I haven't been able to figure out
> > a way to change the actual format.
> >
> > My questions are: Is there a way to do this that I'm not aware of?  If
> > not, could it be added?  I can try to take a crack at it if you think
> > it's a good idea.
>
> Ping.  Were you going to work on a patch for this?
> I'd be happy to help you review at some point.
>
> cf.
> https://yhbt.net/clogger-public/CAPdx2szjqUuFjUtrgoeXXwmz0HzfdnWe+2h2Sp_ywDkTDVL0-g@mail.gmail.com/t/
>
> Thanks.

Re: Clogger request_time formatting

[Eric Wong]

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)

Re: Clogger request_time formatting

[Josh Natanson]

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)

Re: Clogger request_time formatting

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> 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?

Ah, you're aware there's both a C extension and pure-Ruby
implementation in the same tree, right?

I only see changes to the pure-Ruby code.  Btw, I can help with
the C stuff, too, if you're not a C hacker.

Perhaps setting CLOGGER_PURE=1 lets your app work as expected?

The very short GNUmakefile has two targets for testing these
independently:

	make test-ext
	make test-pure
	# (or gmake if you're on *BSD)

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

All the rest seemed fine to me :>

Btw, please don't top-post and trim quotes.  Mostly old school
Usenet conventions, though when in doubt, I don't think quoting
is necessary at all with reliable archives, nowadays.  (it saves
storage + bandwidth for all)

Thanks.

Re: Clogger request_time formatting

[Josh Natanson]

Thanks for the reminder, I hadn't considered the C extension.  I took
a look today, but wasn't able to make any headway - my C is very
rusty, I'm not sure you would want anything I'd write there anyhow.
That leaves me a little stuck, with the code working frozen in my
rails app, but without support in the C layer (or passing tests). I'm
sure you won't want to incorporate a partial change.  If you (or
someone else) has some time to consider the C side, that would be
fantastic.  If not, I might have to go another route for my logging.

Sorry about the email formatting, gmail has ruined me.

Re: Clogger request_time formatting

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> Thanks for the reminder, I hadn't considered the C extension.  I took
> a look today, but wasn't able to make any headway - my C is very
> rusty, I'm not sure you would want anything I'd write there anyhow.
> That leaves me a little stuck, with the code working frozen in my
> rails app, but without support in the C layer (or passing tests). I'm
> sure you won't want to incorporate a partial change.  If you (or
> someone else) has some time to consider the C side, that would be
> fantastic.  If not, I might have to go another route for my logging.

No worries, below is a proposed patch which adds C support.

I also made the Ruby format compilation cap power-of-10 to be
<=9 to reduce likelyhood of overflows and non-sensical values.
There's no way to get higher resolution than nanoseconds in
POSIX, and most clocks/kernels are lower resolution, even.

Arithmetic is not my strong suit, but the C code should be
pretty straightforward if you're familiar with any other
C-like language, Ruby included.

> Sorry about the email formatting, gmail has ruined me.

Not just you, 99% of the Internet :<


Anyways, can you provide a proper commit message describing the
feature?  Thanks.

 ext/clogger_ext/clogger.c | 32 ++++++++++++++++++++++++++++++++
 lib/clogger.rb            |  7 ++++++-
 2 files changed, 38 insertions(+), 1 deletion(-)

diff --git a/ext/clogger_ext/clogger.c b/ext/clogger_ext/clogger.c
index fdc23e3..a316545 100644
--- a/ext/clogger_ext/clogger.c
+++ b/ext/clogger_ext/clogger.c
@@ -374,12 +374,44 @@ 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 608909d..8559841 100644
--- a/lib/clogger.rb
+++ b/lib/clogger.rb
@@ -92,7 +92,12 @@ private
         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 ]
+          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 ]
         when /\A\$request_time\{(\d+)\}\z/
           rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i), 0 ]
         else

Re: Clogger request_time formatting

[Josh Natanson]

Just sent a patch to you, hopefully in the correct format. If not,
please let me know.  Thanks again for all your help, it's very much
appreciated.

- Josh

On Wed, Jul 29, 2020 at 11:54 PM Eric Wong <e@yhbt.net> wrote:
>
> Josh Natanson <josh@natanson.net> wrote:
> > Thanks for the reminder, I hadn't considered the C extension.  I took
> > a look today, but wasn't able to make any headway - my C is very
> > rusty, I'm not sure you would want anything I'd write there anyhow.
> > That leaves me a little stuck, with the code working frozen in my
> > rails app, but without support in the C layer (or passing tests). I'm
> > sure you won't want to incorporate a partial change.  If you (or
> > someone else) has some time to consider the C side, that would be
> > fantastic.  If not, I might have to go another route for my logging.
>
> No worries, below is a proposed patch which adds C support.
>
> I also made the Ruby format compilation cap power-of-10 to be
> <=9 to reduce likelyhood of overflows and non-sensical values.
> There's no way to get higher resolution than nanoseconds in
> POSIX, and most clocks/kernels are lower resolution, even.
>
> Arithmetic is not my strong suit, but the C code should be
> pretty straightforward if you're familiar with any other
> C-like language, Ruby included.
>
> > Sorry about the email formatting, gmail has ruined me.
>
> Not just you, 99% of the Internet :<
>
>
> Anyways, can you provide a proper commit message describing the
> feature?  Thanks.
>
>  ext/clogger_ext/clogger.c | 32 ++++++++++++++++++++++++++++++++
>  lib/clogger.rb            |  7 ++++++-
>  2 files changed, 38 insertions(+), 1 deletion(-)
>
> diff --git a/ext/clogger_ext/clogger.c b/ext/clogger_ext/clogger.c
> index fdc23e3..a316545 100644
> --- a/ext/clogger_ext/clogger.c
> +++ b/ext/clogger_ext/clogger.c
> @@ -374,12 +374,44 @@ 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 608909d..8559841 100644
> --- a/lib/clogger.rb
> +++ b/lib/clogger.rb
> @@ -92,7 +92,12 @@ private
>          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 ]
> +          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 ]
>          when /\A\$request_time\{(\d+)\}\z/
>            rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i), 0 ]
>          else

Re: Clogger request_time formatting

[Josh Natanson]

Damnit, top posted and quoted again.  I can't win!

Re: Clogger request_time formatting

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> Just sent a patch to you, hopefully in the correct format. If not,
> please let me know.  Thanks again for all your help, it's very much
> appreciated.

Thanks Josh.

It also needs to Cc-ed to clogger-public@yhbt.net for the
public record: <https://yhbt.net/clogger-public/>.

The whitespace was mangled in the C part, at least (C source is
hard tabs, here, matching git.git and Linux kernel style).

I recommend setting up git send-email once and being able
to contribute to bunch of projects _very_ easily:

	https://kernel.org/pub/software/scm/git/docs/git-send-email.html

There's also https://git-send-email.io/ for more of a TL;DR.

Attaching a patch is fine for one-offs, too (and even Linus does
it); but it's a slower workflow when you're working with large
patchsets.

Thanks.

Re: Clogger request_time formatting

[Josh Natanson]

Thanks for the pointers.  I fixed the formatting and added the CC,
hopefully the email I just sent preserved it properly (some email
challenges with my current WFH setup).  If not, I'll keep trying...