"Stack level is too deep" on 7.3.3 when calling from Sneakers (7.2.0) worker with Rails 5.2.0 #850

ivan-kolmychek · 2018-06-11T09:02:24Z

Airbrake version: 7.3.3 (airbrake-ruby 2.10.0)
Ruby version: 2.5.0
Framework name & version:
- Rails 5.2.0
- Sneakers 2.7.0

Airbrake config

config/initializers/aribrake.rb (omitting comments other than f-s-l):

# frozen_string_literal: true

Airbrake.configure do |c|
  c.project_id = ENV.fetch('AIRBRAKE_PROJECT_ID', nil)
  c.project_key = ENV.fetch('AIRBRAKE_PROJECT_KEY', nil)

  c.root_directory = Rails.root

  c.logger = Rails.logger

  c.environment = Rails.env

  c.ignore_environments = %w(development test)
  c.blacklist_keys = [/password/i, /authorization/i]

  c.code_hunks = false
end

Right now airbrake is not hooked up into sneakers (as in require 'airbrake/sneakers'), we call it explicitly from workers where needed.

I do see my own comment in code that we decided to not hook it up due to the very similar error in 7.2.1, but right now I cannot think of any reason why I thought just calling it explicitly will fix it.
Looks like, since we fixed the exceptions that were causing the problem, I have not checked that "Stack level is too deep" was actually fixed.

Description

When there is an exception which is sent to Airbrake via Airbrake.notify() from inside Sneakers worker, it raises Stack level is too deep error.
I have searched issues for that before and found #743 which describes a very similar problem. The comment in #743 says it was fixed in airbrake-ruby 2.2.4, but apparently not for our use-case.

Example of trace that we have:

  #<Thread:0x00007f88b82ef570@/app/vendor/bundle/ruby/2.5.0/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/async_sender.rb:98 run> terminated
  with exception (report_on_exception is true):   
  /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `each': stack level too deep (S
  ystemStackError)   
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `map'    
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `as_json'
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:56:in `as_json' 
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `block in as_json' 
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `each'   
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `map'    
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `as_json'
    from /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `block in as_json' 
    ... 1456 levels...
    from /app/vendor/bundle/ruby/2.5.0/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:62:in `tap'    
    from /app/vendor/bundle/ruby/2.5.0/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:62:in `build_post_request'    
    from /app/vendor/bundle/ruby/2.5.0/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:26:in `send'   
    from /app/vendor/bundle/ruby/2.5.0/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/async_sender.rb:101:in `block in spawn_worker'

Please let me know if you need any more details.

The text was updated successfully, but these errors were encountered:

kyrylo · 2018-06-11T21:32:27Z

Hi, thanks for the detailed bug report. I'll need some time to replicate it and I'll let you know if I need any additional info.

airbrake/airbrake#850

kyrylo · 2018-06-13T11:00:10Z

Sorry, I cannot reproduce this bug. I have limited experience with Sneakers and RabbitMQ, so I shared my repository, which I created specifically for this bug: https://github.com/kyrylo/airbrake-bug-850

My worker: https://github.com/kyrylo/airbrake-bug-850/blob/master/app/workers/processor.rb
Initializers:

Can you please take a look and modify it accordingly to make it fail like you showed?

ivan-kolmychek · 2018-06-13T13:55:02Z

@kyrylo thank you. Sure, I will fork it and try to reproduce it there.

ivan-kolmychek · 2018-06-13T19:42:41Z

@kyrylo I was able to partially reproduce it, here is the base code - https://github.com/ivan-kolmychek/airbrake-bug-850/tree/try-to-reproduce-bug

Apparently I was wrong about few things:

manual call to airbrake works fine
we do have airbrake-sneakers integration enabled. I don't know where or why exactly, but it shows up in the self.error_reporters from inside worker, even though it is commented out:

$ grep -R "require 'airbrake/sneakers'" ./app ./config
./config/initializers/sneakers.rb:# require 'airbrake/sneakers'

The integration is what causing problems, "stack level is too deep" shows up on any uncaught exception.

What I did to reproduce the error using code above:

launch two docker-compose run --rm app in different terminals
run in first bundle exec rails sneakers:run, it should start up sneakers
start in second Rails console and publish a message via Sneakers.publish('whatever', to_queue: 'logs')
observe the error in terminal where sneakers are up

2018-06-13T19:33:19Z p-165 t-gq0g1sqaw INFO: INC: work.Processor.handled.error                                        
#<Thread:0x000055d020f589d0@/app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/async_sender.rb:98 run>
terminated with exception (report_on_exception is true):
Traceback (most recent call last):
        1466: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/async_sender.rb:101:in `block in
spawn_worker'
        1465: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:26:in `send'     
        1464: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:62:in `build_post_request'
        1463: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:62:in `tap'      
        1462: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/sync_sender.rb:63:in `block in build_post_request'
        1461: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/notice.rb:81:in `to_json'       
        1460: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/notice.rb:81:in `loop'          
        1459: from /app/vendor/bundle/2.5/gems/airbrake-ruby-2.10.0/lib/airbrake-ruby/notice.rb:83:in `block in to_json'
         ... 1454 levels...
           4: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `map'
           3: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `each'
           2: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'
           1: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `dup'
/app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `initialize_dup': stack level too deep (SystemStackError)
2018-06-13T19:33:19Z p-165 t-gq0g1sqaw INFO: INC: work.Processor.ended

I have placed a binding.irb in vendor/bundle/2.5/gems/airbrake-7.3.3/lib/airbrake/sneakers.rb before call to Airbrake and it looks like context.to_json can cause similar behavior:

From: /app/vendor/bundle/2.5/gems/airbrake-7.3.3/lib/airbrake/sneakers.rb @ line 9 :                                                                                                                                                           
                                                                                                                                                                                                                                               
     4:     #
     5:     # @see https://github.com/jondot/sneakers
     6:     # @since v7.2.0
     7:     class ErrorReporter
     8:       def call(exception, worker = nil, **context)
 =>  9:         binding.irb
    10:         Airbrake.notify(exception, context) do |notice|
    11:           notice[:context][:component] = 'sneakers'
    12:           notice[:context][:action] = worker.class.to_s
    13:         end
    14:       end

irb(#<Airbrake::Sneakers::ErrorReporter:0x00005620ff2747c0>):001:0> context
=> {:log_msg=>"[worker-logs:1:clp2yx][#<Thread:0x00005620ff404810@/app/vendor/bundle/2.5/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:317 run>][logs][#<Sneakers::Configuration:0x00005620ff464b48>] whateve
r", :class=>"Processor", :message=>"whatever", :delivery_info=>{:consumer_tag=>"bunny-1528918723000-690000297111", :delivery_tag=>#<Bunny::VersionedDeliveryTag:0x00005620ff404f68 @tag=1, @version=0>, :redelivered=>false, :exchange=>"sneake
rs", :routing_key=>"logs", :consumer=>#<Bunny::Consumer:47349860706280 @channel_id=1 @queue=logs> @consumer_tag=bunny-1528918723000-690000297111 @exclusive= @no_ack=false>, :channel=>#<Bunny::Channel:47349860756040 @id=1 @connection=#<Bunn
y::Session:0x5620ff44f608 guest@rabbitmq:5672, vhost=/, addresses=[rabbitmq:5672]>>}, :metadata=>{:content_type=>"application/octet-stream", :delivery_mode=>2, :priority=>0}}                                                                
irb(#<Airbrake::Sneakers::ErrorReporter:0x00005620ff2747c0>):002:0> context.to_json
Traceback (most recent call last):
       16: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:56:in `as_json'                                                                                                                    
       15: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `as_json'                                                                                                                   
       14: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `map'
       13: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `each'                                                                                                                      
       12: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'                                                                                                          
       11: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `as_json'                                                                                                                   
       10: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `map'
        9: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `each'
        8: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'
        7: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:56:in `as_json'
        6: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `as_json'
        5: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `map'
        4: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `each'
        3: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'
        2: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `dup'
        1: from /app/vendor/bundle/2.5/gems/activesupport-5.2.0/lib/active_support/core_ext/object/json.rb:171:in `initialize_dup'
SystemStackError (stack level too deep)
irb(#<Airbrake::Sneakers::ErrorReporter:0x00005620ff2747c0>):003:0> 2018-06-13T19:39:11Z p-236 t-gs884k25o DEBUG: Sending a heartbeat, last activity time: 2018-06-13 19:38:43 +0000, interval (s): 14

Hope this helps, please let me know if you need more information.

kyrylo · 2018-06-14T08:44:42Z

Awesome, thanks! Great instructions, I was able to reproduce the bug.

we do have airbrake-sneakers integration enabled

We try to load it automatically when Sneakers is detected. I added a manual require call to be 100% sure.

kyrylo · 2018-06-14T09:08:28Z

context[:delivery_info] is the culprit here. activesupport fails to JSONify it. We've had a similar issue in the past where ActiveSupport was misbehaving: #752 (comment)

My reply here is similar to my reply in that issue. We can't do much but exclude the object from context. How important is context[:delivery_info] for Sneakers users, from your experience?

ivan-kolmychek · 2018-06-14T12:19:57Z

It really depends on use-case I guess.

The context[:delivery_info] itself looks convertable to hash, calling .to_h on it returns:

{
  :consumer_tag=>"bunny-1528977636000-907780786291",
  :delivery_tag => #<Bunny::VersionedDeliveryTag:0x00007f91fc00f588 @tag=1, @version=0>,
  :redelivered => false,
  :exchange => "sneakers",
  :routing_key => "logs",
  :consumer => #<Bunny::Consumer:70132487431280 @channel_id=1 @queue=logs> @consumer_tag=bunny-1528977636000-907780786291 @exclusive= @no_ack=false>,
  :channel => #<Bunny::Channel:46996404621480 @id=1 @connection=#<Bunny::Session:0x557c67fed4c0 guest@rabbitmq:5672, vhost=/, addresses=[rabbitmq:5672]>>
}

Out of the data I see there, I know we may use:

:routing_key - what exactly the message was about? Error can happen on :foo_bar_updated and not on :baz_created
:redelivered - did we already attempt to handle it before?
:exchange - what was it published to? This is useful in case each sender have their own exchange and exception gets raised because one of senders sends malformed stuff.

I am not sure is :consumer_tag important, but my guess would be that :consumer, :channel and :delivery_tag can be ignored.

It may also be a good idea to provide a way for each app to customize the way integration converts it, but it sounds like an overkll to me.

kyrylo · 2018-06-14T12:35:55Z

The context[:delivery_info] itself looks convertable to hash, calling .to_h on it returns:

I wrote context[:delivery_info] for simplicity but what actually fails is:

context[:delivery_info][:delivery_tag]
context[:delivery_info][:channel]
context[:delivery_info][:consumer]

It may also be a good idea to provide a way for each app to customize the way integration converts it, but it sounds like an overkll to me.

Yeah, sounds like an overkill to me. We may want to consider it once more integrations fall under the same use case.

I am not sure is :consumer_tag important, but my guess would be that :consumer, :channel and :delivery_tag can be ignored.

Perfect, I think we can simply ignore those since they are causing as_json to choke and it's not our responsibility to fix that (or define a sensible as_json) on them.

ivan-kolmychek · 2018-06-14T12:47:06Z

I think we can simply ignore those

That would work for our use-cases.
If anyone would actually need those, I think they can open separate issue, here or in Sneakers.

Fixes #850 ("Stack level is too deep" on 7.3.3 when calling from Sneakers (7.2.0) worker with Rails 5.2.0) `as_json` causes problems on certain objects that Sneakers manages. We can't do anything but ignore them.

kyrylo · 2018-06-14T17:06:47Z

I just released v7.3.4 with this fix. Please update.

ivan-kolmychek · 2018-06-16T15:25:25Z

@kyrylo thank you, can confirm now that problem is solved.

kyrylo added Bug Rails labels Jun 11, 2018

kyrylo added a commit to kyrylo/airbrake-bug-850 that referenced this issue Jun 13, 2018

Bug #850

4525cca

airbrake/airbrake#850

kyrylo mentioned this issue Jun 14, 2018

sneakers: fix SystemStackError #852

Merged

kyrylo closed this as completed in #852 Jun 14, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"Stack level is too deep" on 7.3.3 when calling from Sneakers (7.2.0) worker with Rails 5.2.0 #850

"Stack level is too deep" on 7.3.3 when calling from Sneakers (7.2.0) worker with Rails 5.2.0 #850

ivan-kolmychek commented Jun 11, 2018

kyrylo commented Jun 11, 2018

kyrylo commented Jun 13, 2018

ivan-kolmychek commented Jun 13, 2018

ivan-kolmychek commented Jun 13, 2018 •

edited

kyrylo commented Jun 14, 2018

kyrylo commented Jun 14, 2018

ivan-kolmychek commented Jun 14, 2018

kyrylo commented Jun 14, 2018

ivan-kolmychek commented Jun 14, 2018

kyrylo commented Jun 14, 2018

ivan-kolmychek commented Jun 16, 2018

"Stack level is too deep" on 7.3.3 when calling from Sneakers (7.2.0) worker with Rails 5.2.0 #850

"Stack level is too deep" on 7.3.3 when calling from Sneakers (7.2.0) worker with Rails 5.2.0 #850

Comments

ivan-kolmychek commented Jun 11, 2018

Airbrake config

Description

kyrylo commented Jun 11, 2018

kyrylo commented Jun 13, 2018

ivan-kolmychek commented Jun 13, 2018

ivan-kolmychek commented Jun 13, 2018 • edited

kyrylo commented Jun 14, 2018

kyrylo commented Jun 14, 2018

ivan-kolmychek commented Jun 14, 2018

kyrylo commented Jun 14, 2018

ivan-kolmychek commented Jun 14, 2018

kyrylo commented Jun 14, 2018

ivan-kolmychek commented Jun 16, 2018

ivan-kolmychek commented Jun 13, 2018 •

edited