2617 capture editor metrics serverside (#2868)

* Config to allow disabling of logging * Allow for logging of JobEditor merics * Pass through metrics from JobEditor * Implement logging for workflow editor metrics * Refactor UiMetrics * Wire up WorkflowEditor metrics * Fix test name typo * Formatting changes * Docs and CHANGELOG * Test coverage on liveview * Trying out retrying when all the components haven't mounted yet --------- Co-authored-by: Stuart Corbishley <[email protected]>
OpenFn · Jan 28, 2025 · 6439637 · 6439637
1 parent adba8f6
commit 6439637
Show file tree

Hide file tree

Showing 14 changed files with 516 additions and 35 deletions.
diff --git a/.env.example b/.env.example
@@ -286,3 +286,7 @@
 # the flag used to enable/disable this mode
 # LOCAL_ADAPTORS=true
 # OPENFN_ADAPTORS_REPO=/path/to/repo/
+#
+# Control whether metrics reported by the Workflow editor or Job editor are
+# written to the Lightning logs.
+# UI_METRICS_ENABLED=false
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -31,6 +31,8 @@ and this project adheres to
 - Indexes to foreign keys on `workflow_edges` and `steps` tables to try and
   alleviate slow loading of the job editor.
   [#2617](https://github.com/OpenFn/lightning/issues/2617)
+- Add temporary events to allow Lightning to log metrics reported by editors.
+  [#2617](https://github.com/OpenFn/lightning/issues/2617)
 
 ### Changed
 

diff --git a/DEPLOYMENT.md b/DEPLOYMENT.md
@@ -188,6 +188,7 @@ For SMTP, the following environment variables are required:
 | `ADAPTORS_REGISTRY_JSON_PATH`            | Path to adaptor registry file. When provided, the app will attempt to read from it then later fallback to the internet                                                                                                                 |
 | `SECRET_KEY_BASE`                        | A secret key used as a base to generate secrets for encrypting and signing data.                                                                                                                                                       |
 | `SENTRY_DSN`                             | If using Sentry for error monitoring, your DSN                                                                                                                                                                                         |
+| `UI_METRICS_ENABLED`                     | Enable serverside tracking of certain metrics related to the UI. This s temporary functionality. Defaults to `false`.                                                                                                                  |
 | `URL_HOST`                               | The host used for writing URLs (e.g., `demo.openfn.org`)                                                                                                                                                                               |
 | `URL_PORT`                               | The port, usually `443` for production                                                                                                                                                                                                 |
 | `URL_SCHEME`                             | The scheme for writing URLs (e.g., `https`)                                                                                                                                                                                            |

diff --git a/assets/js/job-editor/mount.tsx b/assets/js/job-editor/mount.tsx
@@ -1,14 +1,14 @@
+import pDebounce from 'p-debounce';
+import pRetry from 'p-retry';
 import React from 'react';
 import { createRoot } from 'react-dom/client';
-import type JobEditor from './JobEditor';
-import { sortMetadata } from '../metadata-loader/metadata';
+import { EDITOR_DEBOUNCE_MS } from '../common';
 import { LiveSocket, PhoenixHook } from '../hooks/PhoenixHook';
+import { sortMetadata } from '../metadata-loader/metadata';
+import { Lightning } from '../workflow-diagram/types';
 import type WorkflowEditorEntrypoint from '../workflow-editor';
-import pRetry from 'p-retry';
-import pDebounce from 'p-debounce';
 import { WorkflowStore } from '../workflow-editor/store';
-import { Lightning } from '../workflow-diagram/types';
-import { EDITOR_DEBOUNCE_MS } from '../common';
+import type JobEditor from './JobEditor';
 
 type JobEditorEntrypoint = PhoenixHook<
   {
@@ -46,8 +46,8 @@ let JobEditorComponent: typeof JobEditor | undefined;
 export default {
   findWorkflowEditorStore() {
     return pRetry(
-      () => {
-        console.debug('Looking up WorkflowEditorHook');
+      attempt => {
+        console.debug('Looking up WorkflowEditorHook', { attempt });
         return lookupWorkflowEditorHook(this.liveSocket, this.el);
       },
       { retries: 5 }
@@ -60,7 +60,8 @@ export default {
     // this.handleContentChange(this.currentContent);
   },
   mounted(this: JobEditorEntrypoint) {
-    instrumentStart('editor load');
+    let event = 'editor load';
+    let start = instrumentStart(event);
 
     window.jobEditor = this;
 
@@ -79,7 +80,11 @@ export default {
       this.setupObserver();
       this.render();
 
-      instrumentFinish('editor load');
+      let end = instrumentEnd(event);
+
+      this.pushEventTo(this.el, 'job_editor_metrics_report', {
+        metrics: [{ event, start, end }],
+      });
 
       this.requestMetadata().then(() => this.render());
     });
@@ -106,27 +111,32 @@ export default {
 
     checkAdaptorVersion(adaptor);
 
-    this.findWorkflowEditorStore().then(workflowStore => {
-      const job = workflowStore.getState().getById<Lightning.Job>(jobId);
-
-      if (!job) {
-        console.error('Job not found', jobId);
-        return;
-      }
+    pRetry(
+      async attempt => {
+        console.debug('JobEditor', { attempt });
 
-      if (JobEditorComponent) {
-        this.componentRoot?.render(
-          <JobEditorComponent
-            adaptor={adaptor}
-            source={job.body}
-            metadata={this.metadata}
-            disabled={disabled === 'true'}
-            disabledMessage={disabledMessage}
-            onSourceChanged={src => this.handleContentChange(src)}
-          />
-        );
-      }
-    });
+        const workflowStore = await this.findWorkflowEditorStore();
+        const job = workflowStore.getState().getById<Lightning.Job>(jobId);
+        if (!job) {
+          throw new Error('Job not found in store yet');
+        }
+        if (JobEditorComponent) {
+          this.componentRoot?.render(
+            <JobEditorComponent
+              adaptor={adaptor}
+              source={job.body}
+              metadata={this.metadata}
+              disabled={disabled === 'true'}
+              disabledMessage={disabledMessage}
+              onSourceChanged={src_1 => this.handleContentChange(src_1)}
+            />
+          );
+        } else {
+          throw new Error('JobEditorComponent not loaded yet');
+        }
+      },
+      { retries: 5 }
+    );
   },
   requestMetadata() {
     this.metadata = true; // indicate we're loading
@@ -196,11 +206,15 @@ function checkAdaptorVersion(adaptor: string) {
 }
 
 function instrumentStart(label: string) {
-  console.debug(`${label} - start`, new Date().toISOString());
+  let time = new Date();
+  console.debug(`${label} - start`, time.toISOString());
   console.time(label);
+  return time.getTime();
 }
 
-function instrumentFinish(label: string) {
-  console.debug(`${label} - finish`, new Date().toISOString());
+function instrumentEnd(label: string) {
+  let time = new Date();
+  console.debug(`${label} - end`, time.toISOString());
   console.timeEnd(label);
+  return time.getTime();
 }
diff --git a/assets/js/workflow-editor/index.ts b/assets/js/workflow-editor/index.ts
@@ -66,6 +66,10 @@ const createNewWorkflow = () => {
   return { triggers, jobs, edges };
 };
 
+// To support temporary workflow editor metrics submissions to Lightning
+// server.
+let workflowLoadParamsStart: number | null = null;
+
 export default {
   mounted(this: WorkflowEditorEntrypoint) {
     let setHasLoaded: (href: URL) => void;
@@ -222,7 +226,9 @@ export default {
     });
   },
   getWorkflowParams() {
-    console.debug('get-initial-state pushed', new Date().toISOString());
+    let start = new Date();
+    workflowLoadParamsStart = start.getTime();
+    console.debug('get-initial-state pushed', start.toISOString());
     console.time('workflow-params load');
     this.pushEventTo(this.el, 'get-initial-state', {});
   },
@@ -241,8 +247,18 @@ export default {
     }
 
     this.maybeMountComponent();
+    let end = new Date();
     console.debug('current-worflow-params processed', new Date().toISOString());
     console.timeEnd('workflow-params load');
+    this.pushEventTo(this.el, 'workflow_editor_metrics_report', {
+      metrics: [
+        {
+          event: 'workflow-params load',
+          start: workflowLoadParamsStart,
+          end: end.getTime(),
+        },
+      ],
+    });
   },
   maybeMountComponent() {
     if (!this._isMounting && !this.component) {

diff --git a/lib/lightning/config.ex b/lib/lightning/config.ex
@@ -251,6 +251,15 @@ defmodule Lightning.Config do
     defp promex_config do
       Application.get_env(:lightning, Lightning.PromEx, [])
     end
+
+    @impl true
+    def ui_metrics_tracking_enabled? do
+      Keyword.get(ui_metrics_tracking_config(), :enabled)
+    end
+
+    defp ui_metrics_tracking_config do
+      Application.get_env(:lightning, :ui_metrics_tracking, [])
+    end
   end
 
   @callback apollo(key :: atom() | nil) :: map()
@@ -281,6 +290,7 @@ defmodule Lightning.Config do
   @callback storage() :: term()
   @callback storage(key :: atom()) :: term()
   @callback token_signer() :: Joken.Signer.t()
+  @callback ui_metrics_tracking_enabled?() :: boolean()
   @callback usage_tracking() :: Keyword.t()
   @callback usage_tracking_cleartext_uuids_enabled?() :: boolean()
   @callback usage_tracking_cron_opts() :: [Oban.Plugins.Cron.cron_input()]
@@ -460,6 +470,10 @@ defmodule Lightning.Config do
     impl().promex_metrics_endpoint_token()
   end
 
+  def ui_metrics_tracking_enabled? do
+    impl().ui_metrics_tracking_enabled?()
+  end
+
   defp impl do
     Application.get_env(:lightning, __MODULE__, API)
   end

diff --git a/lib/lightning/config/bootstrap.ex b/lib/lightning/config/bootstrap.ex
@@ -631,6 +631,9 @@ defmodule Lightning.Config.Bootstrap do
         env!("KAFKA_NUMBER_OF_MESSAGES_PER_SECOND", :float, 1),
       number_of_processors: env!("KAFKA_NUMBER_OF_PROCESSORS", :integer, 1)
 
+    config :lightning, :ui_metrics_tracking,
+      enabled: env!("UI_METRICS_ENABLED", &Utils.ensure_boolean/1, false)
+
     # # ==============================================================================
 
     setup_storage()

diff --git a/lib/lightning_web/live/workflow_live/edit.ex b/lib/lightning_web/live/workflow_live/edit.ex
@@ -28,6 +28,7 @@ defmodule LightningWeb.WorkflowLive.Edit do
   alias Lightning.Workflows.Trigger
   alias Lightning.Workflows.Workflow
   alias Lightning.WorkOrders
+  alias LightningWeb.UiMetrics
   alias LightningWeb.WorkflowLive.Helpers
   alias LightningWeb.WorkflowNewLive.WorkflowParams
   alias Phoenix.LiveView.JS
@@ -1322,6 +1323,16 @@ defmodule LightningWeb.WorkflowLive.Edit do
      })}
   end
 
+  @impl true
+  def handle_event("workflow_editor_metrics_report", params, socket) do
+    UiMetrics.log_workflow_editor_metrics(
+      socket.assigns.workflow,
+      params["metrics"]
+    )
+
+    {:noreply, socket}
+  end
+
   def handle_event("get-current-state", _params, socket) do
     {:reply, %{workflow_params: socket.assigns.workflow_params}, socket}
   end

diff --git a/lib/lightning_web/live/workflow_live/editor_pane.ex b/lib/lightning_web/live/workflow_live/editor_pane.ex
@@ -3,6 +3,7 @@ defmodule LightningWeb.WorkflowLive.EditorPane do
 
   alias Lightning.Credentials
   alias LightningWeb.JobLive.JobBuilderComponents
+  alias LightningWeb.UiMetrics
 
   attr :id, :string, required: true
   attr :disabled, :boolean, default: false
@@ -78,6 +79,13 @@ defmodule LightningWeb.WorkflowLive.EditorPane do
     {:noreply, socket}
   end
 
+  @impl true
+  def handle_event("job_editor_metrics_report", params, socket) do
+    UiMetrics.log_job_editor_metrics(socket.assigns.form.data, params["metrics"])
+
+    {:noreply, socket}
+  end
+
   # NOTE: This is dead code and should probably be removed. All events are
   # being handled by 'push-change' in the parent liveview
   def handle_event("job_body_changed", %{"source" => source}, socket) do

diff --git a/lib/lightning_web/ui_metrics.ex b/lib/lightning_web/ui_metrics.ex
@@ -0,0 +1,93 @@
+defmodule LightningWeb.UiMetrics do
+  @moduledoc """
+  A temporary measure to allow WorkflowEditor and JobEditor UI components to
+  report selected metrics and have these logged.
+  """
+  require Logger
+
+  def log_job_editor_metrics(job, metrics) do
+    if Lightning.Config.ui_metrics_tracking_enabled?() do
+      Enum.each(metrics, fn metric ->
+        metric
+        |> enrich_job_editor_metric(job)
+        |> create_job_editor_log_line()
+        |> Logger.info()
+      end)
+    end
+  end
+
+  defp enrich_job_editor_metric(metric, job) do
+    %{id: job_id, workflow_id: workflow_id} = job
+
+    metric
+    |> common_enrichment()
+    |> Map.merge(%{
+      "workflow_id" => workflow_id,
+      "job_id" => job_id
+    })
+  end
+
+  defp create_job_editor_log_line(metric) do
+    %{
+      "event" => event,
+      "workflow_id" => workflow_id,
+      "job_id" => job_id,
+      "start_time" => start_time,
+      "end_time" => end_time,
+      "duration" => duration
+    } = metric
+
+    "UiMetrics: [JobEditor] " <>
+      "event=`#{event}` " <>
+      "workflow_id=#{workflow_id} " <>
+      "job_id=#{job_id} " <>
+      "start_time=#{start_time} " <>
+      "end_time=#{end_time} " <>
+      "duration=#{duration} ms"
+  end
+
+  def log_workflow_editor_metrics(workflow, metrics) do
+    if Lightning.Config.ui_metrics_tracking_enabled?() do
+      Enum.each(metrics, fn metric ->
+        metric
+        |> enrich_workflow_editor_metric(workflow)
+        |> create_workflow_editor_log_line()
+        |> Logger.info()
+      end)
+    end
+  end
+
+  defp enrich_workflow_editor_metric(metric, %{id: workflow_id}) do
+    metric |> common_enrichment() |> Map.put("workflow_id", workflow_id)
+  end
+
+  defp create_workflow_editor_log_line(metric) do
+    %{
+      "event" => event,
+      "workflow_id" => workflow_id,
+      "start_time" => start_time,
+      "end_time" => end_time,
+      "duration" => duration
+    } = metric
+
+    "UiMetrics: [WorkflowEditor] " <>
+      "event=`#{event}` " <>
+      "workflow_id=#{workflow_id} " <>
+      "start_time=#{start_time} " <>
+      "end_time=#{end_time} " <>
+      "duration=#{duration} ms"
+  end
+
+  defp common_enrichment(%{"start" => start_ts, "end" => end_ts} = metric) do
+    metric
+    |> Map.merge(%{
+      "start_time" => convert_ts(start_ts),
+      "end_time" => convert_ts(end_ts),
+      "duration" => end_ts - start_ts
+    })
+  end
+
+  defp convert_ts(ts) do
+    ts |> DateTime.from_unix!(:millisecond) |> DateTime.to_iso8601()
+  end
+end
diff --git a/test/lightning/config_test.exs b/test/lightning/config_test.exs
@@ -33,6 +33,15 @@ defmodule Lightning.Configtest do
 
       assert expected == actual
     end
+
+    test "indicates if the tracking of UI metrics is enabled" do
+      expected =
+        extract_from_config(:ui_metrics_tracking, :enabled)
+
+      actual = API.ui_metrics_tracking_enabled?()
+
+      assert expected == actual
+    end
   end
 
   defp extract_from_config(config, key) do