Skip to content

Conversation

@ximus
Copy link
Contributor

@ximus ximus commented Mar 10, 2023

While using Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor, I noticed that when 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:

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.

@ximus ximus force-pushed the fix-error-logging2 branch from f1ba5a6 to 436dfbf Compare March 10, 2023 19:10
@ximus
Copy link
Contributor Author

ximus commented Mar 10, 2023

wondering if interceptors like gruf-sentry should be updated to log cause in the case of internal errors

@ximus ximus force-pushed the fix-error-logging2 branch from 436dfbf to 68e74d6 Compare February 20, 2024 06:33
@mochja
Copy link

mochja commented Sep 12, 2024

Is there plan to merge the fix? I do experience similar problem with the ConnectionReset Interceptor when the database does not exists,
image

@ximus ximus force-pushed the fix-error-logging2 branch from 68e74d6 to 3ee49c9 Compare September 26, 2024 04:51
@ximus ximus force-pushed the fix-error-logging2 branch from 3ee49c9 to 7294072 Compare January 7, 2025 22:34
@ximus
Copy link
Contributor Author

ximus commented Jan 10, 2025

@splittingred I still think this PR makes sense. I think it's pretty straight forward, any chance we could move it forward?

…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.
@ximus ximus force-pushed the fix-error-logging2 branch from 7294072 to 6c548de Compare February 10, 2025 07:57
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants