Snabbkaffex (snabbkaffex v0.1.0)

Copy Markdown View Source

A thin Elixir wrapper around the Erlang snabbkaffe trace-based testing library.

snabbkaffe ships its instrumentation as Erlang preprocessor macros (-include_lib("snabbkaffe/include/trace.hrl")) which are not usable from Elixir. This module provides the Elixir macro counterparts so that:

  • Trace points placed in production code (tp/2, tp/3, tp_span/3, tp_span/4) only become real snabbkaffe collector calls in :test. Compiled anywhere else they follow snabbkaffe's trace_prod.hrl convention: by default data is evaluated and its value thrown away, level: degrades to a :logger call, and ignore_side_effects: true drops to a bare :ok (see "Why discard in prod?" below).
  • Test helpers (check_trace/2, block_until/2, of_kind/2, ...) wrap the corresponding :snabbkaffe runtime calls. Most are plain functions; only the ones that take an Elixir pattern (block_until, find_pairs, causality, force_ordering, ...) need to be macros: they turn the pattern into a matcher function in place of snabbkaffe's ?match_event.

Why discard in prod?

Snabbkaffex is a test-only dependency (only: :test). The trace-point macros live in regular lib/ code, so they must compile to a cheap no-op when the collector is not present. Following snabbkaffe's own convention, the gate is Mix.env() == :test, evaluated at macro-expansion time so it reflects the environment of the module being compiled.

To match the Erlang semantics precisely, the discarded tp/2 still evaluates its data expression (so side effects behave identically across builds) and then throws the value away. Passing level: makes it degrade to a :logger call in non-test builds instead (just like trace_prod.hrl); passing ignore_side_effects: true skips the data expression entirely. The two are mutually exclusive (passing both raises at compile time), since they pull in opposite directions — keep the event in prod logs vs. drop it to nothing. See tp/3.

Usage

Instrument production code with use Snabbkaffex, only: :trace, which imports only the discardable trace-point macros (tp/2, tp/3, tp_span/3, tp_span/4) and none of the test-only helpers:

defmodule MyServer do
  use Snabbkaffex, only: :trace

  def handle_event(e) do
    tp(:my_server_got_event, %{event: e})
    # ...
  end
end

And in a test, use Snabbkaffex (no options) to also get check_trace/2, of_kind/2, and friends. The trace collector is a global singleton, so a test module that runs traces must be async: false:

use ExUnit.Case, async: false
use Snabbkaffex

test "server processes the event" do
  check_trace(
    fn -> MyServer.handle_event(:hello) end,
    fn trace ->
      assert [%{event: :hello}] = of_kind(trace, :my_server_got_event)
    end
  )
end

use Snabbkaffex emits a compile-time warning if the module is use ExUnit.Case, async: true, since concurrent tests would clobber each other's traces through the shared collector.

Event shape

A trace point tp(:kind, %{a: 1}) is collected as a map %{:"$kind" => :kind, :a => 1, :"~meta" => %{...}}. When pattern matching on events, the kind lives under the :"$kind" key. Prefer of_kind/2 to filter by kind so you rarely need to spell that out.

Argument order

Trace-querying functions (of_kind/2, projection/2, find_pairs/3, causality/3, ...) take the trace as their first argument, unlike the Erlang originals, so they read left-to-right in a pipe:

trace
|> of_kind(:worker_started)
|> projection(:input)

Summary

Types

A check_trace/2,3 check function. Passes unless it raises (its return value is ignored, unlike Erlang snabbkaffe's :snabbkaffe.trace_spec/1, which requires ok/true). Arity 1 receives the trace; arity 2 the run result and the trace.

Field (or fields) to project out of each event; see projection/2.

Functions

Requires Snabbkaffex and imports its macros/helpers.

Fault scenario for inject_crash/2's scenario: option: crash on every matching trace point. This is also inject_crash's default when no strategy option is given.

Print an analysis of all statistics collected via push_stat/2.

Block until an event matching pattern is collected, or until timeout.

block_until/3 waiting for n_events events matching pattern (mirrors Erlang's ?block_until({Predicate, NEvents}, ...) form). Events already in the collected trace count towards n_events, which makes it the right tool for waiting on the Nth occurrence of a recurring event (e.g. a node becoming :ready for the same view a second time, after churn). Returns {:ok, [event]} or {:timeout, [partial]}.

Assert every effect event in trace was preceded by a matching cause event. Pairs may be nested. Raises on a causality violation; otherwise returns true if at least one pair was found, false if none.

causality/3 with a guard expression over both events' bindings.

Run run_fun, collect the resulting trace, then validate it with check_fun.

check_trace/2 with a snabbkaffe run config (a map, e.g. %{timeout: 100}) or an integer statistics bucket.

Reset the collector and nemesis state (drops the buffered trace and any injected crashes/orderings) without stopping the collector.

Flush and return the collected trace, waiting timeout ms for silence first.

Dump trace to a file (as snabbkaffe does on failure) and return the path.

Strip timestamps from every event in trace (useful before comparing traces).

Find cause/effect pairs in trace matching cause_pattern and effect_pattern.

find_pairs/3 with an extra guard expression over both events' bindings.

Remove a crash injected by inject_crash/2 (given its reference).

Enforce an ordering between two classes of events: hold back every event matching the :delay pattern until events matching the :until pattern have been emitted.

Start forwarding trace events emitted on the remote node to this collector.

Return the raw statistics map collected so far.

Assert value is within deviation of expected. Returns true or raises.

Assert the numbers in list are non-decreasing. Returns true or raises.

Inject crashes at trace points matching pattern, returning a reference you can later pass to fix_crash/1.

Build a predicate fn event -> boolean end from an Elixir pattern.

Keep only events in trace whose logger metadata domain equals domain.

Keep only events in trace whose :"$kind" is kind (or one of a list of kinds).

Keep only events in trace emitted on node.

The maximum nesting depth among a list of pairs (from find_pairs/3).

Fault scenario for inject_crash/2's scenario: option: crash periodically, driven by the count of matching trace points (not wall-clock time). Within each cycle of period matches the trace point stays healthy for the first duty_cycle fraction and crashes for the rest; phase (in radians, 0 to 2 * pi) shifts the cycle.

Project field (atom) or fields (list of atoms) out of each event in trace.

Assert every value in expected appears in the projection of fields over trace (i.e. expected is a subset of what was traced). Returns true or raises. The complement of projection_is_subset/3.

Assert the projection of fields over trace contains no values outside expected (i.e. what was traced is a subset of expected). Returns true or raises.

Record a value for metric. With an extra leading argument, records a {x, y} datapoint (push_stat(metric, x, y)). See analyze_statistics/0.

Record many datapoints for metric at once (see :snabbkaffe.push_stats/2,3).

Fault scenario: crash with the given probability (a float in 0.0..1.0). Usually reached via inject_crash(pattern, random_crash: probability).

Wait for the events of a subscription returned by subscribe/1. Returns {:ok, [event]} or {:timeout, [partial]}.

Fault scenario: crash the first n times a trace point matches, then recover. Usually reached via inject_crash(pattern, recover_after: n).

Retry the do block up to n times, sleeping interval ms between attempts, until it stops raising. Returns the block's value.

Split trace at the first event matching pattern, returning {before, [match | after]} (Elixir's Enum.split_while/2 at the marker).

Split trace into segments, each ending with an event matching pattern; a trailing run of non-matching events forms the final segment. Mirrors ?splitl_trace.

Split trace into segments, each starting with an event matching pattern; a leading run of non-matching events forms the first segment. Mirrors ?splitr_trace.

Start the snabbkaffe collector (idempotent).

Stop the snabbkaffe collector.

Like causality/3, but additionally forbids unmatched effect events.

strict_causality/3 with a guard expression over both events' bindings.

Assert the numbers in list are strictly increasing. Returns true or raises.

Subscribe to events matching predicate, returning {:ok, subscription}.

Emit a trace point of the given kind carrying data (a map).

tp/2 with a literal keyword-list of opts

Trace a span around a do block: emits a start event before and a {:complete, return} event after, then returns the block's value.

Stop forwarding node's trace events, reverting it to recording locally.

Assert every event in trace is unique. Returns true or raises.

Subscribe to an event matching pattern, run the do block, then wait (up to timeout) for the event. Returns {block_return, {:ok, event} | :timeout}.

Types

check_fun()

@type check_fun() ::
  (:snabbkaffe.trace() -> any()) | (term(), :snabbkaffe.trace() -> any())

A check_trace/2,3 check function. Passes unless it raises (its return value is ignored, unlike Erlang snabbkaffe's :snabbkaffe.trace_spec/1, which requires ok/true). Arity 1 receives the trace; arity 2 the run result and the trace.

fields()

@type fields() :: atom() | [atom()]

Field (or fields) to project out of each event; see projection/2.

Functions

__using__(opts)

(macro)

Requires Snabbkaffex and imports its macros/helpers.

Options:

  • only: :trace — import only the discardable trace-point macros (tp/2, tp/3, tp_span/3, tp_span/4). Use this in production lib/ modules so you don't pull test-only helpers (stop/0, retry/3, ...) into their namespace.

With no options, imports everything (intended for test modules). In that case Snabbkaffex also installs a @before_compile hook that warns if the module is use ExUnit.Case, async: true, because the trace collector is a global singleton and concurrent tests would corrupt each other's traces.

always_crash()

Fault scenario for inject_crash/2's scenario: option: crash on every matching trace point. This is also inject_crash's default when no strategy option is given.

analyze_statistics()

Print an analysis of all statistics collected via push_stat/2.

block_until(pattern, timeout \\ :infinity, back_in_time \\ :infinity)

(macro)

Block until an event matching pattern is collected, or until timeout.

back_in_time (ms) lets the matcher also consider recently-collected events, avoiding a race when the event fires before the call. Returns {:ok, event} or :timeout.

block_until(pattern, n_events, timeout, back_in_time)

(macro)

block_until/3 waiting for n_events events matching pattern (mirrors Erlang's ?block_until({Predicate, NEvents}, ...) form). Events already in the collected trace count towards n_events, which makes it the right tool for waiting on the Nth occurrence of a recurring event (e.g. a node becoming :ready for the same view a second time, after churn). Returns {:ok, [event]} or {:timeout, [partial]}.

causality(trace, cause_pattern, effect_pattern)

(macro)

Assert every effect event in trace was preceded by a matching cause event. Pairs may be nested. Raises on a causality violation; otherwise returns true if at least one pair was found, false if none.

causality(trace, cause_pattern, effect_pattern, guard)

(macro)

causality/3 with a guard expression over both events' bindings.

check_trace(run_fun, check_fun)

@spec check_trace((-> term()), check_fun()) :: true

Run run_fun, collect the resulting trace, then validate it with check_fun.

run_fun is a zero-arity function whose return value becomes the test result. check_fun is a function of either arity 1 (trace) or arity 2 (result, trace). The check passes unless it raises: use ordinary ExUnit assertions; the function's return value is ignored (unlike Erlang snabbkaffe, which requires true/ok).

check_trace(
  fn -> do_work() end,
  fn result, trace ->
    assert result == :ok
    assert [_] = of_kind(trace, :work_done)
  end
)

check_trace(config, run_fun, check_fun)

@spec check_trace(:snabbkaffe.run_config() | integer(), (-> term()), check_fun()) ::
  true

check_trace/2 with a snabbkaffe run config (a map, e.g. %{timeout: 100}) or an integer statistics bucket.

cleanup()

Reset the collector and nemesis state (drops the buffered trace and any injected crashes/orderings) without stopping the collector.

collect_trace(timeout \\ 0)

@spec collect_trace(integer()) :: :snabbkaffe.trace()

Flush and return the collected trace, waiting timeout ms for silence first.

dump_trace(trace)

Dump trace to a file (as snabbkaffe does on failure) and return the path.

erase_timestamps(trace)

Strip timestamps from every event in trace (useful before comparing traces).

find_pairs(trace, cause_pattern, effect_pattern)

(macro)

Find cause/effect pairs in trace matching cause_pattern and effect_pattern.

find_pairs(trace, cause_pattern, effect_pattern, guard)

(macro)

find_pairs/3 with an extra guard expression over both events' bindings.

fix_crash(reference)

Remove a crash injected by inject_crash/2 (given its reference).

force_ordering(opts)

(macro)

Enforce an ordering between two classes of events: hold back every event matching the :delay pattern until events matching the :until pattern have been emitted.

Takes a literal keyword list so the direction is obvious at the call site — "delay X until Y":

  • :delay (required) — pattern for the events to hold back.
  • :until (required) — pattern for the gate events that release them.
  • :count — release only after this many :until events have been seen (default 1). Events already in the collected trace count towards it.
  • :when — a boolean guard over the variables bound in the :delay and :until patterns, used to tie the two together (e.g. by a shared id). Defaults to always matching.

Examples

# Hold worker :a's :store until worker :b's :miss has fired.
force_ordering(
  delay: %{:"$kind" => :store, worker: :a},
  until: %{:"$kind" => :miss, worker: :b}
)

# Tie the two events together by id, and wait for two gate events.
force_ordering(
  delay: %{:"$kind" => :store, id: sid},
  until: %{:"$kind" => :miss, id: mid},
  count: 2,
  when: sid == mid
)

Wraps snabbkaffe's force_ordering (whose positional argument order differs).

forward_trace(node)

Start forwarding trace events emitted on the remote node to this collector.

Used in multi-node tests so tp calls on node land in the local trace.

get_stats()

Return the raw statistics map collected so far.

give_or_take(expected, deviation, value)

@spec give_or_take(number(), number(), number()) :: true

Assert value is within deviation of expected. Returns true or raises.

increasing(list)

Assert the numbers in list are non-decreasing. Returns true or raises.

inject_crash(pattern, opts \\ [])

(macro)

Inject crashes at trace points matching pattern, returning a reference you can later pass to fix_crash/1.

With no options the process crashes on every matching trace point. Pass at most one strategy option to shape when it crashes:

  • recover_after: n — crash the first n matches, then recover
  • random_crash: p — crash with probability p (a float in 0.0..1.0)
  • scenario: fun — any snabbkaffe fault scenario, for the less common cases (e.g. scenario: periodic_crash(10, 0.5, 0.0))

The reason: option sets the exit reason for the crashing process (defaults to :notmyday).

inject_crash(%{:"$kind" => :write})                        # crash every time
inject_crash(%{:"$kind" => :write}, reason: :disk_full)    # ... with a reason
inject_crash(%{:"$kind" => :before_ack}, recover_after: 1)
inject_crash(%{:"$kind" => :flaky}, random_crash: 0.1)
inject_crash(%{:"$kind" => :wave}, scenario: periodic_crash(10, 0.5, 0.0))

match_event(pattern)

(macro)

Build a predicate fn event -> boolean end from an Elixir pattern.

This is the Elixir counterpart of snabbkaffe's ?match_event, used internally by the pattern-taking macros and exposed for building snabbkaffe subscriptions directly (:snabbkaffe.subscribe/1, etc.).

of_domain(trace, domain)

@spec of_domain(:snabbkaffe.trace(), [atom()]) :: :snabbkaffe.trace()

Keep only events in trace whose logger metadata domain equals domain.

of_kind(trace, kind)

Keep only events in trace whose :"$kind" is kind (or one of a list of kinds).

of_node(trace, node)

@spec of_node(:snabbkaffe.trace(), node()) :: :snabbkaffe.trace()

Keep only events in trace emitted on node.

pair_max_depth(pairs)

The maximum nesting depth among a list of pairs (from find_pairs/3).

periodic_crash(period, duty_cycle, phase)

Fault scenario for inject_crash/2's scenario: option: crash periodically, driven by the count of matching trace points (not wall-clock time). Within each cycle of period matches the trace point stays healthy for the first duty_cycle fraction and crashes for the rest; phase (in radians, 0 to 2 * pi) shifts the cycle.

projection(trace, fields)

@spec projection(:snabbkaffe.trace(), fields()) :: list()

Project field (atom) or fields (list of atoms) out of each event in trace.

With a single atom, returns a list of values; with a list, a list of tuples.

projection_complete(trace, fields, expected)

@spec projection_complete(:snabbkaffe.trace(), fields(), [term()]) :: true

Assert every value in expected appears in the projection of fields over trace (i.e. expected is a subset of what was traced). Returns true or raises. The complement of projection_is_subset/3.

projection_is_subset(trace, fields, expected)

@spec projection_is_subset(:snabbkaffe.trace(), fields(), [term()]) :: true

Assert the projection of fields over trace contains no values outside expected (i.e. what was traced is a subset of expected). Returns true or raises.

push_stat(metric, value)

Record a value for metric. With an extra leading argument, records a {x, y} datapoint (push_stat(metric, x, y)). See analyze_statistics/0.

push_stat(metric, x, y)

See :snabbkaffe.push_stat/3.

push_stats(metric, values)

Record many datapoints for metric at once (see :snabbkaffe.push_stats/2,3).

push_stats(metric, x, values)

See :snabbkaffe.push_stats/3.

random_crash(probability)

Fault scenario: crash with the given probability (a float in 0.0..1.0). Usually reached via inject_crash(pattern, random_crash: probability).

receive_events(subscription)

Wait for the events of a subscription returned by subscribe/1. Returns {:ok, [event]} or {:timeout, [partial]}.

recover_after(n)

Fault scenario: crash the first n times a trace point matches, then recover. Usually reached via inject_crash(pattern, recover_after: n).

retry(interval, n, opts)

(macro)

Retry the do block up to n times, sleeping interval ms between attempts, until it stops raising. Returns the block's value.

retry 10, 5 do
  assert something_eventually_true()
end

split_trace_at(trace, pattern)

(macro)

Split trace at the first event matching pattern, returning {before, [match | after]} (Elixir's Enum.split_while/2 at the marker).

splitl_trace(trace, pattern)

(macro)

Split trace into segments, each ending with an event matching pattern; a trailing run of non-matching events forms the final segment. Mirrors ?splitl_trace.

E.g. splitting [a, b, M, c, M, d] on M gives [[a, b, M], [c, M], [d]].

splitr_trace(trace, pattern)

(macro)

Split trace into segments, each starting with an event matching pattern; a leading run of non-matching events forms the first segment. Mirrors ?splitr_trace.

E.g. splitting [a, b, M, c, M, d] on M gives [[a, b], [M, c], [M, d]].

start_trace()

@spec start_trace() :: :ok

Start the snabbkaffe collector (idempotent).

stop()

@spec stop() :: :ok

Stop the snabbkaffe collector.

strict_causality(trace, cause_pattern, effect_pattern)

(macro)

Like causality/3, but additionally forbids unmatched effect events.

strict_causality(trace, cause_pattern, effect_pattern, guard)

(macro)

strict_causality/3 with a guard expression over both events' bindings.

strictly_increasing(list)

Assert the numbers in list are strictly increasing. Returns true or raises.

subscribe(predicate)

Subscribe to events matching predicate, returning {:ok, subscription}.

Lower-level than block_until/2: pair with receive_events/1 to collect the events later. predicate is a fn event -> boolean end — build one from a pattern with match_event/1. Optional n_events (default 1), timeout, and back_in_time mirror :snabbkaffe.subscribe/1..4.

subscribe(predicate, timeout)

See :snabbkaffe.subscribe/2.

subscribe(predicate, n_events, timeout)

See :snabbkaffe.subscribe/3.

subscribe(predicate, n_events, timeout, back_in_time)

See :snabbkaffe.subscribe/4.

tp(kind, data)

(macro)

Emit a trace point of the given kind carrying data (a map).

In :test this records an event via the snabbkaffe collector. Outside :test the behaviour is controlled by opts (see tp/3); with no options data is evaluated for its side effects and the result discarded, returning :ok (mirroring snabbkaffe's ?tp/2).

tp(kind, data, opts)

(macro)

tp/2 with a literal keyword-list of opts:

  • level: <atom> — set the event's severity. In :test it's the collected event's level; outside :test the call degrades to a :logger call at that level, so the event stays visible in production logs (mirrors ?tp/3).
  • ignore_side_effects: true — outside :test the whole call becomes a bare :ok and data is not evaluated at all (mirrors ?tp_ignore_side_effects_in_prod). Use when building data is expensive or side-effecting and should cost nothing in production; the trade-off is that data must be purely diagnostic. Mutually exclusive with :level (passing both raises ArgumentError at compile time): :level keeps the event in production logs, whereas this drops it entirely outside :test.

Examples:

tp(:got_event, %{event: e}, level: :warning)
tp(:snapshot, %{state: expensive_dump(s)}, ignore_side_effects: true)

tp_span(kind, data, opts)

(macro)

Trace a span around a do block: emits a start event before and a {:complete, return} event after, then returns the block's value.

The keyword list carrying the do: block also accepts the same options as tp/3 (:level, :ignore_side_effects). Unlike the Erlang macro (which expands DATA twice), data is evaluated exactly once. With ignore_side_effects: true, outside :test the span reduces to just the block and data is never evaluated.

tp_span :fetch, %{id: id} do
  do_fetch(id)
end

tp_span :fetch, %{id: id}, level: :info do
  do_fetch(id)
end

tp_span(kind, data, opts, do_block)

(macro)

unforward_trace(node)

@spec unforward_trace(node()) :: :ok

Stop forwarding node's trace events, reverting it to recording locally.

A Snabbkaffex addition — snabbkaffe itself exposes no "unforward" call. forward_trace/1 works by pointing node's trace-point function (the :snabbkaffe_tp_fun persistent term) at :snabbkaffe.remote_tp/5, which RPCs every event back to this collector; this resets it to the default :snabbkaffe.local_tp/5, so node keeps its own trace instead.

The motivating case is netsplit tests: with forwarding left on, every tp/2 on the disconnected node does a synchronous RPC to the collector, which auto-reconnects a node you deliberately Node.disconnect/1'd. Call this while node is still reachable, before disconnecting; re-attach with forward_trace/1 once reconnected.

unique(trace)

Assert every event in trace is unique. Returns true or raises.

wait_async_action(pattern, opts)

(macro)

Subscribe to an event matching pattern, run the do block, then wait (up to timeout) for the event. Returns {block_return, {:ok, event} | :timeout}.

The block is the async action; it runs before the wait even though it reads last. Pass timeout: (ms, default :infinity) in the options alongside the block.

wait_async_action %{"$kind": :work_done} do
  GenServer.cast(pid, :go)
end

wait_async_action %{"$kind": :work_done}, timeout: 100 do
  GenServer.cast(pid, :go)
end

wait_async_action(pattern, opts, do_block)

(macro)