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 on the list. Let's 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 the middlewares list at the same time, some shitty things are happening.
At 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 constantly growing!
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.