Add one-line logs with time #392
Conversation
| def call(%{grpc_type: grpc_type} = stream, req, next, opts) do | ||
| {time, result} = :timer.tc(next, [stream, req]) |
There was a problem hiding this comment.
I believe we need a try-rescue now.
Perhaps instead of timer.tc, keep the previous code structure, and log either on the rescue or after block depending on whether it raised an exception or was successful.
This will probably minimize the code changes.
There was a problem hiding this comment.
Why do you think a try is necessary here? And what about using telemetry instead?
There was a problem hiding this comment.
Because otherwise you won't get any logs for the call anymore. In the previous version you would get the starting but not the terminal log.
I think telemetry would be an addition, but doesn't substitute the logs
There was a problem hiding this comment.
Ah ok, I get you. I'll improve it.
Related to telemetry what I mean is decoupling the call from the interceptor. In the same way phoenix instruments traces (see opentelemetry_phoenix). It will allow clients to make structured logging as well. Basically you emit an event instead of logging and we subscribe in the interceptor to the event, then log in the handle function.
There was a problem hiding this comment.
I think having the log message coupled here is the more natural way, although a telemetry event being published alongside it wouldn't hurt.
There was a problem hiding this comment.
I've applied your suggestions regarding safer logs with try/rescue keeping the same way we were measuring time, without timex.
Context
To properly observe our systems in unary calls, using one-line logs allows the user to see the elapsed time in a single place without joining two separate lines.
Solution
Use timer to measure time and log while maintaining the same behavior.
cc/ @polvalente