Skip to content

Commit

Permalink
Remove accepted_comparators option from logger interceptors (#326)
Browse files Browse the repository at this point in the history 
* 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
  • Loading branch information
@guisehn
guisehn authored Jul 10, 2023
1 parent 691ac21 commit d5ad40a
Show file tree
Hide file tree
Showing 5 changed files with 153 additions and 117 deletions.
18 changes: 6 additions & 12 deletions lib/grpc/client/interceptors/logger.ex
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
Expand Down
22 changes: 2 additions & 20 deletions lib/grpc/server/interceptors/logger.ex
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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)}")
Expand Down
109 changes: 69 additions & 40 deletions test/grpc/client/interceptors/logger_test.exs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
6 changes: 3 additions & 3 deletions test/grpc/integration/endpoint_test.exs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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
Expand Down
115 changes: 73 additions & 42 deletions test/grpc/server/interceptors/logger_test.exs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
)

Expand All @@ -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

0 comments on commit d5ad40a

Please sign in to comment.