From 6439637863eed15ec93531f55dcaa58dfd82c598 Mon Sep 17 00:00:00 2001 From: Rory McKinley Date: Tue, 28 Jan 2025 09:42:48 +0200 Subject: [PATCH] 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 --- .env.example | 4 + CHANGELOG.md | 2 + DEPLOYMENT.md | 1 + assets/js/job-editor/mount.tsx | 80 ++++--- assets/js/workflow-editor/index.ts | 18 +- lib/lightning/config.ex | 14 ++ lib/lightning/config/bootstrap.ex | 3 + lib/lightning_web/live/workflow_live/edit.ex | 11 + .../live/workflow_live/editor_pane.ex | 8 + lib/lightning_web/ui_metrics.ex | 93 ++++++++ test/lightning/config_test.exs | 9 + .../live/workflow_live/edit_test.exs | 51 +++++ .../live/workflow_live/editor_test.exs | 56 ++++- test/lightning_web/ui_metrics_test.exs | 201 ++++++++++++++++++ 14 files changed, 516 insertions(+), 35 deletions(-) create mode 100644 lib/lightning_web/ui_metrics.ex create mode 100644 test/lightning_web/ui_metrics_test.exs diff --git a/.env.example b/.env.example index 777160890d..a21391402d 100644 --- 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 index e6b07a6271..09b817c373 100644 --- 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 index f4e3fe366b..31b01cc2bb 100644 --- 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 index a619602b95..a3a8407577 100644 --- 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(jobId); - - if (!job) { - console.error('Job not found', jobId); - return; - } + pRetry( + async attempt => { + console.debug('JobEditor', { attempt }); - if (JobEditorComponent) { - this.componentRoot?.render( - this.handleContentChange(src)} - /> - ); - } - }); + const workflowStore = await this.findWorkflowEditorStore(); + const job = workflowStore.getState().getById(jobId); + if (!job) { + throw new Error('Job not found in store yet'); + } + if (JobEditorComponent) { + this.componentRoot?.render( + 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 index 1341f0c127..e51eb0d087 100644 --- 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 index e551806147..e3fe429270 100644 --- 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 index 029a9e8baa..a9e7074408 100644 --- 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 index a0dfff1daf..ddd2ecc63f 100644 --- 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 index 244acad73f..380e3b7eb6 100644 --- 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 new file mode 100644 index 0000000000..1c023130b2 --- /dev/null +++ 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 index c4bd252e2c..531d5f7c9a 100644 --- 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 diff --git a/test/lightning_web/live/workflow_live/edit_test.exs b/test/lightning_web/live/workflow_live/edit_test.exs index 40d091e3aa..3607a9abd3 100644 --- a/test/lightning_web/live/workflow_live/edit_test.exs +++ b/test/lightning_web/live/workflow_live/edit_test.exs @@ -3,6 +3,7 @@ defmodule LightningWeb.WorkflowLive.EditTest do import Ecto.Query import Eventually + import ExUnit.CaptureLog import Lightning.Factories import Lightning.JobsFixtures import Lightning.WorkflowLive.Helpers @@ -1853,6 +1854,56 @@ defmodule LightningWeb.WorkflowLive.EditTest do end end + describe "Tracking Workflow editor metrics" do + setup :create_workflow + + setup context do + Mox.stub(Lightning.MockConfig, :ui_metrics_tracking_enabled?, fn -> + true + end) + + current_log_level = Logger.level() + Logger.configure(level: :info) + + on_exit(fn -> + Logger.configure(level: current_log_level) + end) + + context + |> Map.merge(%{ + metrics: [ + %{ + "event" => "foo-bar-event", + "start" => 1_737_635_739_914, + "end" => 1_737_635_808_890 + } + ] + }) + end + + test "logs the metrics", %{ + conn: conn, + metrics: metrics, + project: project, + workflow: %{id: workflow_id} = workflow + } do + assert [] = Presence.list_presences_for(workflow) + refute Presence.has_any_presence?(workflow) + + {:ok, view, _html} = + live(conn, ~p"/projects/#{project.id}/w/#{workflow.id}") + + fun = fn -> + view + |> editor_element() + |> render_hook("workflow_editor_metrics_report", %{"metrics" => metrics}) + end + + assert capture_log(fun) =~ ~r/foo-bar-event/ + assert capture_log(fun) =~ ~r/#{workflow_id}/ + end + end + describe "Save and Sync to Github" do setup :verify_on_exit! setup :create_workflow diff --git a/test/lightning_web/live/workflow_live/editor_test.exs b/test/lightning_web/live/workflow_live/editor_test.exs index ce89d75a11..79e5875bac 100644 --- a/test/lightning_web/live/workflow_live/editor_test.exs +++ b/test/lightning_web/live/workflow_live/editor_test.exs @@ -1,6 +1,7 @@ defmodule LightningWeb.WorkflowLive.EditorTest do use LightningWeb.ConnCase, async: true + import ExUnit.CaptureLog import Phoenix.LiveViewTest import Lightning.WorkflowLive.Helpers import Lightning.Factories @@ -1749,8 +1750,61 @@ defmodule LightningWeb.WorkflowLive.EditorTest do end end + describe "UI metrics events" do + setup context do + Mox.stub(Lightning.MockConfig, :ui_metrics_tracking_enabled?, fn -> + true + end) + + current_log_level = Logger.level() + Logger.configure(level: :info) + + on_exit(fn -> + Logger.configure(level: current_log_level) + end) + + context + |> Map.merge(%{ + metrics: [ + %{ + "event" => "foo-bar-job-event", + "start" => 1_737_635_739_914, + "end" => 1_737_635_808_890 + } + ] + }) + end + + test "writes the UI metrics to the logs", %{ + conn: conn, + metrics: metrics, + project: project, + workflow: workflow + } do + %{id: job_id} = job = workflow.jobs |> hd() + + {:ok, view, _html} = + live( + conn, + ~p"/projects/#{project}/w/#{workflow}?#{[s: job, m: "expand", v: workflow.lock_version]}" + ) + + fun = fn -> + view + |> with_target("#job-editor-pane-#{job.id}") + |> render_hook( + "job_editor_metrics_report", + %{"metrics" => metrics} + ) + end + + assert capture_log(fun) =~ ~r/foo-bar-job-event/ + assert capture_log(fun) =~ ~r/#{job_id}/ + end + end + describe "Output & Logs" do - test "all users can view output and logs for a follwed run", %{ + test "all users can view output and logs for a followed run", %{ conn: conn, project: project, workflow: %{jobs: [job_1 | _rest]} = workflow, diff --git a/test/lightning_web/ui_metrics_test.exs b/test/lightning_web/ui_metrics_test.exs new file mode 100644 index 0000000000..25055fa316 --- /dev/null +++ b/test/lightning_web/ui_metrics_test.exs @@ -0,0 +1,201 @@ +defmodule LightningWeb.UiMetricsTest do + use Lightning.DataCase, async: false + + alias LightningWeb.UiMetrics + + import ExUnit.CaptureLog + + setup do + current_log_level = Logger.level() + Logger.configure(level: :info) + + on_exit(fn -> + Logger.configure(level: current_log_level) + end) + end + + describe "log_job_editor_metrics/2" do + setup do + metrics = [ + %{ + "event" => "mount to 1st render", + "start" => 1_737_635_739_914, + "end" => 1_737_635_808_890 + }, + %{ + "event" => "render before fetching metadata", + "start" => 1_737_637_606_066, + "end" => 1_737_637_623_051 + } + ] + + job = insert(:job) + + %{job: job, metrics: metrics} + end + + test "logs the job editor metrics provided", %{ + job: job, + metrics: metrics + } do + Mox.stub(Lightning.MockConfig, :ui_metrics_tracking_enabled?, fn -> + true + end) + + expected_entry_1 = + job_editor_log_regex( + job: job, + event: "mount to 1st render", + start: 1_737_635_739_914, + end: 1_737_635_808_890 + ) + + expected_entry_2 = + job_editor_log_regex( + job: job, + event: "render before fetching metadata", + start: 1_737_637_606_066, + end: 1_737_637_623_051 + ) + + fun = fn -> UiMetrics.log_job_editor_metrics(job, metrics) end + + assert capture_log(fun) =~ expected_entry_1 + assert capture_log(fun) =~ expected_entry_2 + end + + test "does not write metrics to the log if logging is disabled", %{ + job: job, + metrics: metrics + } do + Mox.stub(Lightning.MockConfig, :ui_metrics_tracking_enabled?, fn -> + false + end) + + fun = fn -> UiMetrics.log_job_editor_metrics(job, metrics) end + + refute capture_log(fun) =~ ~r/UiMetrics/ + end + + def job_editor_log_regex(opts \\ []) do + %{id: job_id, workflow_id: workflow_id} = Keyword.fetch!(opts, :job) + + event = Keyword.fetch!(opts, :event) + + start_time = + opts + |> Keyword.fetch!(:start) + |> DateTime.from_unix!(:millisecond) + + end_time = + opts + |> Keyword.fetch!(:end) + |> DateTime.from_unix!(:millisecond) + + duration = DateTime.diff(end_time, start_time, :millisecond) + + log_line = + "UiMetrics: \\[JobEditor\\] " <> + "event=`#{event}` " <> + "workflow_id=#{workflow_id} " <> + "job_id=#{job_id} " <> + "start_time=#{DateTime.to_iso8601(start_time)} " <> + "end_time=#{DateTime.to_iso8601(end_time)} " <> + "duration=#{duration} ms" + + ~r/#{log_line}/ + end + end + + describe "log_workflow_editor_metrics/2" do + setup do + metrics = [ + %{ + "event" => "workflow-params load", + "start" => 1_737_635_739_914, + "end" => 1_737_635_808_890 + }, + %{ + "event" => "something else important", + "start" => 1_737_637_606_066, + "end" => 1_737_637_623_051 + } + ] + + workflow = insert(:workflow) + + %{metrics: metrics, workflow: workflow} + end + + test "logs the workflow metrics provided", %{ + metrics: metrics, + workflow: workflow + } do + Mox.stub(Lightning.MockConfig, :ui_metrics_tracking_enabled?, fn -> + true + end) + + expected_entry_1 = + workflow_editor_log_regex( + workflow: workflow, + event: "workflow-params load", + start: 1_737_635_739_914, + end: 1_737_635_808_890 + ) + + expected_entry_2 = + workflow_editor_log_regex( + workflow: workflow, + event: "something else important", + start: 1_737_637_606_066, + end: 1_737_637_623_051 + ) + + fun = fn -> UiMetrics.log_workflow_editor_metrics(workflow, metrics) end + + assert capture_log(fun) =~ expected_entry_1 + assert capture_log(fun) =~ expected_entry_2 + end + + test "does not write metrics to the log if logging is disabled", %{ + metrics: metrics, + workflow: workflow + } do + Mox.stub(Lightning.MockConfig, :ui_metrics_tracking_enabled?, fn -> + false + end) + + fun = fn -> UiMetrics.log_workflow_editor_metrics(workflow, metrics) end + + refute capture_log(fun) =~ ~r/UiMetrics/ + end + + def workflow_editor_log_regex(opts \\ []) do + %{id: workflow_id} = Keyword.fetch!(opts, :workflow) + + event = Keyword.fetch!(opts, :event) + + start_time = + opts + |> Keyword.fetch!(:start) + |> DateTime.from_unix!(:millisecond) + + end_time = + opts + |> Keyword.fetch!(:end) + |> DateTime.from_unix!(:millisecond) + + duration = DateTime.diff(end_time, start_time, :millisecond) + + log_line = + "UiMetrics: \\[WorkflowEditor\\] " <> + "event=`#{event}` " <> + "workflow_id=#{workflow_id} " <> + "start_time=#{DateTime.to_iso8601(start_time)} " <> + "end_time=#{DateTime.to_iso8601(end_time)} " <> + "duration=#{duration} ms" + + ~r/#{log_line}/ + end + end +end