From a7e1d8ba9a5f9cdae736dc041a8514ce9169f757 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jonatan=20K=C5=82osko?= Date: Wed, 26 May 2021 19:54:43 +0200 Subject: [PATCH] Capture logger output (#298) * Capture logger output * Add capture integration test --- lib/livebook/application.ex | 4 + lib/livebook/runtime/erl_dist.ex | 3 +- .../runtime/erl_dist/logger_gl_backend.ex | 149 ++++++++++++++++++ lib/livebook/runtime/erl_dist/manager.ex | 8 +- .../runtime/erl_dist/manager_test.exs | 20 ++- 5 files changed, 180 insertions(+), 4 deletions(-) create mode 100644 lib/livebook/runtime/erl_dist/logger_gl_backend.ex diff --git a/lib/livebook/application.ex b/lib/livebook/application.ex index 050bcb190c2..0843ee52b73 100644 --- a/lib/livebook/application.ex +++ b/lib/livebook/application.ex @@ -31,6 +31,10 @@ defmodule Livebook.Application do LivebookWeb.Endpoint ] + # Similarly as with :standard_error, we register our backend + # within the Livebook node, specifically for the embedded runtime + Logger.add_backend(Livebook.Runtime.ErlDist.LoggerGLBackend) + opts = [strategy: :one_for_one, name: Livebook.Supervisor] with {:ok, _} = result <- Supervisor.start_link(children, opts) do diff --git a/lib/livebook/runtime/erl_dist.ex b/lib/livebook/runtime/erl_dist.ex index abfadf00024..c7b2a04dd3d 100644 --- a/lib/livebook/runtime/erl_dist.ex +++ b/lib/livebook/runtime/erl_dist.ex @@ -25,7 +25,8 @@ defmodule Livebook.Runtime.ErlDist do Livebook.Runtime.ErlDist, Livebook.Runtime.ErlDist.Manager, Livebook.Runtime.ErlDist.EvaluatorSupervisor, - Livebook.Runtime.ErlDist.IOForwardGL + Livebook.Runtime.ErlDist.IOForwardGL, + Livebook.Runtime.ErlDist.LoggerGLBackend ] @doc """ diff --git a/lib/livebook/runtime/erl_dist/logger_gl_backend.ex b/lib/livebook/runtime/erl_dist/logger_gl_backend.ex new file mode 100644 index 00000000000..d0812f8235a --- /dev/null +++ b/lib/livebook/runtime/erl_dist/logger_gl_backend.ex @@ -0,0 +1,149 @@ +defmodule Livebook.Runtime.ErlDist.LoggerGLBackend do + @moduledoc false + + # A logger backend used to forward logs to Livebook, + # as with regular output. + # + # The backend is based on `Logger.Backends.Console`, + # but instead of logging to the console, it sends + # log output to the group leader of the soruce process, + # provided the group leader is an instance of + # `Livebook.Evaluator.IOProxy`. + # + # Basic configuration is taken from the console + # logger configuration to match its formatting. + + @behaviour :gen_event + + @type state :: %{ + colors: keyword(), + format: binary(), + level: atom(), + metadata: list(atom()) + } + + @impl true + def init(__MODULE__) do + config = Application.get_env(:logger, :console) + {:ok, init_state(config)} + end + + @impl true + def handle_event({level, gl, {Logger, msg, ts, md}}, state) do + %{level: log_level} = state + + if meet_level?(level, log_level) do + log_event(level, msg, ts, md, gl, state) + end + + {:ok, state} + end + + def handle_event(_, state) do + {:ok, state} + end + + @impl true + def code_change(_old_vsn, state, _extra) do + {:ok, state} + end + + @impl true + def handle_call(_message, state) do + {:ok, :ok, state} + end + + @impl true + def handle_info(_message, state) do + {:ok, state} + end + + @impl true + def terminate(_reason, _state) do + :ok + end + + defp init_state(config) do + level = Keyword.get(config, :level) + format = Logger.Formatter.compile(Keyword.get(config, :format)) + colors = configure_colors(config) + metadata = Keyword.get(config, :metadata, []) |> configure_metadata() + + %{format: format, metadata: metadata, level: level, colors: colors} + end + + defp configure_metadata(:all), do: :all + defp configure_metadata(metadata), do: Enum.reverse(metadata) + + defp configure_colors(config) do + colors = Keyword.get(config, :colors, []) + + %{ + debug: Keyword.get(colors, :debug, :cyan), + info: Keyword.get(colors, :info, :normal), + warn: Keyword.get(colors, :warn, :yellow), + error: Keyword.get(colors, :error, :red), + enabled: Keyword.get(colors, :enabled, IO.ANSI.enabled?()) + } + end + + defp meet_level?(_lvl, nil), do: true + + defp meet_level?(lvl, min) do + Logger.compare_levels(lvl, min) != :lt + end + + defp log_event(level, msg, ts, md, gl, state) do + if io_proxy?(gl) do + output = format_event(level, msg, ts, md, state) + async_io(gl, output) + end + end + + defp io_proxy?(pid) do + info = Process.info(pid, [:dictionary]) + info[:dictionary][:"$initial_call"] == {Livebook.Evaluator.IOProxy, :init, 1} + end + + defp async_io(name, output) when is_atom(name) do + case Process.whereis(name) do + device when is_pid(device) -> + async_io(device, output) + + nil -> + raise "no device registered with the name #{inspect(name)}" + end + end + + defp async_io(device, output) when is_pid(device) do + send(device, {:io_request, self(), make_ref(), {:put_chars, :unicode, output}}) + end + + defp format_event(level, msg, ts, md, state) do + %{format: format, metadata: keys, colors: colors} = state + + format + |> Logger.Formatter.format(level, msg, ts, take_metadata(md, keys)) + |> color_event(level, colors, md) + end + + defp take_metadata(metadata, :all) do + metadata + end + + defp take_metadata(metadata, keys) do + Enum.reduce(keys, [], fn key, acc -> + case Keyword.fetch(metadata, key) do + {:ok, val} -> [{key, val} | acc] + :error -> acc + end + end) + end + + defp color_event(data, _level, %{enabled: false}, _md), do: data + + defp color_event(data, level, %{enabled: true} = colors, md) do + color = md[:ansi_color] || Map.fetch!(colors, level) + IO.ANSI.format([color, data]) + end +end diff --git a/lib/livebook/runtime/erl_dist/manager.ex b/lib/livebook/runtime/erl_dist/manager.ex index 0799ec17b98..196734c3712 100644 --- a/lib/livebook/runtime/erl_dist/manager.ex +++ b/lib/livebook/runtime/erl_dist/manager.ex @@ -37,8 +37,8 @@ defmodule Livebook.Runtime.ErlDist.Manager do from the node. Defaults to `true`. * `:register_standard_error_proxy` - configures whether - manager should start an IOForwardGL process and set - it as the group leader. Defaults to `true`. + manager should start an IOForwardGL process and register + it as `:standard_error`. Defaults to `true`. """ def start(opts \\ []) do {anonymous?, opts} = Keyword.pop(opts, :anonymous, false) @@ -176,6 +176,8 @@ defmodule Livebook.Runtime.ErlDist.Manager do Process.register(io_forward_gl_pid, :standard_error) end + Logger.add_backend(Livebook.Runtime.ErlDist.LoggerGLBackend) + # Set `ignore_module_conflict` only for the Manager lifetime. initial_ignore_module_conflict = Code.compiler_options()[:ignore_module_conflict] Code.compiler_options(ignore_module_conflict: true) @@ -203,6 +205,8 @@ defmodule Livebook.Runtime.ErlDist.Manager do Process.register(state.original_standard_error, :standard_error) end + Logger.remove_backend(Livebook.Runtime.ErlDist.LoggerGLBackend) + ErlDist.unload_required_modules() end diff --git a/test/livebook/runtime/erl_dist/manager_test.exs b/test/livebook/runtime/erl_dist/manager_test.exs index 06fd0a8f9e3..788f5db90c7 100644 --- a/test/livebook/runtime/erl_dist/manager_test.exs +++ b/test/livebook/runtime/erl_dist/manager_test.exs @@ -57,7 +57,7 @@ defmodule Livebook.Runtime.ErlDist.ManagerTest do Manager.stop(node()) end - test "proxies evaluation stderr to stdout" do + test "proxies evaluation stderr to evaluation stdout" do Manager.start() Manager.set_owner(node(), self()) @@ -67,6 +67,24 @@ defmodule Livebook.Runtime.ErlDist.ManagerTest do Manager.stop(node()) end + + @tag capture_log: true + test "proxies logger messages to evaluation stdout" do + Manager.start() + Manager.set_owner(node(), self()) + + code = """ + require Logger + Logger.error("hey") + """ + + Manager.evaluate_code(node(), code, :container1, :evaluation1, nil) + + assert_receive {:evaluation_stdout, :evaluation1, log_message} + assert log_message =~ "[error] hey" + + Manager.stop(node()) + end end describe "request_completion_items/6" do