Log server timeouts captured by Cowboy.Handler (#439)

Co-authored-by: Adriano Santos <[email protected]>

Author: pzhou-thescore

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

@@ -464,6 +464,10 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
     error = %RPCError{status: GRPC.Status.deadline_exceeded(), message: "Deadline expired"}
     req = send_error(req, error, state, :timeout)
 
+    [req: req]
+    |> ReportException.new(error)
+    |> log_error()
+
     {:stop, req, state}
   end
 
@@ -694,7 +698,7 @@ defmodule GRPC.Server.Adapters.Cowboy.Handler do
     {:wait, ref}
   end
 
-  defp log_error(%ReportException{kind: kind} = exception, stacktrace) do
+  defp log_error(%ReportException{kind: kind} = exception, stacktrace \\ []) do
     crash_reason = GRPC.Logger.crash_reason(kind, exception, stacktrace)
 
     kind

test/grpc/integration/server_test.exs

@@ -277,14 +277,20 @@ defmodule GRPC.Integration.ServerTest do
   end
 
   test "return deadline error for slow server" do
-    run_server([TimeoutServer], fn port ->
-      {:ok, channel} = GRPC.Stub.connect("localhost:#{port}")
-      rect = %Routeguide.Rectangle{}
-      error = %GRPC.RPCError{message: "Deadline expired", status: 4}
+    logs =
+      ExUnit.CaptureLog.capture_log(fn ->
+        run_server([TimeoutServer], fn port ->
+          {:ok, channel} = GRPC.Stub.connect("localhost:#{port}")
+          rect = %Routeguide.Rectangle{}
+          error = %GRPC.RPCError{message: "Deadline expired", status: 4}
 
-      assert {:error, ^error} =
-               channel |> Routeguide.RouteGuide.Stub.list_features(rect, timeout: 500)
-    end)
+          assert {:error, ^error} =
+                   channel |> Routeguide.RouteGuide.Stub.list_features(rect, timeout: 500)
+        end)
+      end)
+
+    assert logs =~
+             "Exception raised while handling /routeguide.RouteGuide/ListFeatures:\n** (GRPC.RPCError) Deadline expired"
   end
 
   test "return normally for a little slow server" do