Repository: elixir-grpc/grpc
Pull request #198 (2021-06-29 16:07:52)

Add support for `request_id` in `GRPC.Server.Stream`
The small change adds a new field `request_id` to the `GRPC.Server.Stream` struct. It may be handy for logging purposes. 

polvalente: @ilyashuma let me know if you want me to take over these changes
ilyashuma: Hi, @polvalente, yup, go ahead. Thank you!

Patch:
diff --git a/lib/grpc/logger.ex b/lib/grpc/logger.ex
deleted file mode 100644
index 0c1e9b0..0000000
--- a/lib/grpc/logger.ex
+++ /dev/null
@@ -1,95 +0,0 @@
-defmodule GRPC.Logger.Server do
-  @moduledoc """
-  Print log around server rpc calls, like:
-
-      17:18:45.151 [info]  Handled by HelloServer.say_hello
-      17:18:45.151 [info]  Response :ok in 11µs
-
-  ## Usage
-
-      defmodule Your.Endpoint do
-        use GRPC.Endpoint
-
-        intercept GRPC.Logger.Server, level: :info
-      end
-  """
-  require Logger
-  @behaviour GRPC.ServerInterceptor
-
-  def init(opts) do
-    Keyword.get(opts, :level, :info)
-  end
-
-  def call(req, stream, next, level) do
-    if Logger.compare_levels(level, Logger.level()) != :lt do
-      Logger.log(level, fn ->
-        ["Handled by ", inspect(stream.server), ".", to_string(elem(stream.rpc, 0))]
-      end)
-
-      start = System.monotonic_time()
-      result = next.(req, stream)
-      stop = System.monotonic_time()
-
-      status = elem(result, 0)
-
-      Logger.log(level, fn ->
-        diff = System.convert_time_unit(stop - start, :native, :microsecond)
-
-        ["Response ", inspect(status), " in ", formatted_diff(diff)]
-      end)
-
-      result
-    else
-      next.(req, stream)
-    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
-
-defmodule GRPC.Logger.Client do
-  require Logger
-
-  @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
-
-  ## Usage
-
-      {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [GRPC.Logger.Client])
-      {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Logger.Client, level: :info}])
-  """
-
-  def init(opts) do
-    Keyword.get(opts, :level, :info)
-  end
-
-  def call(%{grpc_type: grpc_type} = stream, req, next, level) do
-    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)
-
-        Logger.log(level, fn ->
-          diff = System.convert_time_unit(stop - start, :native, :microsecond)
-
-          ["Got ", inspect(status), " in ", GRPC.Logger.Server.formatted_diff(diff)]
-        end)
-      end
-
-      result
-    else
-      next.(stream, req)
-    end
-  end
-end
diff --git a/lib/grpc/logger/client.ex b/lib/grpc/logger/client.ex
new file mode 100644
index 0000000..0dab721
--- /dev/null
+++ b/lib/grpc/logger/client.ex
@@ -0,0 +1,48 @@
+defmodule GRPC.Logger.Client do
+  require Logger
+
+  @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
+
+  ## Usage
+
+      {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [GRPC.Logger.Client])
+      {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Logger.Client, level: :info}])
+  """
+
+  def init(opts) do
+    level = Keyword.get(opts, :level) || :info
+    [level: level]
+  end
+
+  def call(%{grpc_type: grpc_type} = stream, req, next, opts) do
+    level = 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)
+
+        Logger.log(level, fn ->
+          diff = System.convert_time_unit(stop - start, :native, :microsecond)
+
+          ["Got ", inspect(status), " in ", GRPC.Logger.Server.formatted_diff(diff)]
+        end)
+      end
+
+      result
+    else
+      next.(stream, req)
+    end
+  end
+end
diff --git a/lib/grpc/logger/server.ex b/lib/grpc/logger/server.ex
new file mode 100644
index 0000000..dbfbcfa
--- /dev/null
+++ b/lib/grpc/logger/server.ex
@@ -0,0 +1,54 @@
+defmodule GRPC.Logger.Server do
+  @moduledoc """
+  Print log around server rpc calls, like:
+
+      17:18:45.151 [info]  Handled by HelloServer.say_hello
+      17:18:45.151 [info]  Response :ok in 11µs
+
+  ## Usage
+
+      defmodule Your.Endpoint do
+        use GRPC.Endpoint
+
+        intercept GRPC.Logger.Server, level: :info
+      end
+  """
+  require Logger
+  @behaviour GRPC.ServerInterceptor
+
+  def init(opts) do
+    level = Keyword.get(opts, :level) || :info
+    [level: level]
+  end
+
+  def call(req, stream, next, opts) do
+    level = Keyword.fetch!(opts, :level)
+
+    if Logger.compare_levels(level, Logger.level()) != :lt do
+      Logger.metadata(request_id: Logger.metadata()[:request_id] || stream.request_id)
+
+      Logger.log(level, fn ->
+        ["Handled by ", inspect(stream.server), ".", to_string(elem(stream.rpc, 0))]
+      end)
+
+      start = System.monotonic_time()
+      result = next.(req, stream)
+      stop = System.monotonic_time()
+
+      status = elem(result, 0)
+
+      Logger.log(level, fn ->
+        diff = System.convert_time_unit(stop - start, :native, :microsecond)
+
+        ["Response ", inspect(status), " in ", formatted_diff(diff)]
+      end)
+
+      result
+    else
+      next.(req, stream)
+    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/lib/grpc/server.ex b/lib/grpc/server.ex
index 557686a..cb06137 100644
--- a/lib/grpc/server.ex
+++ b/lib/grpc/server.ex
@@ -88,11 +88,29 @@ defmodule GRPC.Server do
         {_, {req_mod, req_stream}, {res_mod, res_stream}} = rpc,
         func_name
       ) do
-    stream = %{stream | request_mod: req_mod, response_mod: res_mod, rpc: rpc}
+    request_id = generate_request_id()
+
+    stream = %{
+      stream
+      | request_mod: req_mod,
+        request_id: request_id,
+        response_mod: res_mod,
+        rpc: rpc
+    }
 
     handle_request(req_stream, res_stream, stream, func_name)
   end
 
+  defp generate_request_id do
+    binary = <<
+      System.system_time(:nanosecond)::64,
+      :erlang.phash2({node(), self()}, 16_777_216)::24,
+      :erlang.unique_integer()::32
+    >>
+
+    Base.url_encode64(binary, padding: false)
+  end
+
   defp handle_request(req_s, res_s, %{server: server} = stream, func_name) do
     if function_exported?(server, func_name, 2) do
       do_handle_request(req_s, res_s, stream, func_name)
diff --git a/lib/grpc/server/stream.ex b/lib/grpc/server/stream.ex
index 9463ecf..0ae27ab 100644
--- a/lib/grpc/server/stream.ex
+++ b/lib/grpc/server/stream.ex
@@ -25,6 +25,7 @@ defmodule GRPC.Server.Stream do
           endpoint: atom,
           rpc: tuple,
           request_mod: atom,
+          request_id: String.t() | nil,
           response_mod: atom,
           codec: atom,
           payload: any,
@@ -43,6 +44,7 @@ defmodule GRPC.Server.Stream do
             endpoint: nil,
             rpc: nil,
             request_mod: nil,
+            request_id: nil,
             response_mod: nil,
             codec: GRPC.Codec.Proto,
             payload: nil,


Test patch:
diff --git a/test/grpc/logger/server_test.exs b/test/grpc/logger/server_test.exs
new file mode 100644
index 0000000..6740d43
--- /dev/null
+++ b/test/grpc/logger/server_test.exs
@@ -0,0 +1,21 @@
+defmodule GRPC.Logger.ServerTest do
+  use ExUnit.Case, async: true
+
+  alias GRPC.Logger.Server
+
+  alias GRPC.Server.Stream
+
+  test "request id is only set if not previously set" do
+    assert Logger.metadata() == []
+
+    request_id = to_string(System.monotonic_time())
+    stream = %Stream{server: :server, rpc: {1, 2, 3}, request_id: request_id}
+    Server.call(:request, stream, fn :request, ^stream -> {:ok, :ok} end, level: :info)
+
+    assert [request_id: request_id] == Logger.metadata()
+
+    stream = %{stream | request_id: nil}
+    Server.call(:request, stream, fn :request, ^stream -> {:ok, :ok} end, level: :info)
+    assert request_id == Logger.metadata()[:request_id]
+  end
+end