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"}
```
@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
Most helpful comment
Fixed by #1061