Grape logger always log 500 http response code for rescued exceptions

[nbulaj]

Hi. While exploring the grape-middleware-logger logs I discovered that all requests with errors that are preprocessed with rescue_from are marked with 500 response code:

# api.rb
class API < Grape::API
  use Grape::Middleware::Logger

  format :json

  include ExceptionHandler

  mount V1::Base
end

# exception_handler.rb
module ExceptionHandler
  extend ActiveSupport::Concern

  included do
    rescue_from ActiveRecord::RecordNotFound do
      error!({ error: :not_found }, 404)
    end

    # ... other :rescue_from ...
  end
end

Log:

I, [2016-09-14T14:53:49.896641 #27381] INFO -- : [f4b3b020-ef4b-44ea-9228-fc58d35c1687] ActiveRecord::RecordNotFound (Couldn't find User with 'id'=1010):

I looked at the source code of the gem and added some trace to the code. And what am I found is that rescue_from are invoked after grape-middleware-logger methods such as after_exception and after_failure. So the real status code (and maybe some extra info) does not fall into the log, only 500. I think that is a wrong behaviour.

Gemfile.lock

grape (0.17.0)
grape-middleware-logger (1.7.0)

What do you think about that, @ridiculous?

[ridiculous]

Yeah, that's not ideal behavior. But unfortunately I don't see how to hook into the error handlers registered with rescue_from and relay those responses to the log. I can dig around some more, and will report back if I find anything

[nbulaj]

@ridiculous we can get all the rescue handlers:

rescue_handlers = @env['api.endpoint'].namespace_reverse_stackable(:rescue_handlers)

And find an executable proc for the catched exception by it's class (if it is present in the handlers):

{ActiveRecord::RecordInvalid=>#<Proc:0x00000005ce4960@/project/app/api.rb:14>}

We can invoke the proc and get its results. Usually there is an error! method present in the rescue_from block that returns Rack::Response from where we can get status and other info. The only thing that there may be some heavy code (DB requests, something else) ..

I'm still thinking about the implementation... And I think we need to work in that way to recatch those exceptions.

[ridiculous]

@nbulaj Check out this implementation #15

It's the most efficient way I see to do it. The main issue is that the :rescue_handlers are processed by Grape::Middleware::Error, and there's no way to hook into that

[ridiculous]

I didn't bother to update the tests yet. Let me know what you think and we go from there

[nbulaj]

@ridiculous yes, I have also analyzed Grape events life cycle and found Grape::Middleware::Error. I was thinking about to rerun the error (which I did for the test and without specs(!) - it works). But your PR looks better I think. I will look in more detail a little bit later.

[nbulaj]

Hi @ridiculous. Any news about that issue? :)

[ridiculous]

Nothing new. What do you think of my solution in #15, overloading Rack::Head#call? It's the only solution I can think of, even though it's hacky. The problem of not being able to get the error + code, because it's handled by a default Grape middleware and can't be rearranged, is a fundamental flaw in Grape's stack design.

[ridiculous]

If you're fine with #15, I'm happy to release a new version with it

[marianposaceanu]

same issue here - how about a simpler version with no overloading but a configurable status code per exception class? e.g. validation errors would get a 400/422 and everything else a 500.

EDIT context:

May 12 16:27:34 Grape::Exceptions::ValidationErrors: foo is missing, foo is empty 
May 12 16:27:34 Completed 500 in 59.2ms 

and we could have something like:

custom_status_codes = [
  { exception_class: Grape::Exceptions::ValidationErrors, code: 422 }
]

[nbulaj]

@dakull but Grape already can have custom exception statuses and it will be some kind of overhead (to set the status code multiple times). I think that overloading of Rack::Head is not a problem - look at Roda plugin system, it's doing the same thing

[pkmiec]

I'm running in this issue as well. Why not,

insert_before ::Grape::Middleware::Error, ::Grape::Middleware::Logger, condensed: true

???

[ridiculous]

Did you try it? Does it work?