NoMethodError: undefined method `+' for nil:NilClass

ravinggenius commented 9 years ago

I have a Grape API in a Rails application, and I'm sub-classing GrapeLogging::Middleware::RequestLogger so I can sanitize the #parameters method. I'm getting an error in production that is originating at /gems/grape_logging-1.0.2/lib/grape_logging/middleware/request_logger.rb:11 in block in before. It looks like env[:db_duration] is returning nil. Details below.

Versions:

grape (0.10.1)
grape-entity (0.4.4)
grape_logging (1.0.2)
rails (4.2.1)
Sub-class:

module Api::Middleware
  class RequestLogger < GrapeLogging::Middleware::RequestLogger
    protected

    def parameters(response, duration)
      filters = Rails.application.config.filter_parameters
      ActionDispatch::Http::ParameterFilter.new(filters).filter(super)
    end
  end
end

Usage:

use Api::Middleware::RequestLogger, { logger: Rails.logger }

Stacktrace:

/gems/grape_logging-1.0.2/lib/grape_logging/middleware/request_logger.rb:11 in block in before
/gems/activesupport-4.2.1/lib/active_support/notifications/fanout.rb:127 in call
/gems/activesupport-4.2.1/lib/active_support/notifications/fanout.rb:127 in finish
/gems/activesupport-4.2.1/lib/active_support/notifications/fanout.rb:46 in block in finish
/gems/activesupport-4.2.1/lib/active_support/notifications/fanout.rb:46 in each
/gems/activesupport-4.2.1/lib/active_support/notifications/fanout.rb:46 in finish
/gems/activesupport-4.2.1/lib/active_support/notifications/instrumenter.rb:36 in finish
/gems/activesupport-4.2.1/lib/active_support/notifications/instrumenter.rb:25 in instrument
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:467 in log
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:154 in execute
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql/schema_statements.rb:275 in client_min_messages=
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:673 in configure_connection
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:658 in connect
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:242 in initialize
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:44 in new
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:44 in postgresql_connection
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:438 in new_connection
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:448 in checkout_new_connection
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:422 in acquire_connection
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:349 in block in checkout
/data/gdweb/.rbenv/versions/2.1.5/lib/ruby/2.1.0/monitor.rb:211 in mon_synchronize
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:348 in checkout
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:263 in block in connection
/data/gdweb/.rbenv/versions/2.1.5/lib/ruby/2.1.0/monitor.rb:211 in mon_synchronize
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:262 in connection
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:567 in retrieve_connection
/gems/activerecord-4.2.1/lib/active_record/connection_handling.rb:113 in retrieve_connection
/gems/activerecord-4.2.1/lib/active_record/connection_handling.rb:87 in connection
/gems/activerecord-4.2.1/lib/active_record/query_cache.rb:51 in restore_query_cache_settings
/gems/activerecord-4.2.1/lib/active_record/query_cache.rb:43 in rescue in call
/gems/activerecord-4.2.1/lib/active_record/query_cache.rb:31 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/activerecord-4.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:649 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/actionpack-4.2.1/lib/action_dispatch/middleware/callbacks.rb:29 in block in call
/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:88 in call
/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:88 in _run_callbacks
/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:776 in _run_call_callbacks
/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:81 in run_callbacks
/gems/actionpack-4.2.1/lib/action_dispatch/middleware/callbacks.rb:27 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/actionpack-4.2.1/lib/action_dispatch/middleware/remote_ip.rb:78 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/actionpack-4.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:17 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/actionpack-4.2.1/lib/action_dispatch/middleware/show_exceptions.rb:30 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/lograge-0.3.0/lib/lograge/rails_ext/rack/logger.rb:15 in call_app
/gems/railties-4.2.1/lib/rails/rack/logger.rb:20 in block in call
/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:68 in block in tagged
/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:26 in tagged
/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:68 in tagged
/gems/railties-4.2.1/lib/rails/rack/logger.rb:20 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/actionpack-4.2.1/lib/action_dispatch/middleware/request_id.rb:21 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/rack-1.6.0/lib/rack/methodoverride.rb:22 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/rack-1.6.0/lib/rack/runtime.rb:18 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/activesupport-4.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/rack-1.6.0/lib/rack/sendfile.rb:113 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/railties-4.2.1/lib/rails/engine.rb:518 in call
/gems/railties-4.2.1/lib/rails/application.rb:164 in call
/gems/railties-4.2.1/lib/rails/railtie.rb:194 in public_send
/gems/railties-4.2.1/lib/rails/railtie.rb:194 in method_missing
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
lib/pulse.rb:11 in call
/gems/newrelic_rpm-3.9.9.275/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in call
/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:576 in process_client
/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:670 in worker_loop
/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:525 in spawn_missing_workers
/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:536 in maintain_worker_count
/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:294 in join
/gems/unicorn-4.8.3/bin/unicorn:126 in <top (required)>
/data/gdweb/app/current/bin/unicorn:16 in load
/data/gdweb/app/current/bin/unicorn:16 in <main>

aserafin commented 9 years ago

Thanks for the detailed report! I will be looking into it shortly :)

aserafin commented 9 years ago

I've changed passing around db_duration from env property to instance variable which should help in your case (f465c1027c16f64f0d054fa84a6d976365085248). Please note that I've also changed input parameters for parameters method. I will do some testing on my own tomorrow but feedback from you would also be helpful :)

aserafin commented 9 years ago

Fixed with 1.1.0 release

aserafin / grape_logging