Fork me on GitHub

From Siberia with love

Go Down the Rabbit Hole

All the real application code replaced with demo code.

Not so long ago I’ve fought with strange bug in our app. From time to time app failed to respond with strange backtrace:

Exception in thread "Ruby-0-Thread-52620: -e:1" java.lang.ArrayIndexOutOfBoundsException
at org.jruby.runtime.Helpers.fillNil(Helpers.java:2351)
at org.jruby.RubyArray.spliceOne(RubyArray.java:897)
at org.jruby.RubyArray.insert(RubyArray.java:952)
at org.jruby.RubyArray.insert19(RubyArray.java:961)
at org.jruby.RubyArray$INVOKER$i$insert19.call(RubyArray$INVOKER$i$insert19.gen)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:202)
at rubyjit.Bugsnag::MiddlewareStack$$insert_before_fdd57e746f34236f5a252d37c072ca5fc4fa738a1836019240.__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag/middleware_stack.rb:39)
at rubyjit.Bugsnag::MiddlewareStack$$insert_before_fdd57e746f34236f5a252d37c072ca5fc4fa738a1836019240.__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag/middleware_stack.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:221)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:202)
at rubyjit.Bugsnag::Rack$$initialize_e824fe049c93369fbf06e99bfb1a3414b042e2681836019240.block_0$RUBY$__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag/rack.rb:21)
at rubyjit$Bugsnag::Rack$$initialize_e824fe049c93369fbf06e99bfb1a3414b042e2681836019240$block_0$RUBY$__file__.call(rubyjit$Bugsnag::Rack$$initialize_e824fe049c93369fbf06e99bfb1a3414b042e2681836019240$block_0$RUBY$__file__)
at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135)
at org.jruby.runtime.CompiledBlock19.yieldSpecific(CompiledBlock19.java:97)
at org.jruby.runtime.Block.yieldSpecific(Block.java:120)
at rubyjit.Module$$configure_1cadfc7837da98ed39f8d5a8fda78bd76d2323ce1836019240.__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag.rb:38)
at rubyjit.Module$$configure_1cadfc7837da98ed39f8d5a8fda78bd76d2323ce1836019240.__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag.rb)
at org.jruby.ast.executable.AbstractScript.__file__(AbstractScript.java:38)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:161)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)
at rubyjit.Bugsnag::Rack$$initialize_e824fe049c93369fbf06e99bfb1a3414b042e2681836019240.__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag/rack.rb:7)
at rubyjit.Bugsnag::Rack$$initialize_e824fe049c93369fbf06e99bfb1a3414b042e2681836019240.__file__(/Users/kes/.rbenv/versions/jruby-1.7.18/lib/ruby/gems/shared/gems/bugsnag-2.8.1/lib/bugsnag/rack.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:201)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:177)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:183)
at org.jruby.RubyClass.newInstance(RubyClass.java:856)
at org.jruby.RubyClass$INVOKER$i$newInstance.call(RubyClass$INVOKER$i$newInstance.gen)
at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodZeroOrOneOrNBlock.call(JavaMethod.java:297)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)
at rubyjit.BugsnagThreadingIssue::Core$$initialize_90e721b9af8a5d79a8874b50cae1b272a899c7691836019240.block_1$RUBY$__file__(/Users/kes/Projects/spbtv/supporting/bugsnag_threading_issue/lib/bugsnag_threading_issue.rb:35)
at rubyjit$BugsnagThreadingIssue::Core$$initialize_90e721b9af8a5d79a8874b50cae1b272a899c7691836019240$block_1$RUBY$__file__.call(rubyjit$BugsnagThreadingIssue::Core$$initialize_90e721b9af8a5d79a8874b50cae1b272a899c7691836019240$block_1$RUBY$__file__)
at org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:159)
at org.jruby.runtime.CompiledBlock19.call(CompiledBlock19.java:87)
at org.jruby.runtime.Block.call(Block.java:101)
at org.jruby.RubyProc.call(RubyProc.java:290)
at org.jruby.RubyProc.call(RubyProc.java:228)
at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:99)
at java.lang.Thread.run(Thread.java:745)

First step in such a situation is to look to the Bugsnag::MiddlewareStack#insert_before method:

def insert_before(before, new_middleware)
  return if @disabled_middleware.include?(new_middleware)

  if before.is_a? Array
    index = @middlewares.index {|el| before.include?(el)}
  else
    index = @middlewares.index(before)
  end

  @middlewares.insert index || @middlewares.length, new_middleware
end

Okay, this code inserts middleware in the list. Lets find where @middlewares variable is defined.

module Bugsnag
  class MiddlewareStack
    def initialize
      @middlewares = []
      @disabled_middleware = []
    end
    <..>
  end
end

Thus @middlewares is an array this situation could happen if MiddlewareStack instance shared between threads.

This is the place where it’s accessed:

module Bugsnag
  class Rack
    def initialize(app)
      @app = app

      # Configure bugsnag rack defaults
      Bugsnag.configure do |config|
        <..>
        # Hook up rack-based notification middlewares
        config.middleware.insert_before([Bugsnag::Middleware::Rails3Request,Bugsnag::Middleware::Callbacks], Bugsnag::Middleware::RackRequest) if defined?(::Rack)
        <..>
      end
    end
    <..>
  end
end

So when two threads are trying to modify middlewares list at the same time some shitty things are happening.

At the first glance the fix is to make MiddlewareStack threadsafe and that’s it, but…

I realized that as far as middlewares array is modified on each request then it’s growing constantly!

Small demo to prove:

require 'bugsnag'
require 'bugsnag/rack'
require 'rack'

Bugsnag.configure do |c|
  c.project_root = File.expand_path('..', ENV['BUNDLE_GEMFILE'])
  c.logger = Logger.new('/dev/null')
end

module BugsnagThreadingIssue
  class App
    def initialize
      @app = Rack::Builder.new do
        use Bugsnag::Rack

        map('/') do
          run ->(_) do
            count = Bugsnag.configuration.middleware.instance_variable_get(:@middlewares).count
            p "Bugsnag middlewares: #{count}"
            [200, { 'Content-Type' => 'application/json' }, ["{\"middlewares\":#{count}}"]]
          end
        end
      end
    end

    def call(env)
      @app.call(env)
    end
  end
end

run BugsnagThreadingIssue::App.new
$ bundle exec rackup
[2015-03-25 01:53:20] INFO  WEBrick 1.3.1
[2015-03-25 01:53:20] INFO  ruby 1.9.3 (2014-12-22) [java]
[2015-03-25 01:53:20] INFO  WEBrick::HTTPServer#start: pid=81297 port=9292
"Bugsnag middlewares: 2"
127.0.0.1 - - [25/Mar/2015 01:53:30] "GET / HTTP/1.1" 200 - 0.0190
"Bugsnag middlewares: 3"
127.0.0.1 - - [25/Mar/2015 01:53:30] "GET / HTTP/1.1" 200 - 0.0120
"Bugsnag middlewares: 4"
127.0.0.1 - - [25/Mar/2015 01:53:30] "GET / HTTP/1.1" 200 - 0.0030

So simplest solution is to move configuration code out of initialize method and call it once with file require.

Here is the demo code.

blog comments powered byDisqus