Add one-line logs with time (#392)

* Add on-line logs with time

* Fix typo

* Left assign

* Fix format

* Apply suggestions: add try/rescue and improve testing

* Raise only on GRPC errors

* Improve logging and recover deleted file

* chore: changes due to code review

---------

Co-authored-by: Paulo Valente <16843419+polvalente@users.noreply.github.com>

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

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