Rails.logger methods return breadcrumbs instead of true when breadcrumbs logging is enabled by henrahmagix · Pull Request #1299 · getsentry/sentry-ruby

henrahmagix · 2021-02-26T14:40:34Z

I started writing a bug issue, then thought I'd make the code change and see if any tests fail, and go from there. Saves creating a separate PR when the code change is this small is all =) (at least, small right now, who knows it could balloon! or just be rejected, that's fine also =))

Describe the bug

Without configuring breadcrumbs_logger, Rails.logger.info returns true (or nil depending on the app).

After configuring breadcrumbs_logger, Rails.logger.info returns the entire breadcrumb buffer: https://github.com/getsentry/sentry-ruby/blob/sentry-ruby-v4.2.2/sentry-ruby/lib/sentry/breadcrumb_buffer.rb#L16

This is because Logger methods return the last value, and since Sentry's logger prepends the add method and calls super, it's the last method to run, so it's return value will be returned.

Unfortunately our (big) app has been logging at the end of lots of methods, and it's been ok up til now because we haven't cared about the return value and luckily the return value has been true or nil. However now, with adding breadcrumb logging, we're getting unexpectedly big return values.

Of course, we should be controlling our return values, and we will be putting the work in to do this, but it's a lot of work at the moment. So I'm wondering if this is required functionality of the Sentry logger, or it's possible to change? It feels odd to me for breadcrumbs data to be exposed through the logging interface.

Thanks in advance,
Henry

To Reproduce

In a rails console, regardless of env:

logger = ActiveSupport::Logger.new(STDOUT)
logger.info('hello')

This is for reproducing in a console, but it occurs in our app (even in testing) through Rails.logger. I can't seem to reproduce it with Rails.logger in a console, only with ActiveSupport::Logger.new, but the output detailed below is what I also get from Rails.logger.

Expected behavior

$ RAILS_ENV=test RACK_ENV=test bundle exec rails c
Loading test environment (Rails 6.0.3.5)
irb(main):001:0> logger=ActiveSupport::Logger.new(STDOUT)
=> #<ActiveSupport::Logger:0x00007fbf0d8572c0 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x00007fbf0d857180 @datetime_format=nil>, @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x00007fbf0d857090 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x00007fbf0d857130 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mon_mutex=#<Thread::Mutex:0x00007fbf0d8570b8>, @mon_mutex_owner_object_id=70229271165080, @mon_owner=nil, @mon_count=0>>
irb(main):002:0> logger.info('hello')
hello
=> nil

Actual behavior

$ RAILS_ENV=test RACK_ENV=test bundle exec rails c
Loading test environment (Rails 6.0.3.5)
irb(main):001:0> logger=ActiveSupport::Logger.new(STDOUT)
=> #<ActiveSupport::Logger:0x00007fbf0d8572c0 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x00007fbf0d857180 @datetime_format=nil>, @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x00007fbf0d857090 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x00007fbf0d857130 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mon_mutex=#<Thread::Mutex:0x00007fbf0d8570b8>, @mon_mutex_owner_object_id=70229271165080, @mon_owner=nil, @mon_count=0>>
irb(main):002:0> logger.info('hello')
hello
=> [nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, #<Sentry::Breadcrumb:0x00007fbf0d8239e8 @category="logger", @data={}, @level="info", @message="hello", @timestamp=1614349479, @type="info">]
irb(main):003:0> logger.info('hello')
hello
=> nil

It seems the first log always returns the breadcrumbs. If it doesn't, adding a breadcrumb will cause the next log to return the breadcrumbs:

# continuation of previous shell
irb(main):004:0> Rails.logger.add_breadcrumb(Logger::INFO, 'a breadcrumb')
=> [nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, #<Sentry::Breadcrumb:0x00007fbf0d8239e8 @category="logger", @data={}, @level="info", @message="hello", @timestamp=1614349479, @type="info">, #<Sentry::Breadcrumb:0x00007fbf0df55dd8 @category="logger", @data={}, @level="info", @message="a breadcrumb", @timestamp=1614349612, @type="info">]
irb(main):005:0> logger.info('hello')
hello
=> [nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, nil, #<Sentry::Breadcrumb:0x00007fbf0d8239e8 @category="logger", @data={}, @level="info", @message="hello", @timestamp=1614349479, @type="info">, #<Sentry::Breadcrumb:0x00007fbf0df55dd8 @category="logger", @data={}, @level="info", @message="a breadcrumb", @timestamp=1614349612, @type="info">, #<Sentry::Breadcrumb:0x00007fbf0df59b18 @category="logger", @data={}, @level="info", @message="hello", @timestamp=1614349613, @type="info">]

Environment

Ruby Version: 2.6.6
SDK Version: 4.2.2
Integration Versions (if any):
Rails 6.0.3.5

Raven Config

This is not necessary but could be helpful.

Sentry.init do |config|
  config.dsn = Rails.configuration.sentry.fetch(:sentry_dsn)
  config.enabled_environments = %w[production staging]
  config.send_default_pii = true

  filter = ActiveSupport::ParameterFilter.new(Rails.application.config.filter_parameters)
  # See https://docs.sentry.io/platforms/ruby/guides/rails/configuration/filtering/#using-beforesend
  config.before_send = lambda do |event, _hint|
    # note1: if you have config.async configured, the event here will be a Hash instead of an Event object
    # note2: the code below is just an example, you should adjust the logic based on your needs
    event.request.data = filter.filter(event.request.data)
    event
  end

  config.breadcrumbs_logger = [:sentry_logger]

  config.traces_sample_rate = 0.5
end

sentry-ruby/lib/sentry/breadcrumb/sentry_logger.rb

st0012

@henrahmagix thanks for reporting this and even open the PR! just curious, why do you choose to use sentry_logger instead of active_support_logger?

henrahmagix · 2021-03-04T12:38:43Z

thanks for reporting this and even open the PR!

❤️

just curious, why do you choose to use sentry_logger instead of active_support_logger?

No reason yet – we want to see what breadcrumb logging offers us first before we commit, so we're just trying it out, though I haven't released that addition yet. I just copy-pasted a line I saw somewhere (maybe sentry docs, can't remember though sorry!) so there's no reasoning behind the choice yet =)

henrahmagix · 2021-03-04T13:46:09Z

@st0012 I've rebased onto the main branch to fix the conflicts, so I took the opportunity to squash everything – with test addition – into one commit =)

st0012

thanks for the fix 😄

henrahmagix · 2021-03-04T15:44:09Z

You're welcome @st0012! Thanks for being so responsive =) Could you post here when it's released please, so I get a notification? Ta!

st0012 · 2021-03-04T16:12:04Z

sure, but I can just tell you it'll be next week 🙂

st0012 added bug fix sentry-ruby labels Feb 26, 2021

st0012 reviewed Feb 27, 2021

View reviewed changes

sentry-ruby/lib/sentry/breadcrumb/sentry_logger.rb Show resolved Hide resolved

st0012 reviewed Feb 27, 2021

View reviewed changes

st0012 modified the milestones: sentry-ruby-4.2.3, 4.3.0 Feb 27, 2021

Stop returning breadcrumbs buffer when logging

f07cb22

st0012 approved these changes Mar 4, 2021

View reviewed changes

st0012 merged commit 6143fd0 into getsentry:master Mar 4, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Rails.logger methods return breadcrumbs instead of true when breadcrumbs logging is enabled#1299

Rails.logger methods return breadcrumbs instead of true when breadcrumbs logging is enabled#1299
st0012 merged 1 commit intogetsentry:masterfrom
henrahmagix:master

henrahmagix commented Feb 26, 2021

Uh oh!

Uh oh!

st0012 left a comment

Uh oh!

henrahmagix commented Mar 4, 2021

Uh oh!

henrahmagix commented Mar 4, 2021 •

edited

Loading

Uh oh!

st0012 left a comment

Uh oh!

henrahmagix commented Mar 4, 2021

Uh oh!

st0012 commented Mar 4, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

henrahmagix commented Feb 26, 2021

Uh oh!

Uh oh!

st0012 left a comment

Choose a reason for hiding this comment

Uh oh!

henrahmagix commented Mar 4, 2021

Uh oh!

henrahmagix commented Mar 4, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

st0012 left a comment

Choose a reason for hiding this comment

Uh oh!

henrahmagix commented Mar 4, 2021

Uh oh!

st0012 commented Mar 4, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

henrahmagix commented Mar 4, 2021 •

edited

Loading