diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index eb5f178..ec22100 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -106,6 +106,22 @@ jobs: if: needs.changes.outputs.dashboard == 'true' || needs.changes.outputs.ci == 'true' || github.event_name == 'push' runs-on: ubuntu-latest + # Page tests (DurableDashboard.LiveCase) mount the LiveViews against a + # real Durable instance. + services: + postgres: + image: postgres:18-alpine + env: + POSTGRES_USER: postgres + POSTGRES_PASSWORD: postgres + ports: + - 54321:5432 + options: >- + --health-cmd="pg_isready -U postgres" + --health-interval=10s + --health-timeout=5s + --health-retries=5 + defaults: run: working-directory: durable_dashboard diff --git a/.gitignore b/.gitignore index 541fade..664af51 100644 --- a/.gitignore +++ b/.gitignore @@ -11,3 +11,6 @@ erl_crash.dump /doc/ /_build/ /deps/ + +# macOS Finder metadata +.DS_Store diff --git a/docker-compose.yml b/docker-compose.yml index cd03832..e97b61f 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -7,7 +7,10 @@ services: ports: - "54321:5432" volumes: - - postgres_data:/var/lib/postgresql/data + # Postgres 18+ images keep data under /var/lib/postgresql//, so the + # volume mounts one level up. A new volume name keeps older-major data + # (the old `postgres_data`) from blocking startup. + - postgres18_data:/var/lib/postgresql healthcheck: test: ["CMD-SHELL", "pg_isready -U postgres"] interval: 5s @@ -15,4 +18,4 @@ services: retries: 5 volumes: - postgres_data: + postgres18_data: diff --git a/durable/README.md b/durable/README.md index 3cb9fcc..41d49a4 100644 --- a/durable/README.md +++ b/durable/README.md @@ -483,6 +483,37 @@ parallel do end ``` +### Workflow Options + +```elixir +workflow "process_order", timeout: hours(2), queue: :orders do +``` + +- `:timeout` — how long a run may take from when it's due to start, waits and + sleeps included. A run past it fails with a `"timeout"` error before its next + step and runs its compensations; a waiting run is woken to do so (within the + timeout worker's one-minute sweep). It can't interrupt a step that's running. +- `:queue` — the queue runs start on unless `Durable.start/3` names one. + +Unknown options fail the compile. + +### Errors + +When a step fails, its execution keeps what went wrong as `error`: + +- **Raised** (`raise`, a crash in a library) — `type` (the exception + module), `message`, and `stacktrace`: one frame per line with the app, + file and line, e.g. `(my_app 0.1.0) lib/my_app/orders.ex:28: ...`. +- **Exited** (a `GenServer.call` timeout, a linked process going down) — + `type: "exit"`, a readable `message` (`Exception.format_exit/1`) and the + `stacktrace`. Throws are kept the same way. +- **Returned** — `{:error, reason}` from the step: `reason` itself (a map is + stored as-is), with no stack, because nothing was raised. + +The same applies to compensations and to a branch's `on:` function. A +failed run's `error` is its failing step's. The stack is as deep as the +VM's `:backtrace_depth` (8 frames by default; Phoenix dev raises it to 20). + ### API ```elixir @@ -494,8 +525,23 @@ Durable.cancel(id, "reason") Durable.send_event(id, "event", payload) Durable.provide_input(id, "input_name", data) Durable.list_children(parent_id) + +# Operating +Durable.retry(id) # failed run: resume from the failed step +Durable.rerun(id, input: new_input) # finished run: start a fresh copy +Durable.pause_queue(:default, by: user) # on every node, until resume_queue/2 +Durable.list_nodes() # heartbeating instances and what they run +Durable.prune() # apply the :prune retention now + +# Observing +Durable.Stats.overview(since: dt) # also timeline/1, workflows/1, step_performance/1, + # queues/1, queue_history/1, error_groups/1 +Durable.Activity.list() # recovered runs, fenced workers, queue pauses… ``` +Telemetry events and `Telemetry.Metrics` definitions are documented in +`Durable.Telemetry`. + ## Mix Tasks Durable includes mix tasks for managing workflows from the command line. diff --git a/durable/lib/durable.ex b/durable/lib/durable.ex index 9f2b6c5..0e00fd1 100644 --- a/durable/lib/durable.ex +++ b/durable/lib/durable.ex @@ -94,6 +94,8 @@ defmodule Durable do """ + alias Durable.Config + alias Durable.Queue.Control, as: QueueControl alias Durable.Scheduler.API, as: SchedulerAPI defmacro __using__(_opts) do @@ -245,7 +247,15 @@ defmodule Durable do end @doc """ - Cancels a running or pending workflow. + Cancels a pending, running or waiting workflow, and its child workflows. + + The cancel is final: once it returns `:ok` the run stays `:cancelled`. A + running workflow stops at its next step boundary: the step already in + flight finishes and is recorded, but its output isn't merged into the run's + context and no later step runs. Cancelling does not run compensations. + + Returns `{:error, :already_completed}` if the run has already finished, and + `{:error, :not_found}` for an unknown id. ## Examples @@ -258,6 +268,104 @@ defmodule Durable do Durable.Executor.cancel_workflow(workflow_id, reason) end + @doc """ + Resumes a failed workflow at the step that failed. + + Steps that already completed are not re-run, and the failed step gets its + full retry budget again. Inside a parallel block only the children that + failed are re-queued. + + Returns `{:error, :rolled_back}` for runs whose compensations ran — use + `rerun/2` for those — and `{:error, :not_failed}` for runs that aren't failed. + + ## Options + + - `:durable` - The Durable instance name (default: Durable) + + ## Examples + + {:ok, ^workflow_id} = Durable.retry(workflow_id) + + """ + @spec retry(String.t(), keyword()) :: {:ok, String.t()} | {:error, term()} + def retry(workflow_id, opts \\ []) do + Durable.Executor.retry_workflow(workflow_id, opts) + end + + @doc """ + Starts a fresh run of a finished workflow, with its original input or a new + one. The new run's `trigger` is `:rerun` and its `trigger_ref` is the + original run's id. + + ## Options + + - `:input` - Input for the new run (default: the original run's input) + - `:durable` - The Durable instance name (default: Durable) + + ## Examples + + {:ok, new_id} = Durable.rerun(workflow_id) + {:ok, new_id} = Durable.rerun(workflow_id, input: %{"order_id" => "ORD-1043"}) + + """ + @spec rerun(String.t(), keyword()) :: {:ok, String.t()} | {:error, term()} + def rerun(workflow_id, opts \\ []) do + Durable.Executor.rerun_workflow(workflow_id, opts) + end + + @doc """ + Pauses a queue on every node. Runs already executing finish; no node claims + new work from the queue until `resume_queue/2`. The pause survives restarts. + + Recorded in `Durable.Activity` as `"queue_paused"`. + + ## Options + + - `:durable` - The Durable instance name (default: Durable) + - `:by` - who paused it, kept with the activity record + """ + @spec pause_queue(atom() | String.t(), keyword()) :: :ok | {:error, term()} + def pause_queue(queue, opts \\ []) do + QueueControl.pause(Config.get(Keyword.get(opts, :durable, Durable)), queue, opts) + end + + @doc """ + Resumes a queue paused with `pause_queue/2`, on every node. + """ + @spec resume_queue(atom() | String.t(), keyword()) :: :ok | {:error, term()} + def resume_queue(queue, opts \\ []) do + QueueControl.resume(Config.get(Keyword.get(opts, :durable, Durable)), queue, opts) + end + + @doc """ + Returns the names of queues currently paused with `pause_queue/2`. + """ + @spec paused_queues(keyword()) :: [String.t()] + def paused_queues(opts \\ []) do + QueueControl.paused(Config.get(Keyword.get(opts, :durable, Durable))) + end + + @doc """ + Lists the Durable nodes that have heartbeated recently, newest first. Each + has `:id`, `:queues`, `:version`, `:started_at`, `:heartbeat_at`, a + `:status` of `:alive` or `:missing` (no heartbeat for 30 s), and `:running`, + the number of runs it is executing. + """ + @spec list_nodes(keyword()) :: [map()] + def list_nodes(opts \\ []) do + Durable.NodeRegistry.list(Config.get(Keyword.get(opts, :durable, Durable))) + end + + @doc """ + Deletes finished runs past the `:prune` retention now, instead of waiting + for the hourly sweep. Returns the number deleted per group, or `%{}` when + `:prune` isn't configured. + """ + @spec prune(keyword()) :: %{atom() => non_neg_integer()} + def prune(opts \\ []) do + Durable.Pruner.prune(Config.get(Keyword.get(opts, :durable, Durable))) + end + @doc """ Provides input for a waiting workflow (human-in-the-loop). diff --git a/durable/lib/durable/activity.ex b/durable/lib/durable/activity.ex new file mode 100644 index 0000000..143cd68 --- /dev/null +++ b/durable/lib/durable/activity.ex @@ -0,0 +1,76 @@ +defmodule Durable.Activity do + @moduledoc """ + Operational events worth an operator's attention, kept for a week in + `durable.activity` — the record behind "what happened to my queues?". + + | kind | recorded when | + | --------------------- | -------------------------------------------------------------- | + | `"stale_recovered"` | runs whose node stopped heartbeating went back on the queue | + | `"zombie_recovered"` | runs left `running` with no live worker were failed | + | `"worker_fenced"` | a worker found its run reclaimed by another node and stopped | + | `"ack_failed"` | a worker couldn't release a finished run's lock | + | `"queue_paused"` | `Durable.pause_queue/2` (`details.by` when given) | + | `"queue_resumed"` | `Durable.resume_queue/2` | + | `"schedule_disabled"` | a schedule was turned off after failing repeatedly | + | `"pruned"` | the retention pruner deleted finished runs | + + Each row has `:at`, `:kind`, the `:node_id` that recorded it, and where it + applies `:queue`, `:workflow_id`, a `:count` and `:details`. + + Recording never raises: losing an activity row must not break the recovery + or the action it describes. + """ + + import Ecto.Query + + require Logger + + alias Durable.Config + alias Durable.Repo + alias Durable.Storage.Schemas.ActivityEvent + + @doc false + @spec record(Config.t(), String.t(), keyword()) :: :ok + def record(%Config{} = config, kind, attrs \\ []) do + event = %ActivityEvent{ + at: DateTime.utc_now(), + kind: kind, + node_id: config.node_id, + queue: attrs[:queue] && to_string(attrs[:queue]), + workflow_id: attrs[:workflow_id], + count: Keyword.get(attrs, :count, 1), + details: attrs |> Keyword.get(:details, %{}) |> Durable.Executor.sanitize_for_json() + } + + Repo.insert(event, config) + :ok + rescue + e -> + Logger.debug("[Durable] activity #{kind} not recorded: #{Exception.message(e)}") + :ok + end + + @doc """ + Recent activity, newest first. + + ## Options + + - `:since` - only events at or after this time (default: 24 hours ago) + - `:limit` - at most this many (default: 100) + - `:durable` - the Durable instance (default: `Durable`) + """ + @spec list(keyword()) :: [ActivityEvent.t()] + def list(opts \\ []) do + config = Config.get(Keyword.get(opts, :durable, Durable)) + since = Keyword.get(opts, :since, DateTime.add(DateTime.utc_now(), -86_400, :second)) + + Repo.all( + config, + from(a in ActivityEvent, + where: a.at >= ^since, + order_by: [desc: a.at], + limit: ^Keyword.get(opts, :limit, 100) + ) + ) + end +end diff --git a/durable/lib/durable/config.ex b/durable/lib/durable/config.ex index 0209988..69f28b8 100644 --- a/durable/lib/durable/config.ex +++ b/durable/lib/durable/config.ex @@ -49,6 +49,8 @@ defmodule Durable.Config do sleep_waker_batch_size: pos_integer(), log_level: false | :debug | :info | :warning | :error, pubsub: atom() | nil, + prune: keyword() | nil, + node_id: String.t() | nil, owns_pubsub?: boolean() } @@ -66,6 +68,8 @@ defmodule Durable.Config do :sleep_waker_batch_size, :log_level, :pubsub, + :prune, + :node_id, owns_pubsub?: false ] @@ -140,9 +144,39 @@ defmodule Durable.Config do "Pass an atom like `MyApp.PubSub` to reuse a PubSub started by the host app. " <> "Pass `:start` to have Durable start its own (named after the instance). " <> "Leave as `nil` to disable broadcasting (default)." + ], + prune: [ + type: + {:or, + [ + nil, + {:keyword_list, + [ + completed: [type: :pos_integer, doc: "Keep completed runs this many ms."], + failed: [type: :pos_integer, doc: "Keep failed and rolled-back runs this many ms."], + cancelled: [type: :pos_integer, doc: "Keep cancelled runs this many ms."] + ]} + ]}, + default: nil, + doc: + "Delete finished runs (with their steps, inputs and events) once they are older " <> + "than the given age in ms, e.g. `[completed: :timer.hours(24 * 14)]`. " <> + "Statuses left out are kept forever. Off by default." ] ] + # One id per running instance: the Erlang node name when distributed, else + # the hostname plus a per-boot suffix. Pollers stamp it into `locked_by`, + # and the node registry keys its heartbeat row on it. + defp node_id do + if node() == :nonode@nohost do + {:ok, host} = :inet.gethostname() + "#{host}-#{System.unique_integer([:positive])}" + else + Atom.to_string(node()) + end + end + @doc """ Creates a new validated configuration from options. @@ -160,7 +194,7 @@ defmodule Durable.Config do case NimbleOptions.validate(opts, @schema) do {:ok, validated} -> validated = resolve_pubsub(validated) - {:ok, struct(__MODULE__, validated)} + {:ok, %{struct(__MODULE__, validated) | node_id: node_id()}} {:error, %NimbleOptions.ValidationError{}} = error -> error diff --git a/durable/lib/durable/definition.ex b/durable/lib/durable/definition.ex index c06be33..186f5ef 100644 --- a/durable/lib/durable/definition.ex +++ b/durable/lib/durable/definition.ex @@ -116,8 +116,7 @@ defmodule Durable.Definition do compensations: %{atom() => Compensation.t()}, opts: %{ optional(:timeout) => pos_integer(), - optional(:max_retries) => pos_integer(), - optional(:queue) => atom() + optional(:queue) => atom() | String.t() } } diff --git a/durable/lib/durable/dsl/step.ex b/durable/lib/durable/dsl/step.ex index 75acb4d..ed2fd91 100644 --- a/durable/lib/durable/dsl/step.ex +++ b/durable/lib/durable/dsl/step.ex @@ -266,7 +266,14 @@ defmodule Durable.DSL.Step do condition_fn = Keyword.fetch!(opts, :on) clauses = extract_clauses(block) - branch_id = :erlang.unique_integer([:positive]) + {shape, _} = process_branch_clauses(clauses, 0) + + branch_id = + block_id( + __CALLER__, + :branch, + for({pattern, _, names, _} <- shape, do: {pattern_to_key(pattern), names}) + ) {clause_data, all_step_defs} = process_branch_clauses(clauses, branch_id) @@ -320,6 +327,24 @@ defmodule Durable.DSL.Step do end end + # A block's id prefixes the names of the steps inside it, and those names are + # stored on runs — a run suspended inside a branch resumes by name. So the id + # must survive recompiles and deploys: it's derived from the block's shape + # (clause patterns and step names), never its code, and bumped past ids an + # identical block earlier in the same module already took. + defp block_id(caller, kind, shape) do + taken = Module.get_attribute(caller.module, :__durable_block_ids__) || MapSet.new() + + id = + {kind, shape} + |> :erlang.phash2() + |> Stream.iterate(&(&1 + 1)) + |> Enum.find(&(not MapSet.member?(taken, &1))) + + Module.put_attribute(caller.module, :__durable_block_ids__, MapSet.put(taken, id)) + id + end + defp extract_clauses(block) do clauses = case block do @@ -467,7 +492,8 @@ defmodule Durable.DSL.Step do """ defmacro parallel(opts \\ [], do: block) do - parallel_id = :erlang.unique_integer([:positive]) + shape = for {_, _, %{original_name: name}} <- extract_parallel_steps(block, 0), do: name + parallel_id = block_id(__CALLER__, :parallel, shape) step_defs = extract_parallel_steps(block, parallel_id) step_names = Enum.map(step_defs, fn {name, _, _} -> name end) diff --git a/durable/lib/durable/dsl/workflow.ex b/durable/lib/durable/dsl/workflow.ex index c75154b..b067911 100644 --- a/durable/lib/durable/dsl/workflow.ex +++ b/durable/lib/durable/dsl/workflow.ex @@ -20,9 +20,12 @@ defmodule Durable.DSL.Workflow do ## Options - - `:timeout` - Maximum workflow duration in milliseconds - - `:max_retries` - Maximum retry attempts for the entire workflow - - `:queue` - Default queue for this workflow + - `:timeout` - How long a run may take, in milliseconds, from when it is due + to start — waits and sleeps included. A run past it fails with a + `"timeout"` error before its next step, running compensations like any + failure; a waiting run is woken to do so. The deadline is checked between + steps, so it can't interrupt a step that is still running. + - `:queue` - The queue runs start on unless `Durable.start/3` names one """ @@ -32,7 +35,7 @@ defmodule Durable.DSL.Workflow do Defines a workflow with the given name and options. """ defmacro workflow(name, opts \\ [], do: block) do - normalized_opts = normalize_workflow_opts(opts) + validate_workflow_opts!(opts, name) # Generate unique function names for this workflow definition_fn = :"__workflow_def_#{name}__" @@ -81,7 +84,9 @@ defmodule Durable.DSL.Workflow do module: __MODULE__, steps: unquote(steps_fn)(), compensations: unquote(compensations_fn)(), - opts: unquote(Macro.escape(normalized_opts)) + # Evaluated here, in the workflow module, so `timeout: hours(2)` is + # a number rather than the quoted call. + opts: Map.new(unquote(opts)) } end @@ -95,10 +100,19 @@ defmodule Durable.DSL.Workflow do end end - @doc false - def normalize_workflow_opts(opts) do - opts - |> Keyword.take([:timeout, :max_retries, :queue]) - |> Enum.into(%{}) + @workflow_opts [:timeout, :queue] + + defp validate_workflow_opts!(opts, name) when is_list(opts) do + case Keyword.keys(opts) -- @workflow_opts do + [] -> + :ok + + unknown -> + raise ArgumentError, + "unknown option(s) #{inspect(unknown)} for workflow #{inspect(name)}; " <> + "supported: #{inspect(@workflow_opts)}" + end end + + defp validate_workflow_opts!(_opts, _name), do: :ok end diff --git a/durable/lib/durable/executor.ex b/durable/lib/durable/executor.ex index 078b7ba..e9446d1 100644 --- a/durable/lib/durable/executor.ex +++ b/durable/lib/durable/executor.ex @@ -69,30 +69,196 @@ defmodule Durable.Executor do durable_name = Keyword.get(opts, :durable, Durable) config = Config.get(durable_name) - case Repo.get(config, WorkflowExecution, workflow_id) do - nil -> - {:error, :not_found} + error = if reason, do: %{type: "cancelled", message: reason}, else: %{type: "cancelled"} + now = DateTime.utc_now() + + # One conditional UPDATE, so a run that finishes concurrently can't be + # flipped back to :cancelled. Clearing the lock token fences the worker + # still executing it: its ack/nack become no-ops, and the executor's + # status compare-and-set stops it at the next step boundary. + cancellable = + from(w in WorkflowExecution, + where: w.id == ^workflow_id and w.status in [:pending, :running, :waiting], + select: w + ) - execution when execution.status in [:pending, :running, :waiting] -> - error = if reason, do: %{type: "cancelled", message: reason}, else: %{type: "cancelled"} + case Repo.update_all(config, cancellable, + set: [ + status: :cancelled, + error: error, + completed_at: now, + updated_at: now, + locked_by: nil, + locked_at: nil, + lock_token: nil + ] + ) do + {1, [cancelled]} -> + DurablePubSub.broadcast_workflow(config, :workflow_cancelled, workflow_event(cancelled)) + cancel_child_workflows(config, workflow_id) + :ok - {:ok, cancelled} = - execution - |> WorkflowExecution.status_changeset(:cancelled, %{ - error: error, - completed_at: DateTime.utc_now() - }) - |> Repo.update(config) + {0, _} -> + if Repo.get(config, WorkflowExecution, workflow_id), + do: {:error, :already_completed}, + else: {:error, :not_found} + end + end - DurablePubSub.broadcast_workflow(config, :workflow_cancelled, workflow_event(cancelled)) + @doc """ + Resumes a failed workflow at the step that failed. - # Cascade cancel to child workflows - cancel_child_workflows(config, workflow_id) + Completed steps are not re-run: the run continues from its saved context, + and the failed step gets its full retry budget again. A failure inside a + parallel block re-queues only the children that failed; the ones that + completed keep their results. - :ok + Runs that were rolled back by compensation can't be resumed — their + earlier effects were undone — so use `rerun_workflow/2` for those. + """ + @spec retry_workflow(String.t(), keyword()) :: {:ok, String.t()} | {:error, term()} + def retry_workflow(workflow_id, opts \\ []) do + config = Config.get(Keyword.get(opts, :durable, Durable)) + + with {:ok, execution} <- load_execution(config, workflow_id), + :ok <- ensure_retryable(execution.status), + {:ok, retried} <- reset_for_retry(config, execution) do + DurablePubSub.broadcast_workflow(config, :workflow_retried, workflow_event(retried)) + {:ok, workflow_id} + end + end + + defp ensure_retryable(:failed), do: :ok + + defp ensure_retryable(status) when status in [:compensated, :compensation_failed], + do: {:error, :rolled_back} + + defp ensure_retryable(_status), do: {:error, :not_failed} + + defp reset_for_retry(config, execution) do + retry_attrs = [ + error: nil, + completed_at: nil, + retried_at: DateTime.utc_now(), + scheduled_at: nil, + locked_by: nil, + locked_at: nil, + lock_token: nil, + deadline_at: retried_deadline(execution) + ] + + if parallel_children(execution.context) do + retry_parallel_block(config, execution, retry_attrs) + else + execution + |> Ecto.Changeset.change([status: :pending] ++ retry_attrs) + |> cas_update(config) + |> not_failed_if_superseded() + end + end + + # A retried run gets its full workflow timeout again, from now. + defp retried_deadline(execution) do + case get_workflow_definition_from_execution(execution) do + {:ok, workflow_def} -> deadline(workflow_def, nil) + _ -> execution.deadline_at + end + end + + defp parallel_children(context), + do: Map.get(context, "__parallel_children") || Map.get(context, :__parallel_children) + + # A run that failed inside a parallel block is waiting on a WaitGroup of + # child runs. Re-queue only the children that failed, re-open their + # completion events and the group, and park the parent in :waiting again — + # the last child to finish wakes it, exactly as on the first pass. + defp retry_parallel_block(config, parent, retry_attrs) do + Repo.transaction(config, fn -> reopen_parallel_block(config, parent, retry_attrs) end) + end + + defp reopen_parallel_block(config, parent, retry_attrs) do + child_ids = Map.keys(parallel_children(parent.context)) - _execution -> - {:error, :already_completed} + group_id = + Map.get(parent.context, "__parallel_wait_group_id") || + Map.get(parent.context, :__parallel_wait_group_id) + + now = DateTime.utc_now() + + children = + Repo.all( + config, + from(c in WorkflowExecution, + where: c.id in ^child_ids and c.status != :completed, + select: {c.id, c.status} + ) + ) + + if Enum.any?(children, fn {_, s} -> s in [:compensated, :compensation_failed] end), + do: config.repo.rollback(:rolled_back) + + failed_ids = for {id, s} <- children, s in [:failed, :cancelled], do: id + events = Enum.map(failed_ids, &"__parallel_done:#{&1}") + + Repo.update_all(config, from(c in WorkflowExecution, where: c.id in ^failed_ids), + set: [status: :pending, updated_at: now] ++ retry_attrs + ) + + Repo.update_all( + config, + from(e in PendingEvent, where: e.wait_group_id == ^group_id and e.event_name in ^events), + set: [status: :pending, payload: nil, completed_at: nil, updated_at: now] + ) + + group = Repo.get(config, WaitGroup, group_id) + + {:ok, _} = + group + |> Ecto.Changeset.change( + status: :pending, + completed_at: nil, + received_events: Map.drop(group.received_events, events) + ) + |> Repo.update(config) + + parent + |> Ecto.Changeset.change([status: :waiting] ++ retry_attrs) + |> cas_update(config) + |> not_failed_if_superseded() + |> case do + {:ok, retried} -> retried + {:error, reason} -> config.repo.rollback(reason) + end + end + + defp not_failed_if_superseded({:error, :superseded}), do: {:error, :not_failed} + defp not_failed_if_superseded(result), do: result + + @doc """ + Starts a fresh run of the same workflow, with the original input unless + `:input` is given. The new run records which run it re-runs. + + Only finished runs (completed, failed, cancelled or rolled back) can be + re-run, so an operator can't accidentally double up live work. + """ + @spec rerun_workflow(String.t(), keyword()) :: {:ok, String.t()} | {:error, term()} + def rerun_workflow(workflow_id, opts \\ []) do + durable = Keyword.get(opts, :durable, Durable) + config = Config.get(durable) + + with {:ok, execution} <- load_execution(config, workflow_id), + true <- execution.status not in [:pending, :running, :waiting] || {:error, :not_finished}, + {:ok, _definition} <- get_workflow_definition_from_execution(execution) do + start_workflow( + String.to_existing_atom(execution.workflow_module), + Keyword.get(opts, :input, execution.input), + workflow: execution.workflow_name, + queue: execution.queue, + priority: execution.priority, + durable: durable, + trigger: :rerun, + trigger_ref: execution.id + ) end end @@ -105,37 +271,77 @@ defmodule Durable.Executor do {:ok, map()} | {:waiting, map()} | {:error, term()} def execute_workflow(workflow_id, %Config{} = config) do with {:ok, execution} <- load_execution(config, workflow_id), + true <- execution.status in [:pending, :running] || {:error, :superseded}, {:ok, workflow_def} <- get_workflow_definition_from_execution(execution), + resumed = execution.current_step != nil, {:ok, execution} <- mark_running(config, execution) do # Set workflow ID for logging/observability Context.set_workflow_id(execution.id) - # Check if this is a single-step parallel child execution - parallel_step_flag = - Map.get(execution.context, "__parallel_step") || - Map.get(execution.context, :__parallel_step) + meta = %{ + durable: config.name, + workflow_id: execution.id, + workflow: execution.workflow_name, + workflow_module: execution.workflow_module, + queue: execution.queue, + trigger: execution.trigger, + resumed: resumed + } - if parallel_step_flag do - result = execute_parallel_step(execution, workflow_def, config) - Context.cleanup() - result - else - # Pipeline model: start with workflow input or restored context - initial_data = - if execution.context != %{} do - atomize_keys(execution.context) - else - execution.input - end + Durable.Telemetry.put_run_meta(meta) + + :telemetry.span([:durable, :workflow], meta, fn -> + result = run_until_superseded(execution, workflow_def, config) + {result, Map.put(meta, :status, segment_status(config, execution.id, result))} + end) + end + end - # Execute steps with pipeline data flow - result = execute_steps(workflow_def.steps, execution, config, initial_data) + defp segment_status(_config, _id, {:ok, _}), do: :completed + defp segment_status(_config, _id, {:waiting, _}), do: :waiting + defp segment_status(_config, _id, {:error, :superseded}), do: :superseded - # Cleanup - Context.cleanup() + # A failure may have been compensated; the row has the final word. + defp segment_status(config, id, {:error, _}) do + Repo.one(config, from(w in WorkflowExecution, where: w.id == ^id, select: w.status)) + end - result - end + # A status compare-and-set deep in the step loop throws when another actor + # (cancel, stale-lock recovery) changed the run's status under us. + defp run_until_superseded(execution, workflow_def, config) do + run_execution(execution, workflow_def, config) + catch + :throw, :durable_superseded -> + Context.cleanup() + {:error, :superseded} + end + + defp run_execution(execution, workflow_def, config) do + # Check if this is a single-step parallel child execution + parallel_step_flag = + Map.get(execution.context, "__parallel_step") || + Map.get(execution.context, :__parallel_step) + + if parallel_step_flag do + result = execute_parallel_step(execution, workflow_def, config) + Context.cleanup() + result + else + # Pipeline model: start with workflow input or restored context + initial_data = + if execution.context != %{} do + atomize_keys(execution.context) + else + execution.input + end + + # Execute steps with pipeline data flow + result = execute_steps(workflow_def.steps, execution, config, initial_data) + + # Cleanup + Context.cleanup() + + result end end @@ -164,20 +370,8 @@ defmodule Durable.Executor do safe_additional = sanitize_for_json(additional_context) with {:ok, execution} <- load_execution(config, workflow_id), - true <- execution.status == :waiting || {:error, :not_waiting} do - # Merge additional context - new_context = Map.merge(execution.context || %{}, safe_additional) - - execution - |> Ecto.Changeset.change( - context: new_context, - status: :pending, - scheduled_at: nil, - locked_by: nil, - locked_at: nil - ) - |> Repo.update(config) - + true <- execution.status == :waiting || {:error, :not_waiting}, + {:ok, _} <- mark_resumed(config, execution, safe_additional) do # For inline/synchronous execution (useful for testing) if Keyword.get(opts, :inline, false) do execute_workflow(workflow_id, config) @@ -188,6 +382,24 @@ defmodule Durable.Executor do end end + # Compare-and-set from :waiting, so a cancel that lands between the status + # check above and this write isn't silently undone. + defp mark_resumed(config, execution, additional_context) do + execution + |> Ecto.Changeset.change( + context: Map.merge(execution.context || %{}, additional_context), + status: :pending, + scheduled_at: nil, + locked_by: nil, + locked_at: nil + ) + |> cas_update(config) + |> case do + {:error, :superseded} -> {:error, :not_waiting} + result -> result + end + end + # Private functions defp get_workflow_definition(module, opts) do @@ -212,15 +424,20 @@ defmodule Durable.Executor do end defp create_execution(config, module, %Workflow{} = workflow_def, input, opts) do + scheduled_at = Keyword.get(opts, :scheduled_at) + attrs = %{ workflow_module: Atom.to_string(module), workflow_name: workflow_def.name, status: :pending, - queue: Keyword.get(opts, :queue, "default") |> to_string(), + queue: (opts[:queue] || workflow_def.opts[:queue] || "default") |> to_string(), priority: Keyword.get(opts, :priority, 0), input: input, context: %{}, - scheduled_at: Keyword.get(opts, :scheduled_at) + scheduled_at: scheduled_at, + trigger: Keyword.get(opts, :trigger, :api), + trigger_ref: Keyword.get(opts, :trigger_ref), + deadline_at: deadline(workflow_def, scheduled_at) } %WorkflowExecution{} @@ -235,10 +452,15 @@ defmodule Durable.Executor do end end + # started_at is the first start: a run resumed after a wait keeps it, so + # queue wait (ready → started) and run duration (started → finished) aren't + # measured from the last resume. defp mark_running(config, execution) do + started_at = execution.started_at || DateTime.utc_now() + case execution - |> WorkflowExecution.status_changeset(:running, %{started_at: DateTime.utc_now()}) - |> Repo.update(config) do + |> WorkflowExecution.status_changeset(:running, %{started_at: started_at}) + |> cas_update(config) do {:ok, running} = ok -> DurablePubSub.broadcast_workflow(config, :workflow_resumed, workflow_event(running)) ok @@ -248,6 +470,44 @@ defmodule Durable.Executor do end end + # A run's deadline counts from when it's due to start, so a run scheduled for + # tomorrow doesn't time out before it begins. + defp deadline(%Workflow{opts: %{timeout: ms}}, start) when is_integer(ms) and ms > 0, + do: DateTime.add(start || DateTime.utc_now(), ms, :millisecond) + + defp deadline(_workflow_def, _start), do: nil + + defp past_deadline?(%{deadline_at: %DateTime{} = deadline}), + do: DateTime.compare(DateTime.utc_now(), deadline) != :lt + + defp past_deadline?(_execution), do: false + + # The deadline passed before `step` began. Fail the run the way a failed step + # would — so its compensations run — and stop any child runs it waited on. + defp time_out(execution, step, workflow_def, config) do + cancel_child_workflows(config, execution.id) + {:ok, exec} = update_current_step(config, execution, step.name) + + error = %{ + type: "timeout", + message: + "the run passed its #{format_timeout(workflow_def.opts[:timeout])} timeout " <> + "before #{step.name}" + } + + handle_step_failure(exec, error, workflow_def, config) + end + + defp format_timeout(ms) when is_integer(ms) do + Enum.find_value( + [{86_400_000, "d"}, {3_600_000, "h"}, {60_000, "m"}, {1_000, "s"}], + "#{ms}ms", + fn {size, unit} -> rem(ms, size) == 0 and "#{div(ms, size)}#{unit}" end + ) + end + + defp format_timeout(_ms), do: "workflow" + defp execute_steps(steps, execution, config, initial_data) do # Get workflow definition for compensation lookup {:ok, workflow_def} = get_workflow_definition_from_execution(execution) @@ -304,7 +564,14 @@ defmodule Durable.Executor do config, data ) do - # Handle special step types + if past_deadline?(execution) do + time_out(execution, step, workflow_def, config) + else + dispatch_step(step, remaining_steps, execution, step_index, workflow_def, config, data) + end + end + + defp dispatch_step(step, remaining_steps, execution, step_index, workflow_def, config, data) do case step.type do :branch -> execute_branch(step, remaining_steps, execution, step_index, workflow_def, config, data) @@ -457,11 +724,24 @@ defmodule Durable.Executor do {:ok, execution} = execution |> Ecto.Changeset.change(status: :waiting, scheduled_at: nil) - |> Repo.update(config) + |> cas_update!(config) {:waiting, execution} end + # The branch's `on:` value. The DSL stores the function as `body_fn`; older + # definitions name it in `opts[:condition_fn]`. A raise or exit becomes + # `{:branch_error, error}`, stack and all. + defp branch_condition(%{body_fn: condition_fn} = branch_step, data) do + cond do + is_function(condition_fn, 1) -> condition_fn.(data) + is_function(branch_step.opts[:condition_fn], 1) -> branch_step.opts[:condition_fn].(data) + true -> apply(branch_step.module, branch_step.opts[:condition_fn], [data]) + end + catch + kind, reason -> {:branch_error, caught_error(kind, reason, __STACKTRACE__)} + end + defp execute_branch( branch_step, remaining_steps, @@ -473,34 +753,13 @@ defmodule Durable.Executor do ) do {:ok, exec} = update_current_step(config, execution, branch_step.name) - # Get branch configuration - opts = branch_step.opts - # In the new DSL, the condition function is stored in body_fn - condition_fn = branch_step.body_fn - clauses = opts[:clauses] - all_branch_steps = opts[:all_steps] || [] + clauses = branch_step.opts[:clauses] + all_branch_steps = branch_step.opts[:all_steps] || [] - # Evaluate the condition by calling the function with data - condition_value = - try do - if is_function(condition_fn, 1) do - condition_fn.(data) - else - # Legacy: fall back to opts[:condition_fn] - legacy_fn = opts[:condition_fn] - - if is_function(legacy_fn, 1) do - legacy_fn.(data) - else - apply(branch_step.module, legacy_fn, [data]) - end - end - rescue - e -> - {:error, Exception.message(e)} - end + case branch_condition(branch_step, data) do + {:branch_error, error} -> + handle_step_failure(exec, error, workflow_def, config) - case condition_value do {:error, error} -> handle_step_failure(exec, %{type: "branch_error", message: error}, workflow_def, config) @@ -769,7 +1028,7 @@ defmodule Durable.Executor do status: :waiting, scheduled_at: nil ) - |> Repo.update(config) + |> cas_update!(config) {:waiting, exec} end @@ -791,6 +1050,7 @@ defmodule Durable.Executor do input: data, context: Map.put(parent_context, "__parallel_step", Atom.to_string(step.name)), parent_workflow_id: parent_exec.id, + trigger: :parent, current_step: Atom.to_string(step.name) } @@ -1118,10 +1378,39 @@ defmodule Durable.Executor do } end + # Runs at every step boundary, so it's also where a cancelled run stops. defp update_current_step(config, execution, step_name) do execution |> Ecto.Changeset.change(current_step: Atom.to_string(step_name)) - |> Repo.update(config) + |> cas_update!(config) + end + + # Compare-and-set on status: the write only lands if the row's status is + # still the one this executor read. Operators (cancel) and the queue + # (stale-lock recovery) also write this row; when they got there first the + # run is theirs and we must not overwrite their decision. `force: true` + # makes even a no-change write hit the database, so the check always runs. + defp cas_update(%Ecto.Changeset{} = changeset, config) do + guarded = %{changeset | filters: Map.put(changeset.filters, :status, changeset.data.status)} + + case Repo.update(guarded, config, stale_error_field: :status, force: true) do + {:error, %Ecto.Changeset{errors: errors} = failed} -> + if match?({_, [stale: true]}, errors[:status]), + do: {:error, :superseded}, + else: {:error, failed} + + ok -> + ok + end + end + + # Inside the step loop there is nothing left to do once superseded, so + # unwind straight to run_until_superseded/3. + defp cas_update!(changeset, config) do + case cas_update(changeset, config) do + {:error, :superseded} -> throw(:durable_superseded) + result -> result + end end # Saves data as the workflow context in DB (for persistence/resume) @@ -1153,7 +1442,7 @@ defmodule Durable.Executor do execution |> Ecto.Changeset.change(context: merged) - |> Repo.update(config) + |> cas_update!(config) end # The SleepWaker stamps `__sleep_satisfied__ => ` into context so @@ -1193,7 +1482,7 @@ defmodule Durable.Executor do current_step: nil }) |> Ecto.Changeset.change(locked_by: nil, locked_at: nil, scheduled_at: nil) - |> Repo.update(config) + |> cas_update!(config) DurablePubSub.broadcast_workflow(config, :workflow_completed, workflow_event(execution)) @@ -1218,7 +1507,7 @@ defmodule Durable.Executor do completed_at: DateTime.utc_now() }) |> Ecto.Changeset.change(locked_by: nil, locked_at: nil, scheduled_at: nil) - |> Repo.update(config) + |> cas_update!(config) rescue e -> fallback = %{ @@ -1256,6 +1545,27 @@ defmodule Durable.Executor do end end + @doc false + # What a caught error is stored as: the exception's type and message (an + # exit or a throw made readable) and the stack — app, file and line per + # frame — as text. Frames are as deep as the VM's `:backtrace_depth`. + def caught_error(kind, reason, stacktrace) do + {type, message} = + case kind do + :error -> + exception = Exception.normalize(:error, reason, stacktrace) + {inspect(exception.__struct__), Exception.message(exception)} + + :exit -> + {"exit", Exception.format_exit(reason)} + + :throw -> + {"throw", inspect(reason)} + end + + %{type: type, message: message, stacktrace: Exception.format_stacktrace(stacktrace)} + end + # Recursively convert a term into something Jason can encode. Tuples become # lists, non-Date/DateTime atoms pass through, and anything else exotic # (PIDs, ports, functions, refs) is replaced by its inspect/1 form. @@ -1597,7 +1907,7 @@ defmodule Durable.Executor do {:ok, exec} = execution |> WorkflowExecution.compensating_changeset() - |> Repo.update(config) + |> cas_update!(config) # Run each compensation, collecting results results = @@ -1659,7 +1969,7 @@ defmodule Durable.Executor do locked_by: nil, locked_at: nil ) - |> Repo.update(config) + |> cas_update!(config) {:waiting, execution} end @@ -1686,7 +1996,7 @@ defmodule Durable.Executor do {:ok, execution} = execution |> Ecto.Changeset.change(status: :waiting, scheduled_at: nil) - |> Repo.update(config) + |> cas_update!(config) {:waiting, execution} end @@ -1717,7 +2027,7 @@ defmodule Durable.Executor do {:ok, execution} = execution |> Ecto.Changeset.change(status: :waiting, scheduled_at: nil) - |> Repo.update(config) + |> cas_update!(config) DurablePubSub.broadcast_workflow(config, :workflow_waiting, workflow_event(execution)) DurablePubSub.broadcast_input(config, :input_requested, pending_input_event(pending_input)) @@ -1773,7 +2083,7 @@ defmodule Durable.Executor do {:ok, execution} = execution |> Ecto.Changeset.change(status: :waiting, scheduled_at: nil) - |> Repo.update(config) + |> cas_update!(config) {:waiting, execution} end diff --git a/durable/lib/durable/executor/compensation_runner.ex b/durable/lib/durable/executor/compensation_runner.ex index 6a89204..34c9231 100644 --- a/durable/lib/durable/executor/compensation_runner.ex +++ b/durable/lib/durable/executor/compensation_runner.ex @@ -31,7 +31,21 @@ defmodule Durable.Executor.CompensationRunner do @spec execute(Compensation.t(), String.t(), atom(), Config.t()) :: result() def execute(%Compensation{} = compensation, workflow_id, compensating_step, %Config{} = config) do max_attempts = get_max_attempts(compensation) - execute_with_retry(compensation, workflow_id, compensating_step, 1, max_attempts, config) + + meta = %{ + durable: config.name, + workflow_id: workflow_id, + workflow: Map.get(Durable.Telemetry.run_meta(), :workflow), + compensation: compensation.name, + step: compensating_step + } + + :telemetry.span([:durable, :compensation], meta, fn -> + result = + execute_with_retry(compensation, workflow_id, compensating_step, 1, max_attempts, config) + + {result, Map.put(meta, :result, if(match?({:ok, _}, result), do: :ok, else: :error))} + end) end defp execute_with_retry( @@ -65,17 +79,8 @@ defmodule Durable.Executor.CompensationRunner do try do output = Compensation.execute(compensation, Context.context()) {:ok, output} - rescue - e -> - {:error, - %{ - type: inspect(e.__struct__), - message: Exception.message(e), - stacktrace: Exception.format_stacktrace(__STACKTRACE__) - }} catch - kind, reason -> - {:error, %{type: "#{kind}", message: inspect(reason)}} + kind, reason -> {:error, Durable.Executor.caught_error(kind, reason, __STACKTRACE__)} end end_time = System.monotonic_time(:millisecond) diff --git a/durable/lib/durable/executor/step_runner.ex b/durable/lib/durable/executor/step_runner.ex index 89d93ee..0632936 100644 --- a/durable/lib/durable/executor/step_runner.ex +++ b/durable/lib/durable/executor/step_runner.ex @@ -15,6 +15,7 @@ defmodule Durable.Executor.StepRunner do alias Durable.PubSub, as: DurablePubSub alias Durable.Repo alias Durable.Storage.Schemas.StepExecution + alias Durable.Storage.Schemas.WorkflowExecution import Ecto.Query, only: [from: 2] @@ -63,12 +64,17 @@ defmodule Durable.Executor.StepRunner do defp next_attempt(config, workflow_id, %Step{name: name}) do step_name = Atom.to_string(name) + # Only failures since the last Durable.retry/2 count: an operator retry + # hands the step a fresh max_attempts budget. failed_count = Repo.one( config, from(s in StepExecution, + join: w in WorkflowExecution, + on: w.id == s.workflow_id, where: s.workflow_id == ^workflow_id and s.step_name == ^step_name and s.status == :failed, + where: is_nil(w.retried_at) or s.inserted_at > w.retried_at, select: count(s.id) ) ) @@ -97,25 +103,13 @@ defmodule Durable.Executor.StepRunner do # Execute the step body start_time = System.monotonic_time(:millisecond) + span_meta = step_span_meta(config, workflow_id, step, attempt, max_attempts) result = - try do - Step.execute(step, data) - rescue - e -> - {:error, - %{ - type: inspect(e.__struct__), - message: Exception.message(e), - stacktrace: Exception.format_stacktrace(__STACKTRACE__) - }} - catch - :throw, value -> - {:throw, value} - - kind, reason -> - {:error, %{type: "#{kind}", message: inspect(reason)}} - end + :telemetry.span([:durable, :step], span_meta, fn -> + result = run_body(step, data) + {result, Map.merge(span_meta, step_outcome(result))} + end) end_time = System.monotonic_time(:millisecond) duration_ms = end_time - start_time @@ -138,6 +132,45 @@ defmodule Durable.Executor.StepRunner do handle_result(result, result_ctx) end + defp run_body(step, data) do + Step.execute(step, data) + catch + :throw, value -> {:throw, value} + kind, reason -> {:error, Durable.Executor.caught_error(kind, reason, __STACKTRACE__)} + end + + defp step_span_meta(config, workflow_id, step, attempt, max_attempts) do + %{ + durable: config.name, + workflow_id: workflow_id, + workflow: Map.get(Durable.Telemetry.run_meta(), :workflow), + step: step.name, + step_type: step.type, + attempt: attempt, + max_attempts: max_attempts + } + end + + @suspending [ + :sleep, + :wait_for_event, + :wait_for_input, + :wait_for_any, + :wait_for_all, + :call_workflow + ] + + defp step_outcome({:ok, data}) when is_map(data), do: %{result: :ok} + defp step_outcome({:goto, _target, _data}), do: %{result: :ok} + defp step_outcome({:throw, {kind, _opts}}) when kind in @suspending, do: %{result: :suspended} + defp step_outcome({:error, error}), do: %{result: :error, error: error_summary(error)} + + defp step_outcome(_other), + do: %{result: :error, error: %{type: "invalid_return", message: "unexpected step result"}} + + defp error_summary(%{type: type, message: message}), do: %{type: type, message: message} + defp error_summary(error), do: %{type: "error", message: inspect(error)} + # Handle step result from pipeline model defp handle_result({:ok, new_data}, ctx) when is_map(new_data) do %{step: step, step_exec: step_exec, logs: logs, duration_ms: duration_ms, config: config} = @@ -212,7 +245,17 @@ defmodule Durable.Executor.StepRunner do retry_opts = get_retry_opts(step) backoff_strategy = Map.get(retry_opts, :backoff, :exponential) - Backoff.sleep(backoff_strategy, attempt, retry_opts) + backoff_ms = Backoff.calculate_with_jitter(backoff_strategy, attempt, retry_opts) + + :telemetry.execute( + [:durable, :step, :retry], + %{backoff_ms: backoff_ms}, + config + |> step_span_meta(step_exec.workflow_id, step, attempt, max_attempts) + |> Map.put(:error, error_summary(error)) + ) + + Process.sleep(backoff_ms) execute_with_retry(step, data, step_exec.workflow_id, attempt + 1, max_attempts, config) else diff --git a/durable/lib/durable/log_capture.ex b/durable/lib/durable/log_capture.ex index 53ecc38..be5be42 100644 --- a/durable/lib/durable/log_capture.ex +++ b/durable/lib/durable/log_capture.ex @@ -294,11 +294,15 @@ defmodule Durable.LogCapture do _ -> Process.put(@warn_flag, true) + # `durable_internal` keeps this line out of the step's own logs; it's a + # filter, not something to print, so it isn't in the formatter config. + # credo:disable-for-next-line Credo.Check.Warning.MissedMetadataKeyInLoggerConfig Logger.warning( "[Durable.LogCapture] non-JSON-safe metadata value stringified " <> "to inspect/1 form: #{inspect(v, limit: 80)}. To preserve " <> "structured data, only pass binaries, atoms, numbers, booleans, " <> - "or nil in Logger metadata." + "or nil in Logger metadata.", + durable_internal: true ) end end diff --git a/durable/lib/durable/log_capture/handler.ex b/durable/lib/durable/log_capture/handler.ex index 165083f..78d6551 100644 --- a/durable/lib/durable/log_capture/handler.ex +++ b/durable/lib/durable/log_capture/handler.ex @@ -98,8 +98,9 @@ defmodule Durable.LogCapture.Handler do @doc false def log(%{level: level, msg: msg, meta: meta}, _config) do - # Only capture logs when in workflow context - if Durable.LogCapture.in_workflow_context?() do + # Only capture logs when in workflow context, and not Durable's own lines + # (its default telemetry logger runs in the step's process). + if Durable.LogCapture.in_workflow_context?() and not Map.get(meta, :durable_internal, false) do formatted_message = format_message(msg) metadata = format_metadata(meta) Durable.LogCapture.add_log(level, formatted_message, metadata) @@ -136,7 +137,7 @@ defmodule Durable.LogCapture.Handler do # Metadata formatting - defp format_metadata(meta) when is_map(meta) do + defp format_metadata(meta) do # Convert known keys to atoms for consistent handling meta |> Map.new(fn @@ -145,6 +146,4 @@ defmodule Durable.LogCapture.Handler do {k, v} -> {k, v} end) end - - defp format_metadata(_), do: %{} end diff --git a/durable/lib/durable/migration/migrations/v20261016000000_add_operator_controls.ex b/durable/lib/durable/migration/migrations/v20261016000000_add_operator_controls.ex new file mode 100644 index 0000000..261cad1 --- /dev/null +++ b/durable/lib/durable/migration/migrations/v20261016000000_add_operator_controls.ex @@ -0,0 +1,72 @@ +defmodule Durable.Migration.Migrations.V20261016000000AddOperatorControls do + @moduledoc false + # Operator controls for 1.0: + # + # * `workflow_executions.retried_at` — when `Durable.retry/2` last resumed a + # failed run. Step attempts are counted from here, so a retried step gets + # its full `max_attempts` budget again. + # * `workflow_executions.trigger` / `trigger_ref` — what started the run + # (api | schedule | parent | rerun) and what it points at (the schedule + # name, or the run being re-run). + # * `queues` — cluster-wide pause state, checked by every node's claim query. + # * `nodes` — one heartbeat row per running Durable instance. + # * Time indexes for dashboard ranges ("last 24h") and the retention pruner. + # Plain CREATE INDEX: on very large tables expect a write lock while they + # build, or create them CONCURRENTLY by hand before upgrading. + use Durable.Migration.Base + + @impl true + def version, do: 20_261_016_000_000 + + @impl true + def up(prefix) do + alter table(:workflow_executions, prefix: prefix) do + add_if_not_exists(:retried_at, :utc_datetime_usec) + add_if_not_exists(:trigger, :string) + add_if_not_exists(:trigger_ref, :string) + end + + create_if_not_exists table(:queues, primary_key: false, prefix: prefix) do + add(:name, :string, primary_key: true) + add(:paused_at, :utc_datetime_usec) + timestamps(type: :utc_datetime_usec) + end + + create_if_not_exists table(:nodes, primary_key: false, prefix: prefix) do + add(:id, :string, primary_key: true) + add(:queues, {:array, :string}, null: false, default: []) + add(:version, :string) + add(:started_at, :utc_datetime_usec, null: false) + add(:heartbeat_at, :utc_datetime_usec, null: false) + end + + create_if_not_exists(index(:workflow_executions, [:inserted_at], prefix: prefix)) + + create_if_not_exists( + index(:workflow_executions, [:workflow_name, :inserted_at], prefix: prefix) + ) + + create_if_not_exists(index(:workflow_executions, [:status, :completed_at], prefix: prefix)) + create_if_not_exists(index(:step_executions, [:inserted_at], prefix: prefix)) + + :ok + end + + @impl true + def down(prefix) do + drop_if_exists(index(:step_executions, [:inserted_at], prefix: prefix)) + drop_if_exists(index(:workflow_executions, [:status, :completed_at], prefix: prefix)) + drop_if_exists(index(:workflow_executions, [:workflow_name, :inserted_at], prefix: prefix)) + drop_if_exists(index(:workflow_executions, [:inserted_at], prefix: prefix)) + drop_if_exists(table(:nodes, prefix: prefix)) + drop_if_exists(table(:queues, prefix: prefix)) + + alter table(:workflow_executions, prefix: prefix) do + remove_if_exists(:trigger_ref, :string) + remove_if_exists(:trigger, :string) + remove_if_exists(:retried_at, :utc_datetime_usec) + end + + :ok + end +end diff --git a/durable/lib/durable/migration/migrations/v20261016000001_add_deadlines_and_history.ex b/durable/lib/durable/migration/migrations/v20261016000001_add_deadlines_and_history.ex new file mode 100644 index 0000000..a7aa16d --- /dev/null +++ b/durable/lib/durable/migration/migrations/v20261016000001_add_deadlines_and_history.ex @@ -0,0 +1,67 @@ +defmodule Durable.Migration.Migrations.V20261016000001AddDeadlinesAndHistory do + @moduledoc false + # * `workflow_executions.deadline_at` — when a run with a workflow `timeout:` + # must be finished by. Partial index: only runs that have one. + # * `queue_samples` — one row per queue per minute (ready, scheduled, running, + # waiting), written by whichever node gets there first. Kept for a week. + # * `activity` — operational events worth an operator's attention: recovered + # runs, fenced workers, failed acks, queue pauses, auto-disabled schedules, + # pruning. Kept for a week. + use Durable.Migration.Base + + @impl true + def version, do: 20_261_016_000_001 + + @impl true + def up(prefix) do + alter table(:workflow_executions, prefix: prefix) do + add_if_not_exists(:deadline_at, :utc_datetime_usec) + end + + create_if_not_exists( + index(:workflow_executions, [:deadline_at], + where: "deadline_at IS NOT NULL", + prefix: prefix + ) + ) + + create_if_not_exists table(:queue_samples, primary_key: false, prefix: prefix) do + add(:queue, :string, primary_key: true) + add(:at, :utc_datetime, primary_key: true) + add(:ready, :integer, null: false, default: 0) + add(:scheduled, :integer, null: false, default: 0) + add(:running, :integer, null: false, default: 0) + add(:waiting, :integer, null: false, default: 0) + end + + create_if_not_exists(index(:queue_samples, [:at], prefix: prefix)) + + create_if_not_exists table(:activity, primary_key: false, prefix: prefix) do + add(:id, :binary_id, primary_key: true) + add(:at, :utc_datetime_usec, null: false) + add(:kind, :string, null: false) + add(:node_id, :string) + add(:queue, :string) + add(:workflow_id, :binary_id) + add(:count, :integer, null: false, default: 1) + add(:details, :map, null: false, default: %{}) + end + + create_if_not_exists(index(:activity, [:at], prefix: prefix)) + + :ok + end + + @impl true + def down(prefix) do + drop_if_exists(table(:activity, prefix: prefix)) + drop_if_exists(table(:queue_samples, prefix: prefix)) + drop_if_exists(index(:workflow_executions, [:deadline_at], prefix: prefix)) + + alter table(:workflow_executions, prefix: prefix) do + remove_if_exists(:deadline_at, :utc_datetime_usec) + end + + :ok + end +end diff --git a/durable/lib/durable/migration/migrator.ex b/durable/lib/durable/migration/migrator.ex index 27cdcd9..2a7d3e4 100644 --- a/durable/lib/durable/migration/migrator.ex +++ b/durable/lib/durable/migration/migrator.ex @@ -17,7 +17,9 @@ defmodule Durable.Migration.Migrator do Durable.Migration.Migrations.V20260104000000AddWaitPrimitives, Durable.Migration.Migrations.V20260413000000AddSchedulerResilience, Durable.Migration.Migrations.V20260623000000AddLockFencing, - Durable.Migration.Migrations.V20260623000001AddChildWorkflowLink + Durable.Migration.Migrations.V20260623000001AddChildWorkflowLink, + Durable.Migration.Migrations.V20261016000000AddOperatorControls, + Durable.Migration.Migrations.V20261016000001AddDeadlinesAndHistory ] @doc """ diff --git a/durable/lib/durable/node_registry.ex b/durable/lib/durable/node_registry.ex new file mode 100644 index 0000000..3b35b9b --- /dev/null +++ b/durable/lib/durable/node_registry.ex @@ -0,0 +1,130 @@ +defmodule Durable.NodeRegistry do + @moduledoc """ + Keeps this instance's row in `durable.nodes` fresh, so operators can see + which nodes are alive and which queues each runs. + + A node heartbeats every #{div(10_000, 1_000)} s and removes its row on a + clean shutdown; `list/1` reports a node as `:missing` once its heartbeat is + #{div(30_000, 1_000)} s old. Rows unseen for a day are deleted. + + On boot it also checks the database schema: a library upgrade whose + migrations haven't run is logged as an error naming the missing version. + """ + use GenServer + + require Logger + + import Ecto.Query + + alias Durable.Config + alias Durable.Repo + alias Durable.Storage.Schemas.Node + alias Durable.Storage.Schemas.WorkflowExecution + + @interval 10_000 + @missing_after_ms 30_000 + @forget_after_s 86_400 + + def start_link(opts), do: GenServer.start_link(__MODULE__, Keyword.fetch!(opts, :config)) + + @doc """ + Lists known nodes, newest heartbeat first, each with a `:status` of + `:alive` or `:missing` and `:running`, the number of runs it holds a lock on. + """ + @spec list(Config.t()) :: [map()] + def list(%Config{} = config) do + cutoff = DateTime.add(DateTime.utc_now(), -@missing_after_ms, :millisecond) + + running = + config + |> Repo.all( + from(w in WorkflowExecution, + where: w.status == :running and not is_nil(w.locked_by), + group_by: w.locked_by, + select: {w.locked_by, count(w.id)} + ) + ) + |> Map.new() + + config + |> Repo.all(from(n in Node, order_by: [desc: n.heartbeat_at])) + |> Enum.map(fn node -> + node + |> Map.from_struct() + |> Map.drop([:__meta__]) + |> Map.merge(%{ + status: if(DateTime.before?(node.heartbeat_at, cutoff), do: :missing, else: :alive), + running: Map.get(running, node.id, 0) + }) + end) + end + + @impl true + def init(%Config{} = config) do + Process.flag(:trap_exit, true) + {:ok, %{config: config, started_at: DateTime.utc_now()}, {:continue, :boot}} + end + + @impl true + def handle_continue(:boot, state) do + check_schema(state.config) + {:noreply, beat(state)} + end + + @impl true + def handle_info(:beat, state), do: {:noreply, beat(state)} + + @impl true + def terminate(_reason, %{config: config}) do + safely(fn -> Repo.delete_all(config, from(n in Node, where: n.id == ^config.node_id)) end) + end + + defp beat(%{config: config} = state) do + now = DateTime.utc_now() + + node = %Node{ + id: config.node_id, + queues: + if(config.queue_enabled, do: Enum.map(Map.keys(config.queues), &to_string/1), else: []), + version: Application.spec(:durable, :vsn) |> to_string(), + started_at: state.started_at, + heartbeat_at: now + } + + safely(fn -> + Repo.insert(node, config, + on_conflict: {:replace, [:queues, :version, :heartbeat_at]}, + conflict_target: :id + ) + + forgotten = DateTime.add(now, -@forget_after_s, :second) + Repo.delete_all(config, from(n in Node, where: n.heartbeat_at < ^forgotten)) + end) + + Process.send_after(self(), :beat, @interval) + state + end + + defp check_schema(config) do + safely(fn -> + applied = Durable.Migration.migrated_version(config.repo, prefix: config.prefix) + latest = Durable.Migration.current_version() + + if applied < latest do + Logger.error( + "[Durable] database schema #{inspect(config.prefix)} is at migration #{applied}, " <> + "but this version of Durable needs #{latest}. Run `mix durable.gen.upgrade` " <> + "and migrate — until then runs will fail to start or save." + ) + end + end) + end + + # The registry is advisory; a database blip must never crash Durable's + # supervision tree, so failures here are logged and retried next beat. + defp safely(fun) do + fun.() + rescue + e -> Logger.debug("[Durable] node registry: #{Exception.message(e)}") + end +end diff --git a/durable/lib/durable/orchestration.ex b/durable/lib/durable/orchestration.ex index f9b88f9..7c24a96 100644 --- a/durable/lib/durable/orchestration.ex +++ b/durable/lib/durable/orchestration.ex @@ -225,7 +225,8 @@ defmodule Durable.Orchestration do priority: Keyword.get(opts, :priority, 0), input: input, context: %{}, - parent_workflow_id: parent_id + parent_workflow_id: parent_id, + trigger: :parent } {:ok, execution} = diff --git a/durable/lib/durable/pruner.ex b/durable/lib/durable/pruner.ex new file mode 100644 index 0000000..55ab907 --- /dev/null +++ b/durable/lib/durable/pruner.ex @@ -0,0 +1,99 @@ +defmodule Durable.Pruner do + @moduledoc """ + Deletes finished runs older than the `:prune` config, once an hour. Steps, + pending inputs, events and wait groups go with their run (foreign keys + cascade); child runs keep living and are pruned on their own age. + + Deletes go in batches of #{5_000} with `FOR UPDATE SKIP LOCKED`, so every + node can run the pruner without stepping on the others or holding long + locks. Running and waiting runs are never pruned. + + Each batch emits `[:durable, :pruner, :pruned]` with `%{count}` and the + `:group` (`:completed`, `:failed` or `:cancelled`). + """ + use GenServer + + require Logger + + import Ecto.Query + + alias Durable.Config + alias Durable.Repo + alias Durable.Storage.Schemas.WorkflowExecution + + @interval :timer.hours(1) + @batch 5_000 + @groups [ + completed: [:completed], + failed: [:failed, :compensated, :compensation_failed], + cancelled: [:cancelled] + ] + + def start_link(opts), do: GenServer.start_link(__MODULE__, Keyword.fetch!(opts, :config)) + + @doc """ + Prunes now. Returns how many runs were deleted per group. + """ + @spec prune(Config.t()) :: %{atom() => non_neg_integer()} + def prune(%Config{prune: nil}), do: %{} + + def prune(%Config{prune: policy} = config) do + deleted = + for {group, statuses} <- @groups, keep_ms = policy[group], into: %{} do + cutoff = DateTime.add(DateTime.utc_now(), -keep_ms, :millisecond) + {group, prune_group(config, group, statuses, cutoff, 0)} + end + + total = deleted |> Map.values() |> Enum.sum() + + if total > 0, + do: Durable.Activity.record(config, "pruned", count: total, details: deleted) + + deleted + end + + defp prune_group(config, group, statuses, cutoff, total) do + # Compensated runs have no completed_at; their last write is when they + # finished. + expired = + from(w in WorkflowExecution, + where: w.status in ^statuses, + where: fragment("coalesce(?, ?)", w.completed_at, w.updated_at) < ^cutoff, + select: w.id, + limit: @batch, + lock: "FOR UPDATE SKIP LOCKED" + ) + + {count, _} = + Repo.delete_all(config, from(w in WorkflowExecution, where: w.id in subquery(expired))) + + if count > 0 do + :telemetry.execute([:durable, :pruner, :pruned], %{count: count}, %{ + durable: config.name, + group: group + }) + end + + if count == @batch, + do: prune_group(config, group, statuses, cutoff, total + count), + else: total + count + end + + @impl true + def init(%Config{} = config) do + Process.send_after(self(), :prune, :rand.uniform(60_000)) + {:ok, config} + end + + @impl true + def handle_info(:prune, config) do + try do + prune(config) + rescue + e -> Logger.warning("[Durable] pruning failed, retrying next hour: #{Exception.message(e)}") + end + + Process.send_after(self(), :prune, @interval) + {:noreply, config} + end +end diff --git a/durable/lib/durable/pubsub.ex b/durable/lib/durable/pubsub.ex index 09774bc..cb12cc9 100644 --- a/durable/lib/durable/pubsub.ex +++ b/durable/lib/durable/pubsub.ex @@ -44,6 +44,7 @@ defmodule Durable.PubSub do | :workflow_completed | :workflow_failed | :workflow_cancelled + | :workflow_retried | :step_started | :step_completed | :step_failed diff --git a/durable/lib/durable/query.ex b/durable/lib/durable/query.ex index b358d7c..5042037 100644 --- a/durable/lib/durable/query.ex +++ b/durable/lib/durable/query.ex @@ -53,6 +53,12 @@ defmodule Durable.Query do - `:workflow_name` - Filter by workflow name - `:status` - Filter by status - `:queue` - Filter by queue + - `:current_step` - Runs currently at (or that stopped at) this step + - `:trigger` - What started the run: `:api`, `:schedule`, `:parent` or `:rerun` + - `:trigger_ref` - What it points at: a schedule's name, or the run a rerun copied + - `:error_contains` - Case-insensitive text anywhere in the run's error + - `:input` - Map of dotted input paths to exact values, e.g. + `%{"order_id" => "ORD-1042"}` - `:limit` - Maximum results (default: 50) - `:offset` - Offset for pagination (default: 0) - `:durable` - The Durable instance name (default: Durable) @@ -88,6 +94,21 @@ defmodule Durable.Query do Repo.one(config, query) end + @doc """ + Counts runs per status, applying every filter except `:status` — what a + "Failed (12) · Running (3)" view switcher needs in one query. + """ + @spec count_by_status(keyword()) :: %{atom() => non_neg_integer()} + def count_by_status(filters \\ []) do + config = get_config(filters) + + query = + from(w in WorkflowExecution, group_by: w.status, select: {w.status, count(w.id)}) + |> apply_filters(Keyword.delete(filters, :status)) + + config |> Repo.all(query) |> Map.new() + end + @doc """ Gets step executions for a workflow. """ @@ -388,11 +409,36 @@ defmodule Durable.Query do {:to, to_date}, q -> from(w in q, where: w.inserted_at <= ^to_date) + {:current_step, step}, q when is_binary(step) and step != "" -> + from(w in q, where: w.current_step == ^step) + + {:trigger, trigger}, q when is_atom(trigger) and not is_nil(trigger) -> + from(w in q, where: w.trigger == ^trigger) + + {:trigger_ref, ref}, q when is_binary(ref) and ref != "" -> + from(w in q, where: w.trigger_ref == ^ref) + + # Case-insensitive substring of the stored error (type, message, or any + # field a step returned in `{:error, map}`). + {:error_contains, text}, q when is_binary(text) and text != "" -> + pattern = "%" <> escape_like(text) <> "%" + from(w in q, where: fragment("?::text ILIKE ?", w.error, ^pattern)) + + # Exact match on fields of the run's input, by dotted path: + # `input: %{"order_id" => "ORD-1", "customer.tier" => "gold"}`. + {:input, fields}, q when is_map(fields) -> + Enum.reduce(fields, q, fn {path, value}, acc -> + keys = path |> to_string() |> String.split(".") + from(w in acc, where: fragment("? #>> ? = ?", w.input, ^keys, ^to_string(value))) + end) + _, q -> q end) end + defp escape_like(text), do: String.replace(text, ["\\", "%", "_"], &("\\" <> &1)) + defp execution_to_map(execution, include_steps, include_logs) do base = %{ id: execution.id, @@ -406,9 +452,13 @@ defmodule Durable.Query do current_step: execution.current_step, error: execution.error, parent_workflow_id: execution.parent_workflow_id, + trigger: execution.trigger, + trigger_ref: execution.trigger_ref, + locked_by: execution.locked_by, scheduled_at: execution.scheduled_at, started_at: execution.started_at, completed_at: execution.completed_at, + retried_at: execution.retried_at, inserted_at: execution.inserted_at, updated_at: execution.updated_at } diff --git a/durable/lib/durable/queue/adapters/postgres.ex b/durable/lib/durable/queue/adapters/postgres.ex index fc0ff5e..97bdd4c 100644 --- a/durable/lib/durable/queue/adapters/postgres.ex +++ b/durable/lib/durable/queue/adapters/postgres.ex @@ -30,6 +30,9 @@ defmodule Durable.Queue.Adapters.Postgres do AND queue = $1 AND (scheduled_at IS NULL OR scheduled_at <= NOW()) AND (locked_by IS NULL OR locked_at < NOW() - INTERVAL '#{config.stale_lock_timeout} seconds') + AND NOT EXISTS ( + SELECT 1 FROM #{prefix}.queues q WHERE q.name = $1 AND q.paused_at IS NOT NULL + ) ORDER BY priority DESC, scheduled_at ASC NULLS FIRST, inserted_at ASC LIMIT $2 FOR UPDATE SKIP LOCKED @@ -109,6 +112,11 @@ defmodule Durable.Queue.Adapters.Postgres do inspect(reason) ) + Durable.Activity.record(config, "ack_failed", + workflow_id: job_id, + details: %{attempts: attempt, reason: inspect(reason)} + ) + {:error, reason} end end @@ -129,7 +137,11 @@ defmodule Durable.Queue.Adapters.Postgres do {:error, :not_found} execution -> - if fenced?(execution, lock_token) do + # Only a run still :running needs failing here — the worker crashed + # before the executor could record an outcome. Anything else was + # settled by the executor (failed, compensated, cancelled, waiting) + # and must not be overwritten. + if fenced?(execution, lock_token) or execution.status != :running do :ok else error = normalize_error(reason) diff --git a/durable/lib/durable/queue/control.ex b/durable/lib/durable/queue/control.ex new file mode 100644 index 0000000..0945209 --- /dev/null +++ b/durable/lib/durable/queue/control.ex @@ -0,0 +1,52 @@ +defmodule Durable.Queue.Control do + @moduledoc false + # Cluster-wide queue pause. The state lives in `durable.queues` and is + # enforced by the claim query every node's poller runs (see + # `Durable.Queue.Adapters.Postgres.fetch_jobs/4`), so a pause takes effect on + # the next poll everywhere, with no extra round trip per poll. + # + # `Durable.Queue.Manager.pause/2` is different: it stops this node's poller + # only (e.g. while draining for a deploy) and is forgotten on restart. + + import Ecto.Query + + alias Durable.Config + alias Durable.Repo + alias Durable.Storage.Schemas.Queue + + @spec pause(Config.t(), atom() | String.t(), keyword()) :: :ok | {:error, term()} + def pause(%Config{} = config, queue, opts \\ []) do + with :ok <- put_paused_at(config, queue, DateTime.utc_now()), + do: record(config, "queue_paused", queue, opts) + end + + @spec resume(Config.t(), atom() | String.t(), keyword()) :: :ok | {:error, term()} + def resume(%Config{} = config, queue, opts \\ []) do + with :ok <- put_paused_at(config, queue, nil), + do: record(config, "queue_resumed", queue, opts) + end + + defp record(config, kind, queue, opts) do + details = if opts[:by], do: %{by: to_string(opts[:by])}, else: %{} + Durable.Activity.record(config, kind, queue: queue, details: details) + end + + @spec paused(Config.t()) :: [String.t()] + def paused(%Config{} = config) do + Repo.all(config, from(q in Queue, where: not is_nil(q.paused_at), select: q.name)) + end + + defp put_paused_at(config, queue, paused_at) do + now = DateTime.utc_now() + + %Queue{name: to_string(queue), paused_at: paused_at} + |> Repo.insert(config, + on_conflict: [set: [paused_at: paused_at, updated_at: now]], + conflict_target: :name + ) + |> case do + {:ok, _} -> :ok + error -> error + end + end +end diff --git a/durable/lib/durable/queue/poller.ex b/durable/lib/durable/queue/poller.ex index b96b93e..02e035f 100644 --- a/durable/lib/durable/queue/poller.ex +++ b/durable/lib/durable/queue/poller.ex @@ -117,7 +117,7 @@ defmodule Durable.Queue.Poller do concurrency: Keyword.get(opts, :concurrency, @default_concurrency), poll_interval: Keyword.get(opts, :poll_interval, @default_poll_interval), worker_supervisor: worker_supervisor, - node_id: generate_node_id(), + node_id: config.node_id, active_jobs: MapSet.new(), worker_refs: %{}, job_tokens: %{}, @@ -336,16 +336,6 @@ defmodule Durable.Queue.Poller do %{state | timer_ref: timer_ref} end - defp generate_node_id do - hostname = - case :inet.gethostname() do - {:ok, name} -> to_string(name) - _ -> "unknown" - end - - "#{hostname}-#{:erlang.system_info(:scheduler_id)}-#{System.unique_integer([:positive])}" - end - defp emit_poll_telemetry(queue_name, jobs_fetched, available_slots) do :telemetry.execute( [:durable, :queue, :poll], diff --git a/durable/lib/durable/queue/sampler.ex b/durable/lib/durable/queue/sampler.ex new file mode 100644 index 0000000..0f92010 --- /dev/null +++ b/durable/lib/durable/queue/sampler.ex @@ -0,0 +1,98 @@ +defmodule Durable.Queue.Sampler do + @moduledoc """ + Once a minute, records every queue's depth — ready, scheduled, running, + waiting — in `durable.queue_samples`, so backlog can be charted over time + (`Durable.Stats.queue_history/1`). + + Every node runs a sampler; the row for a queue and minute is written by + whichever gets there first (`ON CONFLICT DO NOTHING`), so the cluster keeps + one sample per minute however many nodes there are. Samples and + `Durable.Activity` rows older than #{7} days are deleted on the way. + """ + use GenServer + + require Logger + + import Ecto.Query + + alias Durable.Config + alias Durable.Repo + alias Durable.Storage.Schemas.{ActivityEvent, QueueSample, WorkflowExecution} + + @keep_s 7 * 86_400 + + def start_link(opts), do: GenServer.start_link(__MODULE__, Keyword.fetch!(opts, :config)) + + @impl true + def init(%Config{} = config) do + schedule_next() + {:ok, config} + end + + @impl true + def handle_info(:sample, config) do + safely(fn -> sample(config) end) + schedule_next() + {:noreply, config} + end + + @doc """ + Writes this minute's sample for every queue, unless another node already + has. Returns the samples it computed. + """ + @spec sample(Config.t()) :: [map()] + def sample(%Config{} = config) do + now = DateTime.utc_now() + minute = %{DateTime.truncate(now, :second) | second: 0} + + counts = + config + |> Repo.all( + from(w in WorkflowExecution, + where: w.status in [:pending, :running, :waiting], + group_by: w.queue, + select: + {w.queue, + %{ + ready: + filter( + count(w.id), + w.status == :pending and (is_nil(w.scheduled_at) or w.scheduled_at <= ^now) + ), + scheduled: filter(count(w.id), w.status == :pending and w.scheduled_at > ^now), + running: filter(count(w.id), w.status == :running), + waiting: filter(count(w.id), w.status == :waiting) + }} + ) + ) + |> Map.new() + + empty = %{ready: 0, scheduled: 0, running: 0, waiting: 0} + + rows = + (Enum.map(Map.keys(config.queues), &to_string/1) ++ Map.keys(counts)) + |> Enum.uniq() + |> Enum.map(&Map.merge(Map.get(counts, &1, empty), %{queue: &1, at: minute})) + + Repo.insert_all(config, QueueSample, rows, on_conflict: :nothing) + + cutoff = DateTime.add(now, -@keep_s, :second) + Repo.delete_all(config, from(s in QueueSample, where: s.at < ^cutoff)) + Repo.delete_all(config, from(a in ActivityEvent, where: a.at < ^cutoff)) + + rows + end + + # Just after the next minute boundary, so every node samples the same minute. + defp schedule_next do + ms = 60_000 - rem(System.os_time(:millisecond), 60_000) + 500 + Process.send_after(self(), :sample, ms) + end + + # History is advisory; a database blip must never crash Durable's tree. + defp safely(fun) do + fun.() + rescue + e -> Logger.debug("[Durable] queue sampler: #{Exception.message(e)}") + end +end diff --git a/durable/lib/durable/queue/stale_job_recovery.ex b/durable/lib/durable/queue/stale_job_recovery.ex index 1ad65fa..93ed26a 100644 --- a/durable/lib/durable/queue/stale_job_recovery.ex +++ b/durable/lib/durable/queue/stale_job_recovery.ex @@ -82,32 +82,38 @@ defmodule Durable.Queue.StaleJobRecovery do adapter = Adapter.default_adapter() stale_result = adapter.recover_stale_locks(config, config.stale_lock_timeout) - log_recovery(:stale, stale_result, config.name) + log_recovery(:stale, stale_result, config) # Zombie recovery is an optional adapter capability. Skip if not implemented. if function_exported?(adapter, :recover_zombie_workflows, 2) do zombie_result = adapter.recover_zombie_workflows(config, config.stale_lock_timeout) - log_recovery(:zombie, zombie_result, config.name) + log_recovery(:zombie, zombie_result, config) end # Preserve the return shape expected by `recover_now/1` callers. stale_result end - defp log_recovery(_kind, {:ok, 0}, _name), do: :ok + defp log_recovery(_kind, {:ok, 0}, _config), do: :ok - defp log_recovery(:stale, {:ok, count}, name) do - Logger.info("Recovered #{count} stale job(s) for #{inspect(name)}") - emit_telemetry(count, name) + defp log_recovery(:stale, {:ok, count}, config) do + Logger.info("Recovered #{count} stale job(s) for #{inspect(config.name)}") + emit_telemetry(count, config.name) + + Durable.Activity.record(config, "stale_recovered", + count: count, + details: %{after_s: config.stale_lock_timeout} + ) end - defp log_recovery(:zombie, {:ok, count}, name) do - Logger.warning("Marked #{count} zombie workflow(s) as failed for #{inspect(name)}") - emit_zombie_telemetry(count, name) + defp log_recovery(:zombie, {:ok, count}, config) do + Logger.warning("Marked #{count} zombie workflow(s) as failed for #{inspect(config.name)}") + emit_zombie_telemetry(count, config.name) + Durable.Activity.record(config, "zombie_recovered", count: count) end - defp log_recovery(kind, {:error, reason}, name) do - Logger.error("Failed #{kind} recovery for #{inspect(name)}: #{inspect(reason)}") + defp log_recovery(kind, {:error, reason}, config) do + Logger.error("Failed #{kind} recovery for #{inspect(config.name)}: #{inspect(reason)}") end defp schedule_recovery(interval) do diff --git a/durable/lib/durable/queue/worker.ex b/durable/lib/durable/queue/worker.ex index 7eef977..3753c1d 100644 --- a/durable/lib/durable/queue/worker.ex +++ b/durable/lib/durable/queue/worker.ex @@ -147,6 +147,11 @@ defmodule Durable.Queue.Worker do # Workflow is waiting for sleep/event/input - not an error :waiting + {:error, :superseded} -> + # Cancelled or reclaimed while we ran: the row's status is someone + # else's now, so the poller must neither ack nor nack it. + :fenced + {:error, error} -> {:error, error} end @@ -164,13 +169,12 @@ defmodule Durable.Queue.Worker do }} catch kind, reason -> - Logger.error("Worker caught #{kind} executing job #{job.id}: #{inspect(reason)}") + Logger.error( + "Worker caught #{kind} executing job #{job.id}: " <> + Exception.format(kind, reason, __STACKTRACE__) + ) - {:error, - %{ - type: "#{kind}", - message: inspect(reason) - }} + {:error, Durable.Executor.caught_error(kind, reason, __STACKTRACE__)} end # We've been fenced: stale-lock recovery released our claim and another worker @@ -191,10 +195,15 @@ defmodule Durable.Queue.Worker do :telemetry.execute( [:durable, :queue, :worker_fenced], - %{count: 1, duration_ms: duration_ms}, + %{count: 1, duration: System.convert_time_unit(duration_ms, :millisecond, :native)}, %{job_id: state.job.id, queue: state.job.queue} ) + Durable.Activity.record(state.config, "worker_fenced", + queue: state.job.queue, + workflow_id: state.job.id + ) + send(state.poller_pid, {:job_complete, state.job.id, :fenced, duration_ms}) {:stop, :normal, %{state | heartbeat_timer: nil}} @@ -212,12 +221,13 @@ defmodule Durable.Queue.Worker do case result do :ok -> :completed :waiting -> :waiting + :fenced -> :superseded {:error, _} -> :failed end :telemetry.execute( [:durable, :queue, :job_completed], - %{duration_ms: duration_ms}, + %{duration: System.convert_time_unit(duration_ms, :millisecond, :native)}, %{ job_id: job.id, queue: job.queue, diff --git a/durable/lib/durable/scheduler/api.ex b/durable/lib/durable/scheduler/api.ex index 42f4c95..94e4198 100644 --- a/durable/lib/durable/scheduler/api.ex +++ b/durable/lib/durable/scheduler/api.ex @@ -292,7 +292,9 @@ defmodule Durable.Scheduler.API do Durable.Executor.start_workflow(module, input, workflow: schedule.workflow_name, queue: String.to_atom(schedule.queue), - durable: durable_name + durable: durable_name, + trigger: :schedule, + trigger_ref: schedule.name ) end end @@ -427,6 +429,29 @@ defmodule Durable.Scheduler.API do end end + @doc """ + The next `count` times a schedule fires, in UTC, from its cron expression + and time zone — whether or not it's enabled. + + [~U[2026-10-17 09:00:00.000000Z], ~U[2026-10-18 09:00:00.000000Z], ...] + """ + @spec upcoming_runs(ScheduledWorkflow.t(), pos_integer()) :: [DateTime.t()] + def upcoming_runs(%ScheduledWorkflow{} = schedule, count \\ 5) do + with {:ok, cron} <- CronParser.parse(schedule.cron_expression), + {:ok, now} <- get_local_time(schedule.timezone) do + cron + |> Scheduler.get_next_run_dates(now) + |> Stream.map(&local_to_utc(&1, schedule.timezone)) + |> Stream.flat_map(fn + {:ok, utc} -> [utc] + _ -> [] + end) + |> Enum.take(count) + else + _ -> [] + end + end + defp get_local_time("UTC"), do: {:ok, NaiveDateTime.utc_now()} defp get_local_time("Etc/UTC"), do: {:ok, NaiveDateTime.utc_now()} @@ -437,12 +462,15 @@ defmodule Durable.Scheduler.API do end end + # Next-run times go into `:utc_datetime_usec` columns, some through + # `put_change` (no cast), so they must carry microsecond precision — cron + # math returns whole seconds. defp local_to_utc(naive_datetime, "UTC") do - {:ok, DateTime.from_naive!(naive_datetime, "Etc/UTC")} + {:ok, naive_datetime |> DateTime.from_naive!("Etc/UTC") |> usec()} end defp local_to_utc(naive_datetime, "Etc/UTC") do - {:ok, DateTime.from_naive!(naive_datetime, "Etc/UTC")} + {:ok, naive_datetime |> DateTime.from_naive!("Etc/UTC") |> usec()} end defp local_to_utc(naive_datetime, timezone) do @@ -454,9 +482,11 @@ defmodule Durable.Scheduler.API do end end + defp usec(%DateTime{microsecond: {us, _}} = dt), do: %{dt | microsecond: {us, 6}} + defp shift_to_utc(datetime, timezone) do case DateTime.shift_zone(datetime, "Etc/UTC") do - {:ok, utc} -> {:ok, utc} + {:ok, utc} -> {:ok, usec(utc)} {:error, reason} -> {:error, {:timezone_error, timezone, reason}} end end diff --git a/durable/lib/durable/scheduler/scheduler.ex b/durable/lib/durable/scheduler/scheduler.ex index f15c06d..5208877 100644 --- a/durable/lib/durable/scheduler/scheduler.ex +++ b/durable/lib/durable/scheduler/scheduler.ex @@ -213,6 +213,15 @@ defmodule Durable.Scheduler do "[Durable.Scheduler] Auto-disabled #{schedule.name} after " <> "#{updated.consecutive_failures} consecutive failures: #{message}" ) + + Durable.Activity.record(config, "schedule_disabled", + queue: schedule.queue, + details: %{ + schedule: schedule.name, + failures: updated.consecutive_failures, + error: message + } + ) else Logger.warning( "[Durable.Scheduler] Schedule #{schedule.name} failure " <> @@ -233,7 +242,9 @@ defmodule Durable.Scheduler do {:ok, cron} -> case CronScheduler.get_next_run_date(cron, DateTime.utc_now() |> DateTime.to_naive()) do {:ok, naive} -> - DateTime.from_naive!(naive, "Etc/UTC") + naive + |> DateTime.from_naive!("Etc/UTC") + |> then(&%{&1 | microsecond: {elem(&1.microsecond, 0), 6}}) _ -> DateTime.add(DateTime.utc_now(), 300, :second) @@ -267,7 +278,9 @@ defmodule Durable.Scheduler do Durable.Executor.start_workflow(module, schedule.input, workflow: schedule.workflow_name, queue: String.to_atom(schedule.queue), - durable: config.name + durable: config.name, + trigger: :schedule, + trigger_ref: schedule.name ) case result do @@ -275,7 +288,7 @@ defmodule Durable.Scheduler do # Update last_run_at and next_run_at case API.mark_run(schedule, config) do {:ok, _} -> - emit_schedule_triggered(schedule, workflow_id) + emit_schedule_triggered(schedule, workflow_id, config) Logger.info("Triggered schedule #{schedule.name} -> workflow_id=#{workflow_id}") @@ -290,15 +303,16 @@ defmodule Durable.Scheduler do end end - defp emit_schedule_triggered(schedule, workflow_id) do + defp emit_schedule_triggered(schedule, workflow_id, config) do :telemetry.execute( - [:durable, :scheduler, :triggered], + [:durable, :schedule, :trigger], %{count: 1}, %{ - schedule_name: schedule.name, + durable: config.name, + schedule: schedule.name, workflow_id: workflow_id, workflow_module: schedule.workflow_module, - workflow_name: schedule.workflow_name, + workflow: schedule.workflow_name, queue: schedule.queue } ) diff --git a/durable/lib/durable/stats.ex b/durable/lib/durable/stats.ex new file mode 100644 index 0000000..f07aaf7 --- /dev/null +++ b/durable/lib/durable/stats.ex @@ -0,0 +1,691 @@ +defmodule Durable.Stats do + @moduledoc """ + Aggregate health of a Durable instance, read straight from its tables — + the numbers behind the dashboard's Overview and Workflow pages, available + to your own alerts and dashboards too. + + Postgres is the source of truth here, so these work across nodes and + survive restarts; use `Durable.Telemetry` for live per-node signals. + + ## Common options + + * `:durable` — instance name (default `Durable`) + * `:since` / `:until` — the window (`DateTime`; default the last 24 hours) + * `:workflow` — limit to one workflow name + * `:include_children` — count child runs too (default `false`: parallel + fan-out and called workflows would otherwise inflate every number) + + A run counts as *started* in the window by `inserted_at` and *finished* by + `completed_at`. "Failed" here means failed, rolled back (compensated) or + rollback-failed — every run that didn't do what it set out to. + """ + + import Ecto.Query + + alias Durable.Config + alias Durable.Repo + + alias Durable.Storage.Schemas.{ + PendingEvent, + PendingInput, + Queue, + QueueSample, + StepExecution, + WorkflowExecution + } + + @failed [:failed, :compensated, :compensation_failed] + @finished [:completed, :cancelled | @failed] + + @doc """ + Headline numbers for the window: + + %{ + started: 12_482, + finished: %{completed: 12_031, failed: 180, compensated: 34, cancelled: 21, ...}, + failure_rate: 0.017, # failed-like ÷ finished + duration_ms: %{p50: 380, p95: 4_210, max: 11_800}, # completed runs + queue_wait_ms: %{p50: 120, p95: 1_300}, # scheduled → started + backlog: 37, # ready to start right now + waiting: %{input: 9, event: 96, sleeping: 23} # right now + } + """ + @spec overview(keyword()) :: map() + def overview(opts \\ []) do + {config, since, until} = window(opts) + runs = runs(opts) + + finished = + Repo.all( + config, + from(w in runs, + where: w.status in ^@finished and w.completed_at >= ^since and w.completed_at < ^until, + group_by: w.status, + select: {w.status, count(w.id)} + ) + ) + |> Map.new() + + total = finished |> Map.values() |> Enum.sum() + failed = @failed |> Enum.map(&Map.get(finished, &1, 0)) |> Enum.sum() + + %{ + started: + Repo.one( + config, + from(w in runs, + where: w.inserted_at >= ^since and w.inserted_at < ^until, + select: count(w.id) + ) + ), + finished: finished, + failure_rate: if(total > 0, do: failed / total, else: 0.0), + duration_ms: duration_percentiles(config, runs, since, until), + queue_wait_ms: queue_wait_percentiles(config, runs, since, until), + backlog: Repo.one(config, from(w in ready(runs), select: count(w.id))), + waiting: waiting(config, opts) + } + end + + @doc """ + The window cut into `:bucket_seconds` (default: ~48 buckets), oldest + first, zero-filled: + + [%{at: ~U[...], started: 260, completed: 251, failed: 6, cancelled: 1, + failure_rate: 0.023, p50_ms: 1_900, p95_ms: 4_200}, ...] + + `failed` includes rolled-back runs; `p50_ms`/`p95_ms` are over runs + completed in the bucket (nil when none). + """ + @spec timeline(keyword()) :: [map()] + def timeline(opts \\ []) do + {config, since, until} = window(opts) + span = DateTime.diff(until, since, :second) + bucket = Keyword.get(opts, :bucket_seconds, max(div(span, 48), 60)) + runs = runs(opts) + origin = DateTime.to_unix(since) + + finished = + Repo.all( + config, + from(w in runs, + where: w.status in ^@finished and w.completed_at >= ^since and w.completed_at < ^until, + group_by: [fragment("bucket"), w.status], + select: { + fragment( + "floor((extract(epoch from ?) - ?) / ?)::int AS bucket", + w.completed_at, + ^origin, + ^bucket + ), + w.status, + count(w.id) + } + ) + ) + + started = + Repo.all( + config, + from(w in runs, + where: w.inserted_at >= ^since and w.inserted_at < ^until, + group_by: fragment("bucket"), + select: { + fragment( + "floor((extract(epoch from ?) - ?) / ?)::int AS bucket", + w.inserted_at, + ^origin, + ^bucket + ), + count(w.id) + } + ) + ) + |> Map.new() + + durations = + Repo.all( + config, + from(w in runs, + where: w.status == :completed and w.completed_at >= ^since and w.completed_at < ^until, + where: not is_nil(w.started_at), + group_by: fragment("bucket"), + select: { + fragment( + "floor((extract(epoch from ?) - ?) / ?)::int AS bucket", + w.completed_at, + ^origin, + ^bucket + ), + fragment( + "percentile_cont(0.5) WITHIN GROUP (ORDER BY extract(epoch from (? - ?)) * 1000)", + w.completed_at, + w.started_at + ), + fragment( + "percentile_cont(0.95) WITHIN GROUP (ORDER BY extract(epoch from (? - ?)) * 1000)", + w.completed_at, + w.started_at + ) + } + ) + ) + |> Map.new(fn {b, p50, p95} -> {b, {round(p50), round(p95)}} end) + + by_bucket = Enum.group_by(finished, &elem(&1, 0), &{elem(&1, 1), elem(&1, 2)}) + + for b <- 0..max(div(span - 1, bucket), 0) do + counts = Map.new(Map.get(by_bucket, b, [])) + failed = @failed |> Enum.map(&Map.get(counts, &1, 0)) |> Enum.sum() + total = counts |> Map.values() |> Enum.sum() + {p50, p95} = Map.get(durations, b, {nil, nil}) + + %{ + at: DateTime.add(since, b * bucket, :second), + started: Map.get(started, b, 0), + completed: Map.get(counts, :completed, 0), + failed: failed, + cancelled: Map.get(counts, :cancelled, 0), + failure_rate: if(total > 0, do: failed / total, else: 0.0), + p50_ms: p50, + p95_ms: p95 + } + end + end + + @doc """ + Failures grouped by what went wrong: error type, message with numbers + replaced by `` (so "timeout after 1503ms" and "after 1499ms" group), and + the step it happened at. Biggest group first. + + [%{workflow: "fulfill_order", step: "ship_order", type: "RuntimeError", + message: "carrier API returned ", count: 41, + first_at: ~U[...], last_at: ~U[...], rolled_back: 41}] + """ + @spec error_groups(keyword()) :: [map()] + def error_groups(opts \\ []) do + {config, since, until} = window(opts) + + Repo.all( + config, + from(w in runs(opts), + where: w.status in ^@failed and w.completed_at >= ^since and w.completed_at < ^until, + group_by: [ + w.workflow_name, + w.current_step, + fragment("? ->> 'type'", w.error), + fragment( + "regexp_replace(coalesce(? ->> 'message', ? ->> 'reason', ?::text), '[0-9]+', '', 'g')", + w.error, + w.error, + w.error + ) + ], + order_by: [desc: count(w.id)], + limit: ^Keyword.get(opts, :limit, 20), + select: %{ + workflow: w.workflow_name, + type: fragment("? ->> 'type'", w.error), + message: + fragment( + "regexp_replace(coalesce(? ->> 'message', ? ->> 'reason', ?::text), '[0-9]+', '', 'g')", + w.error, + w.error, + w.error + ), + step: w.current_step, + count: count(w.id), + first_at: min(w.completed_at), + last_at: max(w.completed_at), + rolled_back: filter(count(w.id), w.status == :compensated) + } + ) + ) + end + + @doc """ + Workflows with failures in the window, worst first, each with its biggest + error group: + + [%{workflow: "fulfill_order", failed: 41, finished: 660, failure_rate: 0.062, + last_failed_at: ~U[...], top_error: %{type:, message:, step:, count:}}] + """ + @spec failing_workflows(keyword()) :: [map()] + def failing_workflows(opts \\ []) do + {config, since, until} = window(opts) + + rows = + Repo.all( + config, + from(w in runs(opts), + where: w.status in ^@finished and w.completed_at >= ^since and w.completed_at < ^until, + group_by: w.workflow_name, + having: filter(count(w.id), w.status in ^@failed) > 0, + order_by: [desc: filter(count(w.id), w.status in ^@failed)], + limit: ^Keyword.get(opts, :limit, 5), + select: %{ + workflow: w.workflow_name, + failed: filter(count(w.id), w.status in ^@failed), + finished: count(w.id), + last_failed_at: filter(max(w.completed_at), w.status in ^@failed) + } + ) + ) + + tops = + opts + |> Keyword.put(:limit, 200) + |> error_groups() + |> Enum.group_by(& &1.workflow) + + Enum.map(rows, fn row -> + top = tops |> Map.get(row.workflow, []) |> List.first() + + Map.merge(row, %{ + failure_rate: row.failed / row.finished, + top_error: top && Map.take(top, [:type, :message, :step, :count]) + }) + end) + end + + @doc """ + Every workflow that has run, with its numbers for the window — one grouped + query, for a catalog page. Busiest first. + + [%{workflow: "fulfill_order", module: "Elixir.App.Orders", started: 660, + finished: 655, failed: 41, failure_rate: 0.063, retried: 121, + p50_ms: 1_920, p95_ms: 4_210, running: 4, waiting: 0, + last_run_at: ~U[...]}] + + `retried` counts runs where some step needed a second attempt. `running`, + `waiting` and `last_run_at` are as of now, not limited to the window. + """ + @spec workflows(keyword()) :: [map()] + def workflows(opts \\ []) do + {config, since, until} = window(opts) + + config + |> Repo.all( + from(w in runs(opts), + as: :run, + group_by: [w.workflow_name, w.workflow_module], + order_by: [desc: max(w.inserted_at)], + select: %{ + workflow: w.workflow_name, + module: w.workflow_module, + started: filter(count(w.id), w.inserted_at >= ^since and w.inserted_at < ^until), + finished: + filter( + count(w.id), + w.status in ^@finished and w.completed_at >= ^since and w.completed_at < ^until + ), + failed: + filter( + count(w.id), + w.status in ^@failed and w.completed_at >= ^since and w.completed_at < ^until + ), + # An Ecto subquery, not raw SQL, so the schema prefix applies to it. + retried: + filter( + count(w.id), + w.inserted_at >= ^since and w.inserted_at < ^until and + exists( + from(s in StepExecution, + where: s.workflow_id == parent_as(:run).id and s.attempt > 1, + select: 1 + ) + ) + ), + p50_ms: + fragment( + "percentile_cont(0.5) WITHIN GROUP (ORDER BY extract(epoch from (? - ?)) * 1000) FILTER (WHERE ? = 'completed' AND ? >= ? AND ? < ?)", + w.completed_at, + w.started_at, + w.status, + w.completed_at, + ^since, + w.completed_at, + ^until + ), + p95_ms: + fragment( + "percentile_cont(0.95) WITHIN GROUP (ORDER BY extract(epoch from (? - ?)) * 1000) FILTER (WHERE ? = 'completed' AND ? >= ? AND ? < ?)", + w.completed_at, + w.started_at, + w.status, + w.completed_at, + ^since, + w.completed_at, + ^until + ), + running: filter(count(w.id), w.status == :running), + waiting: filter(count(w.id), w.status == :waiting), + last_run_at: max(w.inserted_at) + } + ) + ) + |> Enum.map(fn row -> + Map.merge(row, %{ + failure_rate: if(row.finished > 0, do: row.failed / row.finished, else: 0.0), + p50_ms: round_ms(row.p50_ms), + p95_ms: round_ms(row.p95_ms) + }) + end) + end + + @doc """ + Per-step performance over attempts that started in the window, in the + order steps first ran. Durations are active time — sleeps and waits are + not attempts. Compensations are included with `compensation: true`. + + `failed_runs` counts runs whose last attempt at the step failed — runs that + gave up there, as opposed to `failed_attempts` that a retry recovered. + + [%{workflow: "fulfill_order", step: "ship_order", compensation: false, + runs: 660, attempts: 771, failed_attempts: 117, failed_runs: 41, + retried_runs: 121, p50_ms: 640, p95_ms: 2_140, max_ms: 6_040}] + """ + @spec step_performance(keyword()) :: [map()] + def step_performance(opts \\ []) do + {config, since, until} = window(opts) + + query = + from(s in StepExecution, + as: :step, + join: w in WorkflowExecution, + on: w.id == s.workflow_id, + where: s.started_at >= ^since and s.started_at < ^until and s.status != :waiting, + group_by: [w.workflow_name, s.step_name], + order_by: [asc: min(s.started_at)], + select: %{ + workflow: w.workflow_name, + step: s.step_name, + compensation: fragment("bool_or(?)", s.is_compensation), + runs: count(s.workflow_id, :distinct), + attempts: count(s.id), + failed_attempts: filter(count(s.id), s.status == :failed), + failed_runs: + filter( + count(s.workflow_id, :distinct), + s.status == :failed and + not exists( + from(later in StepExecution, + where: + later.workflow_id == parent_as(:step).workflow_id and + later.step_name == parent_as(:step).step_name and + later.status != :waiting and + later.started_at > parent_as(:step).started_at, + select: 1 + ) + ) + ), + retried_runs: + fragment("count(DISTINCT ?) FILTER (WHERE ? > 1)", s.workflow_id, s.attempt), + p50_ms: fragment("percentile_cont(0.5) WITHIN GROUP (ORDER BY ?)", s.duration_ms), + p95_ms: fragment("percentile_cont(0.95) WITHIN GROUP (ORDER BY ?)", s.duration_ms), + max_ms: max(s.duration_ms) + } + ) + + query = + case Keyword.get(opts, :workflow) do + nil -> query + name -> from([s, w] in query, where: w.workflow_name == ^name) + end + + config + |> Repo.all(query) + |> Enum.map(fn row -> %{row | p50_ms: round_ms(row.p50_ms), p95_ms: round_ms(row.p95_ms)} end) + end + + @doc """ + Every queue's state right now — configured queues are listed even when idle: + + [%{queue: "default", paused: false, running: 8, ready: 31, scheduled: 412, + oldest_ready_at: ~U[...], done_last_5m: 910, wait_p95_ms: 1_300}] + + `wait_p95_ms` is scheduled → started over the last hour. + """ + @spec queues(keyword()) :: [map()] + def queues(opts \\ []) do + config = Config.get(Keyword.get(opts, :durable, Durable)) + now = DateTime.utc_now() + hour_ago = DateTime.add(now, -3_600, :second) + five_min_ago = DateTime.add(now, -300, :second) + + live = + Repo.all( + config, + from(w in WorkflowExecution, + where: w.status in [:pending, :running], + group_by: w.queue, + select: + {w.queue, + %{ + running: filter(count(w.id), w.status == :running), + ready: + filter( + count(w.id), + w.status == :pending and (is_nil(w.scheduled_at) or w.scheduled_at <= ^now) + ), + scheduled: filter(count(w.id), w.status == :pending and w.scheduled_at > ^now), + # A raw fragment loses the column type; cast it back so the + # result is a DateTime rather than a NaiveDateTime. + oldest_ready_at: + type( + fragment( + "min(coalesce(?, ?)) FILTER (WHERE ? = 'pending' AND (? IS NULL OR ? <= ?))", + w.scheduled_at, + w.inserted_at, + w.status, + w.scheduled_at, + w.scheduled_at, + ^now + ), + :utc_datetime_usec + ) + }} + ) + ) + |> Map.new() + + recent = + Repo.all( + config, + from(w in WorkflowExecution, + where: not is_nil(w.started_at) and w.started_at >= ^hour_ago, + group_by: w.queue, + select: + {w.queue, + %{ + done_last_5m: filter(count(w.id), w.completed_at >= ^five_min_ago), + wait_p95_ms: + fragment( + "percentile_cont(0.95) WITHIN GROUP (ORDER BY extract(epoch from (? - coalesce(?, ?))) * 1000)", + w.started_at, + w.scheduled_at, + w.inserted_at + ) + }} + ) + ) + |> Map.new() + + paused = + MapSet.new( + Repo.all(config, from(q in Queue, where: not is_nil(q.paused_at), select: q.name)) + ) + + names = Enum.map(Map.keys(config.queues), &to_string/1) + + (names ++ Map.keys(live) ++ Map.keys(recent)) + |> Enum.uniq() + |> Enum.sort() + |> Enum.map(fn name -> + l = Map.get(live, name, %{running: 0, ready: 0, scheduled: 0, oldest_ready_at: nil}) + r = Map.get(recent, name, %{done_last_5m: 0, wait_p95_ms: nil}) + + Map.merge(l, %{ + queue: name, + paused: MapSet.member?(paused, name), + done_last_5m: r.done_last_5m, + wait_p95_ms: round_ms(r.wait_p95_ms) + }) + end) + end + + @doc """ + Each queue's depth per minute over the window, from `Durable.Queue.Sampler`, + oldest first. Minutes with no sample (no node was up) are absent. + + %{"default" => [%{at: ~U[2026-10-16 09:00:00Z], ready: 31, scheduled: 4, + running: 8, waiting: 120}, ...]} + """ + @spec queue_history(keyword()) :: %{String.t() => [map()]} + def queue_history(opts \\ []) do + {config, since, until} = window(opts) + + config + |> Repo.all( + from(s in QueueSample, + where: s.at >= ^since and s.at <= ^until, + order_by: [asc: s.at], + select: %{ + queue: s.queue, + at: s.at, + ready: s.ready, + scheduled: s.scheduled, + running: s.running, + waiting: s.waiting + } + ) + ) + |> Enum.group_by(& &1.queue, &Map.delete(&1, :queue)) + end + + # -------------------------------------------------------------------------- + + defp window(opts) do + config = Config.get(Keyword.get(opts, :durable, Durable)) + until = Keyword.get(opts, :until, DateTime.utc_now()) + since = Keyword.get(opts, :since, DateTime.add(until, -86_400, :second)) + {config, since, until} + end + + defp runs(opts) do + query = WorkflowExecution + + query = + if Keyword.get(opts, :include_children, false), + do: query, + else: from(w in query, where: is_nil(w.parent_workflow_id)) + + case Keyword.get(opts, :workflow) do + nil -> query + name -> from(w in query, where: w.workflow_name == ^name) + end + end + + defp ready(runs) do + now = DateTime.utc_now() + + from(w in runs, + where: w.status == :pending and (is_nil(w.scheduled_at) or w.scheduled_at <= ^now) + ) + end + + defp duration_percentiles(config, runs, since, until) do + Repo.one( + config, + from(w in runs, + where: w.status == :completed and w.completed_at >= ^since and w.completed_at < ^until, + where: not is_nil(w.started_at), + select: %{ + p50: + fragment( + "percentile_cont(0.5) WITHIN GROUP (ORDER BY extract(epoch from (? - ?)) * 1000)", + w.completed_at, + w.started_at + ), + p95: + fragment( + "percentile_cont(0.95) WITHIN GROUP (ORDER BY extract(epoch from (? - ?)) * 1000)", + w.completed_at, + w.started_at + ), + max: fragment("max(extract(epoch from (? - ?)) * 1000)", w.completed_at, w.started_at) + } + ) + ) + |> Map.new(fn {k, v} -> {k, round_ms(v)} end) + end + + defp queue_wait_percentiles(config, runs, since, until) do + Repo.one( + config, + from(w in runs, + where: w.inserted_at >= ^since and w.inserted_at < ^until and not is_nil(w.started_at), + select: %{ + p50: + fragment( + "percentile_cont(0.5) WITHIN GROUP (ORDER BY extract(epoch from (? - coalesce(?, ?))) * 1000)", + w.started_at, + w.scheduled_at, + w.inserted_at + ), + p95: + fragment( + "percentile_cont(0.95) WITHIN GROUP (ORDER BY extract(epoch from (? - coalesce(?, ?))) * 1000)", + w.started_at, + w.scheduled_at, + w.inserted_at + ) + } + ) + ) + |> Map.new(fn {k, v} -> {k, round_ms(v)} end) + end + + # Internal events (`__parallel_done:…`, `__child_done:…`) are plumbing, not + # something a person is waiting on. + defp waiting(config, opts) do + workflow = Keyword.get(opts, :workflow) + + scope = fn query -> + if workflow, + do: from([x, w] in query, where: w.workflow_name == ^workflow), + else: query + end + + inputs = + from(p in PendingInput, + join: w in WorkflowExecution, + on: w.id == p.workflow_id, + where: p.status == :pending + ) + + events = + from(e in PendingEvent, + join: w in WorkflowExecution, + on: w.id == e.workflow_id, + where: e.status == :pending and not like(e.event_name, "\\_\\_%") + ) + + sleeping = + from(w in WorkflowExecution, where: w.status == :waiting and not is_nil(w.scheduled_at)) + + sleeping = + if workflow, do: from(w in sleeping, where: w.workflow_name == ^workflow), else: sleeping + + %{ + input: Repo.one(config, from([p] in scope.(inputs), select: count(p.id))), + event: Repo.one(config, from([e] in scope.(events), select: count(e.id))), + sleeping: Repo.one(config, from(w in sleeping, select: count(w.id))) + } + end + + defp round_ms(nil), do: nil + defp round_ms(value) when is_float(value), do: round(value) + defp round_ms(%Decimal{} = value), do: value |> Decimal.round() |> Decimal.to_integer() + defp round_ms(value), do: value +end diff --git a/durable/lib/durable/storage/schemas/activity_event.ex b/durable/lib/durable/storage/schemas/activity_event.ex new file mode 100644 index 0000000..2603818 --- /dev/null +++ b/durable/lib/durable/storage/schemas/activity_event.ex @@ -0,0 +1,29 @@ +defmodule Durable.Storage.Schemas.ActivityEvent do + @moduledoc """ + An operational event, recorded by `Durable.Activity`. + """ + use Ecto.Schema + + @type t :: %__MODULE__{ + id: Ecto.UUID.t(), + at: DateTime.t(), + kind: String.t(), + node_id: String.t() | nil, + queue: String.t() | nil, + workflow_id: Ecto.UUID.t() | nil, + count: pos_integer(), + details: map() + } + + @primary_key {:id, :binary_id, autogenerate: true} + @schema_prefix "durable" + schema "activity" do + field(:at, :utc_datetime_usec) + field(:kind, :string) + field(:node_id, :string) + field(:queue, :string) + field(:workflow_id, :binary_id) + field(:count, :integer, default: 1) + field(:details, :map, default: %{}) + end +end diff --git a/durable/lib/durable/storage/schemas/node.ex b/durable/lib/durable/storage/schemas/node.ex new file mode 100644 index 0000000..3f5f37c --- /dev/null +++ b/durable/lib/durable/storage/schemas/node.ex @@ -0,0 +1,25 @@ +defmodule Durable.Storage.Schemas.Node do + @moduledoc """ + One row per running Durable instance, refreshed by `Durable.NodeRegistry`. + The id is the instance's node id, which pollers also stamp into + `workflow_executions.locked_by`. + """ + use Ecto.Schema + + @type t :: %__MODULE__{ + id: String.t(), + queues: [String.t()], + version: String.t() | nil, + started_at: DateTime.t(), + heartbeat_at: DateTime.t() + } + + @primary_key {:id, :string, autogenerate: false} + @schema_prefix "durable" + schema "nodes" do + field(:queues, {:array, :string}, default: []) + field(:version, :string) + field(:started_at, :utc_datetime_usec) + field(:heartbeat_at, :utc_datetime_usec) + end +end diff --git a/durable/lib/durable/storage/schemas/queue.ex b/durable/lib/durable/storage/schemas/queue.ex new file mode 100644 index 0000000..95155de --- /dev/null +++ b/durable/lib/durable/storage/schemas/queue.ex @@ -0,0 +1,22 @@ +defmodule Durable.Storage.Schemas.Queue do + @moduledoc """ + Cluster-wide queue state. A row exists only once a queue has been paused or + resumed; a queue with no row is active. Every node's claim query checks + `paused_at`, so pausing here stops the queue on all nodes at once. + """ + use Ecto.Schema + + @type t :: %__MODULE__{ + name: String.t(), + paused_at: DateTime.t() | nil, + inserted_at: DateTime.t(), + updated_at: DateTime.t() + } + + @primary_key {:name, :string, autogenerate: false} + @schema_prefix "durable" + schema "queues" do + field(:paused_at, :utc_datetime_usec) + timestamps(type: :utc_datetime_usec) + end +end diff --git a/durable/lib/durable/storage/schemas/queue_sample.ex b/durable/lib/durable/storage/schemas/queue_sample.ex new file mode 100644 index 0000000..208e1c7 --- /dev/null +++ b/durable/lib/durable/storage/schemas/queue_sample.ex @@ -0,0 +1,26 @@ +defmodule Durable.Storage.Schemas.QueueSample do + @moduledoc """ + A queue's depth at one minute, written by `Durable.Queue.Sampler`. + """ + use Ecto.Schema + + @type t :: %__MODULE__{ + queue: String.t(), + at: DateTime.t(), + ready: non_neg_integer(), + scheduled: non_neg_integer(), + running: non_neg_integer(), + waiting: non_neg_integer() + } + + @primary_key false + @schema_prefix "durable" + schema "queue_samples" do + field(:queue, :string, primary_key: true) + field(:at, :utc_datetime, primary_key: true) + field(:ready, :integer, default: 0) + field(:scheduled, :integer, default: 0) + field(:running, :integer, default: 0) + field(:waiting, :integer, default: 0) + end +end diff --git a/durable/lib/durable/storage/schemas/workflow_execution.ex b/durable/lib/durable/storage/schemas/workflow_execution.ex index 81b75c2..5440819 100644 --- a/durable/lib/durable/storage/schemas/workflow_execution.ex +++ b/durable/lib/durable/storage/schemas/workflow_execution.ex @@ -39,6 +39,9 @@ defmodule Durable.Storage.Schemas.WorkflowExecution do locked_at: DateTime.t() | nil, compensation_results: list(map()), compensated_at: DateTime.t() | nil, + retried_at: DateTime.t() | nil, + trigger: :api | :schedule | :parent | :rerun | nil, + trigger_ref: String.t() | nil, inserted_at: DateTime.t(), updated_at: DateTime.t() } @@ -85,6 +88,16 @@ defmodule Durable.Storage.Schemas.WorkflowExecution do field(:compensation_results, {:array, :map}, default: []) field(:compensated_at, :utc_datetime_usec) + # Operator controls: when Durable.retry/2 last resumed this run (attempt + # budgets count from here), and what started it. + field(:retried_at, :utc_datetime_usec) + field(:trigger, Ecto.Enum, values: [:api, :schedule, :parent, :rerun], default: :api) + field(:trigger_ref, :string) + + # Set from the workflow's `timeout:` when the run is created; a run past it + # fails with a "timeout" error before its next step. + field(:deadline_at, :utc_datetime_usec) + has_many(:step_executions, Durable.Storage.Schemas.StepExecution, foreign_key: :workflow_id) has_many(:pending_inputs, Durable.Storage.Schemas.PendingInput, foreign_key: :workflow_id) @@ -107,7 +120,10 @@ defmodule Durable.Storage.Schemas.WorkflowExecution do :locked_by, :locked_at, :compensation_results, - :compensated_at + :compensated_at, + :trigger, + :trigger_ref, + :deadline_at ] @doc """ @@ -162,14 +178,19 @@ defmodule Durable.Storage.Schemas.WorkflowExecution do Creates a changeset for marking workflow as compensated (all compensations succeeded). """ def compensated_changeset(execution, results) do + now = DateTime.utc_now() + + # A rolled-back run is finished too: completed_at marks the end of every + # terminal run, so durations and retention treat them alike. execution |> cast( %{ status: :compensated, compensation_results: results, - compensated_at: DateTime.utc_now() + compensated_at: now, + completed_at: now }, - [:status, :compensation_results, :compensated_at] + [:status, :compensation_results, :compensated_at, :completed_at] ) end @@ -183,9 +204,10 @@ defmodule Durable.Storage.Schemas.WorkflowExecution do status: :compensation_failed, compensation_results: results, error: error, - compensated_at: DateTime.utc_now() + compensated_at: DateTime.utc_now(), + completed_at: DateTime.utc_now() }, - [:status, :compensation_results, :error, :compensated_at] + [:status, :compensation_results, :error, :compensated_at, :completed_at] ) end end diff --git a/durable/lib/durable/supervisor.ex b/durable/lib/durable/supervisor.ex index a356637..fb85253 100644 --- a/durable/lib/durable/supervisor.ex +++ b/durable/lib/durable/supervisor.ex @@ -103,7 +103,14 @@ defmodule Durable.Supervisor do [] end - base_children = pubsub_children ++ [{Task.Supervisor, name: task_sup_name}] + base_children = + pubsub_children ++ + [ + {Task.Supervisor, name: task_sup_name}, + {Durable.NodeRegistry, config: config}, + {Durable.Queue.Sampler, config: config} + ] ++ + if(config.prune, do: [{Durable.Pruner, config: config}], else: []) children = if config.queue_enabled do diff --git a/durable/lib/durable/telemetry.ex b/durable/lib/durable/telemetry.ex new file mode 100644 index 0000000..fcec8c9 --- /dev/null +++ b/durable/lib/durable/telemetry.ex @@ -0,0 +1,224 @@ +defmodule Durable.Telemetry do + @moduledoc """ + The `:telemetry` events Durable emits. This list is a contract: names, + measurements and metadata keys only change in a major version. + + Spans follow `:telemetry.span/3`: a `:start` event, then exactly one of + `:stop` or `:exception`, with `duration` in native time units — the same + shape as Phoenix, Ecto and Oban, so existing tooling reads them as-is. + + Run, step, compensation and schedule events include `:durable` (the + instance name) in their metadata. + + ## Runs + + A run executes in *segments*: it starts, runs until it finishes or suspends + (sleep, wait for an event or input, parallel fan-out), and later resumes as + a new segment, possibly on another node. Each segment is one span. + + * `[:durable, :workflow, :start]` — `%{system_time, monotonic_time}`; + metadata `:workflow_id`, `:workflow`, `:workflow_module`, `:queue`, + `:trigger`, `:resumed` (false on a run's first segment) + * `[:durable, :workflow, :stop]` — `%{duration, monotonic_time}`; adds + `:status`: `:completed`, `:failed`, `:compensated`, + `:compensation_failed`, `:waiting` (suspended) or `:superseded` + (cancelled or reclaimed by another node mid-segment) + * `[:durable, :workflow, :exception]` — the executor itself crashed; + adds `:kind`, `:reason`, `:stacktrace` + + ## Steps + + One span per attempt. A step that raises or returns an error is a normal + `:stop` with `result: :error` — `:exception` means Durable itself failed. + + * `[:durable, :step, :start]` — metadata `:workflow_id`, `:workflow`, + `:step`, `:step_type`, `:attempt`, `:max_attempts` + * `[:durable, :step, :stop]` — adds `:result` (`:ok`, `:error` or + `:suspended`) and, for errors, `:error` (`%{type, message}`) + * `[:durable, :step, :exception]` + * `[:durable, :step, :retry]` — `%{backoff_ms}`; the step metadata plus + `:error`, emitted before sleeping for the next attempt + + ## Compensations + + * `[:durable, :compensation, :start | :stop | :exception]` — metadata + `:workflow_id`, `:workflow`, `:compensation`, `:step` (the step it + undoes); `:stop` adds `:result` (`:ok` or `:error`) + + ## Queue, scheduler and waits + + * `[:durable, :queue, :job_claimed]` — `%{count}`; `:job_id`, `:queue`, `:node_id` + * `[:durable, :queue, :job_completed]` — `%{duration}`; `:job_id`, + `:queue`, `:workflow_module`, `:workflow_name`, `:status` + * `[:durable, :queue, :poll]` — `%{jobs_fetched}`; `:queue`, `:available_slots` + * `[:durable, :queue, :heartbeat]` — `%{count}`; `:job_id`, `:queue` + * `[:durable, :queue, :stale_recovered]`, `[:durable, :queue, :zombie_recovered]` — `%{count}` + * `[:durable, :queue, :worker_fenced]` — `%{count, duration}`; `:job_id`, `:queue` + * `[:durable, :queue, :ack_failed]` — `%{count, attempts}`; `:job_id`, `:reason` + * `[:durable, :schedule, :trigger]` — `%{count}`; `:schedule`, + `:workflow_id`, `:workflow_module`, `:workflow`, `:queue` + * `[:durable, :wait, :sleep_woken]` — `%{count}` + * `[:durable, :pruner, :pruned]` — `%{count}`; `:group` (`:completed`, + `:failed` or `:cancelled`), once per deleted batch + + ## Reporting + + `metrics/0` returns `Telemetry.Metrics` definitions for any reporter + (Prometheus, StatsD, LiveDashboard) when `:telemetry_metrics` is installed: + + def metrics, do: my_metrics() ++ Durable.Telemetry.metrics() + + `attach_default_logger/1` logs one line per finished run and per failed step. + """ + + require Logger + + @events [ + [:durable, :workflow, :start], + [:durable, :workflow, :stop], + [:durable, :workflow, :exception], + [:durable, :step, :start], + [:durable, :step, :stop], + [:durable, :step, :exception], + [:durable, :step, :retry], + [:durable, :compensation, :start], + [:durable, :compensation, :stop], + [:durable, :compensation, :exception], + [:durable, :queue, :job_claimed], + [:durable, :queue, :job_completed], + [:durable, :queue, :poll], + [:durable, :queue, :heartbeat], + [:durable, :queue, :stale_recovered], + [:durable, :queue, :zombie_recovered], + [:durable, :queue, :worker_fenced], + [:durable, :queue, :ack_failed], + [:durable, :schedule, :trigger], + [:durable, :wait, :sleep_woken], + [:durable, :pruner, :pruned] + ] + + @doc """ + Every event name Durable emits, for `:telemetry.attach_many/4`. + """ + @spec events() :: [[atom()]] + def events, do: @events + + @logger_id "durable-default-logger" + + @doc """ + Logs one line per finished run (`level`, default `:info`) and one warning + per failed step attempt. Detach with `:telemetry.detach("#{@logger_id}")`. + """ + @spec attach_default_logger(keyword()) :: :ok | {:error, :already_exists} + def attach_default_logger(opts \\ []) do + :telemetry.attach_many( + @logger_id, + [[:durable, :workflow, :stop], [:durable, :workflow, :exception], [:durable, :step, :stop]], + &__MODULE__.handle_log_event/4, + Keyword.get(opts, :level, :info) + ) + end + + # Telemetry handlers run in the step's process, so without this the step's + # log capture would record these lines as if the step had logged them. + @internal [durable_internal: true] + + @doc false + def handle_log_event([:durable, :workflow, :stop], %{duration: duration}, meta, level) do + Logger.log( + if(meta.status in [:failed, :compensation_failed], do: :error, else: level), + "[Durable] #{meta.workflow} #{meta.workflow_id} #{meta.status} in #{ms(duration)}ms", + @internal + ) + end + + def handle_log_event([:durable, :workflow, :exception], _measurements, meta, _level) do + Logger.error( + "[Durable] #{meta.workflow} #{meta.workflow_id} crashed: " <> + Exception.format(meta.kind, meta.reason, meta.stacktrace), + @internal + ) + end + + def handle_log_event( + [:durable, :step, :stop], + %{duration: duration}, + %{result: :error} = meta, + _ + ) do + Logger.warning( + "[Durable] #{meta.workflow} #{meta.workflow_id} step #{meta.step} failed " <> + "(attempt #{meta.attempt}/#{meta.max_attempts}, #{ms(duration)}ms): " <> + "#{meta.error.type}: #{meta.error.message}", + @internal + ) + end + + def handle_log_event(_event, _measurements, _meta, _level), do: :ok + + defp ms(native), do: System.convert_time_unit(native, :native, :millisecond) + + # `:telemetry_metrics` is optional, so no `import` here: an import is + # expanded even inside a false `if` and would break compilation for apps + # that don't install it. + @compile {:no_warn_undefined, Telemetry.Metrics} + + if Code.ensure_loaded?(Telemetry.Metrics) do + alias Telemetry.Metrics + + # ms buckets from a fast step to a slow run; reporters without buckets + # ignore them. + @buckets [10, 50, 100, 250, 500, 1_000, 2_500, 5_000, 10_000, 30_000, 60_000, 300_000] + + @doc """ + `Telemetry.Metrics` definitions for Durable's events. Tags are bounded — + workflow, step, queue and schedule names, never run ids. + """ + @spec metrics() :: [Telemetry.Metrics.t()] + def metrics do + ms = [unit: {:native, :millisecond}, reporter_options: [buckets: @buckets]] + # Counters count events. Most of these events carry no `:count`, and + # LiveDashboard drops an event whose measurement is missing. + event = fn _measurements -> 1 end + + [ + Metrics.counter("durable.workflow.stop.count", + tags: [:workflow, :status], + measurement: event + ), + Metrics.distribution( + "durable.workflow.stop.duration", + [tags: [:workflow, :status]] ++ ms + ), + Metrics.counter("durable.step.stop.count", + tags: [:workflow, :step, :result], + measurement: event + ), + Metrics.distribution("durable.step.stop.duration", [tags: [:workflow, :step]] ++ ms), + Metrics.counter("durable.step.retry.count", tags: [:workflow, :step], measurement: event), + Metrics.counter("durable.compensation.stop.count", + tags: [:workflow, :compensation, :result], + measurement: event + ), + Metrics.distribution( + "durable.queue.job_completed.duration", + [tags: [:queue, :status]] ++ ms + ), + Metrics.counter("durable.queue.worker_fenced.count", tags: [:queue], measurement: event), + Metrics.sum("durable.queue.stale_recovered.count", []), + Metrics.sum("durable.queue.zombie_recovered.count", []), + Metrics.counter("durable.schedule.trigger.count", tags: [:schedule], measurement: event) + ] + end + end + + # Run-level metadata, shared with the step and compensation spans that run + # inside it (they only know the workflow id). + @meta_key {__MODULE__, :run} + + @doc false + def put_run_meta(meta), do: Process.put(@meta_key, meta) + + @doc false + def run_meta, do: Process.get(@meta_key, %{}) +end diff --git a/durable/lib/durable/wait/timeout_worker.ex b/durable/lib/durable/wait/timeout_worker.ex index 0addcd1..c31ba06 100644 --- a/durable/lib/durable/wait/timeout_worker.ex +++ b/durable/lib/durable/wait/timeout_worker.ex @@ -1,6 +1,8 @@ defmodule Durable.Wait.TimeoutWorker do @moduledoc """ - Background worker that enforces timeouts for pending inputs and events. + Background worker that enforces timeouts for pending inputs and events, and + wakes waiting runs that passed their workflow `timeout:` so they fail now + rather than when their wait ends. Periodically checks for timed-out waits and either: - Resumes the workflow with the timeout_value (if on_timeout: :resume) @@ -93,6 +95,38 @@ defmodule Durable.Wait.TimeoutWorker do process_timed_out_inputs(config, now) process_timed_out_events(config, now) process_timed_out_wait_groups(config, now) + process_expired_runs(config, now) + end + + # A waiting run past its deadline is resumed; the executor sees the deadline + # before the step re-runs and fails the run (running its compensations). + # Resume first, so an input answered at the same moment isn't marked timed + # out; only then close the waits it no longer needs. + defp process_expired_runs(config, now) do + ids = + Repo.all( + config, + from(w in WorkflowExecution, + where: w.status == :waiting and w.deadline_at <= ^now, + select: w.id, + limit: 500 + ) + ) + + for id <- ids, + {:ok, _} <- [Executor.resume_workflow(id, %{}, durable: config.name)] do + close_waits(config, id, now) + end + end + + defp close_waits(config, workflow_id, now) do + for schema <- [PendingInput, PendingEvent, WaitGroup] do + Repo.update_all( + config, + from(p in schema, where: p.workflow_id == ^workflow_id and p.status == :pending), + set: [status: :timeout, completed_at: now] + ) + end end defp process_timed_out_inputs(config, now) do diff --git a/durable/mix.exs b/durable/mix.exs index 4e2e761..da78a0a 100644 --- a/durable/mix.exs +++ b/durable/mix.exs @@ -68,11 +68,13 @@ defmodule Durable.MixProject do {:crontab, "~> 1.1"}, {:igniter, "~> 0.6", optional: true}, {:phoenix_pubsub, "~> 2.1", optional: true}, + {:telemetry_metrics, "~> 1.0", optional: true}, # Dev/Test {:ex_doc, "~> 0.34", only: :dev, runtime: false}, {:credo, "~> 1.7", only: [:dev, :test], runtime: false}, - {:dialyxir, "~> 1.4", only: [:dev, :test], runtime: false} + {:dialyxir, "~> 1.4", only: [:dev, :test], runtime: false}, + {:stream_data, "~> 1.1", only: [:dev, :test]} ] end diff --git a/durable/mix.lock b/durable/mix.lock index 0f99140..22a2c76 100644 --- a/durable/mix.lock +++ b/durable/mix.lock @@ -31,6 +31,8 @@ "rewrite": {:hex, :rewrite, "1.2.0", "80220eb14010e175b67c939397e1a8cdaa2c32db6e2e0a9d5e23e45c0414ce21", [:mix], [{:glob_ex, "~> 0.1", [hex: :glob_ex, repo: "hexpm", optional: false]}, {:sourceror, "~> 1.0", [hex: :sourceror, repo: "hexpm", optional: false]}, {:text_diff, "~> 0.1", [hex: :text_diff, repo: "hexpm", optional: false]}], "hexpm", "a1cd702bbb9d51613ab21091f04a386d750fc6f4516b81900df082d78b2d8c50"}, "sourceror": {:hex, :sourceror, "1.10.0", "38397dedbbc286966ec48c7af13e228b171332be1ad731974438c77791945ce9", [:mix], [], "hexpm", "29dbdfc92e04569c9d8e6efdc422fc1d815f4bd0055dc7c51b8800fb75c4b3f1"}, "spitfire": {:hex, :spitfire, "0.2.1", "29e154873f05444669c7453d3d931820822cbca5170e88f0f8faa1de74a79b47", [:mix], [], "hexpm", "6eeed75054a38341b2e1814d41bb0a250564092358de2669fdb57ff88141d91b"}, + "stream_data": {:hex, :stream_data, "1.4.0", "026f929db613aabea6208012ae9b8970d3fd5f88b3bdf26831bc536f98c42036", [:mix], [], "hexpm", "2b0ee3a340dcce1c8cf6302a763ee757d1e01c54d6e16d9069062509d68b1dc9"}, "telemetry": {:hex, :telemetry, "1.3.0", "fedebbae410d715cf8e7062c96a1ef32ec22e764197f70cda73d82778d61e7a2", [:rebar3], [], "hexpm", "7015fc8919dbe63764f4b4b87a95b7c0996bd539e0d499be6ec9d7f3875b79e6"}, + "telemetry_metrics": {:hex, :telemetry_metrics, "1.2.0", "7632c19c01d88d8aaca5da1a0e8912f5af39b79e7c08a2c253aeb3c14c2c957e", [:mix], [{:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "71dde12fc29b58b9c77ec17ec319109e5ca848d010fc1965ed4463bba1837c07"}, "text_diff": {:hex, :text_diff, "0.1.0", "1caf3175e11a53a9a139bc9339bd607c47b9e376b073d4571c031913317fecaa", [:mix], [], "hexpm", "d1ffaaecab338e49357b6daa82e435f877e0649041ace7755583a0ea3362dbd7"}, } diff --git a/durable/test/durable/activity_test.exs b/durable/test/durable/activity_test.exs new file mode 100644 index 0000000..44ff787 --- /dev/null +++ b/durable/test/durable/activity_test.exs @@ -0,0 +1,65 @@ +defmodule Durable.ActivityTest do + @moduledoc """ + Queue history (the per-minute sampler) and the operational activity log. + """ + use Durable.DataCase, async: false + + alias Durable.Activity + alias Durable.Config + alias Durable.Queue.Sampler + alias Durable.Stats + alias Durable.Storage.Schemas.{QueueSample, WorkflowExecution} + + defp config, do: Config.get(Durable) + + defp run!(status, attrs \\ %{}) do + config().repo.insert!( + struct( + WorkflowExecution, + Map.merge( + %{workflow_module: "Elixir.Unused", workflow_name: "unused", status: status}, + attrs + ) + ) + ) + end + + test "the sampler writes one row per queue per minute, however often it runs" do + run!(:pending) + run!(:pending, %{scheduled_at: DateTime.add(DateTime.utc_now(), 3_600, :second)}) + run!(:running) + run!(:waiting, %{queue: "emails"}) + + Sampler.sample(config()) + Sampler.sample(config()) + + history = Stats.queue_history() + assert [%{ready: 1, scheduled: 1, running: 1, waiting: 0}] = history["default"] + assert [%{waiting: 1}] = history["emails"] + assert config().repo.aggregate(QueueSample, :count) == 2 + end + + test "pausing and resuming a queue is recorded with who did it" do + :ok = Durable.pause_queue(:default, by: "ops@example.com") + :ok = Durable.resume_queue(:default) + + assert [ + %{kind: "queue_resumed", queue: "default", details: %{}}, + %{kind: "queue_paused", queue: "default", details: %{"by" => "ops@example.com"}} + ] = Activity.list() + end + + test "recording never raises, even for details that can't be stored as JSON" do + assert :ok = Activity.record(config(), "worker_fenced", details: %{pid: self()}) + assert [%{kind: "worker_fenced", details: %{"pid" => "#PID<" <> _}}] = Activity.list() + end + + test "pruning records how many runs it deleted" do + old = DateTime.add(DateTime.utc_now(), -10_000, :second) + run!(:completed, %{completed_at: old, updated_at: old}) + + Durable.Pruner.prune(%{config() | prune: [completed: 1_000]}) + + assert [%{kind: "pruned", count: 1, details: %{"completed" => 1}}] = Activity.list() + end +end diff --git a/durable/test/durable/block_ids_test.exs b/durable/test/durable/block_ids_test.exs new file mode 100644 index 0000000..bd35d69 --- /dev/null +++ b/durable/test/durable/block_ids_test.exs @@ -0,0 +1,73 @@ +defmodule Durable.BlockIdsTest do + @moduledoc """ + Steps inside `parallel` and `branch` blocks are named after their block's + id, and those names are stored on runs. The ids must come out the same on + every compile, or a run suspended inside a block can't resume after a deploy. + """ + use ExUnit.Case, async: true + + @source """ + defmodule MODULE do + use Durable + use Durable.Context + + workflow "fan_out" do + step :start, fn data -> {:ok, data} end + + parallel do + step :a, fn data -> {:ok, data} end + step :b, fn data -> {:ok, BODY} end + end + + branch on: fn data -> data[:kind] end do + :x -> step :on_x, fn data -> {:ok, data} end + _ -> step :otherwise, fn data -> {:ok, data} end + end + end + + workflow "twin" do + parallel do + step :a, fn data -> {:ok, data} end + step :b, fn data -> {:ok, data} end + end + end + end + """ + + defp compile(module, body) do + @source + |> String.replace("MODULE", inspect(module)) + |> String.replace("BODY", body) + |> Code.compile_string() + + for name <- ["fan_out", "twin"], into: %{} do + {:ok, definition} = module.__workflow_definition__(name) + {name, Enum.map(definition.steps, & &1.name)} + end + end + + test "ids survive a recompile and edits to step bodies" do + first = compile(Durable.BlockIdsTest.First, "data") + second = compile(Durable.BlockIdsTest.Second, "Map.put(data, :edited, true)") + + assert first == second + end + + test "identical blocks in one module get different ids" do + names = compile(Durable.BlockIdsTest.Third, "data") + + [fan_out_parallel] = + for n <- names["fan_out"], + String.starts_with?(to_string(n), "parallel_") and + not String.contains?(to_string(n), "__"), + do: n + + [twin_parallel] = + for n <- names["twin"], + String.starts_with?(to_string(n), "parallel_") and + not String.contains?(to_string(n), "__"), + do: n + + assert fan_out_parallel != twin_parallel + end +end diff --git a/durable/test/durable/cancellation_test.exs b/durable/test/durable/cancellation_test.exs new file mode 100644 index 0000000..0a793c1 --- /dev/null +++ b/durable/test/durable/cancellation_test.exs @@ -0,0 +1,161 @@ +defmodule Durable.CancellationTest do + @moduledoc """ + A cancel must stick. When it lands while a run is executing, the run stops at + the next step boundary, and nothing the executor writes afterwards + (completion, failure, waiting) may overwrite `:cancelled`. + """ + use Durable.DataCase, async: false + use ExUnitProperties + + alias Durable.{Config, Executor} + alias Durable.Storage.Schemas.WorkflowExecution + + import Durable.DataCase, only: [create_and_execute_workflow: 2, get_step_executions: 1] + + defmodule FiveSteps do + @moduledoc false + use Durable + + # Input knobs (string or atom keys — data round-trips through JSONB): + # "cancel_at" — the step that cancels its own run, as a concurrent + # operator would, mid-step + # "fail_at" — the step that raises + # "sleep_ms" — how long every step takes + def act(i, data) do + if ms = knob(data, :sleep_ms), do: Process.sleep(ms) + if knob(data, :cancel_at) == i, do: Durable.cancel(Durable.Context.workflow_id()) + if knob(data, :fail_at) == i, do: raise("boom at step #{i}") + {:ok, data} + end + + defp knob(data, key), do: Map.get(data, key) || Map.get(data, Atom.to_string(key)) + + workflow "five_steps" do + step(:s1, fn data -> __MODULE__.act(1, data) end) + step(:s2, fn data -> __MODULE__.act(2, data) end) + step(:s3, fn data -> __MODULE__.act(3, data) end) + step(:s4, fn data -> __MODULE__.act(4, data) end) + step(:s5, fn data -> __MODULE__.act(5, data) end) + end + end + + defmodule WaitsForGo do + @moduledoc false + use Durable + use Durable.Wait + + workflow "waits_for_go" do + step(:ask, fn data -> + _ = wait_for_input("go") + {:ok, data} + end) + + step(:done, fn data -> {:ok, data} end) + end + end + + defp status(id), do: Config.get(Durable).repo.get!(WorkflowExecution, id).status + + defp steps_started(id) do + id + |> get_step_executions() + |> Enum.map(fn s -> s.step_name |> String.trim_leading("s") |> String.to_integer() end) + |> Enum.uniq() + end + + describe "cancel landing mid-run" do + test "stops the run before the next step" do + {:ok, exec} = create_and_execute_workflow(FiveSteps, %{"cancel_at" => 2}) + + assert exec.status == :cancelled + assert steps_started(exec.id) == [1, 2] + end + + test "is not overwritten when the last step completes" do + {:ok, exec} = create_and_execute_workflow(FiveSteps, %{"cancel_at" => 5}) + + assert exec.status == :cancelled + end + + test "is not overwritten when the same step then fails" do + {:ok, exec} = create_and_execute_workflow(FiveSteps, %{"cancel_at" => 3, "fail_at" => 3}) + + assert exec.status == :cancelled + assert steps_started(exec.id) == [1, 2, 3] + end + end + + test "cancelling a finished run is rejected and leaves it finished" do + {:ok, exec} = create_and_execute_workflow(FiveSteps, %{}) + + assert Durable.cancel(exec.id) == {:error, :already_completed} + assert status(exec.id) == :completed + end + + property "any mix of cancel and failure points: the earlier one decides, nothing runs after it" do + check all( + cancel_at <- one_of([constant(nil), integer(1..5)]), + fail_at <- one_of([constant(nil), integer(1..5)]), + max_runs: 60 + ) do + {:ok, exec} = + create_and_execute_workflow(FiveSteps, %{"cancel_at" => cancel_at, "fail_at" => fail_at}) + + stop_at = Enum.min([cancel_at || 6, fail_at || 6, 5]) + + expected = + cond do + cancel_at && cancel_at <= (fail_at || 6) -> :cancelled + fail_at -> :failed + true -> :completed + end + + assert exec.status == expected + assert steps_started(exec.id) == Enum.to_list(1..stop_at) + end + end + + property "a concurrent cancel either wins or is rejected — never reports success and loses" do + check all( + cancel_after_ms <- integer(0..25), + step_ms <- integer(0..6), + max_runs: 40 + ) do + {:ok, id} = Durable.start(FiveSteps, %{"sleep_ms" => step_ms}) + run = Task.async(fn -> Executor.execute_workflow(id, Config.get(Durable)) end) + + Process.sleep(cancel_after_ms) + cancel_result = Durable.cancel(id) + Task.await(run, 5_000) + + case cancel_result do + :ok -> assert status(id) == :cancelled + {:error, :already_completed} -> assert status(id) == :completed + end + end + end + + property "cancel racing provide_input on a waiting run: the cancel always sticks" do + check all( + input_first? <- boolean(), + jitter_ms <- integer(0..3), + max_runs: 80 + ) do + {:ok, exec} = create_and_execute_workflow(WaitsForGo, %{}) + assert exec.status == :waiting + + cancel = fn -> Durable.cancel(exec.id) end + answer = fn -> Durable.provide_input(exec.id, "go", %{"ok" => true}) end + {first, second} = if input_first?, do: {answer, cancel}, else: {cancel, answer} + + t1 = Task.async(first) + Process.sleep(jitter_ms) + t2 = Task.async(second) + Task.await_many([t1, t2], 5_000) + + # Waiting and pending runs are both cancellable, so whichever lands + # first, the run must end cancelled — a resume may never undo it. + assert status(exec.id) == :cancelled + end + end +end diff --git a/durable/test/durable/compensation_test.exs b/durable/test/durable/compensation_test.exs index ffa6c97..0721e92 100644 --- a/durable/test/durable/compensation_test.exs +++ b/durable/test/durable/compensation_test.exs @@ -155,8 +155,10 @@ defmodule Durable.CompensationTest do {:ok, execution} = create_and_execute_workflow(BookTripWorkflow, %{}) workflow_id = execution.id - # Workflow should be in compensated state + # Workflow should be in compensated state, finished like any other + # terminal run assert execution.status == :compensated + assert execution.completed_at != nil # Check compensation results results = execution.compensation_results @@ -190,6 +192,7 @@ defmodule Durable.CompensationTest do {:ok, execution} = create_and_execute_workflow(FailingCompensationWorkflow, %{}) assert execution.status == :compensation_failed + assert execution.completed_at != nil # Should have the original error assert execution.error["message"] == "Step failed" diff --git a/durable/test/durable/error_capture_test.exs b/durable/test/durable/error_capture_test.exs new file mode 100644 index 0000000..fe87445 --- /dev/null +++ b/durable/test/durable/error_capture_test.exs @@ -0,0 +1,96 @@ +defmodule Durable.ErrorCaptureTest do + @moduledoc """ + A failed step keeps what went wrong — the exception's type, a readable + message and the stack, file and line per frame — however it failed. + """ + use Durable.DataCase, async: false + + alias Durable.Config + alias Durable.Executor + alias Durable.Storage.Schemas.{StepExecution, WorkflowExecution} + + defmodule Failing do + use Durable + use Durable.Helpers + + workflow "raises" do + step(:boom, fn _data -> raise ArgumentError, "bad amount" end) + end + + workflow "exits" do + step(:call, fn _data -> exit({:timeout, {GenServer, :call, [:payments, :charge, 5000]}}) end) + end + + workflow "branch_raises" do + step(:start, fn data -> {:ok, data} end) + + branch on: fn _data -> raise KeyError, key: :tier, term: %{} end do + :gold -> step(:gold, fn data -> {:ok, data} end) + end + end + + workflow "compensation_raises" do + step(:reserve, [compensate: :release], fn data -> {:ok, data} end) + step(:charge, fn _data -> raise "card declined" end) + compensate(:release, fn _data -> raise RuntimeError, "release failed" end) + end + end + + defp repo, do: Config.get(Durable).repo + defp run(id), do: repo().get!(WorkflowExecution, id) + + defp step_error(id, name) do + repo().one!( + from(s in StepExecution, + where: s.workflow_id == ^id and s.step_name == ^name, + order_by: [desc: s.inserted_at], + limit: 1, + select: s.error + ) + ) + end + + defp start(name) do + {:ok, definition} = Failing.__workflow_definition__(name) + {:ok, id} = Executor.start_workflow(Failing, %{}, inline: true, workflow: definition.name) + id + end + + test "a raised exception keeps its type, message and a stack with file and line" do + id = start("raises") + + assert %{"type" => "ArgumentError", "message" => "bad amount", "stacktrace" => stack} = + step_error(id, "boom") + + assert stack =~ ~r"test/durable/error_capture_test\.exs:\d+" + assert %{"stacktrace" => ^stack} = run(id).error + end + + test "an exit is stored readably, with its stack" do + id = start("exits") + + assert %{"type" => "exit", "message" => message, "stacktrace" => stack} = + step_error(id, "call") + + assert message =~ "GenServer.call(:payments, :charge, 5000)" + assert message =~ "time out" + assert stack =~ "error_capture_test.exs" + end + + test "a branch's on: function that raises keeps the exception and its stack" do + id = start("branch_raises") + + assert %{"type" => "KeyError", "message" => message, "stacktrace" => stack} = run(id).error + assert message =~ ":tier" + assert stack =~ "error_capture_test.exs" + end + + test "a compensation that raises keeps its stack too" do + id = start("compensation_raises") + + assert %{"type" => "RuntimeError", "message" => "release failed", "stacktrace" => stack} = + step_error(id, "compensate_release") + + assert stack =~ "error_capture_test.exs" + end +end diff --git a/durable/test/durable/operations_test.exs b/durable/test/durable/operations_test.exs new file mode 100644 index 0000000..20559eb --- /dev/null +++ b/durable/test/durable/operations_test.exs @@ -0,0 +1,141 @@ +defmodule Durable.OperationsTest do + @moduledoc """ + Running Durable in production: the retention pruner and the node registry. + """ + use Durable.DataCase, async: false + use ExUnitProperties + + alias Durable.Config + alias Durable.Pruner + alias Durable.Storage.Schemas.{Node, StepExecution, WorkflowExecution} + + @statuses [:pending, :running, :waiting, :completed, :failed, :cancelled, :compensated] + @group %{completed: :completed, failed: :failed, compensated: :failed, cancelled: :cancelled} + + defp insert_run!(status, age_ms) do + repo = Config.get(Durable).repo + finished_at = DateTime.add(DateTime.utc_now(), -age_ms, :millisecond) + + run = + repo.insert!(%WorkflowExecution{ + workflow_module: "Elixir.Unused", + workflow_name: "unused", + status: status, + completed_at: if(status in [:completed, :failed, :cancelled], do: finished_at), + updated_at: finished_at + }) + + repo.insert!(%StepExecution{workflow_id: run.id, step_name: "s", status: :completed}) + run + end + + defp ids(schema), do: schema |> Config.get(Durable).repo.all() |> MapSet.new(& &1.id) + + describe "pruner" do + test "deletes finished runs past their group's age, with their steps" do + config = %{Config.get(Durable) | prune: [completed: 1_000, failed: 60_000]} + + old_done = insert_run!(:completed, 5_000) + fresh_done = insert_run!(:completed, 10) + old_failed = insert_run!(:failed, 120_000) + rolled_back = insert_run!(:compensated, 120_000) + young_failed = insert_run!(:failed, 5_000) + old_cancelled = insert_run!(:cancelled, 120_000) + old_running = insert_run!(:running, 120_000) + + assert Pruner.prune(config) == %{completed: 1, failed: 2} + + survivors = ids(WorkflowExecution) + for gone <- [old_done, old_failed, rolled_back], do: refute(gone.id in survivors) + + for kept <- [fresh_done, young_failed, old_cancelled, old_running], + do: assert(kept.id in survivors) + + steps = Config.get(Durable).repo.all(StepExecution) + refute Enum.any?(steps, &(&1.workflow_id == old_done.id)) + end + + test "is a no-op without a :prune policy" do + insert_run!(:completed, 999_999_999) + assert Durable.prune() == %{} + end + end + + property "the pruner deletes exactly the finished runs older than their group's limit" do + check all( + runs <- list_of(tuple({member_of(@statuses), integer(0..100_000)}), max_length: 12), + policy <- + fixed_map(%{ + completed: one_of([constant(nil), integer(1..100_000)]), + failed: one_of([constant(nil), integer(1..100_000)]), + cancelled: one_of([constant(nil), integer(1..100_000)]) + }), + max_runs: 40 + ) do + Config.get(Durable).repo.delete_all(WorkflowExecution) + policy = for {group, ms} <- policy, ms, do: {group, ms} + config = %{Config.get(Durable) | prune: policy} + + inserted = for {status, age} <- runs, do: {insert_run!(status, age), status, age} + Pruner.prune(config) + survivors = ids(WorkflowExecution) + + for {run, status, age} <- inserted do + limit = policy[@group[status]] + # A run right at its limit races the clock; only assert clear cases. + if limit == nil or age < limit - 50, do: assert(run.id in survivors) + if limit != nil and age > limit + 50, do: refute(run.id in survivors) + end + end + end + + describe "node registry" do + test "this node heartbeats into durable.nodes and is reported alive" do + node_id = Config.get(Durable).node_id + + assert_eventually(fn -> + Enum.any?(Durable.list_nodes(), &(&1.id == node_id and &1.status == :alive)) + end) + end + + test "a node whose heartbeat is 30 s old is reported missing" do + stale = DateTime.add(DateTime.utc_now(), -31, :second) + + Config.get(Durable).repo.insert!(%Node{ + id: "gone-node", + queues: ["default"], + started_at: stale, + heartbeat_at: stale + }) + + assert %{status: :missing} = Enum.find(Durable.list_nodes(), &(&1.id == "gone-node")) + end + + test "counts the runs each node holds a lock on" do + now = DateTime.utc_now() + repo = Config.get(Durable).repo + repo.insert!(%Node{id: "busy-node", queues: [], started_at: now, heartbeat_at: now}) + + for status <- [:running, :running, :completed] do + repo.insert!(%WorkflowExecution{ + workflow_module: "Elixir.Unused", + workflow_name: "unused", + status: status, + locked_by: "busy-node" + }) + end + + assert %{running: 2} = Enum.find(Durable.list_nodes(), &(&1.id == "busy-node")) + end + + test "a cleanly stopped node removes its row" do + node_id = Config.get(Durable).node_id + assert_eventually(fn -> Enum.any?(Durable.list_nodes(), &(&1.id == node_id)) end) + + stop_supervised!(Durable) + + repo = Durable.TestRepo + refute repo.get(Node, node_id, prefix: "durable") + end + end +end diff --git a/durable/test/durable/operator_controls_test.exs b/durable/test/durable/operator_controls_test.exs new file mode 100644 index 0000000..5f5c11b --- /dev/null +++ b/durable/test/durable/operator_controls_test.exs @@ -0,0 +1,241 @@ +defmodule Durable.OperatorControlsTest do + @moduledoc """ + The 1.0 operator controls: retry a failed run from its failed step, rerun a + finished run, pause a queue across the cluster, and record what started + each run. + """ + use Durable.DataCase, async: false + use ExUnitProperties + + alias Durable.Config + alias Durable.Executor + alias Durable.Queue.Adapters.Postgres + alias Durable.Storage.Schemas.{StepExecution, WorkflowExecution} + + import Durable.DataCase, + only: [create_and_execute_workflow: 2, execute_children: 3, get_child_executions: 2] + + # Steps run inline in the test process, so the process dictionary is the + # "outside world": `broken` makes a step raise, `ran` records each step that + # actually ran its side effect. + defmodule Flaky do + @moduledoc false + use Durable + + def act(i, data) do + if Process.get({__MODULE__, :broken}) == i, do: raise("step #{i} is broken") + Process.put({__MODULE__, :ran}, Process.get({__MODULE__, :ran}, []) ++ [i]) + {:ok, data} + end + + workflow "flaky" do + step(:s1, [retry: [max_attempts: 2, backoff: :constant, base: 1]], fn data -> + __MODULE__.act(1, data) + end) + + step(:s2, [retry: [max_attempts: 2, backoff: :constant, base: 1]], fn data -> + __MODULE__.act(2, data) + end) + + step(:s3, [retry: [max_attempts: 2, backoff: :constant, base: 1]], fn data -> + __MODULE__.act(3, data) + end) + + step(:s4, [retry: [max_attempts: 2, backoff: :constant, base: 1]], fn data -> + __MODULE__.act(4, data) + end) + + step(:s5, [retry: [max_attempts: 2, backoff: :constant, base: 1]], fn data -> + __MODULE__.act(5, data) + end) + end + end + + defmodule FlakyParallel do + @moduledoc false + use Durable + + workflow "flaky_parallel" do + step(:setup, fn data -> Flaky.act(1, data) end) + + parallel do + step(:left, fn data -> Flaky.act(2, data) end) + step(:right, fn data -> Flaky.act(3, data) end) + end + + step(:finish, fn data -> Flaky.act(4, data) end) + end + end + + defmodule Compensated do + @moduledoc false + use Durable + + workflow "compensated" do + step(:book, [compensate: :unbook], fn data -> {:ok, data} end) + step(:fail, fn _data -> raise "nope" end) + compensate(:unbook, fn data -> {:ok, data} end) + end + end + + setup do + Process.delete({Flaky, :broken}) + Process.delete({Flaky, :ran}) + %{config: Config.get(Durable)} + end + + defp reload(id), do: Config.get(Durable).repo.get!(WorkflowExecution, id) + defp ran, do: Process.get({Flaky, :ran}, []) + + defp failed_attempts(id, step) do + Config.get(Durable).repo.aggregate( + from(s in StepExecution, + where: s.workflow_id == ^id and s.step_name == ^step and s.status == :failed + ), + :count + ) + end + + describe "retry/2" do + test "resumes at the failed step without re-running completed steps", %{config: config} do + Process.put({Flaky, :broken}, 3) + {:ok, run} = create_and_execute_workflow(Flaky, %{}) + assert run.status == :failed + assert ran() == [1, 2] + assert failed_attempts(run.id, "s3") == 2 + + Process.delete({Flaky, :broken}) + assert {:ok, _} = Durable.retry(run.id) + assert reload(run.id).status == :pending + + Executor.execute_workflow(run.id, config) + + assert reload(run.id).status == :completed + assert ran() == [1, 2, 3, 4, 5] + end + + test "gives the failed step a fresh attempt budget", %{config: config} do + Process.put({Flaky, :broken}, 2) + {:ok, run} = create_and_execute_workflow(Flaky, %{}) + assert failed_attempts(run.id, "s2") == 2 + + # Still broken: the retried step must get 2 more attempts, not 0. + {:ok, _} = Durable.retry(run.id) + Executor.execute_workflow(run.id, config) + + assert reload(run.id).status == :failed + assert failed_attempts(run.id, "s2") == 4 + end + + test "in a parallel block re-queues only the children that failed", %{config: config} do + repo = config.repo + Process.put({Flaky, :broken}, 3) + + {:ok, parent} = create_and_execute_workflow(FlakyParallel, %{}) + execute_children(repo, parent.id, config) + Executor.execute_workflow(parent.id, config) + assert reload(parent.id).status == :failed + assert ran() == [1, 2] + + Process.delete({Flaky, :broken}) + {:ok, _} = Durable.retry(parent.id) + + assert reload(parent.id).status == :waiting + + statuses = repo |> get_child_executions(parent.id) |> Enum.map(& &1.status) |> Enum.sort() + assert statuses == [:completed, :pending] + + execute_children(repo, parent.id, config) + assert reload(parent.id).status == :pending + + Executor.execute_workflow(parent.id, config) + + assert reload(parent.id).status == :completed + # setup and the left branch ran once; only the failed right branch re-ran. + assert ran() == [1, 2, 3, 4] + end + + test "refuses rolled-back, unfinished and unknown runs" do + {:ok, rolled_back} = create_and_execute_workflow(Compensated, %{}) + assert rolled_back.status == :compensated + assert Durable.retry(rolled_back.id) == {:error, :rolled_back} + + {:ok, pending} = Durable.start(Flaky, %{}) + assert Durable.retry(pending) == {:error, :not_failed} + + assert Durable.retry(Ecto.UUID.generate()) == {:error, :not_found} + end + end + + property "retrying a run that failed at any step never re-runs a completed step" do + config = Config.get(Durable) + + check all(broken_at <- integer(1..5), max_runs: 25) do + Process.put({Flaky, :ran}, []) + Process.put({Flaky, :broken}, broken_at) + + {:ok, run} = create_and_execute_workflow(Flaky, %{}) + assert run.status == :failed + assert ran() == Enum.to_list(1..(broken_at - 1)//1) + + Process.delete({Flaky, :broken}) + {:ok, _} = Durable.retry(run.id) + Executor.execute_workflow(run.id, config) + + assert reload(run.id).status == :completed + assert ran() == [1, 2, 3, 4, 5] + end + end + + describe "rerun/2" do + test "starts a fresh run linked to the original, with its input or a new one" do + {:ok, original} = create_and_execute_workflow(Flaky, %{"order" => 1}) + + {:ok, same_input} = Durable.rerun(original.id) + {:ok, new_input} = Durable.rerun(original.id, input: %{"order" => 2}) + + for {id, input} <- [{same_input, %{"order" => 1}}, {new_input, %{"order" => 2}}] do + run = reload(id) + assert run.status == :pending + assert run.input == input + assert run.trigger == :rerun + assert run.trigger_ref == original.id + end + end + + test "refuses runs that haven't finished" do + {:ok, pending} = Durable.start(Flaky, %{}) + assert Durable.rerun(pending) == {:error, :not_finished} + end + end + + describe "pause_queue/2" do + test "stops every node claiming from the queue until resumed", %{config: config} do + {:ok, id} = Durable.start(Flaky, %{}, queue: "billing") + + :ok = Durable.pause_queue(:billing) + assert Durable.paused_queues() == ["billing"] + assert Postgres.fetch_jobs(config, "billing", 10, "node-a") == [] + + :ok = Durable.resume_queue("billing") + assert Durable.paused_queues() == [] + assert [%{id: ^id}] = Postgres.fetch_jobs(config, "billing", 10, "node-a") + end + + test "leaves other queues alone", %{config: config} do + {:ok, id} = Durable.start(Flaky, %{}, queue: "default") + :ok = Durable.pause_queue("billing") + + assert [%{id: ^id}] = Postgres.fetch_jobs(config, "default", 10, "node-a") + end + end + + test "records what started each run" do + {:ok, api} = Durable.start(Flaky, %{}) + assert %{trigger: :api, trigger_ref: nil} = reload(api) + + {:ok, _} = Durable.schedule(Flaky, "0 9 * * *", name: "nightly_flaky") + {:ok, scheduled} = Durable.trigger_schedule("nightly_flaky") + assert %{trigger: :schedule, trigger_ref: "nightly_flaky"} = reload(scheduled) + end +end diff --git a/durable/test/durable/query_test.exs b/durable/test/durable/query_test.exs index f899e65..4080b49 100644 --- a/durable/test/durable/query_test.exs +++ b/durable/test/durable/query_test.exs @@ -181,4 +181,60 @@ defmodule Durable.QueryTest do refute MapSet.member?(ids, old.id) end end + + describe "search filters" do + defp ids(filters), do: filters |> Query.list_executions() |> MapSet.new(& &1.id) + + test "current_step, trigger and error_contains", %{repo: repo} do + shipping = + insert_exec(repo, + status: :failed, + current_step: "ship_order", + error: %{"type" => "RuntimeError", "message" => "carrier returned 503"} + ) + + returned = + insert_exec(repo, + status: :failed, + current_step: "charge", + error: %{"reason" => "Card declined: 50% limit_hit"}, + trigger: :schedule, + trigger_ref: "nightly" + ) + + assert ids(current_step: "ship_order") == MapSet.new([shipping.id]) + assert ids(trigger: :schedule) == MapSet.new([returned.id]) + assert ids(trigger_ref: "nightly") == MapSet.new([returned.id]) + assert ids(error_contains: "CARRIER") == MapSet.new([shipping.id]) + assert ids(error_contains: "declined") == MapSet.new([returned.id]) + + # LIKE wildcards in the search text are literal, not patterns. + assert ids(error_contains: "50%") == MapSet.new([returned.id]) + assert ids(error_contains: "_") == MapSet.new([returned.id]) + end + + test "input matches exact values by dotted path", %{repo: repo} do + gold = insert_exec(repo, input: %{"order_id" => "ORD-1", "customer" => %{"tier" => "gold"}}) + + _silver = + insert_exec(repo, input: %{"order_id" => "ORD-2", "customer" => %{"tier" => "silver"}}) + + numeric = insert_exec(repo, input: %{"order_id" => 42}) + + assert ids(input: %{"order_id" => "ORD-1"}) == MapSet.new([gold.id]) + assert ids(input: %{"customer.tier" => "gold"}) == MapSet.new([gold.id]) + assert ids(input: %{"order_id" => 42}) == MapSet.new([numeric.id]) + assert ids(input: %{"order_id" => "ORD-1", "customer.tier" => "silver"}) == MapSet.new() + end + + test "count_by_status ignores the status filter but honours the rest", %{repo: repo} do + insert_exec(repo, status: :failed, workflow_name: "a") + insert_exec(repo, status: :failed, workflow_name: "a") + insert_exec(repo, status: :completed, workflow_name: "a") + insert_exec(repo, status: :failed, workflow_name: "b") + + assert Query.count_by_status(workflow_name: "a", status: [:completed]) == + %{failed: 2, completed: 1} + end + end end diff --git a/durable/test/durable/queue/adapters/postgres_test.exs b/durable/test/durable/queue/adapters/postgres_test.exs index c2fce64..7046a63 100644 --- a/durable/test/durable/queue/adapters/postgres_test.exs +++ b/durable/test/durable/queue/adapters/postgres_test.exs @@ -431,6 +431,19 @@ defmodule Durable.Queue.Adapters.PostgresTest do assert execution.locked_at == nil assert execution.completed_at != nil end + + # The executor records a run's final status itself; nack is the fallback + # for a worker that crashed before it could. It must never overwrite a + # status the executor already settled (e.g. a saga that rolled back). + test "leaves a status the executor already settled alone" do + for settled <- [:compensated, :compensation_failed, :failed, :cancelled, :waiting] do + job = insert_execution(workflow_name: "test", status: settled) + + :ok = Postgres.nack(config(), job.id, %{message: "worker saw an error"}) + + assert repo().get!(WorkflowExecution, job.id).status == settled + end + end end describe "reschedule/3" do diff --git a/durable/test/durable/queue/worker_test.exs b/durable/test/durable/queue/worker_test.exs index 4f713e6..3be9107 100644 --- a/durable/test/durable/queue/worker_test.exs +++ b/durable/test/durable/queue/worker_test.exs @@ -42,7 +42,7 @@ defmodule Durable.Queue.WorkerTest do assert_receive {:done, ^ref}, 2_000 # Worker emitted job_completed telemetry with status=:completed. - assert_receive {:event, :job_completed, %{duration_ms: dur}, + assert_receive {:event, :job_completed, %{duration: dur}, %{status: :completed, job_id: ^wf_id}}, 2_000 @@ -139,6 +139,9 @@ defmodule Durable.Queue.WorkerTest do # Stale recovery telemetry fired. assert_receive {:event, :stale_recovered, %{count: c}, _meta} when c >= 1, 500 + # ...and it's on the operations record. + assert Enum.any?(Durable.Activity.list(), &(&1.kind == "stale_recovered" and &1.count >= 1)) + # Row back to :pending, lock cleared. Use a generous backoff window — # if the previous recover_now didn't reach our row (e.g. a prior test # left a stale row that won the race), the test should re-trigger diff --git a/durable/test/durable/scheduler_test.exs b/durable/test/durable/scheduler_test.exs index b81c0a4..fb25422 100644 --- a/durable/test/durable/scheduler_test.exs +++ b/durable/test/durable/scheduler_test.exs @@ -324,6 +324,27 @@ defmodule Durable.SchedulerTest do assert schedule.next_run_at != nil end + test "re-enables an every-minute schedule (whole-second next run)" do + {:ok, _} = Durable.schedule(SimpleWorkflow, "* * * * *", name: "minutely", enabled: false) + + assert {:ok, %{enabled: true, next_run_at: next}} = Durable.enable_schedule("minutely") + assert next.second == 0 + assert {:ok, %{enabled: false}} = Durable.disable_schedule("minutely") + assert {:ok, %{enabled: true}} = Durable.enable_schedule("minutely") + end + + test "upcoming_runs lists the next fire times in UTC" do + {:ok, _} = Durable.schedule(SimpleWorkflow, "0 9 * * *", name: "nine") + {:ok, schedule} = Durable.get_schedule("nine") + + [first, second, third] = API.upcoming_runs(schedule, 3) + + assert DateTime.compare(first, DateTime.utc_now()) == :gt + assert {first.hour, first.minute} == {9, 0} + assert DateTime.diff(second, first, :hour) == 24 + assert DateTime.diff(third, second, :hour) == 24 + end + test "disables an enabled schedule" do {:ok, _} = Durable.schedule(SimpleWorkflow, "0 9 * * *", name: "disable_test") diff --git a/durable/test/durable/stats_test.exs b/durable/test/durable/stats_test.exs new file mode 100644 index 0000000..3f9586f --- /dev/null +++ b/durable/test/durable/stats_test.exs @@ -0,0 +1,318 @@ +defmodule Durable.StatsTest do + @moduledoc """ + `Durable.Stats`: the aggregates behind the Overview and Workflow pages, + computed from the tables. + """ + use Durable.DataCase, async: false + use ExUnitProperties + + alias Durable.Config + alias Durable.Stats + alias Durable.Storage.Schemas.{PendingEvent, PendingInput, StepExecution, WorkflowExecution} + + @until ~U[2026-10-16 12:00:00.000000Z] + @since ~U[2026-10-16 00:00:00.000000Z] + + defp at(minutes), do: DateTime.add(@since, minutes * 60, :second) + defp repo, do: Config.get(Durable).repo + + defp run!(attrs) do + defaults = %{ + workflow_module: "Elixir.App.Flow", + workflow_name: "flow", + status: :completed, + queue: "default", + input: %{}, + context: %{}, + inserted_at: at(10), + updated_at: at(10) + } + + repo().insert!(struct(WorkflowExecution, Map.merge(defaults, Map.new(attrs)))) + end + + defp opts(extra \\ []), do: [since: @since, until: @until] ++ extra + + describe "overview/1" do + test "counts what started and finished in the window, and what's waiting now" do + run!(status: :completed, started_at: at(10), completed_at: DateTime.add(at(10), 2, :second)) + run!(status: :completed, started_at: at(20), completed_at: DateTime.add(at(20), 4, :second)) + run!(status: :failed, completed_at: at(30)) + run!(status: :compensated, completed_at: at(31)) + run!(status: :cancelled, completed_at: at(32)) + run!(status: :completed, completed_at: at(-10), inserted_at: at(-20)) + run!(status: :completed, completed_at: at(40), parent_workflow_id: run!([]).id) + + run!(status: :pending, inserted_at: at(50)) + run!(status: :pending, scheduled_at: DateTime.add(DateTime.utc_now(), 3_600, :second)) + + sleeper = + run!(status: :waiting, scheduled_at: DateTime.add(DateTime.utc_now(), 60, :second)) + + asker = run!(status: :waiting) + + repo().insert!(%PendingInput{ + workflow_id: asker.id, + input_name: "approve", + step_name: "ask" + }) + + repo().insert!(%PendingEvent{workflow_id: asker.id, event_name: "paid", step_name: "ask"}) + + repo().insert!(%PendingEvent{ + workflow_id: sleeper.id, + event_name: "__parallel_done:x", + step_name: "p" + }) + + stats = Stats.overview(opts()) + + # 10 top-level runs inserted inside the window — the child's parent + # counts, the child itself doesn't, nor does the run from before. + assert stats.started == 10 + assert stats.finished == %{completed: 2, failed: 1, compensated: 1, cancelled: 1} + assert_in_delta stats.failure_rate, 2 / 5, 0.0001 + assert stats.duration_ms.p50 == 3_000 + assert stats.duration_ms.max == 4_000 + assert stats.backlog == 1 + assert stats.waiting == %{input: 1, event: 1, sleeping: 1} + end + + test "is all zeros and nils on an empty instance" do + stats = Stats.overview(opts()) + assert %{started: 0, finished: %{}, failure_rate: 0.0, backlog: 0} = stats + assert stats.duration_ms == %{p50: nil, p95: nil, max: nil} + end + end + + test "timeline/1 buckets finished runs, zero-filled, oldest first" do + run!(status: :completed, started_at: at(5), completed_at: at(10)) + run!(status: :failed, completed_at: at(70)) + run!(status: :compensated, completed_at: at(75)) + run!(status: :completed, started_at: at(60), completed_at: at(80)) + + buckets = Stats.timeline(opts(bucket_seconds: 3_600)) + + assert length(buckets) == 12 + assert hd(buckets).at == @since + assert [first, second | rest] = buckets + assert %{completed: 1, failed: 0, p50_ms: 300_000} = first + assert %{completed: 1, failed: 2, failure_rate: rate} = second + assert_in_delta rate, 2 / 3, 0.0001 + assert Enum.all?(rest, &(&1.completed == 0 and &1.failed == 0 and &1.p50_ms == nil)) + end + + test "error_groups/1 groups failures by type, numberless message and step" do + run!( + status: :failed, + current_step: "ship", + completed_at: at(1), + error: %{"type" => "RuntimeError", "message" => "timeout after 1503ms"} + ) + + run!( + status: :compensated, + current_step: "ship", + completed_at: at(2), + error: %{"type" => "RuntimeError", "message" => "timeout after 99ms"} + ) + + run!( + status: :failed, + current_step: "charge", + completed_at: at(3), + error: %{"reason" => "card declined"} + ) + + assert [biggest, other] = Stats.error_groups(opts()) + + assert %{ + type: "RuntimeError", + message: "timeout after ms", + step: "ship", + count: 2, + rolled_back: 1 + } = biggest + + assert %{type: nil, message: "card declined", step: "charge", count: 1} = other + end + + test "failing_workflows/1 ranks workflows by failures with their top error" do + for i <- 1..3, + do: + run!( + workflow_name: "orders", + status: :failed, + current_step: "ship", + completed_at: at(i), + error: %{"message" => "503"} + ) + + for i <- 1..7, do: run!(workflow_name: "orders", status: :completed, completed_at: at(i)) + + run!( + workflow_name: "emails", + status: :failed, + completed_at: at(9), + error: %{"message" => "421"} + ) + + run!(workflow_name: "quiet", status: :completed, completed_at: at(9)) + + assert [orders, emails] = Stats.failing_workflows(opts()) + assert %{workflow: "orders", failed: 3, finished: 10, failure_rate: 0.3} = orders + assert %{step: "ship", message: "", count: 3} = orders.top_error + assert emails.workflow == "emails" + end + + test "step_performance/1 reports attempts, retries and active-time percentiles per step" do + for n <- 1..4 do + run = run!(started_at: at(n)) + step!(run, "reserve", 1, :completed, 100 * n, at(n)) + + if n == 4 do + step!(run, "ship", 1, :failed, 2_000, at(n)) + step!(run, "ship", 2, :completed, 500, at(n)) + else + step!(run, "ship", 1, :completed, 500, at(n)) + end + + step!(run, "ship", 1, :waiting, nil, at(n)) + end + + assert [reserve, ship] = Stats.step_performance(opts(workflow: "flow")) + + assert %{ + step: "reserve", + runs: 4, + attempts: 4, + failed_attempts: 0, + retried_runs: 0, + p50_ms: 250, + max_ms: 400 + } = reserve + + assert %{ + step: "ship", + runs: 4, + attempts: 5, + failed_attempts: 1, + retried_runs: 1, + max_ms: 2_000 + } = ship + end + + test "step_performance/1 counts the runs that gave up at a step apart from recovered attempts" do + recovered = run!(started_at: at(1)) + step!(recovered, "ship", 1, :failed, 10, at(1)) + step!(recovered, "ship", 2, :completed, 10, DateTime.add(at(1), 1, :second)) + + gave_up = run!(started_at: at(2)) + step!(gave_up, "ship", 1, :failed, 10, at(2)) + step!(gave_up, "ship", 2, :failed, 10, DateTime.add(at(2), 1, :second)) + + assert [%{step: "ship", runs: 2, failed_attempts: 3, failed_runs: 1}] = + Stats.step_performance(opts(workflow: "flow")) + end + + defp step!(run, name, attempt, status, duration, started) do + repo().insert!(%StepExecution{ + workflow_id: run.id, + step_name: name, + attempt: attempt, + status: status, + duration_ms: duration, + started_at: started + }) + end + + test "queues/1 lists configured queues, live counts and pause state" do + run!(queue: "default", status: :running) + + run!( + queue: "default", + status: :pending, + inserted_at: DateTime.add(DateTime.utc_now(), -30, :second) + ) + + run!( + queue: "billing", + status: :pending, + scheduled_at: DateTime.add(DateTime.utc_now(), 600, :second) + ) + + :ok = Durable.pause_queue(:billing) + + queues = Map.new(Stats.queues(), &{&1.queue, &1}) + + assert %{running: 1, ready: 1, scheduled: 0, paused: false, oldest_ready_at: %DateTime{}} = + queues["default"] + + assert %{running: 0, ready: 0, scheduled: 1, paused: true} = queues["billing"] + end + + test "workflows/1 rolls each workflow up in one query" do + for i <- 1..3 do + run = + run!( + workflow_name: "orders", + status: :completed, + started_at: at(i), + completed_at: DateTime.add(at(i), i, :second) + ) + + if i == 1 do + step!(run, "ship", 1, :failed, 10, at(i)) + step!(run, "ship", 2, :completed, 10, at(i)) + end + + # A failure with no second attempt isn't a retry. + if i == 2, do: step!(run, "pack", 1, :failed, 10, at(i)) + end + + run!(workflow_name: "orders", status: :failed, completed_at: at(5)) + run!(workflow_name: "orders", status: :running) + run!(workflow_name: "emails", status: :waiting) + + rows = Map.new(Stats.workflows(opts()), &{&1.workflow, &1}) + + assert %{ + started: 5, + finished: 4, + failed: 1, + failure_rate: 0.25, + retried: 1, + running: 1, + p50_ms: 2_000 + } = + rows["orders"] + + assert %{started: 1, finished: 0, waiting: 1, failure_rate: 0.0} = rows["emails"] + end + + property "the timeline and the overview agree on what finished" do + check all( + runs <- + list_of( + tuple( + {member_of([:completed, :failed, :compensated, :cancelled]), integer(0..719)} + ), + max_length: 25 + ), + bucket_minutes <- member_of([15, 30, 60, 240]), + max_runs: 30 + ) do + repo().delete_all(WorkflowExecution) + for {status, minute} <- runs, do: run!(status: status, completed_at: at(minute)) + + overview = Stats.overview(opts()) + timeline = Stats.timeline(opts(bucket_seconds: bucket_minutes * 60)) + + assert length(timeline) == div(720, bucket_minutes) + + timeline_total = Enum.sum(Enum.map(timeline, &(&1.completed + &1.failed + &1.cancelled))) + assert timeline_total == overview.finished |> Map.values() |> Enum.sum() + assert timeline_total == length(runs) + end + end +end diff --git a/durable/test/durable/telemetry_test.exs b/durable/test/durable/telemetry_test.exs new file mode 100644 index 0000000..ac7f6d9 --- /dev/null +++ b/durable/test/durable/telemetry_test.exs @@ -0,0 +1,189 @@ +defmodule Durable.TelemetryTest do + @moduledoc """ + The telemetry contract in `Durable.Telemetry`: run, step and compensation + spans, retry events, `metrics/0` and the default logger. + """ + use Durable.DataCase, async: false + use ExUnitProperties + + import ExUnit.CaptureLog + import Durable.DataCase, only: [create_and_execute_workflow: 2, get_step_executions: 1] + + alias Durable.Config + alias Durable.Storage.Schemas.{StepExecution, WorkflowExecution} + + defmodule Steps do + @moduledoc false + use Durable + + def act(i, data) do + if knob(data, :cancel_at) == i, do: Durable.cancel(Durable.Context.workflow_id()) + if knob(data, :fail_at) == i, do: raise("boom at #{i}") + {:ok, data} + end + + defp knob(data, key), do: Map.get(data, key) || Map.get(data, Atom.to_string(key)) + + workflow "telemetry_steps" do + step(:a, [retry: [max_attempts: 2, backoff: :constant, base: 1]], fn data -> + __MODULE__.act(1, data) + end) + + step(:b, fn data -> __MODULE__.act(2, data) end) + step(:c, fn data -> __MODULE__.act(3, data) end) + end + end + + defmodule RollsBack do + @moduledoc false + use Durable + + workflow "rolls_back" do + step(:book, [compensate: :unbook], fn data -> {:ok, data} end) + step(:fail, fn _data -> raise "nope" end) + compensate(:unbook, fn data -> {:ok, data} end) + end + end + + def forward(event, measurements, meta, pid), + do: send(pid, {:telemetry, event, measurements, meta}) + + setup do + handler = "telemetry-test-#{System.unique_integer([:positive])}" + + :ok = + :telemetry.attach_many(handler, Durable.Telemetry.events(), &__MODULE__.forward/4, self()) + + on_exit(fn -> :telemetry.detach(handler) end) + end + + defp drain(acc \\ []) do + receive do + {:telemetry, event, measurements, meta} -> drain([{event, measurements, meta} | acc]) + after + 0 -> Enum.reverse(acc) + end + end + + defp of(events, name), do: for({^name, m, meta} <- events, do: {m, meta}) + + test "a completed run: one workflow span around one step span per step" do + {:ok, run} = create_and_execute_workflow(Steps, %{}) + events = drain() + + assert [{%{system_time: _}, %{workflow: "telemetry_steps", resumed: false}}] = + of(events, [:durable, :workflow, :start]) + + assert [{%{duration: duration}, %{status: :completed, workflow_id: id}}] = + of(events, [:durable, :workflow, :stop]) + + assert id == run.id and duration > 0 + + steps = for {_, meta} <- of(events, [:durable, :step, :stop]), do: {meta.step, meta.result} + assert steps == [a: :ok, b: :ok, c: :ok] + end + + test "a failing step: an error stop per attempt, a retry event between, a failed run" do + {:ok, _run} = create_and_execute_workflow(Steps, %{"fail_at" => 1}) + events = drain() + + stops = for {_, meta} <- of(events, [:durable, :step, :stop]), do: {meta.attempt, meta.result} + assert stops == [{1, :error}, {2, :error}] + + assert [{%{backoff_ms: backoff}, %{attempt: 1, error: %{type: "RuntimeError"}}}] = + of(events, [:durable, :step, :retry]) + + assert backoff >= 0 + assert [{_, %{status: :failed}}] = of(events, [:durable, :workflow, :stop]) + end + + test "a run cancelled mid-segment stops as :superseded" do + {:ok, _run} = create_and_execute_workflow(Steps, %{"cancel_at" => 2}) + + assert [{_, %{status: :superseded}}] = of(drain(), [:durable, :workflow, :stop]) + end + + test "a compensated run: a compensation span, and the run reports :compensated" do + {:ok, run} = create_and_execute_workflow(RollsBack, %{}) + assert run.status == :compensated + events = drain() + + assert [{%{duration: _}, %{compensation: :unbook, result: :ok}}] = + of(events, [:durable, :compensation, :stop]) + + assert [{_, %{status: :compensated}}] = of(events, [:durable, :workflow, :stop]) + end + + test "metrics/0 only references events Durable emits" do + for metric <- Durable.Telemetry.metrics() do + assert metric.event_name in Durable.Telemetry.events(), + "#{inspect(metric.name)} listens to an event Durable never emits" + end + end + + test "counters count every event, whatever its measurements" do + # LiveDashboard drops an event whose named measurement is missing. + for %Telemetry.Metrics.Counter{} = metric <- Durable.Telemetry.metrics() do + assert metric.measurement.(%{duration: 1}) == 1, inspect(metric.name) + end + end + + test "attach_default_logger/1 logs finished runs and failed steps" do + :ok = Durable.Telemetry.attach_default_logger() + on_exit(fn -> :telemetry.detach("durable-default-logger") end) + + log = + capture_log(fn -> + {:ok, _} = create_and_execute_workflow(Steps, %{}) + {:ok, _} = create_and_execute_workflow(Steps, %{"fail_at" => 2}) + end) + + assert log =~ ~r/\[Durable\] telemetry_steps \S+ completed in \d+ms/ + assert log =~ ~r/step b failed \(attempt 1\/1, \d+ms\): RuntimeError: boom at 2/ + assert log =~ ~r/\[Durable\] telemetry_steps \S+ failed in \d+ms/ + + # Durable's own lines don't end up in the step's captured logs. + step_logs = + Config.get(Durable).repo.all(from(s in StepExecution, select: s.logs)) + |> List.flatten() + |> Enum.map(& &1["message"]) + + refute Enum.any?(step_logs, &String.starts_with?(&1, "[Durable]")) + end + + property "spans always close, and what telemetry reports matches what was persisted" do + check all( + fail_at <- one_of([constant(nil), integer(1..3)]), + cancel_at <- one_of([constant(nil), integer(1..3)]), + max_runs: 40 + ) do + drain() + + {:ok, run} = + create_and_execute_workflow(Steps, %{"fail_at" => fail_at, "cancel_at" => cancel_at}) + + events = drain() + + # Every span that starts ends exactly once. + ends = [:stop, :exception] + + for {[:durable, kind, :start], _, %{telemetry_span_context: ref}} <- events do + closes = + for {[:durable, ^kind, phase], _, %{telemetry_span_context: ^ref}} <- events, + phase in ends, + do: phase + + assert length(closes) == 1 + end + + # The run's reported status is the persisted one (a cancel shows up as + # the segment being superseded). + [{_, %{status: reported}}] = of(events, [:durable, :workflow, :stop]) + persisted = Config.get(Durable).repo.get!(WorkflowExecution, run.id).status + assert reported == if(persisted == :cancelled, do: :superseded, else: persisted) + + # One step span per persisted attempt. + assert length(of(events, [:durable, :step, :start])) == length(get_step_executions(run.id)) + end + end +end diff --git a/durable/test/durable/workflow_timeout_test.exs b/durable/test/durable/workflow_timeout_test.exs new file mode 100644 index 0000000..82fed86 --- /dev/null +++ b/durable/test/durable/workflow_timeout_test.exs @@ -0,0 +1,112 @@ +defmodule Durable.WorkflowTimeoutTest do + @moduledoc """ + A workflow's `timeout:` is a deadline for the whole run, waits included. + """ + use Durable.DataCase, async: false + + alias Durable.Config + alias Durable.Executor + alias Durable.Storage.Schemas.{PendingInput, WorkflowExecution} + alias Durable.Wait.TimeoutWorker + + defmodule SlowSaga do + use Durable + use Durable.Helpers + + workflow "slow_saga", timeout: 50, queue: :sagas do + step(:reserve, [compensate: :release], fn data -> + Process.sleep(80) + {:ok, assign(data, :reserved, true)} + end) + + step(:charge, fn data -> {:ok, assign(data, :charged, true)} end) + + compensate(:release, fn data -> {:ok, assign(data, :released, true)} end) + end + end + + defmodule Approval do + use Durable + use Durable.Context + use Durable.Wait + + workflow "timed_approval", timeout: minutes(30) do + step(:ask, fn data -> + wait_for_approval("manager") + {:ok, data} + end) + end + end + + defp repo, do: Config.get(Durable).repo + defp run(id), do: repo().get!(WorkflowExecution, id) + + test "options are evaluated: timeout: minutes(30) is a number of milliseconds" do + {:ok, definition} = Approval.__workflow_definition__("timed_approval") + assert definition.opts.timeout == 30 * 60_000 + end + + test "an unknown workflow option fails the compile" do + assert_raise ArgumentError, ~r/unknown option\(s\) \[:max_retries\]/, fn -> + Code.compile_string(""" + defmodule Durable.WorkflowTimeoutTest.Bad do + use Durable + workflow "bad", max_retries: 3 do + step(:a, fn data -> {:ok, data} end) + end + end + """) + end + end + + test "a run past its deadline fails before the next step and compensates" do + {:ok, id} = Executor.start_workflow(SlowSaga, %{}, inline: true) + run = run(id) + + assert run.queue == "sagas" + assert run.status == :compensated + assert %{"type" => "timeout", "message" => message} = run.error + assert message =~ "50ms timeout before charge" + refute run.context["charged"] + end + + test "a waiting run past its deadline is woken and failed" do + {:ok, id} = Executor.start_workflow(Approval, %{}, inline: true) + assert %{status: :waiting, deadline_at: %DateTime{}} = run(id) + + past = DateTime.add(DateTime.utc_now(), -1, :second) + repo().update_all(from(w in WorkflowExecution, where: w.id == ^id), set: [deadline_at: past]) + + start_supervised!({TimeoutWorker, config: Config.get(Durable), interval: 3_600_000}) + TimeoutWorker.check_timeouts(Durable) + :sys.get_state(TimeoutWorker.worker_name(Durable)) + + assert %{status: :pending} = run(id) + + assert [%{status: :timeout}] = + repo().all(from(p in PendingInput, where: p.workflow_id == ^id)) + + Executor.execute_workflow(id, Config.get(Durable)) + assert %{status: :failed, error: %{"type" => "timeout"}} = run(id) + end + + test "a resumed run keeps its first start time" do + {:ok, id} = Executor.start_workflow(Approval, %{}, inline: true) + %{status: :waiting, started_at: %DateTime{} = first} = run(id) + + :ok = Durable.provide_input(id, "manager", %{"approved" => true}) + Executor.execute_workflow(id, Config.get(Durable)) + + assert %{status: :completed, started_at: ^first} = run(id) + end + + test "a retried run gets its full timeout again" do + {:ok, id} = Executor.start_workflow(SlowSaga, %{}, inline: true) + repo().update_all(from(w in WorkflowExecution, where: w.id == ^id), set: [status: :failed]) + + before = DateTime.utc_now() + {:ok, ^id} = Durable.retry(id) + + assert DateTime.diff(run(id).deadline_at, before, :millisecond) in 40..60 + end +end diff --git a/durable/test/support/telemetry_handler.ex b/durable/test/support/telemetry_handler.ex index 0093a9f..f136769 100644 --- a/durable/test/support/telemetry_handler.ex +++ b/durable/test/support/telemetry_handler.ex @@ -13,7 +13,7 @@ defmodule Durable.TelemetryHandler do # run code that emits [:durable, :queue, :job_completed] - assert_receive {:event, :job_completed, %{duration_ms: _}, %{status: :completed}} + assert_receive {:event, :job_completed, %{duration: _}, %{status: :completed}} """ import ExUnit.Callbacks, only: [on_exit: 1] diff --git a/durable_dashboard/CLAUDE.md b/durable_dashboard/CLAUDE.md index f32e427..011ccdc 100644 --- a/durable_dashboard/CLAUDE.md +++ b/durable_dashboard/CLAUDE.md @@ -37,5 +37,14 @@ mix test ## Test DB -Phoenix demo runs against port `53412`. See `examples/phoenix_demo` in the +`mix test` needs Postgres: the page tests (`DurableDashboard.LiveCase`) mount +the real LiveViews against a Durable instance on `TestRepo` — the compose +Postgres on port `54321` (`docker compose up -d` in the repo root), database +`durable_dashboard_test`, created and migrated by `test_helper.exs`. Runs come +from `DurableDashboard.Fixtures` (real workflows, executed inline). + +A page test that shows a real, unfixed bug is tagged `:known_bug` and +excluded; `mix test --only known_bug` runs them. + +The Phoenix demo runs against port `53412`. See `examples/phoenix_demo` in the repo root. diff --git a/durable_dashboard/DESIGN.md b/durable_dashboard/DESIGN.md index 96ebd8d..8ad7125 100644 --- a/durable_dashboard/DESIGN.md +++ b/durable_dashboard/DESIGN.md @@ -10,187 +10,149 @@ isn't here, codify it here first; don't make it twice. ## 1. Philosophy -Durable Dashboard is a **workflow-engine console**. The aesthetic priorities -are, in order: - -1. **Data density.** Operators read this thing all day. Every pixel that - isn't carrying information is a tax. -2. **Dark-first.** The default theme is dark; light theme is supported with - the same visual fidelity for ops on bright monitors. -3. **Restrained color.** Color carries semantic meaning (status). It is - never used for branding or decoration. -4. **No chrome.** No drop shadows for depth, no gradients for polish, no - illustrations, no marketing copy. Elevation comes from background - contrast, not effects. - -**Inspirations** (not to imitate, but to calibrate against): - -- **Temporal Web** — data density and disciplined hierarchy. -- **Inngest** — polish and motion vocabulary. -- **Linear** — typography rhythm and command-palette discipline. -- **Argo Workflows / n8n** — workflow graph conventions. - -**Visual budget.** Every surface earns its weight. No card-in-card-in-card. -Whitespace is structural, not decorative — it separates regions, not -paragraphs. +Durable Dashboard is a **workflow-engine console** — a control room. The +aesthetic priorities, in order: + +1. **Answers before data.** Every screen leads with the thing an operator + came for (what failed, why, what to do) and puts the action next to it. + A list that can't act on its rows is unfinished. +2. **Data density.** Operators read this all day. Hairlines, not boxes; + tables, not cards; numbers in mono. +3. **Dark-first.** Dark is the default; light is a peer, checked on every + change. +4. **Restrained color.** Color carries meaning — status, or "live". Never + decoration, never branding. +5. **Shape before color.** Every status reads as shape + color + label, so + nothing depends on telling hues apart. + +**Calibrated against** Inngest (trace + inspector, metrics), Temporal Web +(density), Linear (type rhythm, ⌘K). The reference mockups live on the +"Durable Dashboard v1" design canvas; this file is the source of truth. ## 2. Foundations ### 2.1 Colors -Every color comes from a CSS custom property declared in -`assets/src/index.css`. Light + dark values are paired. Tailwind utility -classes (`bg-card`, `text-primary`, `border-border`) read these tokens via -the `@theme inline` block. - -| Token | Light | Dark | Use | -| ----------------------- | ------------------------ | ------------------------- | --------------------------------------------- | -| `--background` | `oklch(1 0 0)` | `oklch(0.145 0 0)` | App canvas | -| `--foreground` | `oklch(0.18 0 0)` | `oklch(0.98 0 0)` | Primary text | -| `--card` | `oklch(0.985 0 0)` | `oklch(0.185 0 0)` | Surfaces above the canvas | -| `--popover` | `oklch(0.99 0 0)` | `oklch(0.205 0 0)` | Floating surfaces | -| `--primary` | `oklch(0.5 0.2 250)` | `oklch(0.72 0.16 250)` | Primary actions, focus, active nav | -| `--secondary` | `oklch(0.96 0 0)` | `oklch(0.22 0 0)` | Secondary buttons, neutral chips | -| `--accent` | `oklch(0.95 0 0)` | `oklch(0.24 0 0)` | Hover backgrounds | -| `--muted` | `oklch(0.96 0 0)` | `oklch(0.21 0 0)` | Subdued surfaces | -| `--muted-foreground` | `oklch(0.5 0 0)` | `oklch(0.62 0 0)` | Secondary text | -| `--success` | `oklch(0.55 0.18 155)` | `oklch(0.78 0.16 155)` | Status: completed / running | -| `--warning` | `oklch(0.65 0.18 75)` | `oklch(0.82 0.16 80)` | Status: waiting / compensating | -| `--destructive` | `oklch(0.55 0.22 22)` | `oklch(0.72 0.20 22)` | Status: failed / timeout, destructive actions | -| `--info` | `oklch(0.55 0.16 230)` | `oklch(0.78 0.13 230)` | Status: scheduled | -| `--border` | `oklch(0.92 0 0)` | `oklch(0.27 0 0)` | Hairline dividers | -| `--input` | `oklch(0.94 0 0)` | `oklch(1 0 0 / 8%)` | Input borders/backgrounds | -| `--ring` | `oklch(0.5 0.2 250 / 0.4)` | `oklch(0.72 0.16 250 / 0.55)` | Focus rings | +Every color is a CSS custom property in `assets/src/index.css`, paired for +light and dark, exposed to Tailwind through `@theme inline` (`bg-card`, +`text-success`, `border-input`, …). + +| Token | Light | Dark | Use | +| --------------------- | --------- | --------- | ------------------------------------------------- | +| `--background` | `#f5f6f8` | `#0b0d10` | App canvas (ink) | +| `--card` | `#ffffff` | `#111418` | Panels, sidebar, tables | +| `--popover` | `#ffffff` | `#181c22` | Floating surfaces | +| `--secondary`/`--muted` | `#eef0f3` | `#181c22` / `#161a20` | Raised chips, selected nav, pill grounds | +| `--accent` | `#f0f2f5` | `#1a1f26` | Hover backgrounds | +| `--foreground` | `#0f1217` | `#e6e8eb` | Primary text | +| `--subtle-foreground` | `#4a5260` | `#a6adb7` | Secondary text, nav items | +| `--muted-foreground` | `#646c78` | `#8b939e` | Captions, labels, meta | +| `--border` | `#e3e6ea` | `#22272e` | Hairlines | +| `--input` | `#d2d7dd` | `#2e343c` | Control borders | +| `--primary` | `#1a5fd0` | `#4c8dff` | **Live**: running, links, focus, active nav icon | +| `--success` | `#00766a` | `#2bb3a3` | Completed (teal) | +| `--destructive` | `#b33a25` | `#f2785b` | Failed (red-orange) | +| `--warning` | `#8a5800` | `#e9b458` | Waiting, saturated | +| `--comp` | `#5e45c8` | `#b3a6f5` | Compensation / rolled back (violet) | +| `--off` | `#8a929c` | `#6b7380` | Pending, cancelled | +| `--chart-ok` / `--chart-fail` | `#00897b` / `#d4462e` | `#23a094` / `#e8603f` | Chart marks for completed / failed | +| `--chart-1…4` | dataviz categorical slots 1–4 | | Series that aren't statuses | + +**Why teal and red-orange.** Green/red failed the color-blind separation +check (deutan ΔE 5.7). Teal/red-orange passes in both themes (ΔE ≥ 12 dark, +≥ 9 light) — re-run the dataviz validator before changing either. + +**Contrast.** Every text color above clears WCAG AA (4.5:1) on its own 13% +tint, which is how pills and chips are drawn. Don't fade text with opacity +modifiers (`text-muted-foreground/60`) — pick the right token instead. + +**Primary is "live".** Blue means *now / running / you are here / a link*. +Primary *buttons* are ink-inverted (`bg-foreground text-background`), not +blue, so the accent stays a signal. #### Forbidden -- Hex literals — `#3b82f6`, `#22c55e`, `#fff`. Use tokens. -- Inline OKLCH/HSL/RGB in components — `oklch(0.78 0.16 155)`, - `rgb(34 197 94)`. Use tokens. -- Tailwind palette colors — `text-blue-500`, `bg-green-100`. Use tokens. -- Any new color outside the table without first adding it here. - -#### Opacity - -Use the slash modifier on token classes for tints: `bg-success/10`, -`text-primary/80`, `border-destructive/20`. Standard tints: `/5`, `/10`, -`/15`, `/20`, `/40`, `/60`, `/80`. Anything else needs justification. +- Hex or OKLCH literals in components. Use tokens (charts too: `var(--chart-ok)`). +- Tailwind palette colors (`text-blue-500`). +- Opacity-faded text. ### 2.2 Typography -- `--font-sans` = **Inter Variable** with `cv11` enabled. -- `--font-mono` = **JetBrains Mono Variable** with ligatures off. - -Use `font-mono` (or the `text-numeric` utility for tabular numerics) on: -IDs, durations, timestamps, JSON, code, status pills, dense numeric tables. - -#### Type scale - -Six sizes only. Anything else needs a comment explaining why. - -| Class | Size | Use | -| -------------- | ---- | ------------------------------------------------------ | -| `text-[9px]` | 9 | *Exception only:* graph-marker micro-eyebrows (start/end labels, group badges). | -| `text-[10px]` | 10 | Eyebrow / uppercase chip / kbd / footer hints | -| `text-[11px]` | 11 | Footnote, dense table cell, tertiary metadata | -| `text-xs` | 12 | Body small, control labels, navigation items | -| `text-[13px]` | 13 | Default body, default button text, form fields | -| `text-sm` | 14 | Card titles, primary body, list-row titles | -| `text-[18px]` | 18 | Section heading (h2) | -| `text-[22px]` | 22 | Page heading (h1) | - -Two heading utilities are declared in `index.css`: - -- `text-heading` — applies `font-weight: 600`, `letter-spacing: -0.015em`, - `line-height: 1.2`. Use on h1/h2/h3. -- `text-numeric` — applies `font-mono`, tabular nums, slashed zero. +- `--font-sans` = **IBM Plex Sans** (400/500/600), `--font-mono` = **IBM Plex + Mono** (400/500), loaded from Google Fonts in `Layouts.root/1`. +- Body is 13px / 1.45. +- **Mono is for machine facts only**: ids, numbers, durations, timestamps, + code, JSON, step names. Never for labels. +- **Labels are sentence case.** No uppercase, no letter-spacing, no mono + eyebrows. `<.label>` is a 12px muted caption; column headers are 12px + medium muted. + +| Size | Use | +| ----------- | ---------------------------------------------------- | +| 11px | Axis ticks, kbd hints, dense chips | +| 12px (`text-xs`) | Labels, captions, column headers, pills, meta | +| 13px | Default body, table cells, buttons, nav | +| 14px (`text-sm`) | Panel titles (semibold) | +| 16px (`text-base`) | Section heading (h2) | +| 20px | Page title (h1), semibold, −0.01em | +| 22–24px mono | KPI values | ### 2.3 Spacing -4 px grid. Allowed tailwind values: `0.5, 1, 1.5, 2, 2.5, 3, 4, 6, 8, 12, 16`. -Snap everything else. - -Common rhythms: - -- `gap-1.5` — chips, inline status indicators -- `gap-2` — adjacent controls (button + button) -- `gap-3` — related controls (input + button group) -- `gap-4` — within a card body -- `gap-6` — between major sections - -Page padding: `px-6 py-4` standard. Sheet / dialog inner padding: `p-4`. +4px grid. Page gutter `px-7`, panel padding 16px, table cell padding +`px-4`, rows 40–46px. Gaps: 8px between controls, 16px between panels. ### 2.4 Radius -Maps to `--radius-*` tokens; use the Tailwind shortcuts: - -| Class | px | Use | -| ---------------- | --- | ------------------------------------------------ | -| `rounded-sm` | 2 | Chips, badges, kbd, dense controls | -| `rounded-md` | 4 | Buttons, inputs, cards, surface containers | -| `rounded-lg` | 6 | Sheets, dialogs, large surfaces | -| `rounded-full` | ∞ | Avatars, status dots, circular buttons | - -No 8 px or 10 px radii. They look like marketing components. +| Use | Radius | +| --------------------------- | ------ | +| Chips, badges, kbd | 4–5px | +| Buttons, inputs, pills, nav | 7px (`rounded-md`) | +| Panels, cards, tables | 10px | -### 2.5 Borders +### 2.5 Borders & elevation -- 1 px hairline default — `border border-border`. -- 1.5 px only for focus rings (`ring-2 ring-ring/40`). -- 2 px reserved for status emphasis (e.g. "current execution" outline on a - graph node — see §11). -- Avoid double borders (border + ring without offset). - -### 2.6 Shadows - -`shadow-sm` only. Elevation is achieved via *background contrast* (card -above canvas), not blurred shadows. The one exception: `` -and other floating overlays may use `shadow-lg` for popovers. +1px hairlines (`border-border`) between rows and around panels; control +borders use `border-input`. **No card shadows** — panels separate by surface +step (ink → card) and hairline. Popovers and menus keep `shadow-pop` because +they float. ## 3. Motion -Three named animations only. Defined in `assets/src/index.css`. - -| Name | Duration | Easing | Use | -| ----------------- | -------- | ----------- | ---------------------------------------------------- | -| `led-dot` | 1.6 s | ease-in-out | Running/active status dots; pulses opacity + glow. | -| `dash-flow` | 1.0 s | linear | Flowing edges in the workflow graph. | -| `animate-pulse` | 2.0 s | cubic-bezier| Skeleton loaders only (never on real content). | - -Transitions: `transition-colors duration-150` for hover/focus. Nothing -slower than 200 ms. Layout transitions (`transition-all`) are forbidden — -they make data-dense UIs feel sluggish. +- **`st-beat`** — the running mark's pulse (1.6s). Only on live things. +- **`dash-flow`** — running edges in the graph. +- **`animate-pulse`** — skeletons only. -`prefers-reduced-motion: reduce` disables all three animations through a -single media query in `index.css`. Don't bypass it. +Hover/focus transitions ≤ 150ms (`transition-colors`). No layout animation. +`prefers-reduced-motion` disables all of it from one media query. ## 4. Status semantics — canonical table -This is the **single source of truth** for every status string the system -emits. Do not invent local mappings. - -| Status | Color tier | Dot | Label | -| ----------------- | --------------- | ------- | -------------- | -| `pending` | `muted` | none | "pending" | -| `running` | `success` | pulse | "running" | -| `waiting` | `warning` | solid | "waiting" | -| `completed` | `success` | solid | "completed" | -| `failed` | `destructive` | none | "failed" | -| `cancelled` | `muted` | none | "cancelled" | -| `compensating` | `warning` | pulse | "compensating" | -| `compensated` | `muted` | none | "compensated" | -| `compensation_failed` | `destructive` | none | "comp. failed" | -| `scheduled` | `info` | none | "scheduled" | -| `timeout` | `destructive` | none | "timeout" | - -To add a status: - -1. Update this table. -2. Update `Components.Core.status_meta/1` (HEEx-side) and the `toneFor` - helpers in `step_node.tsx` and any other React node components. -3. Update the workflow query/schema if needed. - -If those four don't agree, the table wins. +Status is **shape + color + label**, everywhere — `<.status_pill>`, +`<.status_dot>`, trace rows, charts, graph nodes. Shapes are CSS classes +`st-dot st-` in `index.css`. + +| Status | Shape | Color | Label | +| --------------------- | ---------------- | -------------- | -------------------- | +| `pending` | dashed ring | `off` | Pending | +| `running` | disc, pulsing | `primary` | Running | +| `waiting` | hollow ring | `warning` | Waiting | +| `completed` | disc | `success` | Completed | +| `failed` | diamond | `destructive` | Failed | +| `cancelled` | dash | `off` | Cancelled | +| `compensating` | disc, pulsing | `comp` | Compensating | +| `compensated` | disc | `comp` | Compensated | +| `compensation_failed` | diamond | `destructive` | Compensation failed | +| `scheduled` | dashed ring | `off` | Scheduled | +| `timeout` | diamond | `destructive` | Timed out | +| `paused` (queue) | hollow ring | `warning` | Paused | +| `idle` (queue) | dashed ring | `off` | Idle | +| `alive` (node) | disc | `success` | Alive | +| `missing` (node) | diamond | `destructive` | Missing | + +To add a status: update this table, `Core.status_meta/1`, the `st-*` class in +`index.css`, and the React node tone helpers. If they disagree, the table +wins. ## 5. Component primitives — `Components.Core` API contract @@ -200,8 +162,10 @@ already implemented; see the source for the full attr list. ### `<.button>` -Variants: `primary | secondary | ghost | destructive | link`. -Sizes: `sm` (28h) | `md` (32h, default) | `lg` (40h). +Variants: `primary` (ink-inverted — the one main action on a surface) | +`secondary` (card ground, `border-input`; the default) | `ghost` | +`destructive` (outlined, red-orange text — never a filled red slab) | `link`. +Sizes: `sm` (26h) | `md` (30h, default) | `lg` (40h). ```heex <.button kind="primary" type="submit">Save @@ -229,19 +193,24 @@ sun) keep raw markup with an exemption comment pointing at this primitive. ### `<.badge>` -Uppercase eyebrow chip. Variants: `default | primary | success | warning | -destructive | info | muted`. Use for tags, counts, eyebrows. **Don't** use -for live workflow status — that's `<.status_pill>`. +Small sentence-case chip (11px, 5px radius). Variants: `default | primary | +success | warning | destructive | info | muted`. Use for tags and counts. +**Don't** use for run status — that's `<.status_pill>`. ### `<.status_pill>` -Workflow / step state chip. Reads `status` (atom or string) and resolves -to the canonical table in §4. +Run / step state chip: the §4 shape mark + sentence-case label on a 13% +tint of the status color. Reads `status` (atom or string). ```heex <.status_pill status={execution.status} /> ``` +### `<.status_dot>` + +The bare §4 shape mark, for places a pill is too heavy: trace rows, feeds, +graph nodes, the sidebar's live indicator. Always next to a label or name. + **Don't** use for arbitrary tags; the colors carry meaning. ### `<.card>` @@ -282,9 +251,10 @@ Keyboard hint inside command palette / tooltips. Humanized "2m ago" (past) or "in 2h" (future) for durations. Always use this; never hand-format times. It is sign-aware — a future timestamp (e.g. a -schedule's next run) reads "in …", never "just now". The hover tooltip is -localized to the viewer's timezone by the same `local_time.ts` hook (it carries -`data-rel` so only the title is rewritten; the relative text stays). Use +schedule's next run) reads "in …", never "just now". Its tooltip (`tooltip.ts`) +shows the moment in the viewer's zone, how long ago, and UTC. It sets tabular +figures in the **surrounding** font, not mono — it usually sits inside a +sentence ("asked 2m ago"), where a mono space reads as a gap. Use `local_time` instead when the user needs the exact moment shown inline. ### `<.local_time at={dt} format="time|datetime|date">` @@ -298,11 +268,9 @@ use `relative_time` for "ago" durations and `local_time` for the moment. ### `<.label>` and `<.field key="…">` -The canonical "this is a label, not a value" treatment: small mono, -uppercase, `tracking-[0.14em]`, `text-muted-foreground/70`. Use `<.label>` -for **every** field-name / section-header / metadata-key — never hand-roll -the `font-mono … uppercase tracking-…` string again (it was previously -duplicated across the inspector, logs, and IO panels). +The canonical "this is a label, not a value" treatment: a 12px +sentence-case caption in `text-muted-foreground`. Use `<.label>` for every +field name, column header and metadata key. Never uppercase, never mono. ```heex <.label>level @@ -354,47 +322,29 @@ its own `Phoenix.LiveComponent` module under ### Page shell ``` - -
- - -
+
+ + + +
``` -- Sidebar: fixed 220 px, `bg-card/40` + hairline right border, heroicons. - Nav is split into two intent groups under quiet mono eyebrows — - **Observe** (Overview, Workflows, Executions) and **Operate** (Inputs, - Schedules, Settings) — so the destinations read as an IA, not a flat list. - Brand lockup is the **pulse mark**: a muted oscilloscope baseline carrying - one indigo beat, with a pulsing `led-dot` riding the beat's apex (the live - blip). It makes the worker heartbeat literal — "the engine is alive and - durable" — and is echoed by the `connected` heartbeat in the footer. No - tinted box: color stays earned by the live signal, never spent on a branded - surface (§1, §6 live rail). The wordmark is `Durable` (text-sm semibold) - over a lowercase mono `console` caption. -- Topbar: 56 h, breadcrumbs left; the command toolbar right. The toolbar is - the **⌘K trigger** (bordered chip, width hugs `search · "Jump to…" · ⌘K` — - no dead gap, one `⌘K` chip) then a hairline divider and a **meta group**: - running `version` (mono, from `Application.spec(:durable, :vsn)`), a - **GitHub** link, and the **theme** toggle. The trigger keeps the bordered - surface (primary action); the meta controls are **ghost** (icon-only, no - border) so the trigger reads as the one thing to reach for. -- Main: `max-w-[1400px]` to keep line lengths readable on ultrawide monitors. - -#### The live rail (signature) - -The accent (`--primary` indigo) carries **one** meaning across the whole -console: *now / live / you are here*. It is not generic chrome. It appears as: - -- the **active nav rail** — a short `h-4 w-0.5` indigo bar on the left edge - of the current nav item; -- the **selected row** in the ⌘K palette — the same `h-4 w-0.5` bar on the - row you're about to jump to (selection *is* "where you're going next"); -- the **running edge** in the workflow graph (`.flow-edge-running`); -- the **"now" line** / in-flight bars in the Timeline. - -Same hue, same idea, everywhere. Don't spend primary on decoration — if -something is tinted indigo it should mean "live / current." +- **No topbar.** The sidebar carries everything global: brand, ⌘K, nav, + live indicator, version, GitHub and theme toggle. +- **Sidebar** (232px, `bg-card`, hairline right border): + - Brand: the three-step mark (persisted steps rising) + "Durable" over the + schema name. + - ⌘K button ("Jump to run, workflow…"). + - Nav in three intent groups under plain sentence-case captions — + **Observe** (Overview, Runs, Workflows), **Operate** (Inbox, Queues & + nodes, Schedules), **Instrument** (Telemetry, Settings). Active item: + `bg-secondary` with the icon in the live blue. + - Inbox carries an amber count pill when inputs are waiting on a person + (`DurableDashboard.InboxBadge`, an `on_mount` hook every page gets; it + consumes input events unless a page assigns `wants_input_events`). + - Footer: running mark + "Live · version", GitHub, theme toggle. +- **Breadcrumbs** render above the heading only on pages more than one + level deep. ### Page header @@ -407,27 +357,34 @@ something is tinted indigo it should mean "live / current." Subtitle = relative time, scope context, or counts. Never marketing copy. -### Tab strip +### View switch / tab strip -`<.tabs>` from `Components.Workflow.Tabs`. No ad-hoc nav strips. +A row of `patch` links over a hairline bottom border; the active one gets a +2px `border-primary` underline and `text-foreground`, the rest +`text-subtle-foreground`. A count rides in a `bg-secondary` mono pill +(Inbox: "Needs input 22"). The active view lives in the URL (`?tab=` / +`/:view`) so it's shareable. ### Command palette (⌘K) `Components.Command.CommandPalette` — rendered **once** by `Layouts.app` -(needs `base_path` + `durable`), opened by ⌘K or the topbar "Jump to…" -trigger. It is the canonical global jumper (§9) and follows Linear's +(needs `base_path` + `durable`), opened by ⌘K or the sidebar "Jump to run, workflow…" +button. It is the canonical global jumper (§9) and follows Linear's command-palette discipline (§1). - **Searches the console's nouns, grouped** under `<.label>` section - headers: **Go to** (page routes), **Workflows** (live definitions → - their executions), **Recent runs** (latest executions → run detail). - Grouping carries result *type*, so rows don't need per-row type chips. -- **Snapshot on open, filter in memory.** Live data - (`Durable.Query.list_workflows` + recent executions) is fetched once on - `palette:open` and filtered client-of-the-LC-side on each keystroke — - typing never hits the database. Degrades to page routes when `durable` - is `nil`. -- **Selection wears the live rail** (the indigo bar, see signature above) + headers: **Go to** (page routes, plus the Runs saved views once you type — + "fail" → Failed runs), **Workflows** (→ the workflow's page), + **Schedules** (→ the schedule's page, with its cadence and On/Off), + **Recent runs** / **Runs** (→ the run). Grouping carries result *type*, + so rows don't need per-row type chips. Icons are the sidebar's own. +- **Snapshot on open, filter in memory** — workflows, schedules and the + newest runs are fetched once on `palette:open`. The one exception: a + query shaped like a run id (4+ hex characters) is looked up in the + database by prefix, so any run is found, not only the recent ones. The + input is debounced (100 ms). Degrades to page routes when `durable` is + `nil`. +- **Selection is marked in the live blue** plus a `↵` hint that appears only on the selected row. Keyboard nav wraps across groups via a single flat selection index; hover selects. - Row meta is restrained: workflow rows show run count + last-status @@ -435,40 +392,94 @@ command-palette discipline (§1). ### List / table row -- 36–40 h tall, hairline divider between rows. -- Hover: `bg-accent/50`. -- Click anywhere on the row → `live_patch` to detail. -- Right-aligned secondary actions reveal on hover. -- **Column headers** use the canonical `<.label>` idiom — `font-mono - text-[10px] uppercase tracking-[0.14em] text-muted-foreground/70` — so a - table header reads as a label, identical to field-name labels in the detail - panels. This is baked into the `DataTable` LiveComponent; hand-rolled tables - (e.g. Overview's "recent executions") apply the same classes. Sortable - headers add `hover:text-foreground`. Never reach for sans `tracking-wider`. - -### Faceted filter bar - -Filtering a list of the system's nouns (e.g. Executions) uses a **facet row**, -not a search box + dropdowns: a chip per facet (`Components.Data.ExecutionFilters` -— Workflow, Status, Time, ID), each opening a popover. It's the ops-console query -builder (Linear / Datadog) and scales as facets are added. - +- Tables are plain HEEx inside a `Charts.panel` (there is no table + component — each page's columns are its own). 46 px rows, hairline + `border-b border-border` between them, `hover:bg-accent`. +- **Column headers** are sentence case, `text-xs font-medium + text-muted-foreground`, with `border-y` framing the header row. Numbers + right-aligned and mono; never uppercase or letter-spaced. +- The row's primary cell links to the noun's page (run, workflow); actions + sit in a last, right-aligned column as `size="sm"` buttons, rendered only + when the viewer's access allows them (§12 Access). + +### Tooltips + +One tooltip for the whole dashboard (`assets/src/tooltip.ts`): it opens after +a 350 ms hover (instantly while another just closed) or on keyboard focus, +and Esc, a click or scrolling closes it. It sits above its trigger (below when +there's no room), is clamped to the viewport, and is `position: fixed` on +`` — a table or card with `overflow: hidden` can't clip it. While open +it re-reads its trigger, so a live value stays current. + +- **Markup.** `data-tip` is the body (`\n` for a new line); `data-tip-title` + a heading of a few words; `data-tip-meta` a mono footnote under a rule — + ids, raw values, UTC; `data-tip-kbd` a shortcut beside the title; + `data-tip-side="bottom"` to prefer below. Works on SVG elements too. + **Never `title=`** — the browser's tooltip is unstyled, slow and can't be + themed. Every `