From aca989862554559970251877de4f7cdd53dd5dfc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Fri, 3 Oct 2025 12:30:22 -0300 Subject: [PATCH 1/8] Only log code evaluation for regular sessions and preview apps The rationale is that one would want audit log only for people "manually" executing code in an app server. If the code being evaluated is from a deployed app, I'm assuming they reviewed the code before. And if they want to log something there, they can use a logger inside their app's source code. --- lib/livebook/app.ex | 1 + lib/livebook/session.ex | 45 ++++++++++------ test/livebook/session_test.exs | 99 ++++++++++++++++++++++++++++++++++ 3 files changed, 128 insertions(+), 17 deletions(-) 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..d7c28b12ce6 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,26 @@ defmodule Livebook.Session do state end + def log_code_evaluation(cell, state) 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) + ) + 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/test/livebook/session_test.exs b/test/livebook/session_test.exs index 264f0b8ae4e..be4cfa44077 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,104 @@ 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(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 =~ ~s(Evaluating code\n Session mode: default\n Code: "# #{unique_id}") + 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}} + + 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(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 =~ ~s(Evaluating code\n Session mode: app\n Code: "# #{unique_id}") + + App.close(app_pid) + 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} + + # Deploy as a permanent app + app_spec = Livebook.Apps.NotebookAppSpec.new(notebook) + deployer_pid = Livebook.Apps.Deployer.local_deployer() + ref = Livebook.Apps.Deployer.deploy_monitor(deployer_pid, app_spec, permanent: true) + + app_pid = + receive do + {:deploy_result, ^ref, {:ok, pid}} -> + Process.demonitor(ref, [:flush]) + pid + end + + 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(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 + + App.close(app_pid) + end + end + defp start_session(opts \\ []) do {:ok, session} = Livebook.Sessions.create_session(opts) From 8ec644340f29325aa79a233c29b349d1ef816ec7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Fri, 3 Oct 2025 14:36:31 -0300 Subject: [PATCH 2/8] Add structured metadata to code evaluation logs This will be easier to process from an external log aggregator. Useful when auditing code evalution in an app server connected to a prod environment. --- README.md | 10 +++++++--- lib/livebook.ex | 2 ++ lib/livebook/session.ex | 25 +++++++++++++++++++++---- lib/livebook/utils.ex | 5 ++++- 4 files changed, 34 insertions(+), 8 deletions(-) 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/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/session.ex b/lib/livebook/session.ex index d7c28b12ce6..261bc880106 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -2685,8 +2685,20 @@ defmodule Livebook.Session do end def log_code_evaluation(cell, state) do + inspected_code = inspect(cell.source, printable_limit: :infinity) + + # For metadata code, we try to use use the raw source, so it's easier to process + # the logged code in a external log aggregator. + metadata_code = + case cell.source do + source when is_binary(source) -> source + _ -> inspected_code + end + + session_mode = state.data.mode + evaluation_users = - case state.data.mode do + case session_mode do :default -> Map.values(state.data.users_map) :app -> if(state.deployed_by, do: [state.deployed_by], else: []) end @@ -2695,12 +2707,17 @@ defmodule Livebook.Session do [ """ Evaluating code - Session mode: #{state.data.mode} + Session mode: #{session_mode} Code: \ """, - inspect(cell.source, printable_limit: :infinity) + inspected_code ], - Livebook.Utils.logger_users_metadata(evaluation_users) + Keyword.merge( + Livebook.Utils.logger_users_metadata(evaluation_users), + session_mode: session_mode, + code: metadata_code, + event: "code.evaluate" + ) ) end 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 From 68c73db7b5bfb843b9a10b569c607fed40e8e943 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Fri, 3 Oct 2025 14:44:24 -0300 Subject: [PATCH 3/8] Refactor: transform public function into private --- lib/livebook/session.ex | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index 261bc880106..ac04e0b67b8 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -2684,7 +2684,7 @@ defmodule Livebook.Session do state end - def log_code_evaluation(cell, state) do + defp log_code_evaluation(cell, state) do inspected_code = inspect(cell.source, printable_limit: :infinity) # For metadata code, we try to use use the raw source, so it's easier to process From e5446919bc8f7d659c009f958f05e3eb2679eb72 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Mon, 6 Oct 2025 10:41:21 -0300 Subject: [PATCH 4/8] Log the metadata itself. --- lib/livebook/session.ex | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index ac04e0b67b8..393b4d71c6a 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -2703,6 +2703,10 @@ defmodule Livebook.Session do :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( [ """ @@ -2712,6 +2716,10 @@ defmodule Livebook.Session do """, inspected_code ], + Livebook.Utils.logger_users_metadata(evaluation_users) + ) + + Logger.info( Keyword.merge( Livebook.Utils.logger_users_metadata(evaluation_users), session_mode: session_mode, From 615f86eb99874b93fe4107270a792d93e4a5f38a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Mon, 6 Oct 2025 10:56:39 -0300 Subject: [PATCH 5/8] Adds message to code evaluation logs with metadata --- lib/livebook/session.ex | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index 393b4d71c6a..4b4ba9109a5 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -2720,6 +2720,7 @@ defmodule Livebook.Session do ) Logger.info( + "Evaluating code", Keyword.merge( Livebook.Utils.logger_users_metadata(evaluation_users), session_mode: session_mode, From 8d6e2d9887afd92c4a1b32118bee8ddeb0c22ffb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Mon, 6 Oct 2025 11:54:25 -0300 Subject: [PATCH 6/8] Extend and reuese test helper function --- test/livebook/session_test.exs | 16 ++-------------- test/support/app_helpers.ex | 7 +++++-- 2 files changed, 7 insertions(+), 16 deletions(-) diff --git a/test/livebook/session_test.exs b/test/livebook/session_test.exs index be4cfa44077..70209f43f58 100644 --- a/test/livebook/session_test.exs +++ b/test/livebook/session_test.exs @@ -2160,19 +2160,9 @@ defmodule Livebook.SessionTest do section = %{Notebook.Section.new() | cells: [code_cell]} notebook = %{Notebook.new() | sections: [section], app_settings: app_settings} - # Deploy as a permanent app - app_spec = Livebook.Apps.NotebookAppSpec.new(notebook) - deployer_pid = Livebook.Apps.Deployer.local_deployer() - ref = Livebook.Apps.Deployer.deploy_monitor(deployer_pid, app_spec, permanent: true) - - app_pid = - receive do - {:deploy_result, ^ref, {:ok, pid}} -> - Process.demonitor(ref, [:flush]) - pid - end - + 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) @@ -2186,8 +2176,6 @@ defmodule Livebook.SessionTest do # Logs from other test might be captured, so we're using an unique_id refute log =~ unique_id - - App.close(app_pid) end end 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}} -> From bfe4c21be4d4d5e1e1f3297dc2a3ef9953ada92a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Mon, 6 Oct 2025 12:00:03 -0300 Subject: [PATCH 7/8] Simplify code evaluation logging No need to check if cell.source is a string, it's always a string inside a session process. --- lib/livebook/session.ex | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index 4b4ba9109a5..edb3b6353b6 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -2685,16 +2685,6 @@ defmodule Livebook.Session do end defp log_code_evaluation(cell, state) do - inspected_code = inspect(cell.source, printable_limit: :infinity) - - # For metadata code, we try to use use the raw source, so it's easier to process - # the logged code in a external log aggregator. - metadata_code = - case cell.source do - source when is_binary(source) -> source - _ -> inspected_code - end - session_mode = state.data.mode evaluation_users = @@ -2714,7 +2704,7 @@ defmodule Livebook.Session do Session mode: #{session_mode} Code: \ """, - inspected_code + inspect(cell.source, printable_limit: :infinity) ], Livebook.Utils.logger_users_metadata(evaluation_users) ) @@ -2724,7 +2714,7 @@ defmodule Livebook.Session do Keyword.merge( Livebook.Utils.logger_users_metadata(evaluation_users), session_mode: session_mode, - code: metadata_code, + code: cell.source, event: "code.evaluate" ) ) From d1f221b042e0002bccd5e2ad2e39d7d281a06c34 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Hugo=20Bara=C3=BAna?= Date: Mon, 6 Oct 2025 14:23:46 -0300 Subject: [PATCH 8/8] Assert on the new code evaluation log format --- config/test.exs | 4 +++- test/livebook/session_test.exs | 28 ++++++++++++++++++---------- 2 files changed, 21 insertions(+), 11 deletions(-) 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/test/livebook/session_test.exs b/test/livebook/session_test.exs index 70209f43f58..ac498b61641 100644 --- a/test/livebook/session_test.exs +++ b/test/livebook/session_test.exs @@ -2102,16 +2102,19 @@ defmodule Livebook.SessionTest do 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}"}) + Session.set_cell_attributes(session.pid, cell_id, %{source: "#{unique_id}"}) log = - capture_log(fn -> + 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 =~ ~s(Evaluating code\n Session mode: default\n Code: "# #{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 @@ -2128,6 +2131,10 @@ defmodule Livebook.SessionTest do 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) @@ -2135,19 +2142,20 @@ defmodule Livebook.SessionTest do 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}"}) + 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(fn -> + 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 =~ ~s(Evaluating code\n Session mode: app\n Code: "# #{unique_id}") - - App.close(app_pid) + 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 @@ -2156,7 +2164,7 @@ defmodule Livebook.SessionTest do 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}"} + 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} @@ -2169,7 +2177,7 @@ defmodule Livebook.SessionTest do cell_id = code_cell.id log = - capture_log(fn -> + 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)