Skip to content

Commit

Permalink
Controller unhandled errors should be passed as BadStatus to intercep…
Browse files Browse the repository at this point in the history
…tors

While using `Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor`, I noticed that in the event of of unhandled errors raised in my controller (errors that are not of type `GRPC::BadStatus` or raised via `fail!`), I was not getting any request logging in my log.

In a successful controller call I would get something like:

```
[GRPC::Ok] (list_units) [5.24ms] [GRPC::Ok] (rpc.units.list_units) Parameters: {:is_active=>false, :check_can_delete=>false}
```

If an unhandled error was raised I would get nothing.

My assumption is that I should still get logging in that case. Request info is useful to have, including when an unhandled error occurs.

Investingating why I wasn't getting any, I observed that in `Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor`, the interceptor yields to the controller via this line:

```ruby
result = Gruf::Interceptors::Timer.time(&block)
```

`Gruf::Interceptors::Timer.time` knows to `rescue` and handle errors, but only of type `GRPC::BadStatus`. I realized that unhandled errors would not be caught by it, hence the error logging interceptor would get exited right there and never log.

I noticed that the base controller code turns unhandled errors in the `GRPC::BadStatus` errors. But it only does so after all the interceptors have run (or been tripped as above). I thought why not just do this before the interceptors. Seeing how the logging interceptor is designed, maybe it was even meant to be that way. So this is what I propose here.

It works well for me so far.

API changes:

* Now interceptors will get a `GRPC::BadStatus` error in the case of unhandled errors, instead of the original unhandled error. To reach the original error, `GRPC::BadStatus#cause` can be used.
  • Loading branch information
ximus committed Mar 10, 2023
1 parent ffb7508 commit f1ba5a6
Show file tree
Hide file tree
Showing 2 changed files with 16 additions and 6 deletions.
12 changes: 6 additions & 6 deletions lib/gruf/controllers/base.rb
Original file line number Diff line number Diff line change
Expand Up @@ -93,13 +93,13 @@ def call(method_key, &block)
::Gruf.autoloaders.reload if ::Gruf.development?
Interceptors::Context.new(@interceptors).intercept! do
process_action(method_key, &block)
rescue GRPC::BadStatus
raise # passthrough, to be caught by Gruf::Interceptors::Timer
rescue GRPC::Core::CallError, StandardError => e # CallError is not a StandardError
set_debug_info(e.message, e.backtrace) if Gruf.backtrace_on_error
error_message = Gruf.use_exception_message ? e.message : Gruf.internal_error_message
fail!(:internal, :unknown, error_message)
end
rescue GRPC::BadStatus
raise # passthrough, to be caught by Gruf::Interceptors::Timer
rescue GRPC::Core::CallError, StandardError => e # CallError is not a StandardError
set_debug_info(e.message, e.backtrace) if Gruf.backtrace_on_error
error_message = Gruf.use_exception_message ? e.message : Gruf.internal_error_message
fail!(:internal, :unknown, error_message)
end
end
end
Expand Down
10 changes: 10 additions & 0 deletions spec/gruf/controllers/base_spec.rb
Original file line number Diff line number Diff line change
Expand Up @@ -119,6 +119,16 @@
end
end

it 'raises a GRPC::Internal error to interceptors' do
Gruf.interceptors.use(TestServerInterceptor)
expect_any_instance_of(TestServerInterceptor).to receive(:call) do |&block|
error = nil
expect { block.call }.to raise_error(GRPC::Internal) { |err| error = err }
raise error if error
end
expect { subject }.to raise_error(GRPC::Internal)
end

context 'when backtrace_on_error is set to true' do
before do
Gruf.backtrace_on_error = true
Expand Down

0 comments on commit f1ba5a6

Please sign in to comment.