Apply suggestions: add try/rescue and improve testing

lib/grpc/client/interceptors/logger.ex

@@ -3,6 +3,7 @@ defmodule GRPC.Client.Interceptors.Logger do
   Print log around client rpc calls, like
 
       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
 
@@ -29,39 +30,65 @@ defmodule GRPC.Client.Interceptors.Logger do
 
   @impl GRPC.Client.Interceptor
   def call(%{grpc_type: grpc_type} = stream, req, next, opts) do
-    {time, result} = :timer.tc(next, [stream, req])
     level = Keyword.fetch!(opts, :level)
 
     if Logger.compare_levels(level, Logger.level()) != :lt do
-      case grpc_type do
-        :unary ->
-          status = elem(result, 0)
-
-          Logger.log(level, fn ->
-            [
-              "Call ",
-              stream.service_name,
-              ".",
-              to_string(elem(stream.rpc, 0)),
-              " -> ",
-              inspect(status),
-              " (",
-              :io_lib.format("~.3f", [time / 1000]),
-              " ms)"
-            ]
-          end)
-
-          result
-
-        _otherwise ->
-          Logger.log(level, fn ->
-            ["Call ", to_string(elem(stream.rpc, 0)), " of ", stream.service_name]
-          end)
-
-          result
+      try do
+        start = System.monotonic_time()
+        result = next.(stream, req)
+        stop = System.monotonic_time()
+
+        log_result(result, level, grpc_type, stream, start, stop)
+        result
+      rescue
+        error ->
+          log_error(error, stream)
+
+          raise error
       end
     else
       next.(stream, req)
     end
   end
+
+  defp log_error(error, stream) do
+    Logger.log(:error, fn ->
+      [
+        "Call ",
+        stream.service_name,
+        ".",
+        to_string(elem(stream.rpc, 0)),
+        " -> ",
+        inspect(error)
+      ]
+    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),
+            " (",
+            GRPC.Server.Interceptors.Logger.formatted_diff(diff),
+            ")"
+          ]
+        end)
+
+      _otherwise ->
+        Logger.log(level, fn ->
+          ["Call ", to_string(elem(stream.rpc, 0)), " of ", stream.service_name]
+        end)
+    end
+  end
 end

test/grpc/client/interceptors/logger_test.exs

@@ -32,7 +32,7 @@ defmodule GRPC.Client.Interceptors.LoggerTest do
       end)
 
     assert logs =~
-             ~r/\[info\]\s+Call #{@service_name}\.#{to_string(elem(@rpc, 0))} -> :ok \(\d+\.\d+ ms\)/
+             ~r/\[info\]\s+Call #{@service_name}\.#{to_string(elem(@rpc, 0))} -> :ok \(\d+\.\d+ ms|µs\)/
   end
 
   test "allows customizing log level" do
@@ -49,7 +49,24 @@ defmodule GRPC.Client.Interceptors.LoggerTest do
       end)
 
     assert logs =~
-             ~r/\[warn(?:ing)?\]\s+Call #{@service_name}\.#{to_string(elem(@rpc, 0))} -> :ok \(\d+\.\d+ ms\)/
+             ~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
@@ -78,4 +95,23 @@ 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
 end