sentry-ruby
sentry-ruby copied to clipboard
Sentry/Rails: monotonic_active_support_logger results in incorrect timestamps
Issue Description
I believe that the MonotonicActiveSupportLogger
is not submitting correct data to Sentry::Breadcrumb
. We saw breadcrumb dates hovering around 1970 when we enabled this; switching to ActiveSupportLogger
fixed the issue.
The reason for this is that I believe ActiveSupport::Notifications.monotonic_subscribe
uses Process.clock_gettime(Process::CLOCK_MONOTONIC)
. The values from this call are floats that don't correspond to Unix epoch timestamps, which I believe is what Sentry::Breadcrumb expects.
ActiveSupport code in question: https://github.com/rails/rails/blob/v7.0.3.1/activesupport/lib/active_support/notifications/fanout.rb#L240-L255
MonotonicActiveSupportLogger
calls .to_i
on the timestamp:
https://github.com/getsentry/sentry-ruby/blob/71da6736cea07727c9be9ac0fc4ab93309f0b7d5/sentry-rails/lib/sentry/rails/breadcrumb/monotonic_active_support_logger.rb#L23
Reproduction Steps
- Enable
monotonic_active_support_logger
inconfig.breadcrumbs_logger
for Sentry initialization. - Submit some data
- Inspect breadcrumb timestamps in Sentry
Expected Behavior
The timestamps are correct.
Actual Behavior
The timestamps are shown as early in the year 1970.
Ruby Version
3.1.2
SDK Version
5.4.2
Integration and Its Version
No response
Sentry Config
No response
@st0012 we added this logger in https://github.com/getsentry/sentry-ruby/pull/1531
but as far as I understand CLOCK_MONOTONIC
is only useful to compute durations (end - start), it can't actually be converted to any normal timestamp since the reference 0 time is arbitrary.
From man clock_getres
CLOCK_MONOTONIC
A nonsettable system-wide clock that represents monotonic
time since—as described by POSIX—"some unspecified point
in the past". On Linux, that point corresponds to the
number of seconds that the system has been running since
it was booted.
So we should just remove the timestamp
from the breadcrumbs in this logger, but then I also don't see what the use of this separate logger is?
@sl0thentr0py The only difference this logger provides is the timestamp format AFAIK. So if we remove the timestamp we might as well just remove the logger.
I think we can use to_f
instead and let Sentry display the raw value (by sending string?). Then users can use them to compare the time elapse but don't try to think of it as a certain time. WDYT?
Just sending a random float in the timestamp
field will not work as far as I can tell because relay will try to parse it as a Timestamp
and it will probably end up in one of the error cases.
I think this monotonic stuff is more useful in span instrumentation than breadcrumbs because we have durations (end - start) there.
@sl0thentr0py Yeah then I don't see a value of keeping it for breadcrumbs. I think we can remove it from 6.0 by redirecting monotonic_active_support_logger
to active_support_logger
. But I want to check users' opinion before committing to drop it.
@mjhoy Why do you decide to use this logger instead of active_support_logger
in the first place?
@morissetcl Do you still use logger? What do you use it for?
@st0012 Not sure why, to be honest. Probably because "monotonic" sounded better than not being monotonic. Looking at the documentation here: https://docs.sentry.io/platforms/ruby/guides/rails/configuration/options/ At the very least, I would expect that documentation to warn about the somewhat useless timestamp values.