Can't add a scope listener midflight in a transaction

[stevef]

Currently when I run any rake task after adding newrelic-rake to my project, I'm seeing something similar to:

$ rake RAILS_ENV=production db:migrate --trace * Invoke db:migrate (first_time) * Invoke environment (first_time) * Execute environment * Execute db:migrate * Invoke db:schema:dump (first_time) * Invoke environment rake aborted! Can't add a scope listener midflight in a transaction // followed by stack trace

I haven't had time yet to look at NewRelic internals so that's about all I can provide. Issue goes away as soon as I remove the gem. Going to jump into code now and see if there's something that can be done on the newrelic-rake end to mitigate this.

[spectator]

Hmm, I've been testing it lot, sometimes on this task and had no similar issues.

Do you still getting that error? If yes, please try using master gem 'new relic-rake', github: 'flyerhzm/newrelic-rake' and report any issues you see along with newrelic gem version and full trace.

[flyerhzm]

I just released a new version, try to update newrelic-rake gem.

[spectator]

I've got this error too, will dig into it tomorrow.

[AhmedElSharkasy]

I have this error too , any help?

[wadewinningham]

We started getting this running migrations. Here's the output. newrelic_rpm gem v3.5.8.72. Also using the newrelic-rake gem from flyerhzm/newrelic-rake which I updated a few minutes ago.

 * 2013-03-19 10:03:10 executing `deploy:migrate'
  * executing "ls -x /path/to/app/releases"
    servers: ["x.x.x.x"]
    [x.x.x.x] executing command
    command finished in 1709ms
  * executing "cd /path/to/app/releases/20130319145555 && bundle exec rake RAILS_ENV=production db:migrate"
    servers: ["x.x.x.x"]
    [x.x.x.x] executing command
 ** [out :: x.x.x.x] rake aborted!
 ** [out :: x.x.x.x] Can't add a scope listener midflight in a transaction
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/stats_engine/transactions.rb:38:in `transaction_sampler='
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/agent.rb:55:in `block in initialize'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:84:in `call'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:84:in `block (2 levels) in invoke_callbacks'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:82:in `each'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:82:in `block in invoke_callbacks'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:80:in `each'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:80:in `invoke_callbacks'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:25:in `apply_config'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/configuration/manager.rb:47:in `replace_or_add_config'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/control/instance_methods.rb:48:in `init_plugin'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent.rb:238:in `manual_start'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/bundler/gems/newrelic-rake-bfdefdfdf97b/lib/newrelic-rake/instrument.rb:20:in `execute'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/activerecord-3.1.12/lib/active_record/railties/databases.rake:162:in `block (2 levels) in <top (required)>'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/bundler/gems/newrelic-rake-bfdefdfdf97b/lib/newrelic-rake/instrument.rb:22:in `block in execute'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:268:in `block in perform_action_with_newrelic_trace'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/method_tracer.rb:240:in `trace_execution_scoped'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.8.72/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:263:in `perform_action_with_newrelic_trace'
 ** [out :: x.x.x.x] /path/to/app/shared/bundle/ruby/1.9.1/bundler/gems/newrelic-rake-bfdefdfdf97b/lib/newrelic-rake/instrument.rb:21:in `execute'
 ** [out :: x.x.x.x] Tasks: TOP => db:schema:dump
 ** [out :: x.x.x.x] (See full trace by running task with --trace)
    command finished in 21212ms
failed: "sh -c 'cd /path/to/app/releases/20130319145555 && bundle exec rake RAILS_ENV=production db:migrate'" on x.x.x.x

[spectator]

I'm looking into that with no results yet, however this issue comes up if you have threads profiling enabled. As a temporary solution you can disable that unless your app really needs threads profiling.

[spectator]

Doh... wait, I spoke too soon.

[spectator]

So what really happens is that in rake db:migrate case agent starts 4 times (that's why you see that more often on this task, however I got it in different one). I assume it gets triggered when rake runs all dependencies for db:migrate. When every agent initializes it starts sending data to the server using simple locking mechanism (like transaction) and one of the agents fails when it tries to do something with locked resource.

I'm still looking for better solution (agent shouldn't not start 4 times), but you might try disabling sync when agent starts https://github.com/spectator/newrelic-rake/tree/investigating_issue_1

[spectator]

Before going that far to implement this in cleaner way, here is what I come up with.

Pretty dangerous, requires a lot of testing before use on your system (I'll do my best to make sure it doesn't break newrelic functionality), and ugly auto-discovery of rake dispatcher. Surprisingly, NewRelic does a lot of things similar way. I guess there is no perfect way of doing that.

module NewRelic
  class LocalEnvironment
    private

    def discover_dispatcher
      dispatchers = %w[passenger torquebox trinidad glassfish resque rake thin mongrel litespeed webrick fastcgi unicorn sinatra]
      while dispatchers.any? && @discovered_dispatcher.nil?
        send 'check_for_'+(dispatchers.shift)
      end
    end

    def check_for_rake
      @discovered_dispatcher = :rake if defined?(::Rake::Task) &&
        File.basename($0) == 'rake' &&
        ObjectSpace.each_object(Rake::Task).any?{ |task| task.name == ARGV[0] }
    end
  end
end

DependencyDetection.defer do
  @name = :rake

  depends_on do
    defined?(::Rake) and not ::NewRelic::Control.instance['disable_rake']
  end

  executes do
    ::NewRelic::Agent.logger.info 'Installing Rake instrumentation'
  end

  executes do
    ::Rake::Task.class_eval do
      include ::NewRelic::Agent::Instrumentation::ControllerInstrumentation

      alias_method :origin_execute, :execute
      def execute(args=nil)
        perform_action_with_newrelic_trace(:name => self.name, :category => "OtherTransaction/Rake") do
          origin_execute(args)
        end
      end

      # Make sure NewRelic agent flush data to the server according to
      # https://newrelic.com/docs/ruby/monitoring-ruby-background-processes-and-daemons
      # even though Agent configuration is :send_data_on_exit => true
      at_exit { NewRelic::Agent.shutdown }
    end
  end
end

This eliminate necessity to start agent manually, thus starts it only once in the very beginning (during env initialization process).

@flyerhzm ?

[AhmedElSharkasy]

My issue was solved , it was only because i exceed the number of application in my pro newrelic account , after removing some apps , the problem was solved

[flyerhzm]

@spectator, sorry I didn't encounter such problem.

[pekeler]

I'm suddenly getting this issue with newrelic-rake 1.0.0, upgrading to 1.2.0 doesn't help. Help!

[flyerhzm]

I created start_agent_properly branch, which starts newrelic agent only once, pleas let me if it works for you.

[flyerhzm]

I released newrelic-rake 1.3.0 just now, let me know if it works for you.

[pekeler]

Seems to work again with 1.3.0. Thanks!