Add logs for code evaluation (#2880)

Co-authored-by: José Valim <jose.valim@dashbit.co>

README.md

@@ -220,9 +220,6 @@ The following environment variables can be used to configure Livebook on boot:
     configuration. Defaults to "livebook" under the default user data
     directory.
 
-  * `LIVEBOOK_DEBUG` - enables verbose logging, when set to "true". Disabled
-    by default.
-
   * `LIVEBOOK_DEFAULT_RUNTIME` - sets the runtime type that is used by default
     when none is started explicitly for the given notebook. Must be either
     "standalone" (Standalone), "attached:NODE:COOKIE" (Attached node)
@@ -261,6 +258,14 @@ The following environment variables can be used to configure Livebook on boot:
   * `LIVEBOOK_IP` - sets the ip address to start the web application on.
     Must be a valid IPv4 or IPv6 address.
 
+  * `LIVEBOOK_LOG_LEVEL` - sets the logger level, allowing for more verbose
+    logging, either of: error, warning, notice, info, debug. Defaults to warning.
+
+  * `LIVEBOOK_LOG_METADATA` - a comma-separated list of metadata keys that should
+    be included in the log messages. Currently the only Livebook-spcecific key is
+    users (attached to evaluation and request logs). By default includes only
+    request_id.
+
   * `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/dev.exs

@@ -61,8 +61,10 @@ config :livebook, LivebookWeb.Endpoint,
     web_console_logger: true
   ]
 
-# Do not include metadata nor timestamps in development logs
-config :logger, :console, format: "[$level] $message\n"
+# Do not include timestamps in development logs
+config :logger, :console,
+  format: "$metadata[$level] $message\n",
+  metadata: []
 
 # Include HEEx debug annotations as HTML comments in rendered markup
 config :phoenix_live_view, :debug_heex_annotations, true

lib/livebook.ex

@@ -97,8 +97,12 @@ defmodule Livebook do
         Livebook.Config.secret!("LIVEBOOK_SECRET_KEY_BASE") ||
           Livebook.Utils.random_secret_key_base()
 
-    if Livebook.Config.debug!("LIVEBOOK_DEBUG") do
-      config :logger, level: :debug
+    if level = Livebook.Config.log_level!("LIVEBOOK_LOG_LEVEL") do
+      config :logger, level: level
+    end
+
+    if metadata = Livebook.Config.log_metadata!("LIVEBOOK_LOG_METADATA") do
+      config :logger, :console, metadata: metadata
     end
 
     if port = Livebook.Config.port!("LIVEBOOK_PORT") do

lib/livebook/app.ex

@@ -86,7 +86,8 @@ defmodule Livebook.App do
           files_tmp_path: String.t(),
           app_spec: Livebook.Apps.AppSpec.t(),
           permanent: boolean(),
-          warnings: list(String.t())
+          warnings: list(String.t()),
+          deployed_by: Livebook.Users.User.t() | nil
         }
 
   @doc """
@@ -361,7 +362,8 @@ defmodule Livebook.App do
       mode: :app,
       app_pid: self(),
       auto_shutdown_ms: state.deployment_bundle.notebook.app_settings.auto_shutdown_ms,
-      started_by: user
+      started_by: user,
+      deployed_by: state.deployment_bundle.deployed_by
     ]
 
     case Livebook.Sessions.create_session(opts) do

lib/livebook/apps/deployer.ex

@@ -45,13 +45,20 @@ defmodule Livebook.Apps.Deployer do
     * `:permanent` - whether the app is deployed as permanent. Defaults
       to `false`
 
+    * `:deployed_by` - the user performing the deployment
+
   """
   @spec deploy_monitor(pid(), Apps.AppSpec.t(), keyword()) :: reference()
   def deploy_monitor(pid, app_spec, opts \\ []) do
-    opts = Keyword.validate!(opts, start_only: false, permanent: false)
+    opts = Keyword.validate!(opts, start_only: false, permanent: false, deployed_by: nil)
 
     ref = Process.monitor(pid)
-    GenServer.cast(pid, {:deploy, app_spec, opts[:start_only], opts[:permanent], self(), ref})
+
+    GenServer.cast(
+      pid,
+      {:deploy, app_spec, opts[:start_only], opts[:permanent], opts[:deployed_by], self(), ref}
+    )
+
     ref
   end
 
@@ -79,7 +86,7 @@ defmodule Livebook.Apps.Deployer do
   end
 
   @impl true
-  def handle_cast({:deploy, app_spec, start_only, permanent, from, ref}, state) do
+  def handle_cast({:deploy, app_spec, start_only, permanent, deployed_by, from, ref}, state) do
     Logger.info("[app=#{app_spec.slug}] Deploying app")
 
     files_tmp_path = Apps.generate_files_tmp_path(app_spec.slug)
@@ -98,7 +105,8 @@ defmodule Livebook.Apps.Deployer do
           files_tmp_path: files_tmp_path,
           app_spec: app_spec,
           permanent: permanent,
-          warnings: warnings
+          warnings: warnings,
+          deployed_by: deployed_by
         }
 
         name = Apps.global_name(app_spec.slug)

lib/livebook/config.ex

@@ -444,18 +444,31 @@ defmodule Livebook.Config do
   end
 
   @doc """
-  Parses and validates debug mode from env.
+  Parses and validates log level from env.
   """
-  def debug!(env) do
-    if debug = System.get_env(env) do
-      cond do
-        debug in ["1", "true"] -> true
-        debug in ["0", "false"] -> false
-        true -> abort!("expected #{env} to be a boolean, got: #{inspect(debug)}")
+  def log_level!(env) do
+    levels = ~w(error warning notice info debug)
+
+    if level = System.get_env(env) do
+      if level in levels do
+        String.to_atom(level)
+      else
+        abort!("expected #{env} to be one of #{Enum.join(levels, ", ")}, got: #{inspect(levels)}")
       end
     end
   end
 
+  @doc """
+  Parses and validates log metadata keys from env.
+  """
+  def log_metadata!(env) do
+    if metadata = System.get_env(env) do
+      for item <- String.split(metadata, ","),
+          key = String.trim(item),
+          do: String.to_atom(key)
+    end
+  end
+
   @doc """
   Parses and validates the port from env.
   """

lib/livebook/session.ex

@@ -83,6 +83,8 @@ defmodule Livebook.Session do
 
   use GenServer, restart: :temporary
 
+  require Logger
+
   alias Livebook.NotebookManager
   alias Livebook.Session.{Data, FileGuard}
   alias Livebook.{Utils, Notebook, Text, Runtime, LiveMarkdown, FileSystem}
@@ -129,7 +131,8 @@ defmodule Livebook.Session do
           app_pid: pid() | nil,
           auto_shutdown_ms: non_neg_integer() | nil,
           auto_shutdown_timer_ref: reference() | nil,
-          started_by: Livebook.Users.User.t() | nil
+          started_by: Livebook.Users.User.t() | nil,
+          deployed_by: Livebook.Users.User.t() | nil
         }
 
   @type memory_usage ::
@@ -192,6 +195,9 @@ defmodule Livebook.Session do
       for app sessions using the Teams hub, in which case this information
       is accessible from runtime
 
+    * `:deployed_by` - the user that deployed the app, to which this
+      session belongs to. This is only relevant for app sessions
+
   """
   @spec start_link(keyword()) :: {:ok, pid} | {:error, any()}
   def start_link(opts) do
@@ -931,7 +937,8 @@ defmodule Livebook.Session do
         app_pid: opts[:app_pid],
         auto_shutdown_ms: opts[:auto_shutdown_ms],
         auto_shutdown_timer_ref: nil,
-        started_by: opts[:started_by]
+        started_by: opts[:started_by],
+        deployed_by: opts[:deployed_by]
       }
 
       {:ok, state}
@@ -1422,7 +1429,14 @@ defmodule Livebook.Session do
     {:noreply, handle_operation(state, operation)}
   end
 
-  def handle_cast({:deploy_app, _client_pid}, state) do
+  def handle_cast({:deploy_app, client_pid}, state) do
+    client_id = client_id(state, client_pid)
+
+    deployed_by =
+      if user_id = state.data.clients_map[client_id] do
+        state.data.users_map[user_id]
+      end
+
     # In the initial state app settings are empty, hence not valid,
     # so we double-check that we can actually deploy
     if Notebook.AppSettings.valid?(state.data.notebook.app_settings) and
@@ -1433,7 +1447,9 @@ defmodule Livebook.Session do
       }
 
       deployer_pid = Livebook.Apps.Deployer.local_deployer()
-      deployment_ref = Livebook.Apps.Deployer.deploy_monitor(deployer_pid, app_spec)
+
+      deployment_ref =
+        Livebook.Apps.Deployer.deploy_monitor(deployer_pid, app_spec, deployed_by: deployed_by)
 
       {:noreply, %{state | deployment_ref: deployment_ref}}
     else
@@ -2549,6 +2565,24 @@ defmodule Livebook.Session do
   defp handle_action(state, _action), do: state
 
   defp start_evaluation(state, cell, section, evaluation_opts) do
+    evaluation_users =
+      case state.data.mode do
+        :default -> Map.values(state.data.users_map)
+        :app -> if(state.deployed_by, do: [state.deployed_by], else: [])
+      end
+
+    Logger.info(
+      [
+        """
+        Evaluating code
+          Session mode: #{state.data.mode}
+          Code: \
+        """,
+        inspect(cell.source, printable_limit: :infinity)
+      ],
+      Livebook.Utils.logger_users_metadata(evaluation_users)
+    )
+
     path =
       case state.data.file || default_notebook_file(state) do
         nil -> ""

lib/livebook/utils.ex

@@ -833,4 +833,20 @@ defmodule Livebook.Utils do
       []
     end
   end
+
+  @doc """
+  Returns logger metadata for a list of users.
+  """
+  @spec logger_users_metadata(list(Livebook.Users.User.t())) :: keyword()
+  def logger_users_metadata(users) when is_list(users) do
+    list =
+      for user <- users do
+        for key <- [:id, :name, :email],
+            value = Map.get(user, key),
+            do: {key, value},
+            into: %{}
+      end
+
+    [users: inspect(list)]
+  end
 end

lib/livebook_web/live/hooks/user_hook.ex

@@ -2,18 +2,22 @@ defmodule LivebookWeb.UserHook do
   import Phoenix.Component
   import Phoenix.LiveView
 
-  alias Livebook.Users.User
-
   def on_mount(:default, _params, session, socket) do
     socket =
       socket
-      |> assign_new(:current_user, fn -> build_current_user(session, socket) end)
+      |> assign_new(:current_user, fn ->
+        connect_params = get_connect_params(socket) || %{}
+        user_data = connect_params["user_data"]
+        LivebookWeb.UserPlug.build_current_user(session, user_data)
+      end)
       |> attach_hook(:current_user_subscription, :handle_info, &info/2)
 
     if connected?(socket) do
       Livebook.Users.subscribe(socket.assigns.current_user.id)
     end
 
+    Logger.metadata(Livebook.Utils.logger_users_metadata([socket.assigns.current_user]))
+
     {:cont, socket}
   end
 
@@ -25,29 +29,4 @@ defmodule LivebookWeb.UserHook do
   end
 
   defp info(_message, socket), do: {:cont, socket}
-
-  # Builds `Livebook.Users.User` using information from
-  # session and socket.
-  #
-  # Uses `user_data` from socket `connect_params` as initial
-  # attributes if the socket is connected. Otherwise uses
-  # `user_data` from session.
-  defp build_current_user(session, socket) do
-    identity_data = Map.new(session["identity_data"], fn {k, v} -> {Atom.to_string(k), v} end)
-    connect_params = get_connect_params(socket) || %{}
-    attrs = connect_params["user_data"] || session["user_data"] || %{}
-
-    attrs =
-      case Map.merge(attrs, identity_data) do
-        %{"name" => nil, "email" => email} = attrs -> %{attrs | "name" => email}
-        attrs -> attrs
-      end
-
-    user = User.new(session["user_id"])
-
-    case Livebook.Users.update_user(user, attrs) do
-      {:ok, user} -> user
-      {:error, _changeset} -> user
-    end
-  end
 end

lib/livebook_web/plugs/user_plug.ex

@@ -25,6 +25,7 @@ defmodule LivebookWeb.UserPlug do
     |> ensure_user_identity()
     |> ensure_user_data()
     |> mirror_user_data_in_session()
+    |> set_logger_metadata()
   end
 
   defp ensure_user_identity(conn) do
@@ -78,4 +79,35 @@ defmodule LivebookWeb.UserPlug do
     user_data = conn.cookies["lb_user_data"] |> Base.decode64!() |> Jason.decode!()
     put_session(conn, :user_data, user_data)
   end
+
+  defp set_logger_metadata(conn) do
+    current_user = build_current_user(get_session(conn))
+    Logger.metadata(Livebook.Utils.logger_users_metadata([current_user]))
+    conn
+  end
+
+  @doc """
+  Builds `Livebook.Users.User` using information from the session.
+
+  Merges the `user_data` with `identity_data`. Optionally an override
+  for `user_data` can be specified, which we use in `UserHook`, where
+  we get possibly updated `user_data` from `connect_params`.
+  """
+  def build_current_user(session, user_data_override \\ nil) do
+    identity_data = Map.new(session["identity_data"], fn {k, v} -> {Atom.to_string(k), v} end)
+    attrs = user_data_override || session["user_data"] || %{}
+
+    attrs =
+      case Map.merge(attrs, identity_data) do
+        %{"name" => nil, "email" => email} = attrs -> %{attrs | "name" => email}
+        attrs -> attrs
+      end
+
+    user = Livebook.Users.User.new(session["user_id"])
+
+    case Livebook.Users.update_user(user, attrs) do
+      {:ok, user} -> user
+      {:error, _changeset} -> user
+    end
+  end
 end

test/livebook/app_test.exs

@@ -245,7 +245,8 @@ defmodule Livebook.AppTest do
       files_tmp_path: Livebook.Apps.generate_files_tmp_path(app_spec.slug),
       app_spec: app_spec,
       permanent: false,
-      warnings: []
+      warnings: [],
+      deployed_by: nil
     }
   end