Rails + Puma - Bunny raises timeouts on high workloads

[BirknerAlex]

Hello,

I'm running a Rails application. I have a scheduler class which is singleton and shared by the puma workers. This instance has one Bunny::Session instance which is also shared.

Every request get's it own channel because your documentation explains it should not been shared among theads.

This errors are coming randomly:

Connection-level error: CHANNEL_ERROR - expected 'channel.open' Connection-level error: COMMAND_INVALID - second 'channel.open' seen Timeout::Error: execution expired

I've attached one stacktrace for you:

/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/bunny-1.7.0/lib/bunny/session.rb:588:in `raise_if_continuation_resulted_in_a_connection_error!'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/bunny-1.7.0/lib/bunny/session.rb:486:in `open_channel'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/bunny-1.7.0/lib/bunny/channel.rb:218:in `open'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/bunny-1.7.0/lib/bunny/session.rb:328:in `block in create_channel'
/usr/local/rvm/rubies/ruby-2.2.1/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/bunny-1.7.0/lib/bunny/session.rb:323:in `create_channel'
/opt/api-nitrado/releases/20150611144453/lib/nitrapi/scheduler.rb:65:in `add_and_wait_for_response'
/opt/api-nitrado/releases/20150611144453/lib/event.rb:8:in `perform'
/opt/api-nitrado/releases/20150611144453/lib/nitrapi/helpers/gameserver_helper.rb:23:in `status?'
/opt/api-nitrado/releases/20150611144453/app/models/gameserver.rb:59:in `status?'
/opt/api-nitrado/releases/20150611144453/app/controllers/services/gameservers_controller.rb:5:in `index'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/abstract_controller/base.rb:198:in `process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal/rendering.rb:10:in `process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:117:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:117:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:292:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:292:in `block (2 levels) in halting_and_conditional'
/opt/api-nitrado/releases/20150611144453/app/controllers/application_controller.rb:214:in `log_request'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:291:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:291:in `block in halting_and_conditional'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:497:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:497:in `block in around'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:92:in `_run_callbacks'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:776:in `_run_process_action_callbacks'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/abstract_controller/callbacks.rb:19:in `process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal/rescue.rb:29:in `process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/notifications.rb:164:in `block in instrument'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/notifications.rb:164:in `instrument'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/abstract_controller/base.rb:137:in `process'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionview-4.2.1/lib/action_view/rendering.rb:30:in `process'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal.rb:196:in `dispatch'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_controller/metal.rb:237:in `block in action'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/routing/route_set.rb:74:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/routing/route_set.rb:43:in `serve'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/journey/router.rb:43:in `block in serve'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/journey/router.rb:30:in `each'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/journey/router.rb:30:in `serve'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/routing/route_set.rb:819:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/etag.rb:24:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/conditionalget.rb:25:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/head.rb:13:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/flash.rb:260:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/session/abstract/id.rb:225:in `context'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/session/abstract/id.rb:220:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/cookies.rb:560:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:88:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:88:in `_run_callbacks'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:776:in `_run_call_callbacks'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/railties-4.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/railties-4.2.1/lib/rails/rack/logger.rb:20:in `block in call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:68:in `block in tagged'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:26:in `tagged'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:68:in `tagged'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/railties-4.2.1/lib/rails/rack/logger.rb:20:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/actionpack-4.2.1/lib/action_dispatch/middleware/request_id.rb:21:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/methodoverride.rb:22:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/rack-1.6.1/lib/rack/runtime.rb:18:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/activesupport-4.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/railties-4.2.1/lib/rails/engine.rb:518:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/railties-4.2.1/lib/rails/application.rb:164:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/puma-2.11.1/lib/puma/configuration.rb:82:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/puma-2.11.1/lib/puma/server.rb:507:in `handle_request'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/puma-2.11.1/lib/puma/server.rb:375:in `process_client'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/puma-2.11.1/lib/puma/server.rb:262:in `block in run'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/puma-2.11.1/lib/puma/thread_pool.rb:104:in `call'
/opt/api-nitrado/shared/bundle/ruby/2.2.0/gems/puma-2.11.1/lib/puma/thread_pool.rb:104:in `block in spawn_thread'

I've also attached the scheduler class, maybe someone have a idea how I can solve this issue?

require 'socket'
require 'securerandom'
require 'timeout'

module Nitrapi
  class Scheduler
    include Singleton

    #  RabbitMQ network connection once it is gone.
    def initialize
      begin
        @rabbitmq ||= Bunny.new(
            :host => RABBITMQ_CONFIG['events']['hostname'],
            :port => RABBITMQ_CONFIG['events']['port'],
            :user => RABBITMQ_CONFIG['events']['username'],
            :pass => RABBITMQ_CONFIG['events']['password'],
            :vhost => RABBITMQ_CONFIG['events']['vhost'],
            :automatically_recover => false
        )
        @rabbitmq.start unless @rabbitmq.open?

      rescue Bunny::NetworkFailure, Bunny::TCPConnectionFailed, Bunny::ConnectionForced => e
        @rabbitmq = nil
        puts "Error: #{e.to_s}"
        puts "Disconnect from RabbitMQ, reconnecting..."
        sleep 5
        retry
      end
    end

    def add_and_wait_for_response(event, timeout=300)
      begin
        # error handling if rabbitmq connection has been failed and object has been destroyed by bunny
        if not @rabbitmq.kind_of?(Bunny::Session) or not @rabbitmq.open?
          initialize
        end

        event.identifier = SecureRandom.uuid

        # Open the RabbitMQ channel
        c = @rabbitmq.create_channel
        x = c.default_exchange
        q = c.queue("events_#{event.target_host}", auto_delete: false, durable: true)

        x.on_return do |return_info, properties, content|
          raise "Event can't be delivered: #{return_info.to_s}"
        end

        data = {
            hostsystem: event.target_host,
            source_host: Socket.gethostname,
            username: event.username,
            admin: event.admin?,
            event_id: event.identifier,
            event_name: event.to_s,
            event_data: event.data,
            tdl: timeout
        }

        if event.log_document
          log_event(event, data)
        end

        # Open the response channel and wait for the response
        rq_name = "event_response_#{data[:source_host]}_#{event.identifier}"
        rq = c.queue(rq_name, auto_delete: true, durable: false)

        # Send the event
        x.publish(data.to_json, :routing_key => q.name, :mandatory => true)

        response_data = {}
        begin
          Timeout.timeout(timeout) do
            rq.subscribe(:manual_ack => true, :block => true) do |delivery_info, metadata, payload|
              c.acknowledge(delivery_info.delivery_tag, false)
              response_data = JSON.parse(payload)
              c.consumers[delivery_info[:consumer_tag]].cancel
            end
          end
        rescue Timeout::Error
          rq.delete if rq and @rabbitmq.queue_exists?(rq_name)
          result_data = {}
          result_data['error_message'] = "RabbitMQ Receive Timeout for #{data[:source_host]}_#{event.identifier} from #{event.target_host}"
          response_data['data'] = result_data
          response_data['status'] = 'error'
        end

        c.close unless c.closed?

        if event.log_document
          log_event_finalization(event, response_data)
        end
        response_data
      rescue Bunny::NetworkFailure, Bunny::TCPConnectionFailed, Bunny::ConnectionForced => e
        c.maybe_kill_consumer_work_pool! if c

        # if connection has been failed -> resend this event
        @rabbitmq = nil
        puts "Error: #{e.to_s}"
        puts "Disconnect from RabbitMQ, retrying event..."
        initialize
        add_and_wait_for_response(event, timeout)
      end
    end

    def log_event(event, request)
      event.log_document.event_log = Logging::EventLog.new(request.merge({created_at: Time.now}))
    end

    def log_event_finalization(event, response)
      event.log_document.event_log.update_attributes(
          finished_at: Time.now,
          response: response,
          response_status: response[:status])
    end
  end
end

[michaelklishin]

The error RabbitMQ reports has nothing to do with timeouts. It means that a channel id that is currently in use was "opened".

Has been discussed numerous times before on the list, and in issues (which we do not use for questions). Timeout.timeout starts a new thread for every invocation. Bunny itself has recently gotten rid of Timeout because it has multiple issues well covered elsewhere.

Also worth pointing out: timeout of 300 ms is not particularly high. If you run into an alarm or flow control (which is temporary but can last for a 100-200 ms), there you have it.