lograge doesn't handle 500 or 404 responses

[thoughtafter]

I have an app, which maybe is doing something strange but it seems like 404 errors caused by missing routes and 500 errors get send to the log file as a stack trace not a single line entry. Am I missing something? In the code it certainly looks like it should be handling 500 errors but it doesn't seem to work.

[thoughtafter]

Ok, so it looks like ActiveRecord::RecordNotFound is being reported as a 500 error by lograge which is clearly not what is being sent. I get that extract_status is making a guess but in this case it's guessing wrong. And this is the only 500 error in the logs. Other 500 errors show as a stack trace. 404 errors caused by missing routes (ActionController::RoutingError) are also logged as a stack trace.

[roidrage]

Does your application ignore RecordNotFound and turn them into a 404?

If lograge (currently) doesn't receive a status code from the controller, but finds an exception, it outputs that to the logs. With the RecordNotFound it doesn't seem to be getting a status code in your case.

[thoughtafter]

This app is Rails 3.2.11 and uses exception_notification 2.6.1. Other than that there is no special handling of 404 or 500 errors.

There are 2 separate issues I've run into:

1. Stack trace errors in logs with ActionController::RoutingError and any 500 exception. I've still not resolved this.
2. RecordNotFound errors logged as 500 instead of 404. This can be fixed by changing the following in extract_status:

{ :status => 500, :error => "#{exception}:#{message}" }

to:

{
  :status => ActionDispatch::ExceptionWrapper.new({}, exception.constantize.new).status_code,
  :error => "#{exception}:#{message}"
}

[roidrage]

lograge doesn't concern itself with dumping the stacktrace to the logs, happy to be proven wrong, but dumping a stacktrace to the logs on a 500 error is common Rails behaviour.

I can look into using ExceptionWrapper to determine the status code.

[thoughtafter]

Yes, the issue is not so much the stack trace but the fact that there is no log line for the request which caused it. I believe this is because those exceptions are not caught and logged until the debug_exceptions middleware which is outside the scope of ActiveSupport::LogSubscriber. It's worth mentioning because I assumed, incorrectly, that all 404 and 500 errors would be logged by lograge but they are not. So the behaviour was not what I expected and perhaps that may be the case for others. Still it's a great idea and I appreciate you putting it out there.

[bf4]

I do something like

      if event.payload[:exception] && strace = event.payload[:stacktrace]
        quoted_stacktrace = %('#{Array(strace).join("\n\t")}') # depending on if I'm logging as logstash or not
        opts[:stacktrace] = quoted_stacktrace
        # will output as e.g.
        #   "stacktrace":"'[\"/Users/somedev/.rvm/gems/ etc.
        # no need to include the :exception payload as it is already output
        # by the 'error' key, e.g.
        #   "error":"ActionView::Template::Error:bootstrap/carousel.js isn't precompiled"
      end

require "active_support/notifications/instrumenter"
# https://github.com/rails/rails/blob/4-2-stable/activesupport/lib/active_support/notifications/instrumenter.rb
# also see payload[:stacktrace] in config/application.rb
# below per Carl Lerche to preserve skylight patch and our patch
# https://gist.github.com/carllerche/acd5c34e284d90678ac0
class ActiveSupport::Notifications::Instrumenter
  # :nocov:
  alias_method :instrument_original, :instrument

  # rubocop:disable Lint/RescueException
  def instrument(name, payload = {})
    instrument_original(name, payload) do
      begin
        yield
      rescue Exception => e
        # BF added the below line to include backtrace in lograge
        payload[:stacktrace] = e.backtrace
        raise
      end
    end
  end
  # rubocop:enable Lint/RescueException
  # :nocov:
end
# look into adding an exception object via middleware that we can
# use in the :append_info_to_payload method
# e.g. see
# https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rails/action_controller_catcher.rb#L7
#  and https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rails/error_lookup.rb#L7
# https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rails/middleware.rb#L13
#  and https://github.com/airbrake/airbrake/blob/master/lib/airbrake/railtie.rb
#  and https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rack.rb#L44
# since there is a difference between what is available by a subscriber and a middleware
#  see https://github.com/roidrage/lograge/blob/master/lib/lograge.rb

[chongivan]

@bf4 , where do you put the above lines of code?

[aripollak]

I think this is fixed as of #112?