diff --git a/README.md b/README.md index b684a991fb2..5259d1523c1 100644 --- a/README.md +++ b/README.md @@ -265,9 +265,13 @@ The following environment variables can be used to configure Livebook on boot: 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. + be included in the log messages. Livebook-specific keys include: + - `users` (attached to evaluation and request logs) + - `session_mode` (attached to evaluation logs, either "default" or "app") + - `code` (attached to evaluation logs, the code being evaluated) + - `event` (attached to evaluation logs, currently always "code.evaluate") + + 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. diff --git a/config/test.exs b/config/test.exs index ec9f7b41fdb..71c59fabbc8 100644 --- a/config/test.exs +++ b/config/test.exs @@ -22,7 +22,9 @@ config :livebook, :logger, [ {:handler, :json_log, :logger_std_h, %{ config: %{file: ~c"#{path}"}, - formatter: {LoggerJSON.Formatters.Basic, %{metadata: [:users, :request_id]}} + formatter: + {LoggerJSON.Formatters.Basic, + %{metadata: [:request_id, :users, :session_mode, :code, :event]}} }} ] diff --git a/lib/livebook.ex b/lib/livebook.ex index f5269797dc0..bcf9a6b0861 100644 --- a/lib/livebook.ex +++ b/lib/livebook.ex @@ -104,6 +104,8 @@ defmodule Livebook do log_metadata = Livebook.Config.log_metadata!("LIVEBOOK_LOG_METADATA") log_format = Livebook.Config.log_format!("LIVEBOOK_LOG_FORMAT") || :text + config :livebook, :log_format, log_format + case {log_format, log_metadata} do {:json, log_metadata} -> config :logger, :default_handler, diff --git a/lib/livebook/app.ex b/lib/livebook/app.ex index 19c5c6047b1..5e662b1da15 100644 --- a/lib/livebook/app.ex +++ b/lib/livebook/app.ex @@ -361,6 +361,7 @@ defmodule Livebook.App do files_source: {:dir, files_source}, mode: :app, app_pid: self(), + app_permanent: state.deployment_bundle.permanent, auto_shutdown_ms: state.deployment_bundle.notebook.app_settings.auto_shutdown_ms, started_by: user, deployed_by: state.deployment_bundle.deployed_by diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index c99b70fd0bd..edb3b6353b6 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -132,6 +132,7 @@ defmodule Livebook.Session do deployment_ref: reference() | nil, deployed_app_monitor_ref: reference() | nil, app_pid: pid() | nil, + app_permanent: boolean() | nil, auto_shutdown_ms: non_neg_integer() | nil, auto_shutdown_timer_ref: reference() | nil, started_by: Users.User.t() | nil, @@ -191,6 +192,8 @@ defmodule Livebook.Session do * `:app_pid` - the parent app process, when in running in `:app` mode + * `:app_permanent` - whether the app is permanent or a preview app + * `:auto_shutdown_ms` - the inactivity period (no clients) after which the session should close automatically @@ -962,6 +965,7 @@ defmodule Livebook.Session do deployment_ref: nil, deployed_app_monitor_ref: nil, app_pid: opts[:app_pid], + app_permanent: opts[:app_permanent], auto_shutdown_ms: opts[:auto_shutdown_ms], auto_shutdown_timer_ref: nil, started_by: opts[:started_by], @@ -2638,23 +2642,10 @@ 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) - ) + # Only log code evaluation if inside a regular notebook session or a preview app + if state.data.mode == :default or state.app_permanent == false do + log_code_evaluation(cell, state) + end path = case state.data.file || default_notebook_file(state) do @@ -2693,6 +2684,42 @@ defmodule Livebook.Session do state end + defp log_code_evaluation(cell, state) do + session_mode = state.data.mode + + evaluation_users = + case session_mode do + :default -> Map.values(state.data.users_map) + :app -> if(state.deployed_by, do: [state.deployed_by], else: []) + end + + # We plan to deprecate this one in favor of the log call below. + # We're keeping this here because users may be depending on this already. + # Once the new log below, we ask users to migrate, and eventually delete + # this one. + Logger.info( + [ + """ + Evaluating code + Session mode: #{session_mode} + Code: \ + """, + inspect(cell.source, printable_limit: :infinity) + ], + Livebook.Utils.logger_users_metadata(evaluation_users) + ) + + Logger.info( + "Evaluating code", + Keyword.merge( + Livebook.Utils.logger_users_metadata(evaluation_users), + session_mode: session_mode, + code: cell.source, + event: "code.evaluate" + ) + ) + end + defp hydrate_cell_source_digest(state, cell_id, tag) do # Clients prune source, so they can't compute the digest, but it's # necessary for evaluation to know which cells are changed, so we diff --git a/lib/livebook/utils.ex b/lib/livebook/utils.ex index 73a0c8a7c85..f781199ff8e 100644 --- a/lib/livebook/utils.ex +++ b/lib/livebook/utils.ex @@ -854,6 +854,9 @@ defmodule Livebook.Utils do into: %{} end - [users: inspect(list)] + case Application.get_env(:livebook, :log_format) do + :text -> [users: inspect(list)] + :json -> [users: list] + end end end diff --git a/test/livebook/session_test.exs b/test/livebook/session_test.exs index 264f0b8ae4e..ac498b61641 100644 --- a/test/livebook/session_test.exs +++ b/test/livebook/session_test.exs @@ -1,6 +1,7 @@ defmodule Livebook.SessionTest do use ExUnit.Case, async: true + import ExUnit.CaptureLog import Livebook.HubHelpers import Livebook.AppHelpers import Livebook.SessionHelpers @@ -2092,6 +2093,100 @@ defmodule Livebook.SessionTest do end end + describe "code evaluation logging" do + test "logs code evaluation for regular sessions" do + session = start_session() + Session.subscribe(session.id) + + {_section_id, cell_id} = insert_section_and_cell(session.pid) + + unique_id = Utils.random_short_id() + # Use random ID to uniquely identify the source code of this cell + Session.set_cell_attributes(session.pid, cell_id, %{source: "#{unique_id}"}) + + log = + capture_log([level: :info, metadata: [:session_mode, :code, :event]], fn -> + Session.queue_cell_evaluation(session.pid, cell_id) + assert_receive {:operation, {:add_cell_evaluation_response, _, ^cell_id, _, _}} + end) + + # Logs from other test might be captured, so we're using an unique_id + assert log =~ "code=#{unique_id}" + assert log =~ "Evaluating code" + assert log =~ "session_mode=default" + assert log =~ "event=code.evaluate" + end + + test "logs code evaluation for preview apps" do + session = start_session() + Session.subscribe(session.id) + + slug = Utils.random_short_id() + app_settings = %{Notebook.AppSettings.new() | slug: slug} + Session.set_app_settings(session.pid, app_settings) + + {section_id, _cell_id} = insert_section_and_cell(session.pid) + + Apps.subscribe() + Session.deploy_app(session.pid) + assert_receive {:app_created, %{slug: ^slug, pid: app_pid}} + + on_exit(fn -> + App.close(app_pid) + end) + + session_id = App.get_session_id(app_pid) + {:ok, app_session} = Livebook.Sessions.fetch_session(session_id) + + Session.subscribe(app_session.id) + + unique_id = Utils.random_short_id() + # Use random ID to uniquely identify the source code of this cell + Session.insert_cell(app_session.pid, section_id, 0, :code, %{source: "#{unique_id}"}) + assert_receive {:operation, {:insert_cell, _, ^section_id, 0, :code, cell_id, _}} + + log = + capture_log([level: :info, metadata: [:session_mode, :code, :event]], fn -> + Session.queue_cell_evaluation(app_session.pid, cell_id) + assert_receive {:operation, {:add_cell_evaluation_response, _, ^cell_id, _, _}} + end) + + # Logs from other test might be captured, so we're using an unique_id + assert log =~ "code=#{unique_id}" + assert log =~ "Evaluating code" + assert log =~ "session_mode=app" + assert log =~ "event=code.evaluate" + end + + test "does not log code evaluation for permanent apps" do + slug = Utils.random_short_id() + app_settings = %{Notebook.AppSettings.new() | slug: slug} + + unique_id = Utils.random_short_id() + # Use random ID to uniquely identify the source code of this cell + code_cell = %{Notebook.Cell.new(:code) | source: "#{unique_id}"} + section = %{Notebook.Section.new() | cells: [code_cell]} + notebook = %{Notebook.new() | sections: [section], app_settings: app_settings} + + app_pid = deploy_notebook_sync(notebook, permanent: true) + session_id = App.get_session_id(app_pid) + + {:ok, app_session} = Livebook.Sessions.fetch_session(session_id) + + Session.subscribe(app_session.id) + cell_id = code_cell.id + + log = + capture_log([level: :info, metadata: [:session_mode, :code, :event]], fn -> + Session.queue_cell_evaluation(app_session.pid, cell_id) + assert_receive {:operation, {:add_cell_evaluation_response, _, ^cell_id, _, _}} + end) + + # Logs from other test might be captured, so we're using an unique_id + refute log =~ unique_id + end + end + defp start_session(opts \\ []) do {:ok, session} = Livebook.Sessions.create_session(opts) diff --git a/test/support/app_helpers.ex b/test/support/app_helpers.ex index f008d1694bc..33946d47022 100644 --- a/test/support/app_helpers.ex +++ b/test/support/app_helpers.ex @@ -3,11 +3,14 @@ defmodule Livebook.AppHelpers do alias Livebook.TeamsRPC - def deploy_notebook_sync(notebook) do + def deploy_notebook_sync(notebook, opts \\ []) do + opts = Keyword.validate!(opts, permanent: false) + permanent_opts = Keyword.take(opts, [:permanent]) + app_spec = Livebook.Apps.NotebookAppSpec.new(notebook) deployer_pid = Livebook.Apps.Deployer.local_deployer() - ref = Livebook.Apps.Deployer.deploy_monitor(deployer_pid, app_spec) + ref = Livebook.Apps.Deployer.deploy_monitor(deployer_pid, app_spec, permanent_opts) receive do {:deploy_result, ^ref, {:ok, pid}} ->