diff --git a/.gitignore b/.gitignore index ddefaa1..6d2f134 100644 --- a/.gitignore +++ b/.gitignore @@ -1,32 +1,15 @@ -# Build -/_build/ -/deps/ -/doc/ - -# Dialyzer -/priv/plts/ - -# Test -/cover/ - -# Package -philter-*.tar -/philter-*/ - -# VM crash dumps +/_build +/cover +/deps +/doc +/.fetch erl_crash.dump - -# Archive artifacts *.ez - -# Temporary files -/tmp/ - -# IDE -.idea/ -*.swp +*.beam +/config/*.secret.exs .elixir_ls/ -.vscode/ +priv/plts +/philter-*.tar +/philter-*/ -# OS -.DS_Store +.claude/settings.local.json diff --git a/CHANGELOG.md b/CHANGELOG.md index e181a5e..8e98fb0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,15 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.3.0] - 2026-04-09 + +### Changed +- **Breaking**: All timing consolidated into `finished_result.timing` map — `finished_result.duration_us` replaced by `timing.total_us`, and `body_observation.duration_us` / `body_observation.time_to_first_byte_us` removed. Observations are now purely content metadata (hash, size, preview, body) + +### Added +- `collect_timing: true` option for `proxy/2` enables per-phase timing capture (queue, connect, send, recv, idle_time, reused_connection) from HTTP client telemetry +- `Philter.Timing` module for telemetry-based phase timing with lazy global handler attachment + ## [0.2.1] - 2026-03-11 ### Fixed diff --git a/README.md b/README.md index 9f106be..8b32c29 100644 --- a/README.md +++ b/README.md @@ -75,7 +75,6 @@ resp_obs = conn.private[:philter_response_observation] # - :size - Total body size in bytes # - :preview - First 64KB of the body (UTF-8 safe truncation) # - :body - Full body (only if under max_payload_size and content-type matches) -# - :duration_us - Processing time in microseconds ``` ## Handler Callbacks @@ -100,7 +99,7 @@ defmodule MyApp.ProxyHandler do @impl true def handle_response_finished(result, state) do - Logger.info("Completed: #{result.status} in #{result.duration_us}us") + Logger.info("Completed: #{result.status} in #{result.timing.total_us}us") # result contains :request_observation and :response_observation {:ok, state} end diff --git a/lib/philter.ex b/lib/philter.ex index d89e362..10c33a5 100644 --- a/lib/philter.ex +++ b/lib/philter.ex @@ -65,7 +65,7 @@ defmodule Philter do @impl true def handle_response_finished(result, state) do # result contains :request_observation and :response_observation - # each with :hash, :size, :body, :preview, :duration_us + # each with :hash, :size, :body, :preview {:ok, state} end end @@ -101,7 +101,8 @@ defmodule Philter do receive_timeout: pos_integer(), max_payload_size: pos_integer(), persistable_content_types: [String.t()], - log_level: Logger.level() | false + log_level: Logger.level() | false, + collect_timing: boolean() ] @doc """ @@ -172,6 +173,11 @@ defmodule Philter do * `:log_level` - Logger level for lifecycle events (`:debug`, `:info`, etc.) or `false` to disable all logging. Default: `:debug`. + * `:collect_timing` - When `true`, captures per-phase timing breakdown + (queue, connect, send, recv, idle_time, reused_connection) from HTTP client + telemetry events. Phase fields in `timing` are `nil` when disabled. + Default: `false`. + ## Return Value Returns the `conn` with response sent. Observations are stored in: @@ -179,8 +185,7 @@ defmodule Philter do * `conn.private[:philter_request_observation]` - Request body observation * `conn.private[:philter_response_observation]` - Response body observation - Each observation contains `:hash`, `:size`, `:body` (if accumulated), `:preview`, - and `:duration_us`. + Each observation contains `:hash`, `:size`, `:body` (if accumulated), and `:preview`. ## Error Handling @@ -270,13 +275,15 @@ defmodule Philter do upstream_url: upstream_url } - result = - Finch.stream_while( + collect_timing? = Keyword.get(opts, :collect_timing, false) + + {result, timing} = + stream_with_timing( request, config.finch_name, acc, - &handle_stream_message/2, - receive_timeout: config.receive_timeout + [receive_timeout: config.receive_timeout], + collect_timing? ) case result do @@ -309,7 +316,7 @@ defmodule Philter do upstream_url: upstream_url, method: acc.conn.method, status: acc.conn.status, - duration_us: duration_us + timing: build_timing(duration_us, timing) }, handler_state ) @@ -333,7 +340,8 @@ defmodule Philter do started_at: started_at, error: {:timeout, reason}, status: 504, - body: "Gateway Timeout" + body: "Gateway Timeout", + timing: timing }) {:error, %Mint.TransportError{reason: reason}, acc} @@ -344,7 +352,8 @@ defmodule Philter do started_at: started_at, error: {:timeout, reason}, status: 504, - body: "Gateway Timeout" + body: "Gateway Timeout", + timing: timing }) {:error, error, acc} -> @@ -354,7 +363,8 @@ defmodule Philter do started_at: started_at, error: error, status: 502, - body: "Bad Gateway" + body: "Bad Gateway", + timing: timing }) end @@ -595,6 +605,7 @@ defmodule Philter do end observations = Observer.finalize(acc.observer) + duration_us = System.monotonic_time(:microsecond) - info.started_at handler_state = handler_state(acc) notify_response_finished( @@ -606,7 +617,7 @@ defmodule Philter do upstream_url: info.upstream_url, method: info.method, status: nil, - duration_us: System.monotonic_time(:microsecond) - info.started_at + timing: build_timing(duration_us, info.timing) }, handler_state ) @@ -614,6 +625,42 @@ defmodule Philter do acc.conn |> send_resp(info.status, info.body) |> halt() end + defp stream_with_timing(request, finch_name, acc, opts, collect_timing?) do + ref = + if collect_timing? do + Philter.Timing.ensure_attached() + Philter.Timing.start_capture() + end + + try do + Finch.stream_while(request, finch_name, acc, &handle_stream_message/2, opts) + catch + kind, reason -> + if ref, do: Philter.Timing.collect(ref) + :erlang.raise(kind, reason, __STACKTRACE__) + else + result -> + timing = if ref, do: Philter.Timing.collect(ref) + {result, timing} + end + end + + defp build_timing(total_us, nil) do + %{ + total_us: total_us, + queue_us: nil, + connect_us: nil, + send_us: nil, + recv_us: nil, + idle_time_us: nil, + reused_connection?: nil + } + end + + defp build_timing(total_us, phase_timing) do + Map.put(phase_timing, :total_us, total_us) + end + defp notify_request_started(nil, _metadata), do: {:ok, nil} defp notify_request_started({module, args}, metadata) do diff --git a/lib/philter/handler.ex b/lib/philter/handler.ex index 3509462..e2295a1 100644 --- a/lib/philter/handler.ex +++ b/lib/philter/handler.ex @@ -65,23 +65,38 @@ defmodule Philter.Handler do - `:size` - Total body size in bytes - `:body` - Full body content if accumulated, nil otherwise - `:preview` - First 64KB of body (always present) - - `:duration_us` - Time to fully transfer body in microseconds - - `:time_to_first_byte_us` - Time to first byte in microseconds """ @type body_observation :: %{ required(:hash) => String.t(), required(:size) => non_neg_integer(), required(:body) => binary() | nil, - required(:preview) => binary(), - required(:duration_us) => non_neg_integer(), - required(:time_to_first_byte_us) => non_neg_integer() | nil + required(:preview) => binary() + } + + @typedoc """ + Per-phase timing breakdown for a proxy request. + + When `collect_timing: true` is set, phase fields are populated from HTTP + client telemetry. When timing capture is off, phase fields are `nil` and + `reused_connection?` is `nil`. + """ + @type timing :: %{ + required(:total_us) => non_neg_integer(), + required(:queue_us) => non_neg_integer() | nil, + required(:connect_us) => non_neg_integer() | nil, + required(:send_us) => non_neg_integer() | nil, + required(:recv_us) => non_neg_integer() | nil, + required(:idle_time_us) => non_neg_integer() | nil, + required(:reused_connection?) => boolean() | nil } @typedoc """ Result passed to handle_response_finished/2. Contains observations for both request and response bodies, plus any error - that occurred during proxying. + that occurred during proxying. The `:status` field is `nil` when the error + occurred before receiving a response from upstream (e.g., connection refused, + pool checkout timeout). """ @type finished_result :: %{ required(:request_observation) => body_observation(), @@ -90,7 +105,7 @@ defmodule Philter.Handler do required(:upstream_url) => String.t(), required(:method) => String.t(), required(:status) => non_neg_integer() | nil, - required(:duration_us) => non_neg_integer() + required(:timing) => timing() } @doc """ diff --git a/lib/philter/observation.ex b/lib/philter/observation.ex index 52fc09e..af2ee2b 100644 --- a/lib/philter/observation.ex +++ b/lib/philter/observation.ex @@ -2,9 +2,9 @@ defmodule Philter.Observation do @moduledoc false # Internal module: Incremental observation capture for streaming bodies. # - # Captures hash (SHA256), preview (first 64KB), size, and timing data - # incrementally as chunks arrive. Optionally accumulates the full body - # if under a size threshold. + # Captures hash (SHA256), preview (first 64KB), and size incrementally + # as chunks arrive. Optionally accumulates the full body if under a size + # threshold. # # ## Body Accumulation # @@ -24,8 +24,6 @@ defmodule Philter.Observation do :hash_state, :preview, :size, - :started_at, - :first_byte_at, # Accumulation fields :accumulate?, :accumulated_body, @@ -37,8 +35,6 @@ defmodule Philter.Observation do hash_state: term(), preview: binary(), size: non_neg_integer(), - started_at: integer(), - first_byte_at: integer() | nil, accumulate?: boolean(), accumulated_body: iodata() | nil, max_size: non_neg_integer(), @@ -66,8 +62,6 @@ defmodule Philter.Observation do hash_state: :crypto.hash_init(:sha256), preview: <<>>, size: 0, - started_at: System.monotonic_time(:microsecond), - first_byte_at: nil, accumulate?: accumulate?, accumulated_body: if(accumulate?, do: [], else: nil), max_size: max_size, @@ -76,12 +70,11 @@ defmodule Philter.Observation do end @doc """ - Updates observation with a chunk. Updates hash, preview, size, timing, + Updates observation with a chunk. Updates hash, preview, size, and accumulated body (if enabled and under threshold). """ @spec update(t(), binary()) :: t() def update(%__MODULE__{} = obs, chunk) when is_binary(chunk) do - now = System.monotonic_time(:microsecond) chunk_size = byte_size(chunk) new_size = obs.size + chunk_size @@ -91,8 +84,6 @@ defmodule Philter.Observation do hash_state: :crypto.hash_update(obs.hash_state, chunk), preview: capture_preview(obs.preview, chunk), size: new_size, - started_at: obs.started_at, - first_byte_at: obs.first_byte_at || now, accumulate?: obs.accumulate?, accumulated_body: accumulated_body, max_size: obs.max_size, @@ -129,8 +120,6 @@ defmodule Philter.Observation do - `:size` - total bytes - `:preview` - first 64KB (UTF-8 safe) - `:body` - full body binary if accumulated, nil otherwise - - `:duration_us` - total microseconds - - `:time_to_first_byte_us` - microseconds to first chunk (nil if no data) """ @spec finalize(t()) :: Philter.Handler.body_observation() def finalize(%__MODULE__{} = obs) do @@ -142,9 +131,7 @@ defmodule Philter.Observation do hash: hash, preview: preview, size: obs.size, - body: body, - duration_us: System.monotonic_time(:microsecond) - obs.started_at, - time_to_first_byte_us: time_to_first_byte(obs) + body: body } end @@ -171,7 +158,4 @@ defmodule Philter.Observation do <> = chunk existing <> captured end - - defp time_to_first_byte(%{first_byte_at: nil}), do: nil - defp time_to_first_byte(%{first_byte_at: first, started_at: started}), do: first - started end diff --git a/lib/philter/timing.ex b/lib/philter/timing.ex new file mode 100644 index 0000000..e621145 --- /dev/null +++ b/lib/philter/timing.ex @@ -0,0 +1,138 @@ +defmodule Philter.Timing do + @moduledoc """ + Per-phase timing capture for proxy requests. + + Captures pool checkout, connection, send, and receive durations from + the underlying HTTP client's telemetry events. + + Uses a single globally-attached telemetry handler (attached lazily on + first use). Per-request opt-in is via a process dictionary flag — when + no proxy has opted in, the handler is a single `Process.get/1` returning + nil. + + Timing capture is single-flight-per-process: only one `proxy/2` call + per process can capture timing at a time. The `:philter_timing_ref` + process dictionary key is shared, so a reentrant `proxy/2` call in the + same process would overwrite the ref. This is by design — Plug request + processes handle one request at a time. + """ + + @typedoc false + @type t :: %{ + queue_us: non_neg_integer() | nil, + connect_us: non_neg_integer() | nil, + send_us: non_neg_integer() | nil, + recv_us: non_neg_integer() | nil, + idle_time_us: non_neg_integer() | nil, + reused_connection?: boolean() + } + + @events [ + [:finch, :queue, :stop], + [:finch, :connect, :stop], + [:finch, :send, :stop], + [:finch, :recv, :stop], + [:finch, :reused_connection] + ] + + @handler_id "philter-timing" + + ## Lazy global handler attachment + + @doc false + @spec ensure_attached() :: :ok + def ensure_attached do + case :persistent_term.get({__MODULE__, :attached}, false) do + true -> + :ok + + false -> + case :telemetry.attach_many(@handler_id, @events, &__MODULE__.handle_event/4, nil) do + :ok -> :ok + {:error, :already_exists} -> :ok + end + + :persistent_term.put({__MODULE__, :attached}, true) + end + end + + ## Per-request opt-in / collection + + @doc false + @spec start_capture() :: reference() + def start_capture do + ref = make_ref() + Process.put(:philter_timing_ref, ref) + ref + end + + @doc false + @spec collect(reference()) :: t() + def collect(ref) do + Process.delete(:philter_timing_ref) + + result = %{ + queue_us: get_duration(ref, [:finch, :queue, :stop]), + connect_us: get_duration(ref, [:finch, :connect, :stop]), + send_us: get_duration(ref, [:finch, :send, :stop]), + recv_us: get_duration(ref, [:finch, :recv, :stop]), + idle_time_us: get_idle_time(ref), + reused_connection?: get_reused(ref) + } + + cleanup(ref) + result + end + + ## Telemetry handler (called for ALL finch events in any process) + + @doc false + def handle_event(event, measurements, _metadata, _config) do + case Process.get(:philter_timing_ref) do + nil -> :ok + ref -> Process.put({ref, event}, measurements) + end + end + + ## Private helpers + + # Read duration from stored measurements without deleting — other fields + # (e.g. idle_time on queue) may be needed from the same measurements map. + # cleanup/1 handles deletion after all fields are extracted. + defp get_duration(ref, event) do + case Process.get({ref, event}) do + nil -> + nil + + %{duration: duration} -> + System.convert_time_unit(duration, :native, :microsecond) + end + end + + # idle_time is part of the [:finch, :queue, :stop] measurements map + # alongside duration. Read from the same stored measurements. + defp get_idle_time(ref) do + case Process.get({ref, [:finch, :queue, :stop]}) do + nil -> + nil + + %{idle_time: idle_time} -> + System.convert_time_unit(idle_time, :native, :microsecond) + + _no_idle_time -> + nil + end + end + + defp get_reused(ref) do + case Process.get({ref, [:finch, :reused_connection]}) do + nil -> false + _measurements -> true + end + end + + defp cleanup(ref) do + for event <- @events, do: Process.delete({ref, event}) + :ok + end +end diff --git a/mix.exs b/mix.exs index 097cd6d..f0503d6 100644 --- a/mix.exs +++ b/mix.exs @@ -1,7 +1,7 @@ defmodule Philter.MixProject do use Mix.Project - @version "0.2.1" + @version "0.3.0" @source_url "https://github.com/OpenFn/philter" def project do diff --git a/test/philter/observation_test.exs b/test/philter/observation_test.exs index aa57aaf..6478133 100644 --- a/test/philter/observation_test.exs +++ b/test/philter/observation_test.exs @@ -8,8 +8,6 @@ defmodule Philter.ObservationTest do obs = Observation.new() assert obs.size == 0 assert obs.preview == <<>> - assert obs.started_at != nil - assert obs.first_byte_at == nil assert obs.accumulate? == false assert obs.accumulated_body == nil end @@ -64,20 +62,6 @@ defmodule Philter.ObservationTest do assert byte_size(obs.preview) == 64 * 1024 assert obs.size == 64 * 1024 + 5 end - - test "records first byte time on first chunk only" do - obs = Observation.new() - assert obs.first_byte_at == nil - - obs = Observation.update(obs, "data") - first_time = obs.first_byte_at - assert first_time != nil - - Process.sleep(1) - obs = Observation.update(obs, "more") - # Unchanged - assert obs.first_byte_at == first_time - end end describe "finalize/1" do @@ -100,8 +84,7 @@ defmodule Philter.ObservationTest do assert Map.has_key?(obs, :hash) assert Map.has_key?(obs, :preview) assert Map.has_key?(obs, :size) - assert Map.has_key?(obs, :duration_us) - assert Map.has_key?(obs, :time_to_first_byte_us) + assert Map.has_key?(obs, :body) end test "hash is correct for multi-chunk data" do diff --git a/test/philter/observer_test.exs b/test/philter/observer_test.exs index 083c272..3859288 100644 --- a/test/philter/observer_test.exs +++ b/test/philter/observer_test.exs @@ -107,7 +107,7 @@ defmodule Philter.ObserverTest do assert %{request: %{}, response: %{}} = result # Verify both observations have correct keys - for key <- [:hash, :size, :preview, :body, :duration_us, :time_to_first_byte_us] do + for key <- [:hash, :size, :preview, :body] do assert Map.has_key?(result.request, key), "request missing #{key}" assert Map.has_key?(result.response, key), "response missing #{key}" end @@ -234,16 +234,14 @@ defmodule Philter.ObserverTest do hash: ^empty_hash, size: 0, body: nil, - preview: "", - time_to_first_byte_us: nil + preview: "" } = result.request assert %{ hash: ^empty_hash, size: 0, body: nil, - preview: "", - time_to_first_byte_us: nil + preview: "" } = result.response end end diff --git a/test/philter/timing_test.exs b/test/philter/timing_test.exs new file mode 100644 index 0000000..5d2121a --- /dev/null +++ b/test/philter/timing_test.exs @@ -0,0 +1,180 @@ +defmodule Philter.TimingTest do + use ExUnit.Case, async: true + + alias Philter.Timing + + setup do + Timing.ensure_attached() + :ok + end + + describe "ensure_attached/0" do + test "calling twice does not crash" do + assert :ok = Timing.ensure_attached() + assert :ok = Timing.ensure_attached() + end + end + + describe "handle_event/4" do + test "does nothing when :philter_timing_ref is not in process dictionary" do + # Ensure no timing ref is set + Process.delete(:philter_timing_ref) + + # Fire an event — should be a no-op, not a crash + :telemetry.execute([:finch, :queue, :stop], %{duration: 100}, %{}) + + # Nothing should be stored in the process dictionary for any ref + assert Process.get(:philter_timing_ref) == nil + end + end + + describe "capture and collect round-trip" do + test "events are captured and collect returns populated map" do + one_us_native = System.convert_time_unit(1, :microsecond, :native) + + ref = Timing.start_capture() + + :telemetry.execute( + [:finch, :queue, :stop], + %{duration: one_us_native * 10, idle_time: one_us_native * 2}, + %{} + ) + + :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native * 20}, %{}) + :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native * 30}, %{}) + :telemetry.execute([:finch, :recv, :stop], %{duration: one_us_native * 40}, %{}) + + result = Timing.collect(ref) + + assert result.queue_us == 10 + assert result.connect_us == 20 + assert result.send_us == 30 + assert result.recv_us == 40 + assert result.idle_time_us == 2 + assert result.reused_connection? == false + end + end + + describe "duration conversion" do + test "native time units are converted to microseconds" do + one_us_native = System.convert_time_unit(1, :microsecond, :native) + + ref = Timing.start_capture() + :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native}, %{}) + + result = Timing.collect(ref) + + assert result.send_us == 1 + end + end + + describe "reused_connection?" do + test "defaults to false" do + ref = Timing.start_capture() + result = Timing.collect(ref) + + assert result.reused_connection? == false + end + + test "set to true when [:finch, :reused_connection] fires" do + ref = Timing.start_capture() + :telemetry.execute([:finch, :reused_connection], %{}, %{}) + + result = Timing.collect(ref) + + assert result.reused_connection? == true + end + end + + describe "cleanup" do + test "process dictionary entries for the ref are removed after collect" do + one_us_native = System.convert_time_unit(1, :microsecond, :native) + + ref = Timing.start_capture() + + :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native}, %{}) + :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native}, %{}) + :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native}, %{}) + :telemetry.execute([:finch, :recv, :stop], %{duration: one_us_native}, %{}) + :telemetry.execute([:finch, :reused_connection], %{}, %{}) + + _result = Timing.collect(ref) + + # The timing ref itself should be removed + assert Process.get(:philter_timing_ref) == nil + + # All event entries for this ref should be removed + assert Process.get({ref, [:finch, :queue, :stop]}) == nil + assert Process.get({ref, [:finch, :connect, :stop]}) == nil + assert Process.get({ref, [:finch, :send, :stop]}) == nil + assert Process.get({ref, [:finch, :recv, :stop]}) == nil + assert Process.get({ref, [:finch, :reused_connection]}) == nil + end + end + + describe "mutual exclusivity of connect vs reused_connection" do + test "reused_connection means connect_us is nil; connect means reused_connection? is false" do + one_us_native = System.convert_time_unit(1, :microsecond, :native) + + # Case 1: reused_connection fires, no connect event + ref1 = Timing.start_capture() + :telemetry.execute([:finch, :reused_connection], %{}, %{}) + result1 = Timing.collect(ref1) + + assert result1.reused_connection? == true + assert result1.connect_us == nil + + # Case 2: connect fires, no reused_connection event + ref2 = Timing.start_capture() + :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native * 5}, %{}) + result2 = Timing.collect(ref2) + + assert result2.reused_connection? == false + assert result2.connect_us == 5 + end + end + + describe "idle_time_us" do + test "populated from [:finch, :queue, :stop] measurements" do + one_us_native = System.convert_time_unit(1, :microsecond, :native) + + ref = Timing.start_capture() + + :telemetry.execute( + [:finch, :queue, :stop], + %{duration: one_us_native * 10, idle_time: one_us_native * 7}, + %{} + ) + + result = Timing.collect(ref) + + assert result.idle_time_us == 7 + end + + test "nil when queue event does not carry idle_time" do + one_us_native = System.convert_time_unit(1, :microsecond, :native) + + ref = Timing.start_capture() + :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native * 10}, %{}) + + result = Timing.collect(ref) + + assert result.queue_us == 10 + assert result.idle_time_us == nil + end + end + + describe "no events fired" do + test "collect returns all-nil phase fields and reused_connection?: false" do + ref = Timing.start_capture() + result = Timing.collect(ref) + + assert result.queue_us == nil + assert result.connect_us == nil + assert result.send_us == nil + assert result.recv_us == nil + assert result.idle_time_us == nil + assert result.reused_connection? == false + end + end +end diff --git a/test/philter_test.exs b/test/philter_test.exs index 3d0405e..1a7c853 100644 --- a/test/philter_test.exs +++ b/test/philter_test.exs @@ -219,6 +219,7 @@ defmodule PhilterTest do assert result.error == nil assert result.request_observation.hash != nil assert result.response_observation.hash != nil + assert is_integer(result.timing.total_us) and result.timing.total_us > 0 end test "uses caller-supplied headers when provided", %{bypass: bypass, upstream: upstream} do @@ -399,6 +400,7 @@ defmodule PhilterTest do assert_receive {:response_finished, result} assert result.error != nil assert result.status == nil + assert is_integer(result.timing.total_us) and result.timing.total_us > 0 end test "rejects proxy with handler-controlled status and body", %{upstream: upstream} do @@ -762,6 +764,90 @@ defmodule PhilterTest do end end + describe "proxy/2 timing" do + test "without collect_timing, timing has total_us and nil phase fields", %{ + bypass: bypass, + upstream: upstream + } do + Bypass.expect(bypass, "GET", "/timing-default", fn conn -> + conn + |> put_resp_header("content-type", "text/plain") + |> send_resp(200, "hello") + end) + + conn = + conn(:get, "/timing-default") + |> Philter.proxy( + upstream: upstream, + finch_name: Philter.TestFinch, + handler: {TestHandler, %{test_pid: self()}} + ) + + assert conn.status == 200 + + assert_receive {:response_finished, result} + timing = result.timing + + assert is_integer(timing.total_us) and timing.total_us > 0 + assert timing.queue_us == nil + assert timing.connect_us == nil + assert timing.send_us == nil + assert timing.recv_us == nil + assert timing.idle_time_us == nil + assert timing.reused_connection? == nil + end + + test "with collect_timing: true, phase timing fields are populated", %{ + bypass: bypass, + upstream: upstream + } do + Bypass.expect(bypass, "GET", "/timing-collect", fn conn -> + conn + |> put_resp_header("content-type", "text/plain") + |> send_resp(200, "hello") + end) + + conn = + conn(:get, "/timing-collect") + |> Philter.proxy( + upstream: upstream, + finch_name: Philter.TestFinch, + handler: {TestHandler, %{test_pid: self()}}, + collect_timing: true + ) + + assert conn.status == 200 + + assert_receive {:response_finished, result} + timing = result.timing + + assert is_integer(timing.total_us) and timing.total_us > 0 + assert is_integer(timing.queue_us) and timing.queue_us >= 0 + assert is_integer(timing.send_us) and timing.send_us >= 0 + assert is_integer(timing.recv_us) and timing.recv_us >= 0 + assert is_boolean(timing.reused_connection?) + + assert timing.idle_time_us == nil or + (is_integer(timing.idle_time_us) and timing.idle_time_us >= 0) + end + + test "error paths still get timing", %{upstream: _upstream} do + conn = + conn(:get, "/test") + |> Philter.proxy( + upstream: "http://localhost:59999", + finch_name: Philter.TestFinch, + handler: {TestHandler, %{test_pid: self()}} + ) + + assert conn.status == 502 + + assert_receive {:response_finished, result} + assert result.error != nil + assert is_integer(result.timing.total_us) and result.timing.total_us > 0 + end + end + describe "logging" do test "default :debug level emits request start with method, URL, and host", %{ bypass: bypass,