Add structured data in code evaluation logs (#3077)

Author: hugobarauna

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.

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]}}
    }}
 ]
 

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,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

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,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)
 

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}} ->