Add structured data in code evaluation logs

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.

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,

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

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,43 @@ defmodule Livebook.Session do
     state
   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 =
+      case session_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: #{session_mode}
+          Code: \
+        """,
+        inspected_code
+      ],
+      Keyword.merge(
+        Livebook.Utils.logger_users_metadata(evaluation_users),
+        session_mode: session_mode,
+        code: metadata_code,
+        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

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

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)