Merge pull request #381 from beligante/add-crash-report-to-error-log

[ 377 ] Add `crash_report` logger metadata for exceptions captured by `Cowboy.Handler`

lib/grpc/logger.ex

@@ -0,0 +1,9 @@
+defmodule GRPC.Logger do
+  @doc """
+  Normalizes the exception and stacktrace inputs by its kind to match the format specified for `crash_report` metadata
+  in [Logger](https://hexdocs.pm/logger/main/Logger.html#module-metadata)
+  """
+  def crash_reason(:throw, reason, stacktrace), do: {{:nocatch, reason}, stacktrace}
+  def crash_reason(:error, reason, stack), do: {Exception.normalize(:error, reason, stack), stack}
+  def crash_reason(:exit, reason, stacktrace), do: {reason, stacktrace}
+end

lib/grpc/server/adapters/cowboy/handler.ex

@@ -3,6 +3,7 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
   A cowboy handler accepting all requests and calls corresponding functions defined by users.
   """
 
+  alias GRPC.Server.Adapters.ReportException
   alias GRPC.Transport.HTTP2
   alias GRPC.RPCError
   require Logger
@@ -72,7 +73,7 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
         http_transcode: transcode?(req)
       }
 
-      server_rpc_pid = spawn_link(__MODULE__, :call_rpc, [server, route, stream])
+      server_rpc_pid = :proc_lib.spawn_link(__MODULE__, :call_rpc, [server, route, stream])
       Process.flag(:trap_exit, true)
 
       req = :cowboy_req.set_resp_headers(HTTP2.server_headers(stream), req)
@@ -455,27 +456,37 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
   end
 
   # expected error raised from user to return error immediately
-  def info({:EXIT, pid, {%RPCError{} = error, _stacktrace}}, req, state = %{pid: pid}) do
+  def info({:EXIT, pid, {%RPCError{} = error, stacktrace}}, req, state = %{pid: pid}) do
     req = send_error(req, error, state, :rpc_error)
+
+    [req: req]
+    |> ReportException.new(error, stacktrace)
+    |> log_error(stacktrace)
+
     {:stop, req, state}
   end
 
   # unknown error raised from rpc
-  def info({:EXIT, pid, {:handle_error, _kind}} = err, req, state = %{pid: pid}) do
-    Logger.warning("3. #{inspect(state)} #{inspect(err)}")
+  def info({:EXIT, pid, {:handle_error, error}}, req, state = %{pid: pid}) do
+    %{kind: kind, reason: reason, stack: stack} = error
+    rpc_error = %RPCError{status: GRPC.Status.unknown(), message: "Internal Server Error"}
+    req = send_error(req, rpc_error, state, :error)
 
-    error = %RPCError{status: GRPC.Status.unknown(), message: "Internal Server Error"}
-    req = send_error(req, error, state, :error)
+    [req: req]
+    |> ReportException.new(reason, stack, kind)
+    |> log_error(stack)
 
     {:stop, req, state}
   end
 
   def info({:EXIT, pid, {reason, stacktrace}}, req, state = %{pid: pid}) do
-    Logger.error(Exception.format(:error, reason, stacktrace))
-
     error = %RPCError{status: GRPC.Status.unknown(), message: "Internal Server Error"}
     req = send_error(req, error, state, reason)
 
+    [req: req]
+    |> ReportException.new(reason, stacktrace)
+    |> log_error(stacktrace)
+
     {:stop, req, state}
   end
 
@@ -500,17 +511,17 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
         end
       catch
         kind, e ->
-          Logger.error(Exception.format(kind, e, __STACKTRACE__))
+          reason = Exception.normalize(kind, e, __STACKTRACE__)
 
-          exit({:handle_error, kind})
+          {:error, %{kind: kind, reason: reason, stack: __STACKTRACE__}}
       end
 
     case result do
       {:error, %GRPC.RPCError{} = e} ->
-        exit({e, ""})
+        exit({e, _stacktrace = []})
 
-      {:error, %{kind: kind}} ->
-        exit({:handle_error, kind})
+      {:error, %{kind: _kind, reason: _reason, stack: _stack} = e} ->
+        exit({:handle_error, e})
 
       other ->
         other
@@ -648,4 +659,12 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
 
     {:wait, ref}
   end
+
+  defp log_error(%ReportException{kind: kind} = exception, stacktrace) do
+    crash_reason = GRPC.Logger.crash_reason(kind, exception, stacktrace)
+
+    kind
+    |> Exception.format(exception, stacktrace)
+    |> Logger.error(crash_reason: crash_reason)
+  end
 end

lib/grpc/server/adapters/report_exception.ex

@@ -0,0 +1,17 @@
+defmodule GRPC.Server.Adapters.ReportException do
+  @moduledoc """
+  Exception raised by server adapter, meant to be used as part of metadata `crash_report`
+  """
+
+  defexception [:kind, :reason, :stack, :adapter_extra]
+
+  def new(adapter_extra, %{__exception__: _} = exception, stack \\ [], kind \\ :error) do
+    exception(kind: kind, reason: exception, stack: stack, adapter_extra: adapter_extra)
+  end
+
+  def message(%__MODULE__{adapter_extra: [{:req, req}], kind: kind, reason: reason, stack: stack}) do
+    # Cowboy adapter message builder
+    path = :cowboy_req.path(req)
+    "Exception raised while handling #{path}:\n" <> Exception.format_banner(kind, reason, stack)
+  end
+end

test/grpc/integration/server_test.exs

@@ -224,27 +224,37 @@ defmodule GRPC.Integration.ServerTest do
   end
 
   test "returns appropriate error for unary requests" do
-    run_server([HelloErrorServer], fn port ->
-      {:ok, channel} = GRPC.Stub.connect("localhost:#{port}")
-      req = %Helloworld.HelloRequest{name: "Elixir"}
-      {:error, reply} = channel |> Helloworld.Greeter.Stub.say_hello(req)
+    logs =
+      ExUnit.CaptureLog.capture_log(fn ->
+        run_server([HelloErrorServer], fn port ->
+          {:ok, channel} = GRPC.Stub.connect("localhost:#{port}")
+          req = %Helloworld.HelloRequest{name: "Elixir"}
+          {:error, reply} = channel |> Helloworld.Greeter.Stub.say_hello(req)
 
-      assert %GRPC.RPCError{
-               status: GRPC.Status.unauthenticated(),
-               message: "Please authenticate"
-             } == reply
-    end)
+          assert %GRPC.RPCError{
+                   status: GRPC.Status.unauthenticated(),
+                   message: "Please authenticate"
+                 } == reply
+        end)
+      end)
+
+    assert logs =~ "Exception raised while handling /helloworld.Greeter/SayHello"
   end
 
   test "return errors for unknown errors" do
-    run_server([HelloErrorServer], fn port ->
-      {:ok, channel} = GRPC.Stub.connect("localhost:#{port}")
-      req = %Helloworld.HelloRequest{name: "unknown error"}
+    logs =
+      ExUnit.CaptureLog.capture_log(fn ->
+        run_server([HelloErrorServer], fn port ->
+          {:ok, channel} = GRPC.Stub.connect("localhost:#{port}")
+          req = %Helloworld.HelloRequest{name: "unknown error"}
 
-      assert {:error,
-              %GRPC.RPCError{message: "Internal Server Error", status: GRPC.Status.unknown()}} ==
-               channel |> Helloworld.Greeter.Stub.say_hello(req)
-    end)
+          assert {:error,
+                  %GRPC.RPCError{message: "Internal Server Error", status: GRPC.Status.unknown()}} ==
+                   channel |> Helloworld.Greeter.Stub.say_hello(req)
+        end)
+      end)
+
+    assert logs =~ "Exception raised while handling /helloworld.Greeter/SayHello"
   end
 
   test "returns appropriate error for stream requests" do