Hanami: Hanammi::CommonLogger#log should use Process.clock_gettime(Process::CLOCK_MONOTONIC) instead of Time.now

Created on 4 Jan 2021  路  2Comments  路  Source: hanami/hanami

In the Hanami::CommonLogger the method log uses Time.now without considering if this value is coherent with the began_at given by rack.

module Hanami
  class CommonLogger < Rack::CommonLogger
    ....
    def log(env, status, header, began_at)
      now    = Time.now
      length = extract_content_length(header)

      msg = Hash[
        http:    env[HTTP_VERSION],
        verb:    env[REQUEST_METHOD],
        status:  status.to_s[0..3],
        ip:      env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR],
        path:    env[SCRIPT_NAME] + env[PATH_INFO].to_s,
        length:  length,
        params:  extract_params(env),
        elapsed: now - began_at
      ]
    ...
  end
end

began_at is set by rack gem using Rack::Utils.clock_time which is defined in the version 2.2.3 of the gem as follows:

if defined?(Process::CLOCK_MONOTONIC)
  def clock_time
    Process.clock_gettime(Process::CLOCK_MONOTONIC)
  end
else
  # :nocov:
  def clock_time
    Time.now.to_f
  end
  # :nocov:
end

In the most of the systems, the time picked will be Process.clock_gettime(Process::CLOCK_MONOTONIC) which is not necessarily Time.now. This causes that the elapsed time appears as a timestamp and not as the time passed:

{"app":"my_app","severity":"INFO","time":"2020-09-25T14:30:00Z","http":null,"verb":"GET","status":"200","ip":"127.0.0.1","path":"/api/my_path","length":"710","params":{},"elapsed":"2020-09-20 13:42:56 +0200"}

```

bug

Most helpful comment

Fixed by #1061

All 2 comments

@heragu I'll take a look at this issue, the good point is that we're already using concurrent-ruby dependency which provides us a multi implementation method to return the monotonic time.

I'd like to take a look further though at the implication of the current implementation vs the new one.

Fixed by #1061

Was this page helpful?
0 / 5 - 0 ratings