logging status 500 instead of status 404

[martnst]

In case of an an ActiveRecord::RecordNotFound a status code 500gets logged while actually a 404 response gets returned.

If noticed that this is an issue for quite some time - according to #27. However, this thread is 2 years old now and it also addresses a more complex issue.

[pxlpnk]

@maremmle I submitted a fix in #112 does this solve your problem?

[martnst]

@pxlpnk Yes it does log 404 for ActiveRecord::RecordNotFound now.

However for ActionController::RoutingError i now get this ugly error logged:

  Could not log "process_action.action_controller" event. ArgumentError: wrong number of arguments (0 for 1..2) [
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_controller/metal/exceptions.rb:22:in `initialize'", 
    "~/.rvm/gems/ruby-2.1.5/bundler/gems/lograge-a14ca702824e/lib/lograge/log_subscriber.rb:72:in `new'", 
    "~/.rvm/gems/ruby-2.1.5/bundler/gems/lograge-a14ca702824e/lib/lograge/log_subscriber.rb:72:in `get_error_status_code'", 
    "~/.rvm/gems/ruby-2.1.5/bundler/gems/lograge-a14ca702824e/lib/lograge/log_subscriber.rb:64:in `extract_status'", 
    "~/.rvm/gems/ruby-2.1.5/bundler/gems/lograge-a14ca702824e/lib/lograge/log_subscriber.rb:13:in `process_action'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/subscriber.rb:91:in `finish'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/log_subscriber.rb:83:in `finish'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/fanout.rb:96:in `finish'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/fanout.rb:40:in `block in finish'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/fanout.rb:40:in `each'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/fanout.rb:40:in `finish'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/instrumenter.rb:36:in `finish'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/instrumenter.rb:25:in `ensure in instrument'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications/instrumenter.rb:25:in `instrument'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/notifications.rb:159:in `instrument'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_controller/metal/instrumentation.rb:30:in `process_action'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activerecord-4.1.0/lib/active_record/railties/controller_runtime.rb:18:in `process_action'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/abstract_controller/base.rb:136:in `process'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionview-4.1.0/lib/action_view/rendering.rb:30:in `process'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_controller/metal.rb:195:in `dispatch'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_controller/metal.rb:231:in `block in action'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/routing/route_set.rb:80:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/routing/route_set.rb:80:in `dispatch'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/routing/route_set.rb:48:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/journey/router.rb:71:in `block in call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/journey/router.rb:59:in `each'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/journey/router.rb:59:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/routing/route_set.rb:676:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/deflater.rb:25:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/warden-1.2.3/lib/warden/manager.rb:35:in `block in call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/warden-1.2.3/lib/warden/manager.rb:34:in `catch'", 
    "~/.rvm/gems/ruby-2.1.5/gems/warden-1.2.3/lib/warden/manager.rb:34:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/etag.rb:23:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/conditionalget.rb:25:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/head.rb:11:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/params_parser.rb:27:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/flash.rb:254:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/cookies.rb:560:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activerecord-4.1.0/lib/active_record/query_cache.rb:36:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activerecord-4.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:621:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activerecord-4.1.0/lib/active_record/migration.rb:380:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/callbacks.rb:82:in `run_callbacks'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/callbacks.rb:27:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/reloader.rb:73:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/remote_ip.rb:76:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/bundler/gems/lograge-a14ca702824e/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'", 
    "~/.rvm/gems/ruby-2.1.5/gems/railties-4.1.0/lib/rails/rack/logger.rb:20:in `block in call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/tagged_logging.rb:68:in `block in tagged'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/tagged_logging.rb:26:in `tagged'", 
    "~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.0/lib/active_support/tagged_logging.rb:68:in `tagged'", 
    "~/.rvm/gems/ruby-2.1.5/gems/railties-4.1.0/lib/rails/rack/logger.rb:20:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/request_store-1.1.0/lib/request_store/middleware.rb:8:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/request_id.rb:21:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/runtime.rb:17:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/lock.rb:17:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/actionpack-4.1.0/lib/action_dispatch/middleware/static.rb:64:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/sendfile.rb:112:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/railties-4.1.0/lib/rails/engine.rb:514:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/railties-4.1.0/lib/rails/application.rb:144:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/builder.rb:138:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/urlmap.rb:65:in `block in call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `each'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-cors-0.2.9/lib/rack/cors.rb:54:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/lock.rb:17:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/content_length.rb:14:in `call'", 
    "~/.rvm/gems/ruby-2.1.5/gems/rack-1.5.2/lib/rack/handler/webrick.rb:60:in `service'", 
    "~/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/webrick/httpserver.rb:138:in `service'", 
    "~/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/webrick/httpserver.rb:94:in `run'", 
    "~/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/webrick/server.rb:295:in `block in start_thread'"]

[pxlpnk]

This looks bad. I think I will make the handling a bit more explicit to only cat the errors we are aware of.
Like:

• RecordNotFound
• RoutingError

Any other exceptions that come to your mind?

[pxlpnk]

I can not reproduce your error @maremmle.
I am using rails 4.1.0 with lograge@master.

ActionController::RoutingError (No route matches [GET] "/postsa/2"):
  actionpack (4.1.0) lib/action_dispatch/middleware/debug_exceptions.rb:21:in `call'
  actionpack (4.1.0) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  /Users/at/src/private/ruby/lograge/lograge-src/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
  railties (4.1.0) lib/rails/rack/logger.rb:20:in `block in call'
  activesupport (4.1.0) lib/active_support/tagged_logging.rb:68:in `block in tagged'
  activesupport (4.1.0) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (4.1.0) lib/active_support/tagged_logging.rb:68:in `tagged'
  railties (4.1.0) lib/rails/rack/logger.rb:20:in `call'
  actionpack (4.1.0) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.5.2) lib/rack/methodoverride.rb:21:in `call'
  rack (1.5.2) lib/rack/runtime.rb:17:in `call'
  activesupport (4.1.0) lib/active_support/cache/strategy/local_cache_middleware.rb:26:in `call'
  rack (1.5.2) lib/rack/sendfile.rb:112:in `call'
  railties (4.1.0) lib/rails/engine.rb:514:in `call'
  railties (4.1.0) lib/rails/application.rb:144:in `call'
  rack (1.5.2) lib/rack/lock.rb:17:in `call'
  rack (1.5.2) lib/rack/content_length.rb:14:in `call'
  rack (1.5.2) lib/rack/handler/webrick.rb:60:in `service'
  /Users/at/.rbenv/versions/2.2.0/lib/ruby/2.2.0/webrick/httpserver.rb:138:in `service'
  /Users/at/.rbenv/versions/2.2.0/lib/ruby/2.2.0/webrick/httpserver.rb:94:in `run'
  /Users/at/.rbenv/versions/2.2.0/lib/ruby/2.2.0/webrick/server.rb:294:in `block in start_thread'