search

rollbar / rollbar-gem

Exception tracking and logging from Ruby to Rollbar
https://docs.rollbar.com/docs/ruby
MIT License
444 stars 279 forks source link

bug: intermittent ArgumentError from ignore_before_process on JRuby #1129

Closed bf4 closed 2 weeks ago

bf4 commented 1 year ago

I can't tell what causes this since it's internal code to rollbar which looks fine. Sharing in case this happens to anyone else.

JRuby 9.4.1.0, ruby 3.1.0

backtrace

2023-08-25T21:11:52.546856+00:00 app[scheduler.7589]: ArgumentError: wrong number of arguments (given 3, expected 4)
2023-08-25T21:11:52.546856+00:00 app[scheduler.7589]: ignore_before_process? at /app/vendor/bundle/jruby/3.1.0/gems/rollbar-3.4.0/lib/rollbar/notifier.rb:150
2023-08-25T21:11:52.546856+00:00 app[scheduler.7589]: log at /app/vendor/bundle/jruby/3.1.0/gems/rollbar-3.4.0/lib/rollbar/notifier.rb:138
2023-08-25T21:11:52.546856+00:00 app[scheduler.7589]: error at /app/vendor/bundle/jruby/3.1.0/gems/rollbar-3.4.0/lib/rollbar/notifier.rb:197
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: error at /app/vendor/ruby-3.1.0-jruby-9.4.1.0/lib/ruby/stdlib/forwardable.rb:238
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: display_error_message_with_rollbar at /app/vendor/bundle/jruby/3.1.0/gems/rollbar-3.4.0/lib/rollbar/plugins/rake.rb:21
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: standard_exception_handling at /app/vendor/bundle/jruby/3.1.0/gems/rake-13.0.6/lib/rake/application.rb:195
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: load_rakefile at /app/vendor/bundle/jruby/3.1.0/gems/rake-13.0.6/lib/rake/application.rb:103
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: run at /app/vendor/bundle/jruby/3.1.0/gems/rake-13.0.6/lib/rake/application.rb:82
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: standard_exception_handling at /app/vendor/bundle/jruby/3.1.0/gems/rake-13.0.6/lib/rake/application.rb:186
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: run at /app/vendor/bundle/jruby/3.1.0/gems/rake-13.0.6/lib/rake/application.rb:80
2023-08-25T21:11:52.546857+00:00 app[scheduler.7589]: <main> at /app/vendor/bundle/jruby/3.1.0/gems/rake-13.0.6/exe/rake:27
2023-08-25T21:11:52.546858+00:00 app[scheduler.7589]: load at org/jruby/RubyKernel.java:1091
2023-08-25T21:11:52.546858+00:00 app[scheduler.7589]: <main> at bin/rake:29
2023-08-25T21:11:52.546858+00:00 app[scheduler.7589]: ... 14 levels...

2023-08-25T21:11:52.547113+00:00 app[scheduler.7589]: ActiveRecord::StatementInvalid: ActiveRecord::JDBCError: org.postgresql.util.PSQLException: This connection has been closed.
2023-08-25T21:11:52.547114+00:00 app[scheduler.7589]: log at /app/vendor/bundle/jruby/3.1.0/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract_adapter.rb:699
bangrrrt commented 1 year ago

Rails 7.0.6 Rollbar 3.4.0 jruby 9.4.3.0 ruby 3.1.4

We experienced the same thing. We can't create a minimal example to reproduce the issue but we got around it with this patch.

Rollbar::Notifier.class_eval do
  def use_exception_level_filters?(options)
    option_value = options && options[:use_exception_level_filters]

    return option_value unless option_value.nil?

    configuration.use_exception_level_filters_default
  end
end

The difference is options[:use_exception_level_filters] vs options.delete(:use_exception_level_filters)

https://github.com/rollbar/rollbar-gem/blob/master/lib/rollbar/notifier.rb#L409

These args are passed to Rollbar.log. At this point extra is a hash.

[1] pry(#<Rollbar::Notifier>)> extra
=> {:use_exception_level_filters=>true}
[2] pry(#<Rollbar::Notifier>)> extra.class
=> Hash

After use_exception_level_filters? is called extra returns a weird error.

[1] pry(#<Rollbar::Notifier>)> extra
ArgumentError: wrong number of arguments (given 0, expected 1)
from /usr/local/rvm/gems/default/gems/pry-0.14.2-java/lib/pry/ring.rb:43:in `<<'
Caused by RuntimeError: foo
from /workspaces/Profile/app/controllers/name_controller.rb:8:in `edit'
[2] pry(#<Rollbar::Notifier>)> extra.class
=> Hash

When ignore_before_process? is called it's with extra it produces this error. 

[1] pry(#<Rollbar::Notifier>)> ignore_before_process?(level, exception, message, extra)
ArgumentError: wrong number of arguments (given 3, expected 4)
from /usr/local/rvm/gems/default/gems/rollbar-3.4.0/lib/rollbar/notifier.rb:158:in `ignore_before_process?'
Caused by RuntimeError: foobar
from /workspaces/Profile/app/controllers/name_controller.rb:8:in `edit'

When plugging in the actual value all is good.

[2] pry(#<Rollbar::Notifier>)> ignore_before_process?(level, exception, message, {:use_exception_level_filters=>true})
=> false

Side note: The method use_exception_level_filters? is a bit misleading as it also mutates the options.

lenny commented 1 year ago

While many consider avoiding mutation of method arguments preferable, this bug appears to be rooted in a Jruby issue. I've submitted Unexpected ArgumentError calling Forwardable delegated single splat method with keyword arguments

bf4 commented 2 weeks ago

Thanks for getting this fixed in JRuby!