Rack middleware "trapping" stack trace

Question

I have a piece of Rack middleware that loads a tenant, via subdomain, and applies some default settings. The middleware, while not pretty, does it's job fine enough. However, when an exception is thrown within the app the middleware "traps" the full stack trace. When I say trap I mean it hides the expected stack trace.

Here is an example.

I am throwing an exception in an a controller action like so:

def index
  throw "Exception in a Rails controller action"
  @taxonomies = Spree::Taxonomy.all
end

You would expect that the stack trace would reference this location but it does not. Instead it reference a line in the middleware.

Completed 500 Internal Server Error in 139ms

UncaughtThrowError (uncaught throw "Exception in a Rails controller action"):
lib/tenant_manager/middleware/loader.rb:42:in `call'

Why does this happen? Have you seen anything like this before?

Here is the middleware:

# lib/tenant_manager/middleware/loader.rb
module TenantManager
  module Middleware
    class Loader
    # Middleware to detect an tenant via subdomain early in
    # the request process
    #
    # Usage:
    #   # config/application.rb
    #   config.middleware.use TenantManager::Middleware::Loader
    #
    # A scaled down version of https://github.com/radar/houser

      def initialize(app)
        @app = app
      end

      def call(env)
        domain_parts = env['HTTP_HOST'].split('.')
        if domain_parts.length > 2
          subdomain = domain_parts.first
          tenant = Leafer::Tenant.find_by_database(subdomain)
          if tenant
            ENV['CURRENT_TENANT_ID'] = tenant.id.to_s
            ENV['RAILS_CACHE_ID'] = tenant.database
            Spree::Image.change_paths tenant.database
            Apartment::Tenant.process(tenant.database) do
              country = Spree::Country.find_by_name('United States')
              Spree.config do |config|
                config.default_country_id = country.id if country.present?
                config.track_inventory_levels = false
              end
              Spree::Auth::Config.set(:registration_step => false)
            end
          end
        else
          ENV['CURRENT_TENANT_ID'] = nil
          ENV['RAILS_CACHE_ID'] = ""
        end
        @app.call(env)
      end

    end
  end
end

I am running ruby 2.2.0p0 and rails 4.1.8.

I have searched the webs for this but could not find anything, probably because I'm not serching for the right thing.

Any thoughts on why this is happening and what I am doing wrong?

Cheers!

Trichiasis

Answer 1

I finally found the solution to this. It turns out that the last line in what is considered my application is in the middleware. I was running the rest of the code in a local rails engine located in a components directory. All we needed to do was create a new silencer for BacktraceCleaner. Notice components dir is now included.

# config/initializers/backtrace_silencers.rb
Rails.backtrace_cleaner.remove_silencers!
Rails.backtrace_cleaner.add_silencer { |line| line !~ /^\/(app|config|lib|test|components)/}

If you are interested here is an issue I posted on the rails project about how to replicate this in detail. https://github.com/rails/rails/issues/22265

Trichiasis

Answer 2

Your middleware seems good. I think you have an issue with your backtrace_cleaner setting. Perhaps the cleaner gets overridden by a 3rd party gem. Try put a breakpoint (debugger) in the controller action method before the error raising, and print:

puts env['action_dispatch.backtrace_cleaner'].instance_variable_get(:@silencers).map(&:source_location).map{|l| l.join(':')}

to see the source locations of all the silencers which strip off non-app traces. By default it should only use Rails::BacktraceCleaner which locates at railties-4.1.8/lib/rails/backtrace_cleaner.rb

To directly see the silencer source code:

puts env['action_dispatch.backtrace_cleaner'].instance_variable_get(:@silencers).map{|s| RubyVM::InstructionSequence.disasm s }

See more from https://github.com/rails/rails/blob/master/railties/lib/rails/backtrace_cleaner.rb https://github.com/rails/rails/blob/master/activesupport/lib/active_support/backtrace_cleaner.rb

Botts

Answer 3

You're not doing anything wrong. But a lot of middleware traps exceptions in order to do cleanup, including middleware that Rack inserts automatically in development mode. There is a specific Rack middleware inserted in development that will catch uncaught exceptions and give a reasonable HTML page instead of a raw stack dump (which you often won't see at all with common app servers.)

• You can catch the exception yourself by putting a begin/rescue/end around your top level. Remember to catch "Exception", not just the default "rescue" with no arg, if you want to get everything. And you may want to re-throw the exception if you're going to leave this code in.
• You can run in production mode -- that might stop the middleware from being inserted automatically by Rack.
• You can find out what middleware is inserted (in Rails: "rake middleware") and then remove the middleware manually (in Rails "config.middleware.delete" or "config.middleware.disable").

There are probably other methods.

Bio