Adds JSON as a format for the log (#3017)

Co-authored-by: José Valim <jose.valim@dashbit.co>
Co-authored-by: Jonatan Kłosko <jonatanklosko@gmail.com>

README.md

@@ -266,6 +266,9 @@ The following environment variables can be used to configure Livebook on boot:
     users (attached to evaluation and request logs). By default includes only
     request_id.
 
+  * `LIVEBOOK_LOG_FORMAT` - sets the log output format, either "text" (default)
+    for human-readable logs or "json" for structured JSON.
+
   * `LIVEBOOK_NODE` - sets the node name for running Livebook in a cluster.
     Note that Livebook always runs using long names distribution, so the
     node host name must use a fully qualified domain name (FQDN) or an IP

config/config.exs

@@ -10,7 +10,7 @@ config :livebook, LivebookWeb.Endpoint,
   render_errors: [formats: [html: LivebookWeb.ErrorHTML], layout: false]
 
 # Configures Elixir's Logger
-config :logger, :console,
+config :logger, :default_formatter,
   format: "$date $time $metadata[$level] $message\n",
   metadata: [:request_id]
 

config/dev.exs

@@ -62,7 +62,7 @@ config :livebook, LivebookWeb.Endpoint,
   ]
 
 # Do not include timestamps in development logs
-config :logger, :console,
+config :logger, :default_formatter,
   format: "$metadata[$level] $message\n",
   metadata: []
 

config/test.exs

@@ -6,8 +6,25 @@ config :livebook, LivebookWeb.Endpoint,
   http: [port: 4002],
   server: false
 
-# Print only warnings and errors during test
-config :logger, level: :warning
+# Print only warnings and errors during test.
+#
+# We configure the default handler instead of Logger on purpose,
+# as we want all calls to be processed, especially when using
+# the JSON formatter.
+config :logger, :default_handler, level: :warning
+
+# Also configure the JSON formatter for test.
+# We make sure we write all currently available metadata.
+path = "tmp/test.log.json"
+File.rm(path)
+
+config :livebook, :logger, [
+  {:handler, :json_log, :logger_std_h,
+   %{
+     config: %{file: ~c"#{path}"},
+     formatter: {LoggerJSON.Formatters.Basic, %{metadata: [:users, :request_id]}}
+   }}
+]
 
 # Disable authentication in tests
 config :livebook,

lib/livebook.ex

@@ -101,8 +101,19 @@ defmodule Livebook do
       config :logger, level: level
     end
 
-    if metadata = Livebook.Config.log_metadata!("LIVEBOOK_LOG_METADATA") do
-      config :logger, :console, metadata: metadata
+    log_metadata = Livebook.Config.log_metadata!("LIVEBOOK_LOG_METADATA")
+    log_format = Livebook.Config.log_format!("LIVEBOOK_LOG_FORMAT") || :text
+
+    case {log_format, log_metadata} do
+      {:json, log_metadata} ->
+        config :logger, :default_handler,
+          formatter: {LoggerJSON.Formatters.Basic, %{metadata: log_metadata || [:request_id]}}
+
+      {:text, log_metadata} when not is_nil(log_metadata) ->
+        config :logger, :default_formatter, metadata: log_metadata
+
+      _ ->
+        :ok
     end
 
     if port = Livebook.Config.port!("LIVEBOOK_PORT") do

lib/livebook/application.ex

@@ -4,6 +4,7 @@ defmodule Livebook.Application do
   require Logger
 
   def start(_type, _args) do
+    Logger.add_handlers(:livebook)
     Livebook.ZTA.init()
     create_teams_hub = parse_teams_hub()
     setup_optional_dependencies()

lib/livebook/config.ex

@@ -479,6 +479,23 @@ defmodule Livebook.Config do
     end
   end
 
+  @doc """
+  Parses and validates log format from env.
+  """
+  def log_format!(env) do
+    formats = ~w(text json)
+
+    if format = System.get_env(env) do
+      if format in formats do
+        String.to_atom(format)
+      else
+        abort!(
+          "expected #{env} to be one of #{Enum.join(formats, ", ")}, got: #{inspect(format)}"
+        )
+      end
+    end
+  end
+
   @doc """
   Parses and validates the port from env.
   """

mix.exs

@@ -125,6 +125,7 @@ defmodule Livebook.MixProject do
       {:phoenix_live_reload, "~> 1.2", only: :dev},
       {:lazy_html, "~> 0.1.0", only: :test},
       {:bypass, "~> 2.1", only: :test},
+      {:logger_json, "~> 6.1"},
       # So that we can test Python evaluation in the same node
       {:pythonx, "~> 0.4.2", only: :test},
       # ZTA deps

mix.lock

@@ -25,6 +25,7 @@
   "jsx": {:hex, :jsx, "3.1.0", "d12516baa0bb23a59bb35dccaf02a1bd08243fcbb9efe24f2d9d056ccff71268", [:rebar3], [], "hexpm", "0c5cc8fdc11b53cc25cf65ac6705ad39e54ecc56d1c22e4adb8f5a53fb9427f3"},
   "kubereq": {:hex, :kubereq, "0.3.2", "e425dd94bd74b6510dc45a9557d9378d3fd6ca0ea3ebe0dad2a9c85a08c2e20a", [:mix], [{:fresh, "~> 0.4.4", [hex: :fresh, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}, {:mint, "~> 1.0", [hex: :mint, repo: "hexpm", optional: false]}, {:mint_web_socket, "~> 1.0", [hex: :mint_web_socket, repo: "hexpm", optional: false]}, {:pluggable, "~> 1.0", [hex: :pluggable, repo: "hexpm", optional: false]}, {:req, "~> 0.5.0", [hex: :req, repo: "hexpm", optional: false]}, {:yaml_elixir, "~> 2.0", [hex: :yaml_elixir, repo: "hexpm", optional: false]}], "hexpm", "d13293ac66bbfe7ac238881ac0404662af5a01f96f9325dd556594fd858f2a3e"},
   "lazy_html": {:hex, :lazy_html, "0.1.0", "619c4c124a7375ecbf66263de90270d221ffc7479afde436717a4e5cceaac954", [:make, :mix], [{:cc_precompiler, "~> 0.1", [hex: :cc_precompiler, repo: "hexpm", optional: false]}, {:elixir_make, "~> 0.9.0", [hex: :elixir_make, repo: "hexpm", optional: false]}, {:fine, "~> 0.1.0", [hex: :fine, repo: "hexpm", optional: false]}], "hexpm", "a212f417b0e546055b7d5d72d302fce747b63ac9dfe0cf491c1f9af6d198e256"},
+  "logger_json": {:hex, :logger_json, "6.2.1", "a1db30e1164e6057f2328a1e4d6b632b9583c015574fdf6c38cf73721128edcb", [:mix], [{:decimal, ">= 0.0.0", [hex: :decimal, repo: "hexpm", optional: true]}, {:ecto, "~> 3.11", [hex: :ecto, repo: "hexpm", optional: true]}, {:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: false]}, {:plug, "~> 1.15", [hex: :plug, repo: "hexpm", optional: true]}, {:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "34acd0bfd419d5fcf08c4108a8a4b59b695fcc60409dc1dd1a868b70c42e1d1f"},
   "makeup": {:hex, :makeup, "1.2.1", "e90ac1c65589ef354378def3ba19d401e739ee7ee06fb47f94c687016e3713d1", [:mix], [{:nimble_parsec, "~> 1.4", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "d36484867b0bae0fea568d10131197a4c2e47056a6fbe84922bf6ba71c8d17ce"},
   "makeup_elixir": {:hex, :makeup_elixir, "1.0.1", "e928a4f984e795e41e3abd27bfc09f51db16ab8ba1aebdba2b3a575437efafc2", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "7284900d412a3e5cfd97fdaed4f5ed389b8f2b4cb49efc0eb3bd10e2febf9507"},
   "makeup_erlang": {:hex, :makeup_erlang, "1.0.2", "03e1804074b3aa64d5fad7aa64601ed0fb395337b982d9bcf04029d68d51b6a7", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "af33ff7ef368d5893e4a267933e7744e46ce3cf1f61e2dccf53a111ed3aa3727"},

test/livebook/config_test.exs

@@ -43,6 +43,34 @@ defmodule Livebook.ConfigTest do
     end
   end
 
+  describe "log_metadata!/1" do
+    test "parses valida metadata configs" do
+      with_env([TEST_LOG_METADATA: "users,request_id"], fn ->
+        assert Config.log_metadata!("TEST_LOG_METADATA") == [:users, :request_id]
+      end)
+    end
+
+    test "returns nil when environment variable is not set" do
+      assert Config.log_metadata!("TEST_LOG_METADATA") == nil
+    end
+  end
+
+  describe "log_format!/1" do
+    test "parses valid formats" do
+      with_env([TEST_LOG_FORMAT: "text"], fn ->
+        assert Config.log_format!("TEST_LOG_FORMAT") == :text
+      end)
+
+      with_env([TEST_LOG_FORMAT: "json"], fn ->
+        assert Config.log_format!("TEST_LOG_FORMAT") == :json
+      end)
+    end
+
+    test "returns nil when environment variable is not set" do
+      assert Config.log_format!("TEST_LOG_FORMAT") == nil
+    end
+  end
+
   defp with_env(env_vars, fun) do
     existing =
       Enum.map(env_vars, fn {env, _value} ->