From 68e74d690043405e7499b1e569f0bbb7dd780ce2 Mon Sep 17 00:00:00 2001 From: ximus Date: Fri, 10 Mar 2023 10:49:35 -0800 Subject: [PATCH] Controller unhandled errors should be passed as BadStatus to interceptors 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. --- CHANGELOG.md | 12 ++++++++++++ lib/gruf/controllers/base.rb | 12 ++++++------ spec/gruf/controllers/base_spec.rb | 10 ++++++++++ 3 files changed, 28 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a2fdb47..c96f7b9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,18 @@ Changelog for the gruf gem. This includes internal history before the gem was ma ### Pending release * [#190] Remove unsued `e2mmap` and `thwait` gems from `runtime_dependency`. +* [#184] [Breaking] Controller unhandled errors should be passed as BadStatus to interceptors. + * Server interceptors should now expect a `GRPC::BadStatus` error in the case of unhandled errors. + Orignal unhandled error can be reached via `cause`. example: + ```ruby + def call + begin + yield + rescue => err + err.cause + end + end + ``` ### 2.19.0 diff --git a/lib/gruf/controllers/base.rb b/lib/gruf/controllers/base.rb index e86fdf0..43a5019 100644 --- a/lib/gruf/controllers/base.rb +++ b/lib/gruf/controllers/base.rb @@ -92,13 +92,13 @@ def process_action(method_key, &block) def call(method_key, &block) 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 diff --git a/spec/gruf/controllers/base_spec.rb b/spec/gruf/controllers/base_spec.rb index 0b1c631..3a16b89 100644 --- a/spec/gruf/controllers/base_spec.rb +++ b/spec/gruf/controllers/base_spec.rb @@ -97,6 +97,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