diff --git a/lib/grpc/client/interceptors/logger.ex b/lib/grpc/client/interceptors/logger.ex index 12ad5e2b..48e52314 100644 --- a/lib/grpc/client/interceptors/logger.ex +++ b/lib/grpc/client/interceptors/logger.ex @@ -2,8 +2,8 @@ defmodule GRPC.Client.Interceptors.Logger do @moduledoc """ Print log around client rpc calls, like - 17:13:33.021 [info] Call say_hello of helloworld.Greeter - 17:13:33.079 [info] Got :ok in 58ms + 17:13:33.021 [info] Call helloworld.Greeter.say_hello -> :ok (58 ms) + 17:13:33.021 [error] Call helloworld.Greeter.say_hello -> %GRPC.RPCError{status: 3, message: "Invalid argument"} (58 ms) ## Options @@ -18,42 +18,87 @@ defmodule GRPC.Client.Interceptors.Logger do {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Client.Interceptors.Logger, level: :warning}]) """ - require Logger - @behaviour GRPC.Client.Interceptor - @impl true + require Logger + + @impl GRPC.Client.Interceptor def init(opts) do level = Keyword.get(opts, :level) || :info [level: level] end - @impl true + @impl GRPC.Client.Interceptor def call(%{grpc_type: grpc_type} = stream, req, next, opts) do level = Keyword.fetch!(opts, :level) if Logger.compare_levels(level, Logger.level()) != :lt do - Logger.log(level, fn -> - ["Call ", to_string(elem(stream.rpc, 0)), " of ", stream.service_name] - end) - start = System.monotonic_time() - result = next.(stream, req) - stop = System.monotonic_time() - if grpc_type == :unary do - status = elem(result, 0) + try do + result = next.(stream, req) + stop = System.monotonic_time() - Logger.log(level, fn -> - diff = System.convert_time_unit(stop - start, :native, :microsecond) + log_result(result, level, grpc_type, stream, start, stop) + result + rescue + error in GRPC.RPCError -> + stop = System.monotonic_time() + log_error(error, stream, start, stop) - ["Got ", inspect(status), " in ", GRPC.Server.Interceptors.Logger.formatted_diff(diff)] - end) + reraise error, __STACKTRACE__ end - - result else next.(stream, req) end end + + defp log_error(error, stream, start, stop) do + diff = System.convert_time_unit(stop - start, :native, :microsecond) + + Logger.log(:error, fn -> + [ + "Call ", + stream.service_name, + ".", + to_string(elem(stream.rpc, 0)), + " -> ", + inspect(error), + " (", + formatted_diff(diff), + ")" + ] + end) + end + + defp log_result(result, level, grpc_type, stream, start, stop) do + case grpc_type do + :unary -> + status = elem(result, 0) + + diff = System.convert_time_unit(stop - start, :native, :microsecond) + + Logger.log(level, fn -> + [ + "Call ", + stream.service_name, + ".", + to_string(elem(stream.rpc, 0)), + " -> ", + inspect(status), + " (", + formatted_diff(diff), + ")" + ] + end) + + _otherwise -> + Logger.log(level, fn -> + ["Call ", to_string(elem(stream.rpc, 0)), " of ", stream.service_name] + end) + end + end + + def formatted_diff(diff) when diff > 1000, do: [diff |> div(1000) |> Integer.to_string(), "ms"] + def formatted_diff(diff), do: [Integer.to_string(diff), "µs"] end diff --git a/test/grpc/client/interceptors/logger_test.exs b/test/grpc/client/interceptors/logger_test.exs index 01021f11..35539a3a 100644 --- a/test/grpc/client/interceptors/logger_test.exs +++ b/test/grpc/client/interceptors/logger_test.exs @@ -31,7 +31,8 @@ defmodule GRPC.Client.Interceptors.LoggerTest do LoggerInterceptor.call(stream, request, next, opts) end) - assert logs =~ ~r/\[info\]\s+Call #{to_string(elem(@rpc, 0))} of #{@service_name}/ + assert logs =~ + ~r/\[info\]\s+Call #{@service_name}\.#{to_string(elem(@rpc, 0))} -> :ok \(\d+\.\d+ ms|µs\)/ end test "allows customizing log level" do @@ -47,7 +48,25 @@ defmodule GRPC.Client.Interceptors.LoggerTest do LoggerInterceptor.call(stream, request, next, opts) end) - assert logs =~ ~r/\[warn(?:ing)?\]\s+Call #{to_string(elem(@rpc, 0))} of #{@service_name}/ + assert logs =~ + ~r/\[warn(?:ing)?\]\s+Call #{@service_name}\.#{to_string(elem(@rpc, 0))} -> :ok \(\d+\.\d+ ms|µs\)/ + end + + test "logs stream requests" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :client_stream, rpc: @rpc, service_name: @service_name} + next = fn _stream, _request -> {:ok, :stream} end + opts = LoggerInterceptor.init([]) + + logs = + capture_log(fn -> + LoggerInterceptor.call(stream, request, next, opts) + end) + + assert logs =~ + ~r/\[info\]\s+Call #{to_string(elem(@rpc, 0))} of #{@service_name}/ end @tag capture_log: true @@ -76,4 +95,41 @@ defmodule GRPC.Client.Interceptors.LoggerTest do assert_receive {:next_called, ^stream, ^request} end + + test "logs error when next raises" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :unary, rpc: @rpc, service_name: @service_name} + next = fn _stream, _request -> raise GRPC.RPCError, status: :invalid_argument end + opts = LoggerInterceptor.init(level: :info) + + assert_raise(GRPC.RPCError, fn -> + logs = + capture_log(fn -> + LoggerInterceptor.call(stream, request, next, opts) + end) + + assert logs =~ + ~r/\[error\]\s+Call #{@service_name}\.#{to_string(elem(@rpc, 0))} -> %GRPC.RPCError{status: 3, message: "Client specified an invalid argument"}/ + end) + end + + test "does not log when error is not a GRPC.RPCError" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :unary, rpc: @rpc, service_name: @service_name} + next = fn _stream, _request -> raise "oops" end + opts = LoggerInterceptor.init(level: :info) + + assert_raise(RuntimeError, fn -> + logs = + capture_log(fn -> + LoggerInterceptor.call(stream, request, next, opts) + end) + + assert logs == "" + end) + end end