From d5ad40a88755e26a000d585291ddd0888aba7f5a Mon Sep 17 00:00:00 2001 From: Guilherme Sehn Date: Mon, 10 Jul 2023 17:32:44 -0300 Subject: [PATCH] Remove `accepted_comparators` option from logger interceptors (#326) * reverse logger level comparison logic * add more details to example * remove accepted_comparator * adjust client tests * adjust server tests * prevent log level from being changed globally * mix format * adjust tests to (hopefully) pass for all elixir/otp versions * one more attempt to have tests working for all elixir versions --- lib/grpc/client/interceptors/logger.ex | 18 +-- lib/grpc/server/interceptors/logger.ex | 22 +--- test/grpc/client/interceptors/logger_test.exs | 109 +++++++++++------ test/grpc/integration/endpoint_test.exs | 6 +- test/grpc/server/interceptors/logger_test.exs | 115 +++++++++++------- 5 files changed, 153 insertions(+), 117 deletions(-) diff --git a/lib/grpc/client/interceptors/logger.ex b/lib/grpc/client/interceptors/logger.ex index 35f7b6a8..5a61e514 100644 --- a/lib/grpc/client/interceptors/logger.ex +++ b/lib/grpc/client/interceptors/logger.ex @@ -8,18 +8,14 @@ defmodule GRPC.Client.Interceptors.Logger do ## Options * `:level` - the desired log level. Defaults to `:info` - * `:accepted_comparators` - a list with the accepted `Logger.compare_levels(configured_level, Logger.level())` results. - Defaults to `[:lt, :eq]` ## Usage {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [GRPC.Client.Interceptors.Logger]) - # This will log on `:info` and greater priority - {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Client.Interceptors.Logger, level: :info}]) - # This will log only on `:info` - {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Client.Interceptors.Logger, level: :info, accepted_comparators: [:eq]}]) - # This will log on `:info` and lower priority - {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Client.Interceptors.Logger, level: :info, accepted_comparators: [:eq, :gt]}]) + + ## Usage with custom level + + {:ok, channel} = GRPC.Stub.connect("localhost:50051", interceptors: [{GRPC.Client.Interceptors.Logger, level: :warn}]) """ require Logger @@ -29,16 +25,14 @@ defmodule GRPC.Client.Interceptors.Logger do @impl true def init(opts) do level = Keyword.get(opts, :level) || :info - accepted_comparators = Keyword.get(opts, :accepted_comparators) || [:lt, :eq] - [level: level, accepted_comparators: accepted_comparators] + [level: level] end @impl true def call(%{grpc_type: grpc_type} = stream, req, next, opts) do level = Keyword.fetch!(opts, :level) - accepted_comparators = Keyword.fetch!(opts, :accepted_comparators) - if Logger.compare_levels(level, Logger.level()) in accepted_comparators 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) diff --git a/lib/grpc/server/interceptors/logger.ex b/lib/grpc/server/interceptors/logger.ex index 5f6e5d1d..3b93310f 100644 --- a/lib/grpc/server/interceptors/logger.ex +++ b/lib/grpc/server/interceptors/logger.ex @@ -8,8 +8,6 @@ defmodule GRPC.Server.Interceptors.Logger do ## Options * `:level` - the desired log level. Defaults to `:info` - * `:accepted_comparators` - a list with the accepted `Logger.compare_levels(configured_level, Logger.level())` results. - Defaults to `[:lt, :eq]` ## Usage @@ -18,20 +16,6 @@ defmodule GRPC.Server.Interceptors.Logger do intercept GRPC.Server.Interceptors.Logger, level: :info end - - defmodule Your.Endpoint do - use GRPC.Endpoint - - # logs on :info and higher priority (warn, error...) - intercept GRPC.Server.Interceptors.Logger, level: :info, accepted_comparators: [:lt, :eq] - end - - defmodule Your.Endpoint do - use GRPC.Endpoint - - # logs only on :error - intercept GRPC.Server.Interceptors.Logger, level: :error, accepted_comparators: [:eq] - end """ require Logger @@ -41,16 +25,14 @@ defmodule GRPC.Server.Interceptors.Logger do @impl true def init(opts) do level = Keyword.get(opts, :level) || :info - accepted_comparators = Keyword.get(opts, :accepted_comparators) || [:lt, :eq] - [level: level, accepted_comparators: accepted_comparators] + [level: level] end @impl true def call(req, stream, next, opts) do level = Keyword.fetch!(opts, :level) - accepted_comparators = opts[:accepted_comparators] - if Logger.compare_levels(level, Logger.level()) in accepted_comparators do + if Logger.compare_levels(level, Logger.level()) != :lt do Logger.metadata(request_id: Logger.metadata()[:request_id] || stream.request_id) Logger.log(level, "Handled by #{inspect(stream.server)}.#{elem(stream.rpc, 0)}") diff --git a/test/grpc/client/interceptors/logger_test.exs b/test/grpc/client/interceptors/logger_test.exs index 7fc45130..e3dbc63d 100644 --- a/test/grpc/client/interceptors/logger_test.exs +++ b/test/grpc/client/interceptors/logger_test.exs @@ -6,45 +6,74 @@ defmodule GRPC.Client.Interceptors.LoggerTest do alias GRPC.Client.Interceptors.Logger, as: LoggerInterceptor alias GRPC.Client.Stream - test "accepted_comparators filter logs correctly" do - for {configured_level, accepted_comparators, should_log} <- - [ - {:error, [:lt], false}, - {:error, [:eq], false}, - {:error, [:gt], true}, - {:debug, [:eq], false}, - {:debug, [:eq, :gt], false}, - {:info, [:lt, :eq], true} - ] do - logger_level = Logger.level() - assert logger_level == :info - - service_name = "service_name" - rpc = {1, 2, 3} - - logs = - capture_log(fn -> - stream = %Stream{grpc_type: :unary, rpc: rpc, service_name: service_name} - - LoggerInterceptor.call( - stream, - :request, - fn ^stream, :request -> {:ok, :ok} end, - LoggerInterceptor.init( - level: configured_level, - accepted_comparators: accepted_comparators - ) - ) - end) - - if should_log do - assert Regex.match?( - ~r/\[#{configured_level}\]\s+Call #{to_string(elem(rpc, 0))} of #{service_name}/, - logs - ) - else - assert logs == "" - end - end + defmodule FakeRequest do + defstruct [] + end + + @service_name "service_name" + @rpc {1, 2, 3} + + setup do + log_level = Logger.level() + on_exit(fn -> Logger.configure(level: log_level) end) + end + + test "logs info-level by default" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :unary, rpc: @rpc, service_name: @service_name} + next = fn _stream, _request -> {:ok, :ok} 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 + + test "allows customizing log level" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :unary, rpc: @rpc, service_name: @service_name} + next = fn _stream, _request -> {:ok, :ok} end + opts = LoggerInterceptor.init(level: :warn) + + logs = + capture_log(fn -> + LoggerInterceptor.call(stream, request, next, opts) + end) + + assert logs =~ ~r/\[warn(?:ing)?\]\s+Call #{to_string(elem(@rpc, 0))} of #{@service_name}/ + end + + @tag capture_log: true + test "calls next when above :logger level" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :unary, rpc: @rpc, service_name: @service_name} + next = fn stream, req -> send(self(), {:next_called, stream, req}) end + opts = LoggerInterceptor.init(level: :info) + + LoggerInterceptor.call(stream, request, next, opts) + + assert_receive {:next_called, ^stream, ^request} + end + + test "calls next when below :logger level" do + Logger.configure(level: :warn) + + request = %FakeRequest{} + stream = %Stream{grpc_type: :unary, rpc: @rpc, service_name: @service_name} + next = fn stream, req -> send(self(), {:next_called, stream, req}) end + opts = LoggerInterceptor.init(level: :info) + + LoggerInterceptor.call(stream, request, next, opts) + + assert_receive {:next_called, ^stream, ^request} end end diff --git a/test/grpc/integration/endpoint_test.exs b/test/grpc/integration/endpoint_test.exs index af3d338a..5f1afb46 100644 --- a/test/grpc/integration/endpoint_test.exs +++ b/test/grpc/integration/endpoint_test.exs @@ -13,7 +13,7 @@ defmodule GRPC.Integration.EndpointTest do defmodule HelloEndpoint do use GRPC.Endpoint - intercept GRPC.Server.Interceptors.Logger, level: :info, accepted_comparators: [:lt, :eq, :gt] + intercept GRPC.Server.Interceptors.Logger run HelloServer end @@ -51,14 +51,14 @@ defmodule GRPC.Integration.EndpointTest do defmodule FeatureEndpoint do use GRPC.Endpoint - intercept GRPC.Server.Interceptors.Logger, accepted_comparators: [:lt, :eq, :gt] + intercept GRPC.Server.Interceptors.Logger run FeatureServer end defmodule FeatureAndHelloHaltEndpoint do use GRPC.Endpoint - intercept GRPC.Server.Interceptors.Logger, accepted_comparators: [:lt, :eq, :gt] + intercept GRPC.Server.Interceptors.Logger run HelloServer, interceptors: [HelloHaltInterceptor] run FeatureServer end diff --git a/test/grpc/server/interceptors/logger_test.exs b/test/grpc/server/interceptors/logger_test.exs index 3370063f..b62b3a8a 100644 --- a/test/grpc/server/interceptors/logger_test.exs +++ b/test/grpc/server/interceptors/logger_test.exs @@ -6,16 +6,29 @@ defmodule GRPC.Server.Interceptors.LoggerTest do alias GRPC.Server.Interceptors.Logger, as: LoggerInterceptor alias GRPC.Server.Stream + defmodule FakeRequest do + defstruct [] + end + + @server_name :server + @rpc {1, 2, 3} + + setup do + log_level = Logger.level() + on_exit(fn -> Logger.configure(level: log_level) end) + end + 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} + request = %FakeRequest{} + stream = %Stream{server: @server_name, rpc: @rpc, request_id: request_id} LoggerInterceptor.call( - :request, + request, stream, - fn :request, ^stream -> {:ok, :ok} end, + fn ^request, ^stream -> {:ok, :ok} end, LoggerInterceptor.init(level: :info) ) @@ -33,44 +46,62 @@ defmodule GRPC.Server.Interceptors.LoggerTest do assert request_id == Logger.metadata()[:request_id] end - test "accepted_comparators filter logs correctly" do - for {configured_level, accepted_comparators, should_log} <- - [ - {:error, [:lt], false}, - {:error, [:eq], false}, - {:error, [:gt], true}, - {:debug, [:eq], false}, - {:debug, [:eq, :gt], false}, - {:info, [:lt, :eq], true} - ] do - server_name = :"server_#{System.unique_integer()}" - - logger_level = Logger.level() - assert logger_level == :info - - logs = - capture_log(fn -> - stream = %Stream{server: server_name, rpc: {1, 2, 3}, request_id: "1234"} - - LoggerInterceptor.call( - :request, - stream, - fn :request, ^stream -> {:ok, :ok} end, - LoggerInterceptor.init( - level: configured_level, - accepted_comparators: accepted_comparators - ) - ) - end) - - if should_log do - assert Regex.match?( - ~r/\[#{configured_level}\]\s+Handled by #{inspect(server_name)}/, - logs - ) - else - assert logs == "" - end - end + test "logs info-level by default" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{server: @server_name, rpc: @rpc, request_id: nil} + next = fn _stream, _request -> {:ok, :ok} end + opts = LoggerInterceptor.init([]) + + logs = + capture_log(fn -> + LoggerInterceptor.call(request, stream, next, opts) + end) + + assert logs =~ ~r/\[info\]\s+Handled by #{inspect(@server_name)}/ + end + + test "allows customizing log level" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{server: @server_name, rpc: @rpc, request_id: nil} + next = fn _stream, _request -> {:ok, :ok} end + opts = LoggerInterceptor.init(level: :warn) + + logs = + capture_log(fn -> + LoggerInterceptor.call(request, stream, next, opts) + end) + + assert logs =~ ~r/\[warn(?:ing)?\]\s+Handled by #{inspect(@server_name)}/ + end + + @tag capture_log: true + test "calls next when above :logger level" do + Logger.configure(level: :all) + + request = %FakeRequest{} + stream = %Stream{server: @server_name, rpc: @rpc, request_id: nil} + next = fn stream, req -> send(self(), {:next_called, stream, req}) end + opts = LoggerInterceptor.init(level: :info) + + LoggerInterceptor.call(request, stream, next, opts) + + assert_receive {:next_called, ^request, ^stream} + end + + test "calls next when below :logger level" do + Logger.configure(level: :warn) + + request = %FakeRequest{} + stream = %Stream{server: @server_name, rpc: @rpc, request_id: nil} + next = fn stream, req -> send(self(), {:next_called, stream, req}) end + opts = LoggerInterceptor.init(level: :info) + + LoggerInterceptor.call(request, stream, next, opts) + + assert_receive {:next_called, ^request, ^stream} end end