From b7d187b914b2c69094c8d8ff8795652daf5ae905 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jonatan=20K=C5=82osko?= Date: Fri, 29 Nov 2024 21:22:13 +0800 Subject: [PATCH] Add logs for code evaluation (#2880) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: José Valim --- README.md | 11 +++++-- config/dev.exs | 6 ++-- lib/livebook.ex | 8 +++-- lib/livebook/app.ex | 6 ++-- lib/livebook/apps/deployer.ex | 16 ++++++--- lib/livebook/config.ex | 27 +++++++++++---- lib/livebook/session.ex | 42 +++++++++++++++++++++--- lib/livebook/utils.ex | 16 +++++++++ lib/livebook_web/live/hooks/user_hook.ex | 35 ++++---------------- lib/livebook_web/plugs/user_plug.ex | 32 ++++++++++++++++++ test/livebook/app_test.exs | 3 +- 11 files changed, 149 insertions(+), 53 deletions(-) diff --git a/README.md b/README.md index 17e56f6ac..b4c1cffb7 100644 --- a/README.md +++ b/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 diff --git a/config/dev.exs b/config/dev.exs index 4049d77b5..59348b447 100644 --- a/config/dev.exs +++ b/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 diff --git a/lib/livebook.ex b/lib/livebook.ex index ac085cf0d..188d298c2 100644 --- a/lib/livebook.ex +++ b/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 diff --git a/lib/livebook/app.ex b/lib/livebook/app.ex index 756b7e3c7..19c5c6047 100644 --- a/lib/livebook/app.ex +++ b/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 diff --git a/lib/livebook/apps/deployer.ex b/lib/livebook/apps/deployer.ex index f042a29d3..3ad7f690a 100644 --- a/lib/livebook/apps/deployer.ex +++ b/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) diff --git a/lib/livebook/config.ex b/lib/livebook/config.ex index 9a8b9e97c..a5c8e392a 100644 --- a/lib/livebook/config.ex +++ b/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. """ diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index 8c3afc8a1..efa434230 100644 --- a/lib/livebook/session.ex +++ b/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 -> "" diff --git a/lib/livebook/utils.ex b/lib/livebook/utils.ex index 7b62ed3ad..5be6a7bf4 100644 --- a/lib/livebook/utils.ex +++ b/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 diff --git a/lib/livebook_web/live/hooks/user_hook.ex b/lib/livebook_web/live/hooks/user_hook.ex index b84043d77..7208ca622 100644 --- a/lib/livebook_web/live/hooks/user_hook.ex +++ b/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 diff --git a/lib/livebook_web/plugs/user_plug.ex b/lib/livebook_web/plugs/user_plug.ex index 1de146591..695a47102 100644 --- a/lib/livebook_web/plugs/user_plug.ex +++ b/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 diff --git a/test/livebook/app_test.exs b/test/livebook/app_test.exs index 9dca37a16..4281940ee 100644 --- a/test/livebook/app_test.exs +++ b/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