From 6bb300d1331ce0e180cd980a2112d2ccc9e2db0c Mon Sep 17 00:00:00 2001 From: kunwar-axilio Date: Wed, 23 Sep 2026 10:05:10 -0700 Subject: [PATCH 1/3] feat(metrics): per-attempt delivery latency and latency measures on /metrics/attempts (#1079) * feat(destregistry): record per-attempt latency on the attempt Time the provider's Publish call in PublishEvent and stamp the elapsed milliseconds on the attempt as LatencyMs, exposed as latency_ms on the attempt object. Measuring at the registry rather than inside a provider covers every destination type in one place, and it is the same call that DeliveryTimeout already bounds, so a timed-out attempt records roughly the timeout rather than nothing. Successful and failed attempts both get a value; an attempt that never reached the provider (publisher resolution or validation failure) has none, and the field is nullable so that stays distinguishable from a fast reply. * feat(logstore): persist attempt latency in ClickHouse, Postgres and memory Add a nullable latency_ms column to the attempts table in both SQL stores (ClickHouse 000004, Postgres 000011) and carry the field through insert, list and retrieve in all three drivers. No index: the column is only ever aggregated, never filtered on. Nullable on purpose. Attempts written before this migration have no value, and NULL is skipped by AVG / percentile aggregates, so historical rows do not drag the numbers down and the API can report them honestly as null. The CRUD conformance test now asserts the value round-trips and that nil comes back as nil. * feat(metrics): latency measures on GET /metrics/attempts Add avg_latency, p50_latency, p95_latency and p99_latency (milliseconds) to the attempt metrics API so response time can be sliced and bucketed with the same dimensions, filters and granularity as the existing measures. ClickHouse computes the three percentiles from a single quantilesTDigest state per group (bounded memory, one pass; quantileExact would materialize every value per group). Postgres uses percentile_cont, the in-memory driver linear interpolation between closest ranks, i.e. the same definition. The conformance dataset pins avg exactly and the percentiles within a tolerance that still resolves to a single expected value, so the t-digest estimate is checked, not just tolerated. Latency has no meaningful zero, so unlike counts and rates these measures are null rather than 0 for a bucket in which no attempt recorded a latency, including empty zero-filled buckets. A 0ms point on a response time chart would be a lie. * chore(bench): seed attempt latency and add latency metrics cases Seed latency_ms in both backends (20..520ms body, every 200th event's attempts at the 5000ms timeout as a p99 tail) and add avg / percentile cases, including the per-destination hourly and single-destination daily shapes a dashboard issues. Also fix the event seeds, which still inserted events.destination_id: that column was replaced by matched_destination_ids in migrations 000002 (CH) and 000007 (PG), so the scripts no longer ran on main. * refactor(chlogstore): use quantilesTiming for latency percentiles Purpose-built for millisecond latencies: deterministic, exact below 1024ms and within 16ms up to 30s, one bounded state per group. Benchmarks ~15% faster than quantilesTDigest on the same grouped month query. * test(destregistry): drop the latency upper bound The lower bound already proves the publish call is timed; a 500ms ceiling can fail on a busy parallel CI runner. * docs: latency_ms in the operator event attempt example Operator event payloads embed *models.Attempt, so the field appears there too. * chore(bench): paired dashboard cases with and without latency The marginal cost of avg + p95 latency on count + error_rate by destination, hourly over a day and a month and daily over a month. --- cmd/bench/metrics/README.md | 1 + cmd/bench/metrics/bench_test.go | 97 +++++++++++++++++ cmd/bench/metrics/ch/seed.sql | 28 +++-- cmd/bench/metrics/pg/seed.sql | 32 ++++-- docs/apis/openapi.yaml | 29 ++++- docs/content/features/metrics.mdoc | 7 ++ docs/content/features/operator-events.mdoc | 1 + internal/apirouter/log_handlers.go | 2 + internal/apirouter/log_handlers_test.go | 24 +++- internal/apirouter/metrics_handlers.go | 18 ++- internal/apirouter/metrics_handlers_test.go | 85 +++++++++++++++ internal/destregistry/registry.go | 4 + internal/destregistry/registry_test.go | 79 +++++++++++++- internal/logstore/chlogstore/chlogstore.go | 41 ++++++- internal/logstore/chlogstore/metrics.go | 43 ++++++++ internal/logstore/driver/metrics.go | 6 + internal/logstore/drivertest/crud.go | 23 ++++ .../drivertest/metrics_characteristics.go | 5 + .../drivertest/metrics_data_correctness.go | 103 ++++++++++++++++++ .../logstore/drivertest/metrics_dataset.go | 15 ++- internal/logstore/memlogstore/memlogstore.go | 5 + internal/logstore/memlogstore/metrics.go | 59 ++++++++++ internal/logstore/pglogstore/metrics.go | 46 ++++++++ internal/logstore/pglogstore/pglogstore.go | 24 +++- .../000004_attempt_latency.down.sql | 1 + .../clickhouse/000004_attempt_latency.up.sql | 1 + .../postgres/000011_attempt_latency.down.sql | 5 + .../postgres/000011_attempt_latency.up.sql | 17 +++ internal/models/entities.go | 3 + internal/util/testutil/event.go | 6 + 30 files changed, 773 insertions(+), 37 deletions(-) create mode 100644 internal/migrator/migrations/clickhouse/000004_attempt_latency.down.sql create mode 100644 internal/migrator/migrations/clickhouse/000004_attempt_latency.up.sql create mode 100644 internal/migrator/migrations/postgres/000011_attempt_latency.down.sql create mode 100644 internal/migrator/migrations/postgres/000011_attempt_latency.up.sql diff --git a/cmd/bench/metrics/README.md b/cmd/bench/metrics/README.md index 370c5b2eb..a8f533c0b 100644 --- a/cmd/bench/metrics/README.md +++ b/cmd/bench/metrics/README.md @@ -60,4 +60,5 @@ Deterministic via modulo arithmetic (identical for both backends): - **3 topics** — `order.created`, `order.updated`, `payment.received` - **Time** — evenly spread across January 2000 - **Attempts** — chained retries (1 event -> 1-4 attempts), 0.5% permanently failed +- **Latency** — `20 + (n*7919) % 500` ms per attempt; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail for the percentile benchmarks) - 10M events -> ~12.6M attempts (22.6M total rows) diff --git a/cmd/bench/metrics/bench_test.go b/cmd/bench/metrics/bench_test.go index 0cb59bf68..269571244 100644 --- a/cmd/bench/metrics/bench_test.go +++ b/cmd/bench/metrics/bench_test.go @@ -220,6 +220,103 @@ var attemptCases = []struct { Filters: tenant0(), }, }, + { + name: "AvgLatencyAll", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Measures: []string{"avg_latency"}, + Filters: tenant0(), + }, + }, + { + name: "LatencyPercentilesAll", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Measures: []string{"p50_latency", "p95_latency", "p99_latency"}, + Filters: tenant0(), + }, + }, + { + name: "LatencyPercentilesByDestinationHourly", + req: driver.MetricsRequest{ + TimeRange: oneDay, + Granularity: hourly(), + Measures: []string{"count", "avg_latency", "p95_latency"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, + { + name: "LatencyPercentilesSingleDestinationDaily", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Granularity: daily(), + Measures: []string{"count", "error_rate", "avg_latency", "p50_latency", "p95_latency", "p99_latency"}, + Filters: withTenant0(map[string][]string{"destination_id": {"dest_42"}}), + }, + }, + // Marginal cost of latency on a query a dashboard already runs: the same + // count + error_rate by destination, with and without avg + p95 latency. + { + name: "Dashboard_Hourly_1Day", + req: driver.MetricsRequest{ + TimeRange: oneDay, + Granularity: hourly(), + Measures: []string{"count", "error_rate"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, + { + name: "DashboardWithLatency_Hourly_1Day", + req: driver.MetricsRequest{ + TimeRange: oneDay, + Granularity: hourly(), + Measures: []string{"count", "error_rate", "avg_latency", "p95_latency"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, + { + name: "Dashboard_Hourly_1Month", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Granularity: hourly(), + Measures: []string{"count", "error_rate"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, + { + name: "DashboardWithLatency_Hourly_1Month", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Granularity: hourly(), + Measures: []string{"count", "error_rate", "avg_latency", "p95_latency"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, + { + name: "Dashboard_Daily_1Month", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Granularity: daily(), + Measures: []string{"count", "error_rate"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, + { + name: "DashboardWithLatency_Daily_1Month", + req: driver.MetricsRequest{ + TimeRange: fullMonth, + Granularity: daily(), + Measures: []string{"count", "error_rate", "avg_latency", "p95_latency"}, + Dimensions: []string{"destination_id"}, + Filters: tenant0(), + }, + }, { name: "FailedRate", req: driver.MetricsRequest{ diff --git a/cmd/bench/metrics/ch/seed.sql b/cmd/bench/metrics/ch/seed.sql index 84efb697e..4977c964a 100644 --- a/cmd/bench/metrics/ch/seed.sql +++ b/cmd/bench/metrics/ch/seed.sql @@ -31,11 +31,11 @@ SELECT concat('Seeding ', toString({rows:UInt64}), ' events + chained attempts.. SELECT '[1/7] Inserting events...' AS message; -INSERT INTO events (event_id, tenant_id, destination_id, topic, eligible_for_retry, event_time, metadata, data) +INSERT INTO events (event_id, tenant_id, matched_destination_ids, topic, eligible_for_retry, event_time, metadata, data) SELECT concat('evt_', toString(number)) AS event_id, if(number % 10 = 0, 'tenant_1', 'tenant_0') AS tenant_id, - concat('dest_', toString(number % 500)) AS destination_id, + [concat('dest_', toString(number % 500))] AS matched_destination_ids, multiIf( number % 3 = 0, 'order.created', number % 3 = 1, 'order.updated', @@ -62,7 +62,7 @@ SELECT '[2/7] Inserting attempt 1 (all events)...' AS message; INSERT INTO attempts ( event_id, tenant_id, destination_id, topic, eligible_for_retry, event_time, metadata, data, - attempt_id, status, attempt_time, code, response_data, manual, attempt_number + attempt_id, status, attempt_time, code, response_data, manual, attempt_number, latency_ms ) SELECT concat('evt_', toString(number)) AS event_id, @@ -95,14 +95,16 @@ SELECT ) AS code, '' AS response_data, false AS manual, - toUInt32(1) AS attempt_number + toUInt32(1) AS attempt_number, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + toUInt32(if(number % 200 = 0, 5000, 20 + (number * 7919) % 500)) AS latency_ms FROM numbers({rows:UInt64}); SELECT '[3/7] Inserting attempt 2 (20% of events)...' AS message; INSERT INTO attempts ( event_id, tenant_id, destination_id, topic, eligible_for_retry, event_time, metadata, data, - attempt_id, status, attempt_time, code, response_data, manual, attempt_number + attempt_id, status, attempt_time, code, response_data, manual, attempt_number, latency_ms ) SELECT concat('evt_', toString(number)) AS event_id, @@ -135,7 +137,9 @@ SELECT ) AS code, '' AS response_data, false AS manual, - toUInt32(2) AS attempt_number + toUInt32(2) AS attempt_number, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + toUInt32(if(number % 200 = 0, 5000, 20 + (number * 7919) % 500)) AS latency_ms FROM numbers({rows:UInt64}) WHERE number % 5 = 0; @@ -143,7 +147,7 @@ SELECT '[4/7] Inserting attempt 3 (5% of events)...' AS message; INSERT INTO attempts ( event_id, tenant_id, destination_id, topic, eligible_for_retry, event_time, metadata, data, - attempt_id, status, attempt_time, code, response_data, manual, attempt_number + attempt_id, status, attempt_time, code, response_data, manual, attempt_number, latency_ms ) SELECT concat('evt_', toString(number)) AS event_id, @@ -176,7 +180,9 @@ SELECT ) AS code, '' AS response_data, number % 10 = 9 AS manual, - toUInt32(3) AS attempt_number + toUInt32(3) AS attempt_number, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + toUInt32(if(number % 200 = 0, 5000, 20 + (number * 7919) % 500)) AS latency_ms FROM numbers({rows:UInt64}) WHERE number % 20 = 0; @@ -184,7 +190,7 @@ SELECT '[5/7] Inserting attempt 4 (1% of events)...' AS message; INSERT INTO attempts ( event_id, tenant_id, destination_id, topic, eligible_for_retry, event_time, metadata, data, - attempt_id, status, attempt_time, code, response_data, manual, attempt_number + attempt_id, status, attempt_time, code, response_data, manual, attempt_number, latency_ms ) SELECT concat('evt_', toString(number)) AS event_id, @@ -217,7 +223,9 @@ SELECT ) AS code, '' AS response_data, number % 10 = 9 AS manual, - toUInt32(4) AS attempt_number + toUInt32(4) AS attempt_number, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + toUInt32(if(number % 200 = 0, 5000, 20 + (number * 7919) % 500)) AS latency_ms FROM numbers({rows:UInt64}) WHERE number % 100 = 0; diff --git a/cmd/bench/metrics/pg/seed.sql b/cmd/bench/metrics/pg/seed.sql index aff9b45a5..aa7440827 100644 --- a/cmd/bench/metrics/pg/seed.sql +++ b/cmd/bench/metrics/pg/seed.sql @@ -38,14 +38,14 @@ SELECT COALESCE(:'ROWS', '10000000') AS rows_count \gset \echo [1/7] Inserting events... -INSERT INTO events (id, tenant_id, destination_id, time, topic, eligible_for_retry, data, metadata) +INSERT INTO events (id, tenant_id, matched_destination_ids, time, topic, eligible_for_retry, data, metadata) SELECT 'evt_' || n AS id, CASE WHEN n % 10 = 0 THEN 'tenant_1' ELSE 'tenant_0' END AS tenant_id, - 'dest_' || (n % 500) AS destination_id, + ARRAY['dest_' || (n % 500)] AS matched_destination_ids, '2000-01-01'::timestamptz + (n::double precision / :'rows_count'::double precision) * ('2000-02-01'::timestamptz - '2000-01-01'::timestamptz) @@ -74,7 +74,8 @@ FROM generate_series(0, :'rows_count'::int - 1) AS n; INSERT INTO attempts ( id, event_id, tenant_id, destination_id, topic, status, time, attempt_number, manual, code, response_data, - event_time, eligible_for_retry, event_data, event_metadata + event_time, eligible_for_retry, event_data, event_metadata, + latency_ms ) SELECT 'att_' || n || '_0' AS id, @@ -106,7 +107,9 @@ SELECT AS event_time, (n % 3 != 2) AS eligible_for_retry, '{}' AS event_data, - '{}'::jsonb AS event_metadata + '{}'::jsonb AS event_metadata, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + CASE WHEN n % 200 = 0 THEN 5000 ELSE 20 + (n::bigint * 7919) % 500 END AS latency_ms FROM generate_series(0, :'rows_count'::int - 1) AS n; \echo [3/7] Inserting attempt 2 (20% of events)... @@ -114,7 +117,8 @@ FROM generate_series(0, :'rows_count'::int - 1) AS n; INSERT INTO attempts ( id, event_id, tenant_id, destination_id, topic, status, time, attempt_number, manual, code, response_data, - event_time, eligible_for_retry, event_data, event_metadata + event_time, eligible_for_retry, event_data, event_metadata, + latency_ms ) SELECT 'att_' || n || '_1' AS id, @@ -146,7 +150,9 @@ SELECT AS event_time, (n % 3 != 2) AS eligible_for_retry, '{}' AS event_data, - '{}'::jsonb AS event_metadata + '{}'::jsonb AS event_metadata, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + CASE WHEN n % 200 = 0 THEN 5000 ELSE 20 + (n::bigint * 7919) % 500 END AS latency_ms FROM generate_series(0, :'rows_count'::int - 1) AS n WHERE n % 5 = 0; @@ -155,7 +161,8 @@ WHERE n % 5 = 0; INSERT INTO attempts ( id, event_id, tenant_id, destination_id, topic, status, time, attempt_number, manual, code, response_data, - event_time, eligible_for_retry, event_data, event_metadata + event_time, eligible_for_retry, event_data, event_metadata, + latency_ms ) SELECT 'att_' || n || '_2' AS id, @@ -187,7 +194,9 @@ SELECT AS event_time, (n % 3 != 2) AS eligible_for_retry, '{}' AS event_data, - '{}'::jsonb AS event_metadata + '{}'::jsonb AS event_metadata, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + CASE WHEN n % 200 = 0 THEN 5000 ELSE 20 + (n::bigint * 7919) % 500 END AS latency_ms FROM generate_series(0, :'rows_count'::int - 1) AS n WHERE n % 20 = 0; @@ -196,7 +205,8 @@ WHERE n % 20 = 0; INSERT INTO attempts ( id, event_id, tenant_id, destination_id, topic, status, time, attempt_number, manual, code, response_data, - event_time, eligible_for_retry, event_data, event_metadata + event_time, eligible_for_retry, event_data, event_metadata, + latency_ms ) SELECT 'att_' || n || '_3' AS id, @@ -228,7 +238,9 @@ SELECT AS event_time, (n % 3 != 2) AS eligible_for_retry, '{}' AS event_data, - '{}'::jsonb AS event_metadata + '{}'::jsonb AS event_metadata, + -- latency: 20..520ms body; every 200th event's attempts time out at 5000ms (~1.6% of attempts, a p99 tail) + CASE WHEN n % 200 = 0 THEN 5000 ELSE 20 + (n::bigint * 7919) % 500 END AS latency_ms FROM generate_series(0, :'rows_count'::int - 1) AS n WHERE n % 100 = 0; diff --git a/docs/apis/openapi.yaml b/docs/apis/openapi.yaml index e7200cfe6..b514cc505 100644 --- a/docs/apis/openapi.yaml +++ b/docs/apis/openapi.yaml @@ -2791,6 +2791,11 @@ components: type: boolean description: Whether this attempt was manually triggered (e.g., a retry initiated by a user). example: false + latency_ms: + type: integer + nullable: true + description: Time in milliseconds from sending the attempt to receiving the destination's response (or the error), measured around the provider's publish call. Null for attempts that never reached the provider and for attempts recorded before latency was tracked. + example: 212 event_id: type: string description: The ID of the associated event. @@ -4068,6 +4073,7 @@ paths: time: "2024-01-01T00:00:05Z" code: "200" attempt_number: 1 + latency_ms: 212 event_id: "evt_123" destination_id: "des_456" - id: "att_124" @@ -4075,6 +4081,7 @@ paths: time: "2024-01-02T10:00:01Z" code: "503" attempt_number: 2 + latency_ms: 1502 event_id: "evt_789" destination_id: "des_789" @@ -4093,6 +4100,7 @@ paths: time: "2024-01-01T00:00:05Z" code: "200" attempt_number: 1 + latency_ms: 212 event_id: "evt_123" destination_id: "des_456" event: @@ -4161,6 +4169,7 @@ paths: time: "2024-01-01T00:00:05Z" code: "200" attempt_number: 1 + latency_ms: 212 event_id: "evt_123" destination_id: "des_456" AttemptWithIncludeExample: @@ -4175,6 +4184,7 @@ paths: body: '{"status":"ok"}' headers: { "content-type": "application/json" } attempt_number: 1 + latency_ms: 212 event_id: "evt_123" destination_id: "des_456" event: @@ -4755,6 +4765,7 @@ paths: time: "2024-01-01T00:00:05Z" code: "200" attempt_number: 1 + latency_ms: 212 event_id: "evt_123" destination_id: "des_456" - id: "atm_124" @@ -4762,6 +4773,7 @@ paths: time: "2024-01-02T10:00:01Z" code: "503" attempt_number: 2 + latency_ms: 1502 event_id: "evt_789" destination_id: "des_456" @@ -4828,6 +4840,7 @@ paths: time: "2024-01-01T00:00:05Z" code: "200" attempt_number: 1 + latency_ms: 212 event_id: "evt_123" destination_id: "des_456" "401": @@ -5325,7 +5338,11 @@ paths: **Measures:** `count`, `successful_count`, `failed_count`, `error_rate`, `first_attempt_count`, `retry_count`, `manual_retry_count`, `avg_attempt_number`, - `rate`, `successful_rate`, `failed_rate` + `rate`, `successful_rate`, `failed_rate`, `avg_latency`, `p50_latency`, `p95_latency`, `p99_latency` + + Latency measures are in milliseconds and computed over attempts that recorded a + latency (see `latency_ms` on the attempt object). They are `null` for a bucket + with no such attempts, rather than `0`. **Dimensions:** `tenant_id` (admin-only), `destination_id`, `destination_type`, `topic`, `status`, `code`, `manual`, `attempt_number` @@ -5370,13 +5387,13 @@ paths: schema: oneOf: - type: string - enum: [count, successful_count, failed_count, error_rate, first_attempt_count, retry_count, manual_retry_count, avg_attempt_number, rate, successful_rate, failed_rate] + enum: [count, successful_count, failed_count, error_rate, first_attempt_count, retry_count, manual_retry_count, avg_attempt_number, rate, successful_rate, failed_rate, avg_latency, p50_latency, p95_latency, p99_latency] - type: array items: type: string - enum: [count, successful_count, failed_count, error_rate, first_attempt_count, retry_count, manual_retry_count, avg_attempt_number, rate, successful_rate, failed_rate] - description: Measures to compute. At least one required. Rate measures (`rate`, `successful_rate`, `failed_rate`) are throughput in events/second. Use bracket notation for multiple values (e.g., `measures[0]=count&measures[1]=error_rate`). - example: ["count", "error_rate"] + enum: [count, successful_count, failed_count, error_rate, first_attempt_count, retry_count, manual_retry_count, avg_attempt_number, rate, successful_rate, failed_rate, avg_latency, p50_latency, p95_latency, p99_latency] + description: Measures to compute. At least one required. Rate measures (`rate`, `successful_rate`, `failed_rate`) are throughput in events/second. Latency measures (`avg_latency`, `p50_latency`, `p95_latency`, `p99_latency`) are destination response times in milliseconds, `null` when no attempt in the bucket recorded a latency. Use bracket notation for multiple values (e.g., `measures[0]=count&measures[1]=error_rate`). + example: ["count", "error_rate", "p95_latency"] - name: dimensions in: query required: false @@ -5487,6 +5504,8 @@ paths: successful_count: 1393 failed_count: 30 error_rate: 0.0211 + avg_latency: 212.4 + p95_latency: 810 metadata: granularity: "1d" query_time_ms: 38 diff --git a/docs/content/features/metrics.mdoc b/docs/content/features/metrics.mdoc index 4556869dc..874908136 100644 --- a/docs/content/features/metrics.mdoc +++ b/docs/content/features/metrics.mdoc @@ -12,6 +12,7 @@ Use metrics to answer questions like: - What is our delivery success rate? - Are errors increasing for a specific destination? - Which status codes are causing the most failed attempts? +- How quickly is a destination responding, and is its p95 drifting? ## Metrics Scope @@ -48,6 +49,12 @@ Each dataset supports a specific set of `measures` values. | `rate` | Attempt throughput (attempts per second). | | `successful_rate` | Successful attempt throughput (successful attempts per second). | | `failed_rate` | Failed attempt throughput (failed attempts per second). | +| `avg_latency` | Average destination response time in milliseconds. | +| `p50_latency` | Median destination response time in milliseconds. | +| `p95_latency` | 95th percentile destination response time in milliseconds. | +| `p99_latency` | 99th percentile destination response time in milliseconds. | + +Latency is measured per attempt around the provider's publish call and stored as `latency_ms` on the attempt. Failed attempts count too (a timeout records roughly the delivery timeout), so filter by `status` to look at successful deliveries only. The latency measures are `null`, not `0`, for a bucket in which no attempt recorded a latency, which includes attempts logged before latency tracking existed. ## Available Dimensions and Filters diff --git a/docs/content/features/operator-events.mdoc b/docs/content/features/operator-events.mdoc index 940f7768d..7cb11557e 100644 --- a/docs/content/features/operator-events.mdoc +++ b/docs/content/features/operator-events.mdoc @@ -233,6 +233,7 @@ Emitted once per delivery attempt, keyed by outcome. The two topics share one pa "status": "failed", "time": "2025-06-01T12:00:05Z", "code": "500", + "latency_ms": 1502, "response_data": { "status": 500, "body": "internal server error" diff --git a/internal/apirouter/log_handlers.go b/internal/apirouter/log_handlers.go index 327a15aee..54053c111 100644 --- a/internal/apirouter/log_handlers.go +++ b/internal/apirouter/log_handlers.go @@ -90,6 +90,7 @@ type APIAttempt struct { AttemptNumber int `json:"attempt_number"` Manual bool `json:"manual"` DestinationType string `json:"destination_type"` + LatencyMs *int64 `json:"latency_ms"` EventID string `json:"event_id"` DestinationID string `json:"destination_id"` @@ -157,6 +158,7 @@ func toAPIAttempt(ar *logstore.AttemptRecord, opts IncludeOptions, destDisplay * AttemptNumber: ar.Attempt.AttemptNumber, Manual: ar.Attempt.Manual, DestinationType: ar.Attempt.DestinationType, + LatencyMs: ar.Attempt.LatencyMs, EventID: ar.Attempt.EventID, DestinationID: ar.Attempt.DestinationID, } diff --git a/internal/apirouter/log_handlers_test.go b/internal/apirouter/log_handlers_test.go index 477ee31cd..360b228bd 100644 --- a/internal/apirouter/log_handlers_test.go +++ b/internal/apirouter/log_handlers_test.go @@ -1054,7 +1054,7 @@ func TestAPI_Attempts(t *testing.T) { h := newAPITest(t) e := ef.AnyPointer(ef.WithTenantID("t1")) - a := attemptForEvent(e, af.WithID("a1")) + a := attemptForEvent(e, af.WithID("a1"), af.WithLatencyMs(212)) require.NoError(t, h.logStore.InsertMany(t.Context(), []*models.LogEntry{ {Event: e, Attempt: a}, })) @@ -1067,6 +1067,28 @@ func TestAPI_Attempts(t *testing.T) { var attempt apirouter.APIAttempt require.NoError(t, json.Unmarshal(resp.Body.Bytes(), &attempt)) assert.Equal(t, "a1", attempt.ID) + require.NotNil(t, attempt.LatencyMs) + assert.Equal(t, int64(212), *attempt.LatencyMs) + }) + + t.Run("attempt without latency serializes null", func(t *testing.T) { + h := newAPITest(t) + + e := ef.AnyPointer(ef.WithTenantID("t1")) + a := attemptForEvent(e, af.WithID("a2")) + require.NoError(t, h.logStore.InsertMany(t.Context(), []*models.LogEntry{ + {Event: e, Attempt: a}, + })) + + req := httptest.NewRequest(http.MethodGet, "/api/v1/attempts/a2", nil) + resp := h.do(h.withAPIKey(req)) + + require.Equal(t, http.StatusOK, resp.Code) + + var raw map[string]json.RawMessage + require.NoError(t, json.Unmarshal(resp.Body.Bytes(), &raw)) + require.Contains(t, raw, "latency_ms", "latency_ms is always present") + assert.Equal(t, "null", string(raw["latency_ms"])) }) t.Run("nonexistent attempt returns 404", func(t *testing.T) { diff --git a/internal/apirouter/metrics_handlers.go b/internal/apirouter/metrics_handlers.go index a92a88033..73846accc 100644 --- a/internal/apirouter/metrics_handlers.go +++ b/internal/apirouter/metrics_handlers.go @@ -55,7 +55,7 @@ var ( eventDimensions = newStringSet("tenant_id", "topic", "destination_id") eventFilters = newStringSet("tenant_id", "topic", "destination_id") - attemptMeasures = newStringSet("count", "successful_count", "failed_count", "error_rate", "first_attempt_count", "retry_count", "manual_retry_count", "avg_attempt_number", "rate", "successful_rate", "failed_rate") + attemptMeasures = newStringSet("count", "successful_count", "failed_count", "error_rate", "first_attempt_count", "retry_count", "manual_retry_count", "avg_attempt_number", "rate", "successful_rate", "failed_rate", "avg_latency", "p50_latency", "p95_latency", "p99_latency") attemptDimensions = newStringSet("tenant_id", "destination_id", "destination_type", "topic", "status", "code", "manual", "attempt_number") attemptFilters = newStringSet("tenant_id", "destination_id", "destination_type", "topic", "status", "code", "manual", "attempt_number") ) @@ -386,6 +386,14 @@ func attemptDataPointToAPI(dp logstore.AttemptMetricsDataPoint, measures, dimens metrics["successful_rate"] = derefFloat64(dp.SuccessfulRate) case "failed_rate": metrics["failed_rate"] = derefFloat64(dp.FailedRate) + case "avg_latency": + metrics["avg_latency"] = nullableFloat64(dp.AvgLatency) + case "p50_latency": + metrics["p50_latency"] = nullableFloat64(dp.P50Latency) + case "p95_latency": + metrics["p95_latency"] = nullableFloat64(dp.P95Latency) + case "p99_latency": + metrics["p99_latency"] = nullableFloat64(dp.P99Latency) } } @@ -434,6 +442,14 @@ func derefFloat64(p *float64) float64 { return 0 } +// nullableFloat64 keeps nil as JSON null. +func nullableFloat64(p *float64) any { + if p != nil { + return *p + } + return nil +} + func derefString(p *string) string { if p != nil { return *p diff --git a/internal/apirouter/metrics_handlers_test.go b/internal/apirouter/metrics_handlers_test.go index 25dda2313..0683f686f 100644 --- a/internal/apirouter/metrics_handlers_test.go +++ b/internal/apirouter/metrics_handlers_test.go @@ -602,6 +602,91 @@ func TestAPI_MetricsAttempts(t *testing.T) { assert.Empty(t, result.Data) }) + // Attempts default to time.Now(), which is past baseEnd; pin them in the window. + inWindow := baseStart.Add(30 * time.Minute) + + t.Run("latency measures", func(t *testing.T) { + h := newAPITest(t) + + e1 := ef.AnyPointer(ef.WithTenantID("t1")) + require.NoError(t, h.logStore.InsertMany(t.Context(), []*models.LogEntry{ + {Event: e1, Attempt: attemptForEvent(e1, af.WithTime(inWindow), af.WithLatencyMs(100))}, + {Event: e1, Attempt: attemptForEvent(e1, af.WithTime(inWindow), af.WithLatencyMs(300))}, + {Event: e1, Attempt: attemptForEvent(e1, af.WithTime(inWindow))}, // no latency: skipped, not counted as 0 + })) + + req := httptest.NewRequest(http.MethodGet, + "/api/v1/metrics/attempts?"+baseQS+"&measures[0]=count&measures[1]=avg_latency&measures[2]=p50_latency&measures[3]=p95_latency&measures[4]=p99_latency", nil) + resp := h.do(h.withAPIKey(req)) + + require.Equal(t, http.StatusOK, resp.Code) + + var result apirouter.APIMetricsResponse + require.NoError(t, json.Unmarshal(resp.Body.Bytes(), &result)) + require.Len(t, result.Data, 1) + m := result.Data[0].Metrics + assert.Equal(t, float64(3), m["count"]) + assert.Equal(t, 200.0, m["avg_latency"]) + assert.Equal(t, 200.0, m["p50_latency"]) + assert.Equal(t, 290.0, m["p95_latency"]) + assert.Equal(t, 298.0, m["p99_latency"]) + }) + + t.Run("latency measures are null when nothing was recorded", func(t *testing.T) { + h := newAPITest(t) + + e1 := ef.AnyPointer(ef.WithTenantID("t1")) + require.NoError(t, h.logStore.InsertMany(t.Context(), []*models.LogEntry{ + {Event: e1, Attempt: attemptForEvent(e1, af.WithTime(inWindow))}, + })) + + req := httptest.NewRequest(http.MethodGet, + "/api/v1/metrics/attempts?"+baseQS+"&measures[0]=count&measures[1]=avg_latency&measures[2]=p95_latency", nil) + resp := h.do(h.withAPIKey(req)) + + require.Equal(t, http.StatusOK, resp.Code) + + var result apirouter.APIMetricsResponse + require.NoError(t, json.Unmarshal(resp.Body.Bytes(), &result)) + require.Len(t, result.Data, 1) + m := result.Data[0].Metrics + assert.Equal(t, float64(1), m["count"]) + require.Contains(t, m, "avg_latency", "requested measures are always present") + assert.Nil(t, m["avg_latency"], "no recorded latency must be null, not 0") + assert.Nil(t, m["p95_latency"]) + }) + + t.Run("latency measures are null in empty buckets", func(t *testing.T) { + h := newAPITest(t) + + e1 := ef.AnyPointer(ef.WithTenantID("t1")) + require.NoError(t, h.logStore.InsertMany(t.Context(), []*models.LogEntry{ + {Event: e1, Attempt: attemptForEvent(e1, af.WithTime(inWindow), af.WithLatencyMs(150))}, + })) + + req := httptest.NewRequest(http.MethodGet, + "/api/v1/metrics/attempts?"+baseQS+"&granularity=1m&measures[0]=count&measures[1]=avg_latency", nil) + resp := h.do(h.withAPIKey(req)) + + require.Equal(t, http.StatusOK, resp.Code) + + var result apirouter.APIMetricsResponse + require.NoError(t, json.Unmarshal(resp.Body.Bytes(), &result)) + require.Greater(t, len(result.Data), 1) + + populated := 0 + for _, dp := range result.Data { + require.Contains(t, dp.Metrics, "avg_latency") + if dp.Metrics["count"] == float64(0) { + assert.Nil(t, dp.Metrics["avg_latency"], "empty bucket %s must be null", dp.TimeBucket) + continue + } + populated++ + assert.Equal(t, 150.0, dp.Metrics["avg_latency"]) + } + assert.Equal(t, 1, populated) + }) + t.Run("rate measures without counts", func(t *testing.T) { h := newAPITest(t) diff --git a/internal/destregistry/registry.go b/internal/destregistry/registry.go index 385c6d70b..23978a519 100644 --- a/internal/destregistry/registry.go +++ b/internal/destregistry/registry.go @@ -189,7 +189,9 @@ func (r *registry) PublishEvent(ctx context.Context, destination *models.Destina timeoutCtx, cancel := context.WithTimeout(ctx, r.config.DeliveryTimeout) defer cancel() + publishStart := time.Now() deliveryData, err := publisher.Publish(timeoutCtx, event) + latencyMs := time.Since(publishStart).Milliseconds() if err != nil { // Context canceled = system shutdown, return nil attempt to trigger nack → requeue. // This is handled centrally so individual publishers don't need to check for it. @@ -203,6 +205,7 @@ func (r *registry) PublishEvent(ctx context.Context, destination *models.Destina attempt.Status = deliveryData.Status attempt.Code = deliveryData.Code attempt.ResponseData = deliveryData.Response + attempt.LatencyMs = &latencyMs } else { attempt = nil } @@ -259,6 +262,7 @@ func (r *registry) PublishEvent(ctx context.Context, destination *models.Destina attempt.Status = deliveryData.Status attempt.Code = deliveryData.Code attempt.ResponseData = deliveryData.Response + attempt.LatencyMs = &latencyMs return attempt, nil } diff --git a/internal/destregistry/registry_test.go b/internal/destregistry/registry_test.go index 1fd4e3758..4fb76cc8a 100644 --- a/internal/destregistry/registry_test.go +++ b/internal/destregistry/registry_test.go @@ -21,6 +21,7 @@ type mockProvider struct { *destregistry.BaseProvider publishDelay time.Duration mockError error + failDelivery *destregistry.Delivery } type mockPublisher struct { @@ -28,6 +29,8 @@ type mockPublisher struct { closed bool publishDelay time.Duration mockError error + // Returned alongside mockError, like a real publisher's classified failure. + failDelivery *destregistry.Delivery } var mockPublisherID int64 @@ -98,6 +101,7 @@ func (p *mockProvider) CreatePublisher(ctx context.Context, dest *models.Destina pub := newMockPublisher() pub.publishDelay = p.publishDelay pub.mockError = p.mockError + pub.failDelivery = p.failDelivery return pub, nil } @@ -112,7 +116,7 @@ func (p *mockPublisher) Publish(ctx context.Context, event *models.Event) (*dest select { case <-time.After(p.publishDelay): if p.mockError != nil { - return nil, p.mockError + return p.failDelivery, p.mockError } return &destregistry.Delivery{ Status: "success", @@ -700,6 +704,79 @@ func TestPublishEventTimeout(t *testing.T) { }) } +// TestPublishEventLatency tests that LatencyMs is set on successful and failed +// attempts and unset when the provider was never reached. +func TestPublishEventLatency(t *testing.T) { + t.Parallel() + + const delay = 50 * time.Millisecond + + t.Run("successful attempt records latency", func(t *testing.T) { + t.Parallel() + + registry := destregistry.NewRegistry(&destregistry.Config{ + DeliveryTimeout: time.Second, + }, testutil.CreateTestLogger(t)) + + provider, err := newMockProvider() + require.NoError(t, err) + provider.publishDelay = delay + require.NoError(t, registry.RegisterProvider("test", provider)) + + attempt, err := registry.PublishEvent(context.Background(), &models.Destination{Type: "test"}, &models.Event{}) + require.NoError(t, err) + require.NotNil(t, attempt) + require.NotNil(t, attempt.LatencyMs, "latency must be recorded on success") + assert.GreaterOrEqual(t, *attempt.LatencyMs, delay.Milliseconds()) + }) + + t.Run("failed attempt with delivery records latency", func(t *testing.T) { + t.Parallel() + + registry := destregistry.NewRegistry(&destregistry.Config{ + DeliveryTimeout: time.Second, + }, testutil.CreateTestLogger(t)) + + provider, err := newMockProvider() + require.NoError(t, err) + provider.publishDelay = delay + provider.failDelivery = &destregistry.Delivery{Status: "failed", Code: "503"} + provider.mockError = destregistry.NewErrDestinationPublishAttempt( + errors.New("request failed with status 503"), + "test", + map[string]interface{}{"status": 503}, + ) + require.NoError(t, registry.RegisterProvider("test", provider)) + + attempt, err := registry.PublishEvent(context.Background(), &models.Destination{Type: "test"}, &models.Event{}) + require.Error(t, err) + require.NotNil(t, attempt) + assert.Equal(t, "failed", attempt.Status) + require.NotNil(t, attempt.LatencyMs, "a failed attempt still took time to fail") + assert.GreaterOrEqual(t, *attempt.LatencyMs, delay.Milliseconds()) + }) + + t.Run("attempt that never reached the provider has no latency", func(t *testing.T) { + t.Parallel() + + registry := destregistry.NewRegistry(&destregistry.Config{}, testutil.CreateTestLogger(t)) + + provider := &mockFailingProvider{ + createErr: destregistry.NewErrDestinationPublishAttempt( + errors.New("bad credentials"), + "test", + map[string]interface{}{"error": "client_creation_failed"}, + ), + } + require.NoError(t, registry.RegisterProvider("test", provider)) + + attempt, err := registry.PublishEvent(context.Background(), &models.Destination{ID: "dest-1", Type: "test"}, &models.Event{ID: "evt-1"}) + require.Error(t, err) + require.NotNil(t, attempt) + assert.Nil(t, attempt.LatencyMs, "no publish call happened, so there is nothing to measure") + }) +} + // TestPublishEventCanceled tests that context.Canceled errors are handled centrally // and return nil delivery to trigger nack → requeue behavior. // See: https://github.com/hookdeck/outpost/issues/571 diff --git a/internal/logstore/chlogstore/chlogstore.go b/internal/logstore/chlogstore/chlogstore.go index 1834ed1f7..a589552a9 100644 --- a/internal/logstore/chlogstore/chlogstore.go +++ b/internal/logstore/chlogstore/chlogstore.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "math" "strconv" "strings" "time" @@ -466,7 +467,8 @@ func buildAttemptQuery(table string, req driver.ListAttemptRequest, q pagination code, response_data, manual, - attempt_number + attempt_number, + latency_ms FROM %s WHERE %s %s @@ -496,6 +498,7 @@ func scanAttemptRecords(rows clickhouse.Rows) ([]attemptRecordWithPosition, erro responseDataStr string manual bool attemptNumber uint32 + latencyMs *uint32 ) err := rows.Scan( @@ -515,6 +518,7 @@ func scanAttemptRecords(rows clickhouse.Rows) ([]attemptRecordWithPosition, erro &responseDataStr, &manual, &attemptNumber, + &latencyMs, ) if err != nil { return nil, fmt.Errorf("scan failed: %w", err) @@ -548,6 +552,7 @@ func scanAttemptRecords(rows clickhouse.Rows) ([]attemptRecordWithPosition, erro Time: attemptTime, Code: code, ResponseData: responseData, + LatencyMs: latencyFromCH(latencyMs), }, Event: &models.Event{ ID: eventID, @@ -669,7 +674,8 @@ func (s *logStoreImpl) RetrieveAttempt(ctx context.Context, req driver.RetrieveA code, response_data, manual, - attempt_number + attempt_number, + latency_ms FROM %s WHERE %s LIMIT 1`, s.attemptsTable, whereClause) @@ -693,6 +699,7 @@ func (s *logStoreImpl) RetrieveAttempt(ctx context.Context, req driver.RetrieveA responseDataStr string manual bool attemptNumber uint32 + latencyMs *uint32 ) err := row.Scan( @@ -712,6 +719,7 @@ func (s *logStoreImpl) RetrieveAttempt(ctx context.Context, req driver.RetrieveA &responseDataStr, &manual, &attemptNumber, + &latencyMs, ) if err != nil { if errors.Is(err, sql.ErrNoRows) { @@ -747,6 +755,7 @@ func (s *logStoreImpl) RetrieveAttempt(ctx context.Context, req driver.RetrieveA Time: attemptTime, Code: code, ResponseData: responseData, + LatencyMs: latencyFromCH(latencyMs), }, Event: &models.Event{ ID: eventID, @@ -829,7 +838,7 @@ func (s *logStoreImpl) InsertMany(ctx context.Context, entries []*models.LogEntr attemptBatch, err := s.chDB.PrepareBatch(ctx, fmt.Sprintf(`INSERT INTO %s ( event_id, tenant_id, destination_id, destination_type, topic, eligible_for_retry, event_time, metadata, data, - attempt_id, status, attempt_time, code, response_data, manual, attempt_number + attempt_id, status, attempt_time, code, response_data, manual, attempt_number, latency_ms )`, s.attemptsTable), ) if err != nil { @@ -871,6 +880,7 @@ func (s *logStoreImpl) InsertMany(ctx context.Context, entries []*models.LogEntr string(responseDataJSON), a.Manual, uint32(a.AttemptNumber), + latencyToCH(a.LatencyMs), ); err != nil { return fmt.Errorf("attempts batch append failed: %w", err) } @@ -905,3 +915,28 @@ func buildAttemptCursorCondition(compare, position string) (string, []any) { return condition, []any{attemptTimeMs, attemptTimeMs, attemptID} } + +// latencyToCH maps the model's *int64 to the Nullable(UInt32) column, clamping +// out-of-range values. +func latencyToCH(ms *int64) *uint32 { + if ms == nil { + return nil + } + v := *ms + if v < 0 { + v = 0 + } + if v > math.MaxUint32 { + v = math.MaxUint32 + } + u := uint32(v) + return &u +} + +func latencyFromCH(ms *uint32) *int64 { + if ms == nil { + return nil + } + v := int64(*ms) + return &v +} diff --git a/internal/logstore/chlogstore/metrics.go b/internal/logstore/chlogstore/metrics.go index 8b12394e3..cd1af1559 100644 --- a/internal/logstore/chlogstore/metrics.go +++ b/internal/logstore/chlogstore/metrics.go @@ -3,6 +3,7 @@ package chlogstore import ( "context" "fmt" + "math" "strings" "time" @@ -300,8 +301,11 @@ func (s *logStoreImpl) QueryAttemptMetrics(ctx context.Context, req driver.Metri sfRetryCount sfManualRetry sfAvgAttemptNum + sfAvgLatency + sfLatencyQuantiles ) var order []sf + wantLatencyQuantiles := false // Time bucket if req.Granularity != nil { @@ -379,6 +383,21 @@ func (s *logStoreImpl) QueryAttemptMetrics(ctx context.Context, req driver.Metri case "avg_attempt_number": selectExprs = append(selectExprs, "avg(attempt_number)") order = append(order, sfAvgAttemptNum) + case "avg_latency": + // avg over a Nullable column is Nullable(Float64): NULL when no + // row has a value. + selectExprs = append(selectExprs, "avg(latency_ms)") + order = append(order, sfAvgLatency) + case "p50_latency", "p95_latency", "p99_latency": + if wantLatencyQuantiles { + continue + } + wantLatencyQuantiles = true + // One quantilesTiming state per group serves all three percentiles. + // It is built for millisecond latencies: deterministic, exact below + // 1024ms and within 16ms up to 30s, bounded memory. + selectExprs = append(selectExprs, "quantilesTiming(0.5, 0.95, 0.99)(latency_ms)") + order = append(order, sfLatencyQuantiles) } } @@ -452,6 +471,8 @@ func (s *logStoreImpl) QueryAttemptMetrics(ctx context.Context, req driver.Metri retryCount uint64 manualRetry uint64 avgAttemptNum float64 + avgLatency *float64 + latencyQuantiles []float32 ) scanDests := make([]any, len(order)) @@ -491,6 +512,10 @@ func (s *logStoreImpl) QueryAttemptMetrics(ctx context.Context, req driver.Metri scanDests[i] = &manualRetry case sfAvgAttemptNum: scanDests[i] = &avgAttemptNum + case sfAvgLatency: + scanDests[i] = &avgLatency + case sfLatencyQuantiles: + scanDests[i] = &latencyQuantiles } } @@ -554,6 +579,16 @@ func (s *logStoreImpl) QueryAttemptMetrics(ctx context.Context, req driver.Metri case sfAvgAttemptNum: v := avgAttemptNum dp.AvgAttemptNumber = &v + case sfAvgLatency: + if avgLatency != nil { + dp.AvgLatency = latencyMeasure(*avgLatency) + } + case sfLatencyQuantiles: + if len(latencyQuantiles) == 3 { + dp.P50Latency = latencyMeasure(float64(latencyQuantiles[0])) + dp.P95Latency = latencyMeasure(float64(latencyQuantiles[1])) + dp.P99Latency = latencyMeasure(float64(latencyQuantiles[2])) + } } } data = append(data, dp) @@ -597,3 +632,11 @@ func wrapCHMetricsError(op string, err error) error { } return fmt.Errorf("%s: %w", op, err) } + +// latencyMeasure maps the NaN quantilesTiming returns for an all-NULL group to nil. +func latencyMeasure(v float64) *float64 { + if math.IsNaN(v) { + return nil + } + return &v +} diff --git a/internal/logstore/driver/metrics.go b/internal/logstore/driver/metrics.go index 363bd2f58..164bac50f 100644 --- a/internal/logstore/driver/metrics.go +++ b/internal/logstore/driver/metrics.go @@ -101,6 +101,12 @@ type AttemptMetricsDataPoint struct { Rate *float64 SuccessfulRate *float64 FailedRate *float64 + // Latency measures ignore attempts with a nil LatencyMs and are nil, not + // zero, when a group has none (including zero-filled empty buckets). + AvgLatency *float64 + P50Latency *float64 + P95Latency *float64 + P99Latency *float64 // Dimensions TenantID *string DestinationID *string diff --git a/internal/logstore/drivertest/crud.go b/internal/logstore/drivertest/crud.go index 7828588b1..d5bc273b2 100644 --- a/internal/logstore/drivertest/crud.go +++ b/internal/logstore/drivertest/crud.go @@ -57,6 +57,7 @@ func testCRUD(t *testing.T, newHarness HarnessMaker) { testutil.AttemptFactory.WithDestinationID(destID), testutil.AttemptFactory.WithStatus("success"), testutil.AttemptFactory.WithTime(baseTime.Add(-30*time.Minute)), + testutil.AttemptFactory.WithLatencyMs(123), ) err := logStore.InsertMany(ctx, []*models.LogEntry{{Event: event, Attempt: delivery}}) @@ -79,6 +80,8 @@ func testCRUD(t *testing.T, newHarness HarnessMaker) { require.Len(t, response.Data, 1) assert.Equal(t, event.ID, response.Data[0].Event.ID) assert.Equal(t, "success", response.Data[0].Attempt.Status) + require.NotNil(t, response.Data[0].Attempt.LatencyMs, "latency must round-trip") + assert.Equal(t, int64(123), *response.Data[0].Attempt.LatencyMs) // Verify via Retrieve retrieved, err := logStore.RetrieveEvent(ctx, driver.RetrieveEventRequest{ @@ -410,6 +413,26 @@ func testCRUD(t *testing.T, newHarness HarnessMaker) { assert.Equal(t, knownAttemptID, retrieved.Attempt.ID) }) + t.Run("RetrieveAttempt round-trips latency", func(t *testing.T) { + retrieved, err := logStore.RetrieveAttempt(ctx, driver.RetrieveAttemptRequest{ + TenantID: tenantID, + AttemptID: "single_del", + }) + require.NoError(t, err) + require.NotNil(t, retrieved) + require.NotNil(t, retrieved.Attempt.LatencyMs) + assert.Equal(t, int64(123), *retrieved.Attempt.LatencyMs) + + // Inserted without a latency: nil must round-trip as nil. + noLatency, err := logStore.RetrieveAttempt(ctx, driver.RetrieveAttemptRequest{ + TenantID: tenantID, + AttemptID: "batch_del_00", + }) + require.NoError(t, err) + require.NotNil(t, noLatency) + assert.Nil(t, noLatency.Attempt.LatencyMs) + }) + t.Run("RetrieveAttempt non-existent returns nil", func(t *testing.T) { retrieved, err := logStore.RetrieveAttempt(ctx, driver.RetrieveAttemptRequest{ TenantID: tenantID, diff --git a/internal/logstore/drivertest/metrics_characteristics.go b/internal/logstore/drivertest/metrics_characteristics.go index 095f7ac7e..cd88c07cc 100644 --- a/internal/logstore/drivertest/metrics_characteristics.go +++ b/internal/logstore/drivertest/metrics_characteristics.go @@ -244,6 +244,11 @@ func testMetricsCharacteristics(t *testing.T, ctx context.Context, logStore driv assert.Equal(t, 0.0, *dp.Rate, "rate must be 0.0") assert.Equal(t, 0.0, *dp.SuccessfulRate, "successful_rate must be 0.0") assert.Equal(t, 0.0, *dp.FailedRate, "failed_rate must be 0.0") + // Latency measures are nil in empty buckets, not 0. + assert.Nil(t, dp.AvgLatency, "avg_latency must be nil in empty bucket at %s", dp.TimeBucket) + assert.Nil(t, dp.P50Latency, "p50_latency must be nil in empty bucket at %s", dp.TimeBucket) + assert.Nil(t, dp.P95Latency, "p95_latency must be nil in empty bucket at %s", dp.TimeBucket) + assert.Nil(t, dp.P99Latency, "p99_latency must be nil in empty bucket at %s", dp.TimeBucket) } } }) diff --git a/internal/logstore/drivertest/metrics_data_correctness.go b/internal/logstore/drivertest/metrics_data_correctness.go index c40de3d59..0d7763e80 100644 --- a/internal/logstore/drivertest/metrics_data_correctness.go +++ b/internal/logstore/drivertest/metrics_data_correctness.go @@ -11,6 +11,12 @@ import ( "github.com/stretchr/testify/require" ) +// latencyPercentileTolerance covers the difference between interpolated +// percentiles (PG percentile_cont, mem) and ClickHouse's histogram-based +// quantilesTiming. Dataset values are 50ms apart, so 25ms still pins each +// percentile to one expected value. +const latencyPercentileTolerance = 25.0 + func testMetricsDataCorrectness(t *testing.T, ctx context.Context, logStore driver.LogStore, ds *metricsDataset) { fullRange := ds.timeRange.toDriver() denseRange := ds.denseDayRange.toDriver() @@ -377,6 +383,103 @@ func testMetricsDataCorrectness(t *testing.T, ctx context.Context, logStore driv assert.InDelta(t, 1.0, *dp.AvgAttemptNumber, 0.001) }) + t.Run("latency measures", func(t *testing.T) { + resp, err := logStore.QueryAttemptMetrics(ctx, driver.MetricsRequest{ + Filters: map[string][]string{"tenant_id": {ds.tenant1}}, + TimeRange: fullRange, + Measures: []string{"avg_latency", "p50_latency", "p95_latency", "p99_latency"}, + }) + require.NoError(t, err) + require.Len(t, resp.Data, 1) + dp := resp.Data[0] + require.NotNil(t, dp.AvgLatency) + require.NotNil(t, dp.P50Latency) + require.NotNil(t, dp.P95Latency) + require.NotNil(t, dp.P99Latency) + // 270 recorded (manual attempts have none): values 100..500, 30 each + assert.InDelta(t, 300.0, *dp.AvgLatency, 0.001) + assert.InDelta(t, 300.0, *dp.P50Latency, latencyPercentileTolerance) + assert.InDelta(t, 500.0, *dp.P95Latency, latencyPercentileTolerance) + assert.InDelta(t, 500.0, *dp.P99Latency, latencyPercentileTolerance) + }) + + t.Run("latency by destination_id", func(t *testing.T) { + resp, err := logStore.QueryAttemptMetrics(ctx, driver.MetricsRequest{ + Filters: map[string][]string{"tenant_id": {ds.tenant1}}, + TimeRange: fullRange, + Measures: []string{"count", "avg_latency"}, + Dimensions: []string{"destination_id"}, + }) + require.NoError(t, err) + require.Len(t, resp.Data, 2) + for _, dp := range resp.Data { + require.NotNil(t, dp.DestinationID) + require.NotNil(t, dp.AvgLatency) + // dest_1.1: 100,200,300,400,500 (avg 300); dest_1.2: 150,250,350,450 (avg 300) + assert.InDelta(t, 300.0, *dp.AvgLatency, 0.001, "destination %s", *dp.DestinationID) + } + }) + + t.Run("latency is nil when no attempt recorded one", func(t *testing.T) { + resp, err := logStore.QueryAttemptMetrics(ctx, driver.MetricsRequest{ + Filters: map[string][]string{"tenant_id": {ds.tenant2}}, + TimeRange: fullRange, + Measures: []string{"count", "avg_latency", "p50_latency", "p95_latency", "p99_latency"}, + }) + require.NoError(t, err) + require.Len(t, resp.Data, 1) + dp := resp.Data[0] + require.NotNil(t, dp.Count) + assert.Equal(t, 5, *dp.Count) + assert.Nil(t, dp.AvgLatency, "avg_latency must be nil, not 0, when nothing was recorded") + assert.Nil(t, dp.P50Latency) + assert.Nil(t, dp.P95Latency) + assert.Nil(t, dp.P99Latency) + }) + + t.Run("latency filtered to manual attempts is nil", func(t *testing.T) { + // Manual attempts have no latency: a non-empty all-NULL group is nil. + resp, err := logStore.QueryAttemptMetrics(ctx, driver.MetricsRequest{ + Filters: map[string][]string{"tenant_id": {ds.tenant1}, "manual": {"true"}}, + TimeRange: fullRange, + Measures: []string{"count", "avg_latency", "p95_latency"}, + }) + require.NoError(t, err) + require.Len(t, resp.Data, 1) + dp := resp.Data[0] + require.NotNil(t, dp.Count) + assert.Equal(t, 30, *dp.Count) + assert.Nil(t, dp.AvgLatency) + assert.Nil(t, dp.P95Latency) + }) + + t.Run("latency with 1h granularity on dense day", func(t *testing.T) { + resp, err := logStore.QueryAttemptMetrics(ctx, driver.MetricsRequest{ + Filters: map[string][]string{"tenant_id": {ds.tenant1}}, + TimeRange: denseRange, + Granularity: &driver.Granularity{Value: 1, Unit: "h"}, + Measures: []string{"count", "avg_latency", "p95_latency"}, + }) + require.NoError(t, err) + require.Len(t, resp.Data, 24) + + for _, dp := range resp.Data { + require.NotNil(t, dp.TimeBucket) + require.NotNil(t, dp.Count) + h := dp.TimeBucket.Hour() + if h < 10 || h > 14 { + assert.Nil(t, dp.AvgLatency, "hour %d is empty: avg_latency must be nil", h) + assert.Nil(t, dp.P95Latency, "hour %d is empty: p95_latency must be nil", h) + continue + } + require.NotNil(t, dp.AvgLatency, "hour %d has data: avg_latency must be set", h) + require.NotNil(t, dp.P95Latency, "hour %d has data: p95_latency must be set", h) + assert.GreaterOrEqual(t, *dp.AvgLatency, 100.0) + assert.LessOrEqual(t, *dp.AvgLatency, 500.0) + assert.GreaterOrEqual(t, *dp.P95Latency, *dp.AvgLatency-latencyPercentileTolerance) + } + }) + t.Run("rate no granularity", func(t *testing.T) { resp, err := logStore.QueryAttemptMetrics(ctx, driver.MetricsRequest{ Filters: map[string][]string{"tenant_id": {ds.tenant1}}, diff --git a/internal/logstore/drivertest/metrics_dataset.go b/internal/logstore/drivertest/metrics_dataset.go index 0942037c2..952e067ad 100644 --- a/internal/logstore/drivertest/metrics_dataset.go +++ b/internal/logstore/drivertest/metrics_dataset.go @@ -61,6 +61,7 @@ import ( // attempt_number: 1 (each entry is a unique event, not a retry) // manual: i % 10 == 9 // eligible_for_retry: i % 3 != 2 +// latency_ms: manual (i%10==9) → nil, otherwise 100 + (i%10)*50 // // ── Derived Totals (Tenant 1, all 300) ─────────────────────────────────── // @@ -83,6 +84,11 @@ import ( // retry (attempt_number>1): 0 // manual (i%10==9): 30 // avg_attempt_number: 1.0 +// latency (270 recorded, 30 nil): nine values 100..500, 30 each +// avg_latency: 300 +// p50_latency: 300 (rank 0.5*269=134.5, both neighbours 300) +// p95_latency: 500 (rank 255.55) +// p99_latency: 500 // // Dense day — Jan 15 (250 events, indices 50..299): // hourly buckets: 10:00→25, 11:00→50, 12:00→100, 13:00→50, 14:00→25 @@ -90,7 +96,7 @@ import ( // ── Tenant 2 ───────────────────────────────────────────────────────────── // // 5 events, all topic=user.created, dest=dest_2.1, status=success, code=200, -// attempt_number=1, manual=false, eligible_for_retry=true +// attempt_number=1, manual=false, eligible_for_retry=true, no latency // // Jan 5 09:00, Jan 10 09:00, Jan 15 12:15, Jan 22 09:00, Jan 27 09:00 // @@ -178,6 +184,10 @@ func buildMetricsDataset() *metricsDataset { attemptNum := 1 // Each entry is a unique event, not a retry manual := idx%10 == 9 eligible := idx%3 != 2 + var attemptOpts []func(*models.Attempt) + if !manual { + attemptOpts = append(attemptOpts, testutil.AttemptFactory.WithLatencyMs(int64(100+(idx%10)*50))) + } event := testutil.EventFactory.AnyPointer( testutil.EventFactory.WithID(fmt.Sprintf("m_evt_1_%d", idx)), @@ -199,6 +209,9 @@ func buildMetricsDataset() *metricsDataset { testutil.AttemptFactory.WithAttemptNumber(attemptNum), testutil.AttemptFactory.WithManual(manual), ) + for _, opt := range attemptOpts { + opt(attempt) + } idx++ return &models.LogEntry{Event: event, Attempt: attempt} diff --git a/internal/logstore/memlogstore/memlogstore.go b/internal/logstore/memlogstore/memlogstore.go index bc56a8624..e61358c1d 100644 --- a/internal/logstore/memlogstore/memlogstore.go +++ b/internal/logstore/memlogstore/memlogstore.go @@ -480,6 +480,11 @@ func copyAttempt(a *models.Attempt) *models.Attempt { Code: a.Code, } + if a.LatencyMs != nil { + v := *a.LatencyMs + copied.LatencyMs = &v + } + if a.ResponseData != nil { copied.ResponseData = make(map[string]any, len(a.ResponseData)) for k, v := range a.ResponseData { diff --git a/internal/logstore/memlogstore/metrics.go b/internal/logstore/memlogstore/metrics.go index 433a8df87..98163c1a4 100644 --- a/internal/logstore/memlogstore/metrics.go +++ b/internal/logstore/memlogstore/metrics.go @@ -3,6 +3,7 @@ package memlogstore import ( "context" "fmt" + "math" "slices" "time" @@ -202,6 +203,7 @@ func (s *memLogStore) QueryAttemptMetrics(ctx context.Context, req driver.Metric var data []driver.AttemptMetricsDataPoint for key, attempts := range groups { dp := driver.AttemptMetricsDataPoint{} + var latencies []float64 // built on first latency measure if key.timeBucket != "" { tb, _ := time.Parse(time.RFC3339, key.timeBucket) @@ -292,6 +294,20 @@ func (s *memLogStore) QueryAttemptMetrics(ctx context.Context, req driver.Metric avg = float64(total) / float64(len(attempts)) } dp.AvgAttemptNumber = &avg + case "avg_latency", "p50_latency", "p95_latency", "p99_latency": + if latencies == nil { + latencies = sortedLatencies(attempts) + } + switch measure { + case "avg_latency": + dp.AvgLatency = meanLatency(latencies) + case "p50_latency": + dp.P50Latency = percentileLatency(latencies, 0.5) + case "p95_latency": + dp.P95Latency = percentileLatency(latencies, 0.95) + case "p99_latency": + dp.P99Latency = percentileLatency(latencies, 0.99) + } } } @@ -423,3 +439,46 @@ type attemptWithEvent struct { attempt *models.Attempt event *models.Event } + +// sortedLatencies returns the group's recorded latencies in ascending order, +// skipping attempts without one. +func sortedLatencies(attempts []attemptWithEvent) []float64 { + out := make([]float64, 0, len(attempts)) + for _, ae := range attempts { + if ae.attempt.LatencyMs != nil { + out = append(out, float64(*ae.attempt.LatencyMs)) + } + } + slices.Sort(out) + return out +} + +// meanLatency returns nil when no attempt recorded a latency. +func meanLatency(sorted []float64) *float64 { + if len(sorted) == 0 { + return nil + } + sum := 0.0 + for _, v := range sorted { + sum += v + } + mean := sum / float64(len(sorted)) + return &mean +} + +// percentileLatency interpolates between closest ranks, like percentile_cont. +// Returns nil for an empty input. +func percentileLatency(sorted []float64, p float64) *float64 { + n := len(sorted) + if n == 0 { + return nil + } + rank := p * float64(n-1) + lo := int(math.Floor(rank)) + hi := int(math.Ceil(rank)) + v := sorted[lo] + if hi != lo { + v += (rank - float64(lo)) * (sorted[hi] - sorted[lo]) + } + return &v +} diff --git a/internal/logstore/pglogstore/metrics.go b/internal/logstore/pglogstore/metrics.go index a1f524ca7..696d663b0 100644 --- a/internal/logstore/pglogstore/metrics.go +++ b/internal/logstore/pglogstore/metrics.go @@ -303,6 +303,10 @@ func (s *logStore) QueryAttemptMetrics(ctx context.Context, req driver.MetricsRe sfRetryCount sfManualRetry sfAvgAttemptNum + sfAvgLatency + sfP50Latency + sfP95Latency + sfP99Latency ) var order []sf @@ -379,6 +383,19 @@ func (s *logStore) QueryAttemptMetrics(ctx context.Context, req driver.MetricsRe case "avg_attempt_number": selectExprs = append(selectExprs, "AVG(attempt_number)::float8") order = append(order, sfAvgAttemptNum) + // Latency aggregates are NULL when no row in the group has a value. + case "avg_latency": + selectExprs = append(selectExprs, "AVG(latency_ms)::float8") + order = append(order, sfAvgLatency) + case "p50_latency": + selectExprs = append(selectExprs, "percentile_cont(0.5) WITHIN GROUP (ORDER BY latency_ms)::float8") + order = append(order, sfP50Latency) + case "p95_latency": + selectExprs = append(selectExprs, "percentile_cont(0.95) WITHIN GROUP (ORDER BY latency_ms)::float8") + order = append(order, sfP95Latency) + case "p99_latency": + selectExprs = append(selectExprs, "percentile_cont(0.99) WITHIN GROUP (ORDER BY latency_ms)::float8") + order = append(order, sfP99Latency) } } @@ -447,6 +464,10 @@ func (s *logStore) QueryAttemptMetrics(ctx context.Context, req driver.MetricsRe retryCount int manualRetry int avgAttemptNum float64 + avgLatency *float64 + p50Latency *float64 + p95Latency *float64 + p99Latency *float64 ) scanDests := make([]any, len(order)) @@ -486,6 +507,14 @@ func (s *logStore) QueryAttemptMetrics(ctx context.Context, req driver.MetricsRe scanDests[i] = &manualRetry case sfAvgAttemptNum: scanDests[i] = &avgAttemptNum + case sfAvgLatency: + scanDests[i] = &avgLatency + case sfP50Latency: + scanDests[i] = &p50Latency + case sfP95Latency: + scanDests[i] = &p95Latency + case sfP99Latency: + scanDests[i] = &p99Latency } } @@ -549,6 +578,14 @@ func (s *logStore) QueryAttemptMetrics(ctx context.Context, req driver.MetricsRe case sfAvgAttemptNum: v := avgAttemptNum dp.AvgAttemptNumber = &v + case sfAvgLatency: + dp.AvgLatency = copyFloat64(avgLatency) + case sfP50Latency: + dp.P50Latency = copyFloat64(p50Latency) + case sfP95Latency: + dp.P95Latency = copyFloat64(p95Latency) + case sfP99Latency: + dp.P99Latency = copyFloat64(p99Latency) } } data = append(data, dp) @@ -579,3 +616,12 @@ func (s *logStore) QueryAttemptMetrics(ctx context.Context, req driver.MetricsRe }, }, nil } + +// copyFloat64 detaches a scanned nullable value from the reusable scan slot. +func copyFloat64(p *float64) *float64 { + if p == nil { + return nil + } + v := *p + return &v +} diff --git a/internal/logstore/pglogstore/pglogstore.go b/internal/logstore/pglogstore/pglogstore.go index 45394f91c..5a583d403 100644 --- a/internal/logstore/pglogstore/pglogstore.go +++ b/internal/logstore/pglogstore/pglogstore.go @@ -409,7 +409,8 @@ func buildAttemptQuery(req driver.ListAttemptRequest, q pagination.QueryInput) ( event_time, eligible_for_retry, event_data, - event_metadata + event_metadata, + latency_ms FROM attempts WHERE %s %s @@ -461,6 +462,7 @@ func scanAttemptRecords(rows pgx.Rows) ([]attemptRecordWithPosition, error) { eligibleForRetry bool eventData string eventMetadata map[string]string + latencyMs *int64 ) if err := rows.Scan( @@ -480,6 +482,7 @@ func scanAttemptRecords(rows pgx.Rows) ([]attemptRecordWithPosition, error) { &eligibleForRetry, &eventData, &eventMetadata, + &latencyMs, ); err != nil { return nil, fmt.Errorf("scan failed: %w", err) } @@ -509,6 +512,7 @@ func scanAttemptRecords(rows pgx.Rows) ([]attemptRecordWithPosition, error) { Time: attemptTime, Code: code, ResponseData: responseData, + LatencyMs: latencyMs, }, Event: &models.Event{ ID: eventID, @@ -624,7 +628,8 @@ func (s *logStore) RetrieveAttempt(ctx context.Context, req driver.RetrieveAttem event_time, eligible_for_retry, event_data, - event_metadata + event_metadata, + latency_ms FROM attempts WHERE %s LIMIT 1`, whereClause) @@ -648,6 +653,7 @@ func (s *logStore) RetrieveAttempt(ctx context.Context, req driver.RetrieveAttem eligibleForRetry bool eventData string eventMetadata map[string]string + latencyMs *int64 ) err := row.Scan( @@ -667,6 +673,7 @@ func (s *logStore) RetrieveAttempt(ctx context.Context, req driver.RetrieveAttem &eligibleForRetry, &eventData, &eventMetadata, + &latencyMs, ) if err == pgx.ErrNoRows { return nil, nil @@ -699,6 +706,7 @@ func (s *logStore) RetrieveAttempt(ctx context.Context, req driver.RetrieveAttem Time: attemptTime, Code: code, ResponseData: responseData, + LatencyMs: latencyMs, }, Event: &models.Event{ ID: eventID, @@ -770,17 +778,20 @@ func (s *logStore) InsertMany(ctx context.Context, entries []*models.LogEntry) e INSERT INTO attempts ( id, event_id, tenant_id, destination_id, destination_type, topic, status, time, attempt_number, manual, code, response_data, - event_time, eligible_for_retry, event_data, event_metadata + event_time, eligible_for_retry, event_data, event_metadata, + latency_ms ) SELECT * FROM unnest( $1::text[], $2::text[], $3::text[], $4::text[], $5::text[], $6::text[], $7::text[], $8::timestamptz[], $9::integer[], $10::boolean[], $11::text[], $12::text[], - $13::timestamptz[], $14::boolean[], $15::text[], $16::jsonb[] + $13::timestamptz[], $14::boolean[], $15::text[], $16::jsonb[], + $17::integer[] ) ON CONFLICT (time, id) DO UPDATE SET status = EXCLUDED.status, code = EXCLUDED.code, - response_data = EXCLUDED.response_data + response_data = EXCLUDED.response_data, + latency_ms = EXCLUDED.latency_ms `, attemptArrays(entries)...) if err != nil { return fmt.Errorf("insert attempts failed: %w", err) @@ -854,6 +865,7 @@ func attemptArrays(entries []*models.LogEntry) []any { eligibleForRetries := make([]bool, n) eventDatas := make([]string, n) eventMetadatas := make([]map[string]string, n) + latencies := make([]*int64, n) for i, entry := range entries { a := entry.Attempt @@ -881,6 +893,7 @@ func attemptArrays(entries []*models.LogEntry) []any { eventMetadata = map[string]string{} } eventMetadatas[i] = eventMetadata + latencies[i] = a.LatencyMs } return []any{ @@ -900,5 +913,6 @@ func attemptArrays(entries []*models.LogEntry) []any { eligibleForRetries, eventDatas, eventMetadatas, + latencies, } } diff --git a/internal/migrator/migrations/clickhouse/000004_attempt_latency.down.sql b/internal/migrator/migrations/clickhouse/000004_attempt_latency.down.sql new file mode 100644 index 000000000..8d1471b45 --- /dev/null +++ b/internal/migrator/migrations/clickhouse/000004_attempt_latency.down.sql @@ -0,0 +1 @@ +ALTER TABLE {deployment_prefix}attempts DROP COLUMN IF EXISTS latency_ms; diff --git a/internal/migrator/migrations/clickhouse/000004_attempt_latency.up.sql b/internal/migrator/migrations/clickhouse/000004_attempt_latency.up.sql new file mode 100644 index 000000000..fd18dd779 --- /dev/null +++ b/internal/migrator/migrations/clickhouse/000004_attempt_latency.up.sql @@ -0,0 +1 @@ +ALTER TABLE {deployment_prefix}attempts ADD COLUMN latency_ms Nullable(UInt32); diff --git a/internal/migrator/migrations/postgres/000011_attempt_latency.down.sql b/internal/migrator/migrations/postgres/000011_attempt_latency.down.sql new file mode 100644 index 000000000..0f0cc1d90 --- /dev/null +++ b/internal/migrator/migrations/postgres/000011_attempt_latency.down.sql @@ -0,0 +1,5 @@ +BEGIN; + +ALTER TABLE attempts DROP COLUMN IF EXISTS latency_ms; + +COMMIT; diff --git a/internal/migrator/migrations/postgres/000011_attempt_latency.up.sql b/internal/migrator/migrations/postgres/000011_attempt_latency.up.sql new file mode 100644 index 000000000..6c286183e --- /dev/null +++ b/internal/migrator/migrations/postgres/000011_attempt_latency.up.sql @@ -0,0 +1,17 @@ +BEGIN; + +-- ============================================================================= +-- Migration: Add per-attempt latency +-- +-- latency_ms is the time the destination took to respond to the attempt (or +-- to fail), measured around the provider's Publish call. It is only aggregated +-- (avg / percentiles on the metrics API), never filtered on, so no index. +-- +-- Nullable on purpose: attempts written before this migration have no value, +-- and NULL is skipped by AVG / percentile_cont so historical rows don't drag +-- the numbers down. +-- ============================================================================= + +ALTER TABLE attempts ADD COLUMN latency_ms integer; + +COMMIT; diff --git a/internal/models/entities.go b/internal/models/entities.go index 46fd3e512..ec5ca0fd8 100644 --- a/internal/models/entities.go +++ b/internal/models/entities.go @@ -138,6 +138,9 @@ type Attempt struct { Time time.Time `json:"time"` Code string `json:"code"` ResponseData map[string]interface{} `json:"response_data"` + // Provider response time in ms, measured around Publish. Nil when the + // attempt never reached the provider or predates latency tracking. + LatencyMs *int64 `json:"latency_ms"` } // ============================== Types ============================== diff --git a/internal/util/testutil/event.go b/internal/util/testutil/event.go index bc23e3673..ad4d5c0f6 100644 --- a/internal/util/testutil/event.go +++ b/internal/util/testutil/event.go @@ -193,6 +193,12 @@ func (f *mockAttemptFactory) WithCode(code string) func(*models.Attempt) { } } +func (f *mockAttemptFactory) WithLatencyMs(latencyMs int64) func(*models.Attempt) { + return func(attempt *models.Attempt) { + attempt.LatencyMs = &latencyMs + } +} + func (f *mockAttemptFactory) WithTime(time time.Time) func(*models.Attempt) { return func(attempt *models.Attempt) { attempt.Time = time From edd46a32659cbd91309e8ca2a5a8e59214e63cbc Mon Sep 17 00:00:00 2001 From: Alex Luong Date: Thu, 24 Sep 2026 00:08:48 +0700 Subject: [PATCH 2/3] feat(publishmq): PUBLISH_PROXY_URL for the RabbitMQ publish queue (#1086) * refactor: move proxy chain dialer to internal/proxychain The CONNECT chain dialer and proxy URL parsing move out of destregistry into their own package so non-HTTP clients can tunnel through the same chain. Renames: ParseProxyURL -> proxychain.Parse, RedactedProxyURL -> proxychain.Redact, ProxyConnectError -> proxychain.ConnectError. NewDialer's DialContext tunnels to any addr through every hop; the HTTP client keeps passing all but the last hop. The in-process CONNECT proxy test helper moves to proxychaintest. Co-Authored-By: Claude Opus 5.5 * feat(publishmq): PUBLISH_PROXY_URL for the RabbitMQ publish queue Tunnels the RabbitMQ publish queue connection through an HTTP CONNECT proxy chain (same format as DESTINATIONS_WEBHOOK_PROXY_URL), so a broker that allowlists source IPs sees the proxy's address. amqp091 layers amqps TLS over the tunneled conn, so broker TLS stays end to end. The dial keeps amqp091's defaults (10s heartbeat, en_US locale) and honours the URI's connection_timeout. Other publish providers connect directly: the variable is ignored with one info log. Internal delivery/log queues never use it. A malformed value fails startup. Co-Authored-By: Claude Opus 5.5 * docs: PUBLISH_PROXY_URL Co-Authored-By: Claude Opus 5.5 * refactor(publishmq): rely on amqp091 default locale, build publish queue config once Co-Authored-By: Claude Opus 5.5 --------- Co-authored-by: Claude Opus 5.5 --- .env.example | 2 + .../publishing/publish-from-rabbitmq.mdoc | 14 + docs/content/self-hosting/configuration.mdoc | 8 + .../self-hosting/guides/webhook-proxy.mdoc | 4 + internal/config/config.go | 1 + internal/config/publishmq.go | 31 +- internal/config/publishmq_test.go | 76 ++++ internal/config/validation.go | 4 +- internal/config/validation_test.go | 30 ++ internal/destregistry/baseprovider_test.go | 5 +- internal/destregistry/httpclient.go | 4 +- .../destregistry/httpclient_proxy_test.go | 256 +++++++++++++ internal/destregistry/providers/default.go | 3 +- .../providers/destwebhook/destwebhook.go | 2 +- .../providers/destwebhook/proxytransport.go | 4 +- .../destwebhook/proxytransport_test.go | 3 +- internal/destregistry/proxychain_dial_test.go | 360 ------------------ internal/mqs/queue_rabbitmq.go | 38 +- internal/mqs/queue_rabbitmq_proxy_test.go | 183 +++++++++ internal/proxychain/dialer_test.go | 113 ++++++ .../proxychain.go | 52 +-- .../proxychain_test.go | 22 +- internal/proxychain/proxychaintest/proxy.go | 130 +++++++ internal/services/builder.go | 8 +- 24 files changed, 942 insertions(+), 411 deletions(-) create mode 100644 internal/destregistry/httpclient_proxy_test.go delete mode 100644 internal/destregistry/proxychain_dial_test.go create mode 100644 internal/mqs/queue_rabbitmq_proxy_test.go create mode 100644 internal/proxychain/dialer_test.go rename internal/{destregistry => proxychain}/proxychain.go (72%) rename internal/{destregistry => proxychain}/proxychain_test.go (70%) create mode 100644 internal/proxychain/proxychaintest/proxy.go diff --git a/.env.example b/.env.example index b3f96a03d..d91c1bd5d 100644 --- a/.env.example +++ b/.env.example @@ -88,6 +88,8 @@ # PUBLISH_RABBITMQ_SERVER_URL="amqp://guest:guest@rabbitmq:5672" # PUBLISH_RABBITMQ_QUEUE="publish" # PUBLISH_RABBITMQ_EXCHANGE="outpost" +# Forward proxy for the publish queue connection (RabbitMQ only). +# PUBLISH_PROXY_URL="http://user:pass@proxy:10000" ## AWS SQS # PUBLISH_AWS_SQS_ENDPOINT="http://aws:4566" diff --git a/docs/content/publishing/publish-from-rabbitmq.mdoc b/docs/content/publishing/publish-from-rabbitmq.mdoc index 299de90c0..c6800a028 100644 --- a/docs/content/publishing/publish-from-rabbitmq.mdoc +++ b/docs/content/publishing/publish-from-rabbitmq.mdoc @@ -61,6 +61,20 @@ publishmq: queue: publish ``` +### Connecting through a proxy + +If your broker only accepts connections from allowlisted IPs, set `PUBLISH_PROXY_URL` (YAML: `publishmq.proxy_url`) to route the publish queue connection through an HTTP forward proxy with a static egress IP, then allowlist that IP on the broker. + +``` +PUBLISH_PROXY_URL="http://user:pass@proxy.example.com:8080" +``` + +Outpost opens an HTTP `CONNECT` tunnel through the proxy to the broker's host and port and runs AMQP inside it. With `amqps://`, TLS is negotiated with the broker end to end through the tunnel, so the proxy never sees message contents or broker credentials. Multiple whitespace-separated proxy URLs are tunneled in order, nearest first; the broker sees the connection coming from the last one. Each hop may carry its own basic auth credentials. + +The proxy must allow `CONNECT` to the broker's port (`5672` for `amqp`, `5671` for `amqps` by default). Any idle timeout on the proxy must be longer than the AMQP heartbeat interval (10 seconds unless the server URL sets `heartbeat`). The [Webhook Forward Proxy](/docs/outpost/self-hosting/guides/webhook-proxy) guide has a reference Envoy configuration that works for both. + +`PUBLISH_PROXY_URL` applies to the RabbitMQ publish queue only. AWS SQS, GCP Pub/Sub and Azure Service Bus publish queues connect directly and ignore it, and it never applies to Outpost's internal delivery and log queues. + ### Troubleshooting - [Ask a question](https://github.com/hookdeck/outpost/discussions/new?category=q-a) diff --git a/docs/content/self-hosting/configuration.mdoc b/docs/content/self-hosting/configuration.mdoc index 34c5dbe80..a71e571ac 100644 --- a/docs/content/self-hosting/configuration.mdoc +++ b/docs/content/self-hosting/configuration.mdoc @@ -59,6 +59,14 @@ Whichever way you authenticate, the principal needs these actions on the Outpost | `AZURE_SERVICEBUS_CLIENT_ID` | Service principal client ID | | `AZURE_SERVICEBUS_CLIENT_SECRET` | Service principal client secret | +## Publish Queue + +Optional. Configures the queue Outpost consumes published events from; see [Publishing Events](/docs/outpost/publishing/events) for each provider's variables. + +| Variable | Default | Description | +|----------|---------|-------------| +| `PUBLISH_PROXY_URL` | — | HTTP `CONNECT` forward proxy for the publish queue connection, e.g. `http://user:pass@proxy:8080`. Multiple whitespace-separated URLs are tunneled in order. RabbitMQ only; other providers connect directly and ignore it. See [Publish from RabbitMQ](/docs/outpost/publishing/publish-from-rabbitmq#connecting-through-a-proxy). | + ## Log Storage Choose one for event log persistence: diff --git a/docs/content/self-hosting/guides/webhook-proxy.mdoc b/docs/content/self-hosting/guides/webhook-proxy.mdoc index 07aca46e6..896d7b4c8 100644 --- a/docs/content/self-hosting/guides/webhook-proxy.mdoc +++ b/docs/content/self-hosting/guides/webhook-proxy.mdoc @@ -28,6 +28,10 @@ Outpost separates failures the proxy is responsible for from failures the destin If you expect proxy outages longer than your queue's redelivery window, raise `MinRetryBackoff`, `MaxRetryBackoff`, and `RetryLimit` in your queue configuration so the redelivery window covers the worst case. See [Configuration](/docs/outpost/self-hosting/configuration). +## Publish queue + +The same kind of proxy can carry the connection to a RabbitMQ [publish queue](/docs/outpost/publishing/publish-from-rabbitmq#connecting-through-a-proxy), so a broker that allowlists source IPs sees the proxy's address. Set `PUBLISH_PROXY_URL` in the same format as `DESTINATIONS_WEBHOOK_PROXY_URL`; the two are independent. Outpost tunnels AMQP through every hop with `CONNECT`, so each hop must allow `CONNECT` to the broker's port. `PUBLISH_PROXY_URL` is RabbitMQ only: AWS SQS, GCP Pub/Sub and Azure Service Bus publish queues connect directly. + ## Using Envoy When the proxy is [Envoy](https://www.envoyproxy.io/), Outpost automatically reads `x-envoy-response-flags` from proxy responses and maps them to the same network error codes used elsewhere (e.g. `UT` → `timeout`, `DF` → `dns_error`). No Outpost-side configuration is required, but Envoy must be configured to emit the header. diff --git a/internal/config/config.go b/internal/config/config.go index c1a234bef..c07bc5e1c 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -127,6 +127,7 @@ var ( ErrMissingAESSecret = errors.New("config validation error: AES encryption secret is required") ErrInvalidPortalProxyURL = errors.New("config validation error: invalid portal proxy url") ErrInvalidWebhookProxyURL = errors.New("config validation error: invalid webhook proxy url") + ErrInvalidPublishProxyURL = errors.New("config validation error: invalid publish proxy url") ErrInvalidDeploymentID = errors.New("config validation error: deployment_id must contain only alphanumeric characters, hyphens, and underscores (max 64 characters)") ErrInvalidRedisPoolSize = errors.New("config validation error: redis pool_size must be >= 0") ) diff --git a/internal/config/publishmq.go b/internal/config/publishmq.go index 68d3261fc..6407e881c 100644 --- a/internal/config/publishmq.go +++ b/internal/config/publishmq.go @@ -1,9 +1,13 @@ package config import ( + "context" "fmt" + "net" + "strings" "github.com/hookdeck/outpost/internal/mqs" + "github.com/hookdeck/outpost/internal/proxychain" ) type PublishAWSSQSConfig struct { @@ -38,6 +42,7 @@ type PublishMQConfig struct { AzureServiceBus PublishAzureServiceBusConfig `yaml:"azure_servicebus" desc:"Configuration for using Azure Service Bus as the publish message queue. Only one publish MQ provider should be configured." required:"N"` GCPPubSub PublishGCPPubSubConfig `yaml:"gcp_pubsub" desc:"Configuration for using GCP Pub/Sub as the publish message queue. Only one publish MQ provider should be configured." required:"N"` RabbitMQ PublishRabbitMQConfig `yaml:"rabbitmq" desc:"Configuration for using RabbitMQ as the publish message queue. Only one publish MQ provider should be configured." required:"N"` + ProxyURL string `yaml:"proxy_url" env:"PUBLISH_PROXY_URL" desc:"HTTP CONNECT forward proxy for the publish queue connection, e.g. 'http://user:pass@proxy:10000'. Multiple whitespace-separated URLs are tunneled in order, nearest first. RabbitMQ only; ignored for other providers." required:"N"` } func (c PublishMQConfig) GetInfraType() string { @@ -92,6 +97,7 @@ func (c *PublishMQConfig) GetQueueConfig() *mqs.QueueConfig { ServerURL: c.RabbitMQ.ServerURL, Exchange: c.RabbitMQ.Exchange, Queue: c.RabbitMQ.Queue, + Dial: c.proxyDial(), }, } default: @@ -99,8 +105,12 @@ func (c *PublishMQConfig) GetQueueConfig() *mqs.QueueConfig { } } -// Validate enforces the AWS SQS partial-credential rule for the selected provider. +// Validate enforces the AWS SQS partial-credential rule for the selected +// provider and rejects a malformed proxy chain. func (c *PublishMQConfig) Validate() error { + if _, err := proxychain.Parse(c.ProxyURL); err != nil { + return fmt.Errorf("%w: %w", ErrInvalidPublishProxyURL, err) + } if c.GetInfraType() == "awssqs" { if (c.AWSSQS.AccessKeyID == "") != (c.AWSSQS.SecretAccessKey == "") { return errPartialAWSSQSCredentials @@ -126,3 +136,22 @@ func hasPublishGCPPubSubConfig(config PublishGCPPubSubConfig) bool { func hasPublishRabbitMQConfig(config PublishRabbitMQConfig) bool { return config.ServerURL != "" } + +// ProxyIgnored reports whether a proxy is configured for a provider that +// connects directly. +func (c *PublishMQConfig) ProxyIgnored() bool { + infraType := c.GetInfraType() + return strings.TrimSpace(c.ProxyURL) != "" && infraType != "" && infraType != "rabbitmq" +} + +func (c *PublishMQConfig) proxyDial() proxychain.DialFunc { + hops, err := proxychain.Parse(c.ProxyURL) + if err != nil { + // Validate rejects this at startup; never fall back to a direct dial. + return func(context.Context, string, string) (net.Conn, error) { return nil, err } + } + if len(hops) == 0 { + return nil + } + return proxychain.NewDialer(hops, nil, nil).DialContext +} diff --git a/internal/config/publishmq_test.go b/internal/config/publishmq_test.go index 700e38419..ce3492d6f 100644 --- a/internal/config/publishmq_test.go +++ b/internal/config/publishmq_test.go @@ -1,6 +1,7 @@ package config_test import ( + "context" "testing" "github.com/hookdeck/outpost/internal/config" @@ -91,3 +92,78 @@ func TestPublishMQConfig_Validate(t *testing.T) { }) } } + +func TestPublishMQConfig_ProxyURL(t *testing.T) { + t.Parallel() + const proxy = "http://user:pass@proxy:10000" + + t.Run("rabbitmq publish queue dials through the proxy", func(t *testing.T) { + t.Parallel() + cfg := config.PublishMQConfig{ + RabbitMQ: config.PublishRabbitMQConfig{ServerURL: "amqp://broker:5672", Queue: "q"}, + ProxyURL: proxy, + } + require.NotNil(t, cfg.GetQueueConfig().RabbitMQ.Dial) + assert.False(t, cfg.ProxyIgnored()) + }) + + t.Run("unset proxy keeps the direct dial", func(t *testing.T) { + t.Parallel() + cfg := config.PublishMQConfig{ + RabbitMQ: config.PublishRabbitMQConfig{ServerURL: "amqp://broker:5672", Queue: "q"}, + ProxyURL: " \n", + } + assert.Nil(t, cfg.GetQueueConfig().RabbitMQ.Dial) + assert.False(t, cfg.ProxyIgnored()) + }) + + t.Run("invalid proxy fails the dial instead of connecting directly", func(t *testing.T) { + t.Parallel() + cfg := config.PublishMQConfig{ + RabbitMQ: config.PublishRabbitMQConfig{ServerURL: "amqp://broker:5672", Queue: "q"}, + ProxyURL: "socks5://proxy:1080", + } + dial := cfg.GetQueueConfig().RabbitMQ.Dial + require.NotNil(t, dial) + _, err := dial(context.Background(), "tcp", "broker:5672") + require.Error(t, err) + }) + + for name, cfg := range map[string]config.PublishMQConfig{ + "awssqs": {AWSSQS: config.PublishAWSSQSConfig{Region: "us-east-1", Queue: "q"}}, + "gcppubsub": {GCPPubSub: config.PublishGCPPubSubConfig{Project: "p", Topic: "t", Subscription: "s"}}, + "azureservicebus": {AzureServiceBus: config.PublishAzureServiceBusConfig{ConnectionString: "cs", Topic: "t", Subscription: "s"}}, + } { + t.Run(name+" ignores the proxy", func(t *testing.T) { + t.Parallel() + cfg.ProxyURL = proxy + require.NoError(t, cfg.Validate()) + require.NotNil(t, cfg.GetQueueConfig()) + assert.True(t, cfg.ProxyIgnored()) + }) + } + + t.Run("no publish provider does not report the proxy as ignored", func(t *testing.T) { + t.Parallel() + cfg := config.PublishMQConfig{ProxyURL: proxy} + assert.False(t, cfg.ProxyIgnored()) + }) +} + +func TestPublishProxyURL_InternalMQsConnectDirectly(t *testing.T) { + t.Parallel() + c := &config.Config{} + c.InitDefaults() + c.MQs.RabbitMQ.ServerURL = "amqp://internal:5672" + c.PublishMQ.RabbitMQ.ServerURL = "amqp://publish:5672" + c.PublishMQ.RabbitMQ.Queue = "publish" + c.PublishMQ.ProxyURL = "http://proxy:10000" + + for _, queueType := range []string{"deliverymq", "logmq"} { + qc, err := c.MQs.ToQueueConfig(context.Background(), queueType) + require.NoError(t, err) + require.NotNil(t, qc.RabbitMQ) + assert.Nil(t, qc.RabbitMQ.Dial, queueType) + } + require.NotNil(t, c.PublishMQ.GetQueueConfig().RabbitMQ.Dial) +} diff --git a/internal/config/validation.go b/internal/config/validation.go index 141fa0a18..201d07ee2 100644 --- a/internal/config/validation.go +++ b/internal/config/validation.go @@ -6,7 +6,7 @@ import ( "net/url" "regexp" - "github.com/hookdeck/outpost/internal/destregistry" + "github.com/hookdeck/outpost/internal/proxychain" ) // Validate checks if the configuration is valid @@ -176,7 +176,7 @@ func (c *Config) validatePortal() error { // validateDestinations fails boot on a malformed webhook proxy chain so a bad // hop never reaches the delivery path. func (c *Config) validateDestinations() error { - if _, err := destregistry.ParseProxyURL(c.Destinations.Webhook.ProxyURL); err != nil { + if _, err := proxychain.Parse(c.Destinations.Webhook.ProxyURL); err != nil { return fmt.Errorf("%w: %w", ErrInvalidWebhookProxyURL, err) } return nil diff --git a/internal/config/validation_test.go b/internal/config/validation_test.go index a26f75cb3..6d32ed143 100644 --- a/internal/config/validation_test.go +++ b/internal/config/validation_test.go @@ -306,6 +306,36 @@ func TestMisc(t *testing.T) { }(), wantErr: config.ErrInvalidWebhookProxyURL, }, + { + name: "publish proxy chain is valid", + config: func() *config.Config { + c := validConfig() + c.PublishMQ.RabbitMQ.ServerURL = "amqp://broker:5672" + c.PublishMQ.ProxyURL = "http://user:pass@a:10000 https://b:8443" + return c + }(), + wantErr: nil, + }, + { + name: "invalid publish proxy url", + config: func() *config.Config { + c := validConfig() + c.PublishMQ.RabbitMQ.ServerURL = "amqp://broker:5672" + c.PublishMQ.ProxyURL = "socks5://a:1080" + return c + }(), + wantErr: config.ErrInvalidPublishProxyURL, + }, + { + name: "invalid publish proxy url with a non-rabbitmq provider", + config: func() *config.Config { + c := validConfig() + c.PublishMQ.GCPPubSub.Project = "p" + c.PublishMQ.ProxyURL = "://invalid" + return c + }(), + wantErr: config.ErrInvalidPublishProxyURL, + }, { name: "webhook compat signature is valid", config: func() *config.Config { diff --git a/internal/destregistry/baseprovider_test.go b/internal/destregistry/baseprovider_test.go index f4ffe63a8..02d6e2633 100644 --- a/internal/destregistry/baseprovider_test.go +++ b/internal/destregistry/baseprovider_test.go @@ -7,6 +7,7 @@ import ( "testing" "github.com/hookdeck/outpost/internal/destregistry" + "github.com/hookdeck/outpost/internal/proxychain" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -84,7 +85,7 @@ func TestMakeHTTPClient_Proxy(t *testing.T) { defer targetServer.Close() // Create client with proxy configured - proxy, err := destregistry.ParseProxyURL(proxyServer.URL) + proxy, err := proxychain.Parse(proxyServer.URL) require.NoError(t, err) client, err := destregistry.NewHTTPClient(destregistry.HTTPClientConfig{ Proxy: proxy, @@ -104,7 +105,7 @@ func TestMakeHTTPClient_Proxy(t *testing.T) { t.Run("returns error for invalid proxy URL", func(t *testing.T) { t.Parallel() - _, err := destregistry.ParseProxyURL("://invalid-url") + _, err := proxychain.Parse("://invalid-url") require.Error(t, err) assert.Contains(t, err.Error(), "proxy hop 0") }) diff --git a/internal/destregistry/httpclient.go b/internal/destregistry/httpclient.go index 3c770b90e..a9ffce203 100644 --- a/internal/destregistry/httpclient.go +++ b/internal/destregistry/httpclient.go @@ -6,6 +6,8 @@ import ( "net/http/httptrace" "net/url" "time" + + "github.com/hookdeck/outpost/internal/proxychain" ) type HTTPClientConfig struct { @@ -71,7 +73,7 @@ func NewHTTPClient(config HTTPClientConfig) (*http.Client, error) { if n > 1 { // Go talks to the last hop; the dialer gets it there through // every hop before it. - transport.DialContext = newChainDialer(config.Proxy[:n-1], transport.DialContext, func() *tls.Config { return transport.TLSClientConfig }).DialContext + transport.DialContext = proxychain.NewDialer(config.Proxy[:n-1], transport.DialContext, func() *tls.Config { return transport.TLSClientConfig }).DialContext } if config.WrapTransport != nil { rt = config.WrapTransport(transport, last) diff --git a/internal/destregistry/httpclient_proxy_test.go b/internal/destregistry/httpclient_proxy_test.go new file mode 100644 index 000000000..6465ddcb4 --- /dev/null +++ b/internal/destregistry/httpclient_proxy_test.go @@ -0,0 +1,256 @@ +package destregistry_test + +import ( + "context" + "crypto/tls" + "crypto/x509" + "errors" + "io" + "net" + "net/http" + "net/http/httptest" + "net/url" + "strings" + "sync" + "testing" + "time" + + "github.com/hookdeck/outpost/internal/destregistry" + "github.com/hookdeck/outpost/internal/proxychain" + "github.com/hookdeck/outpost/internal/proxychain/proxychaintest" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// rootPool trusts every httptest TLS server's certificate. +func rootPool(servers ...*httptest.Server) *x509.CertPool { + pool := x509.NewCertPool() + for _, s := range servers { + pool.AddCert(s.Certificate()) + } + return pool +} + +func newChainClient(t *testing.T, chain string, roots *x509.CertPool, onConn func(bool)) *http.Client { + t.Helper() + hops, err := proxychain.Parse(chain) + require.NoError(t, err) + client, err := destregistry.NewHTTPClient(destregistry.HTTPClientConfig{ + Proxy: hops, + OnConnection: onConn, + WrapTransport: func(tr *http.Transport, _ *url.URL) http.RoundTripper { + if roots != nil { + tr.TLSClientConfig = &tls.Config{RootCAs: roots} + } + return tr + }, + }) + require.NoError(t, err) + return client +} + +func newDestination(t *testing.T, useTLS bool) *httptest.Server { + t.Helper() + h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + body, _ := io.ReadAll(r.Body) + w.Header().Set("X-Echo", string(body)) + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("ok")) + }) + var s *httptest.Server + if useTLS { + s = httptest.NewTLSServer(h) + } else { + s = httptest.NewServer(h) + } + t.Cleanup(s.Close) + return s +} + +func TestChainDialer_TwoHops_HTTPSDestination(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + client := newChainClient(t, hop0.URL+" "+hop1.URL, rootPool(dest), nil) + resp, err := client.Post(dest.URL, "text/plain", strings.NewReader("hello")) + require.NoError(t, err) + defer resp.Body.Close() + body, _ := io.ReadAll(resp.Body) + assert.Equal(t, "ok", string(body)) + assert.Equal(t, "hello", resp.Header.Get("X-Echo")) + + assert.Equal(t, []string{proxychaintest.HostOf(hop1.URL)}, hop0.Connects(), "hop 0 only tunnels to hop 1") + assert.Equal(t, []string{proxychaintest.HostOf(dest.URL)}, hop1.Connects(), "hop 1 tunnels to the destination") +} + +func TestChainDialer_TwoHops_HTTPDestination(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + dest := newDestination(t, false) + + client := newChainClient(t, hop0.URL+" "+proxychaintest.WithCreds(hop1.URL, "last", "secret"), nil, nil) + resp, err := client.Get(dest.URL) + require.NoError(t, err) + resp.Body.Close() + assert.Equal(t, http.StatusOK, resp.StatusCode) + + assert.Equal(t, []string{proxychaintest.HostOf(hop1.URL)}, hop0.Connects()) + assert.Empty(t, hop1.Connects(), "plain-http target is forwarded absolute-URI, no CONNECT at the last hop") +} + +func TestChainDialer_ThreeHops(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + hop2 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + client := newChainClient(t, strings.Join([]string{hop0.URL, hop1.URL, hop2.URL}, " "), rootPool(dest), nil) + resp, err := client.Get(dest.URL) + require.NoError(t, err) + resp.Body.Close() + + assert.Equal(t, []string{proxychaintest.HostOf(hop1.URL)}, hop0.Connects()) + assert.Equal(t, []string{proxychaintest.HostOf(hop2.URL)}, hop1.Connects()) + assert.Equal(t, []string{proxychaintest.HostOf(dest.URL)}, hop2.Connects()) +} + +func TestChainDialer_HTTPSFirstHop(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, true) + hop1 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + client := newChainClient(t, hop0.URL+" "+hop1.URL, rootPool(hop0.Server, dest), nil) + resp, err := client.Get(dest.URL) + require.NoError(t, err) + resp.Body.Close() + assert.Equal(t, []string{proxychaintest.HostOf(hop1.URL)}, hop0.Connects()) + assert.Equal(t, []string{proxychaintest.HostOf(dest.URL)}, hop1.Connects()) +} + +func TestChainDialer_HTTPSIntermediateHop(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, true) + hop2 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + client := newChainClient(t, strings.Join([]string{hop0.URL, hop1.URL, hop2.URL}, " "), rootPool(hop1.Server, dest), nil) + resp, err := client.Get(dest.URL) + require.NoError(t, err) + resp.Body.Close() + assert.Equal(t, []string{proxychaintest.HostOf(hop2.URL)}, hop1.Connects(), "TLS to hop 1 runs inside hop 0's tunnel") +} + +func TestChainDialer_CredentialsPerHop(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + chain := proxychaintest.WithCreds(hop0.URL, "first", "pw0") + " " + proxychaintest.WithCreds(hop1.URL, "last", "pw1") + client := newChainClient(t, chain, rootPool(dest), nil) + resp, err := client.Get(dest.URL) + require.NoError(t, err) + resp.Body.Close() + + assert.Equal(t, []string{"Basic Zmlyc3Q6cHcw"}, hop0.Auths(), "first:pw0") + assert.Equal(t, []string{"Basic bGFzdDpwdzE="}, hop1.Auths(), "last:pw1, written by Go's transport") +} + +func TestChainDialer_TunnelReused(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + var reused []bool + var mu sync.Mutex + client := newChainClient(t, hop0.URL+" "+hop1.URL, rootPool(dest), func(r bool) { + mu.Lock() + reused = append(reused, r) + mu.Unlock() + }) + for range 2 { + resp, err := client.Get(dest.URL) + require.NoError(t, err) + _, _ = io.Copy(io.Discard, resp.Body) + resp.Body.Close() + } + assert.Equal(t, []bool{false, true}, reused) + assert.Len(t, hop0.Connects(), 1, "one tunnel serves both requests") +} + +func TestChainDialer_FirstHopUnreachable(t *testing.T) { + t.Parallel() + dead := httptest.NewServer(http.NotFoundHandler()) + deadURL := dead.URL + dead.Close() + hop1 := proxychaintest.New(t, false) + + client := newChainClient(t, proxychaintest.WithCreds(deadURL, "u", "topsecret")+" "+hop1.URL, nil, nil) + _, err := client.Get("https://example.invalid/") + require.Error(t, err) + var opErr *net.OpError + require.True(t, errors.As(err, &opErr)) + assert.Equal(t, "proxyconnect", opErr.Op) + assert.NotContains(t, err.Error(), "topsecret") +} + +func TestChainDialer_IntermediateHopRejects(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop0.Reject = func(string) (int, http.Header) { + return http.StatusServiceUnavailable, http.Header{"X-Envoy-Response-Flags": {"UF"}} + } + hop1 := proxychaintest.New(t, false) + + client := newChainClient(t, proxychaintest.WithCreds(hop0.URL, "u", "topsecret")+" "+hop1.URL, nil, nil) + _, err := client.Get("https://example.invalid/") + require.Error(t, err) + + var connectErr *proxychain.ConnectError + require.True(t, errors.As(err, &connectErr), "got %v", err) + assert.Equal(t, http.StatusServiceUnavailable, connectErr.Status) + assert.Equal(t, "UF", connectErr.Header.Get("X-Envoy-Response-Flags")) + assert.Equal(t, proxychaintest.HostOf(hop1.URL), connectErr.Next) + assert.Equal(t, "http://"+proxychaintest.HostOf(hop0.URL), connectErr.Hop) + assert.NotContains(t, err.Error(), "topsecret") + assert.Empty(t, hop1.Connects()) +} + +func TestChainDialer_ContextTimeoutDuringConnect(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + hop0.Hold = make(chan struct{}) + defer close(hop0.Hold) + hop1 := proxychaintest.New(t, false) + + client := newChainClient(t, hop0.URL+" "+hop1.URL, nil, nil) + ctx, cancel := context.WithTimeout(context.Background(), 200*time.Millisecond) + defer cancel() + req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "https://example.invalid/", nil) + start := time.Now() + _, err := client.Do(req) + require.Error(t, err) + assert.Less(t, time.Since(start), 5*time.Second) + assert.True(t, errors.Is(err, context.DeadlineExceeded) || strings.Contains(err.Error(), "deadline"), "got %v", err) +} + +func TestChainDialer_SingleHopUnchanged(t *testing.T) { + t.Parallel() + hop0 := proxychaintest.New(t, false) + dest := newDestination(t, true) + + client := newChainClient(t, hop0.URL, rootPool(dest), nil) + resp, err := client.Get(dest.URL) + require.NoError(t, err) + resp.Body.Close() + tr := client.Transport.(*http.Transport) + assert.NotNil(t, tr.Proxy) + assert.Equal(t, []string{proxychaintest.HostOf(dest.URL)}, hop0.Connects()) +} diff --git a/internal/destregistry/providers/default.go b/internal/destregistry/providers/default.go index 4fbe48263..d93057d42 100644 --- a/internal/destregistry/providers/default.go +++ b/internal/destregistry/providers/default.go @@ -16,6 +16,7 @@ import ( "github.com/hookdeck/outpost/internal/destregistry/providers/destrabbitmq" "github.com/hookdeck/outpost/internal/destregistry/providers/destwebhook" "github.com/hookdeck/outpost/internal/emetrics" + "github.com/hookdeck/outpost/internal/proxychain" ) // WebhookHeaderConfig is the resolved directive for a single webhook system @@ -94,7 +95,7 @@ func RegisterDefault(registry destregistry.Registry, opts RegisterDefaultDestina var proxy []*url.URL if opts.Webhook != nil { - proxy, err = destregistry.ParseProxyURL(opts.Webhook.ProxyURL) + proxy, err = proxychain.Parse(opts.Webhook.ProxyURL) if err != nil { return fmt.Errorf("webhook proxy: %w", err) } diff --git a/internal/destregistry/providers/destwebhook/destwebhook.go b/internal/destregistry/providers/destwebhook/destwebhook.go index 3d43eac0f..d87a1eaee 100644 --- a/internal/destregistry/providers/destwebhook/destwebhook.go +++ b/internal/destregistry/providers/destwebhook/destwebhook.go @@ -191,7 +191,7 @@ func WithMetadataName(name string) Option { } // WithProxy routes every request through the given forward proxies, -// nearest hop first. See destregistry.ParseProxyURL. +// nearest hop first. See proxychain.Parse. func WithProxy(hops []*url.URL) Option { return func(w *WebhookDestination) { w.proxy = hops diff --git a/internal/destregistry/providers/destwebhook/proxytransport.go b/internal/destregistry/providers/destwebhook/proxytransport.go index 62a775a9a..59c14237f 100644 --- a/internal/destregistry/providers/destwebhook/proxytransport.go +++ b/internal/destregistry/providers/destwebhook/proxytransport.go @@ -11,7 +11,7 @@ import ( "sort" "strings" - "github.com/hookdeck/outpost/internal/destregistry" + "github.com/hookdeck/outpost/internal/proxychain" ) // WrapTransport is the destregistry.HTTPClientConfig.WrapTransport hook for @@ -271,7 +271,7 @@ func (t *proxyTransport) classifyTransportError(err error, req *http.Request) er // An intermediate hop refused to tunnel to the next one. Go wraps the // dialer's error in the same proxyconnect OpError as a plain dial // failure, so this has to run before the substring check below. - var connectErr *destregistry.ProxyConnectError + var connectErr *proxychain.ConnectError if errors.As(err, &connectErr) { return classifyConnectResponse(connectErr.Status, connectErr.Header, err, hostOnly(connectErr.Next)) } diff --git a/internal/destregistry/providers/destwebhook/proxytransport_test.go b/internal/destregistry/providers/destwebhook/proxytransport_test.go index de2c646f9..c5003b5e9 100644 --- a/internal/destregistry/providers/destwebhook/proxytransport_test.go +++ b/internal/destregistry/providers/destwebhook/proxytransport_test.go @@ -10,6 +10,7 @@ import ( "github.com/hookdeck/outpost/internal/destregistry" "github.com/hookdeck/outpost/internal/destregistry/providers/destwebhook" + "github.com/hookdeck/outpost/internal/proxychain" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -43,7 +44,7 @@ func newCONNECTRejectingProxyWithHeaders(t *testing.T, status int, headers map[s // the proxyTransport wrapper, matching the NewHTTPClient flow. func makeProxiedClient(t *testing.T, proxyURL string) *http.Client { t.Helper() - proxy, err := destregistry.ParseProxyURL(proxyURL) + proxy, err := proxychain.Parse(proxyURL) require.NoError(t, err) client, err := destregistry.NewHTTPClient(destregistry.HTTPClientConfig{ Proxy: proxy, diff --git a/internal/destregistry/proxychain_dial_test.go b/internal/destregistry/proxychain_dial_test.go deleted file mode 100644 index 17d92d3e7..000000000 --- a/internal/destregistry/proxychain_dial_test.go +++ /dev/null @@ -1,360 +0,0 @@ -package destregistry_test - -import ( - "context" - "crypto/tls" - "crypto/x509" - "errors" - "io" - "net" - "net/http" - "net/http/httptest" - "net/url" - "strings" - "sync" - "testing" - "time" - - "github.com/hookdeck/outpost/internal/destregistry" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" -) - -// connectProxy is an httptest forward proxy: CONNECT is hijacked and piped -// to the requested authority, plain requests are forwarded absolute-URI -// style. It records every CONNECT authority and Proxy-Authorization it saw. -type connectProxy struct { - *httptest.Server - mu sync.Mutex - connects []string - auths []string - // reject, if set, is consulted for each CONNECT; a non-zero status short - // circuits with that status and headers. - reject func(target string) (int, http.Header) - // hold, if set, is closed by the test to release a CONNECT that is - // deliberately left unanswered. - hold chan struct{} -} - -func newConnectProxy(t *testing.T, useTLS bool) *connectProxy { - t.Helper() - p := &connectProxy{} - handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - if r.Method != http.MethodConnect { - out, err := http.DefaultTransport.RoundTrip(&http.Request{ - Method: r.Method, URL: r.URL, Header: r.Header, Body: r.Body, Host: r.Host, - }) - if err != nil { - http.Error(w, err.Error(), http.StatusBadGateway) - return - } - defer out.Body.Close() - for k, v := range out.Header { - w.Header()[k] = v - } - w.WriteHeader(out.StatusCode) - _, _ = io.Copy(w, out.Body) - return - } - p.mu.Lock() - p.connects = append(p.connects, r.Host) - p.auths = append(p.auths, r.Header.Get("Proxy-Authorization")) - p.mu.Unlock() - - if p.hold != nil { - <-p.hold - } - if p.reject != nil { - if status, h := p.reject(r.Host); status != 0 { - for k, v := range h { - w.Header()[k] = v - } - w.WriteHeader(status) - return - } - } - upstream, err := net.DialTimeout("tcp", r.Host, 5*time.Second) - if err != nil { - w.WriteHeader(http.StatusBadGateway) - return - } - defer upstream.Close() - hj, ok := w.(http.Hijacker) - require.True(t, ok) - w.WriteHeader(http.StatusOK) - conn, buf, err := hj.Hijack() - require.NoError(t, err) - defer conn.Close() - _ = buf.Flush() - done := make(chan struct{}, 2) - // Read through buf: the server may already hold the client's first - // post-CONNECT bytes there, and reading the raw conn would drop them. - go func() { _, _ = io.Copy(upstream, buf); done <- struct{}{} }() - go func() { _, _ = io.Copy(conn, upstream); done <- struct{}{} }() - <-done - }) - if useTLS { - p.Server = httptest.NewTLSServer(handler) - } else { - p.Server = httptest.NewServer(handler) - } - t.Cleanup(p.Close) - return p -} - -func (p *connectProxy) sawConnects() []string { - p.mu.Lock() - defer p.mu.Unlock() - return append([]string(nil), p.connects...) -} - -func (p *connectProxy) sawAuths() []string { - p.mu.Lock() - defer p.mu.Unlock() - return append([]string(nil), p.auths...) -} - -// withCreds rewrites a server URL to carry userinfo. -func withCreds(rawURL, user, pass string) string { - u, _ := url.Parse(rawURL) - u.User = url.UserPassword(user, pass) - return u.String() -} - -func hostOf(rawURL string) string { - u, _ := url.Parse(rawURL) - return u.Host -} - -// rootPool trusts every httptest TLS server's certificate. -func rootPool(servers ...*httptest.Server) *x509.CertPool { - pool := x509.NewCertPool() - for _, s := range servers { - pool.AddCert(s.Certificate()) - } - return pool -} - -func newChainClient(t *testing.T, chain string, roots *x509.CertPool, onConn func(bool)) *http.Client { - t.Helper() - hops, err := destregistry.ParseProxyURL(chain) - require.NoError(t, err) - client, err := destregistry.NewHTTPClient(destregistry.HTTPClientConfig{ - Proxy: hops, - OnConnection: onConn, - WrapTransport: func(tr *http.Transport, _ *url.URL) http.RoundTripper { - if roots != nil { - tr.TLSClientConfig = &tls.Config{RootCAs: roots} - } - return tr - }, - }) - require.NoError(t, err) - return client -} - -func newDestination(t *testing.T, useTLS bool) *httptest.Server { - t.Helper() - h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - body, _ := io.ReadAll(r.Body) - w.Header().Set("X-Echo", string(body)) - w.WriteHeader(http.StatusOK) - _, _ = w.Write([]byte("ok")) - }) - var s *httptest.Server - if useTLS { - s = httptest.NewTLSServer(h) - } else { - s = httptest.NewServer(h) - } - t.Cleanup(s.Close) - return s -} - -func TestChainDialer_TwoHops_HTTPSDestination(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop1 := newConnectProxy(t, false) - dest := newDestination(t, true) - - client := newChainClient(t, hop0.URL+" "+hop1.URL, rootPool(dest), nil) - resp, err := client.Post(dest.URL, "text/plain", strings.NewReader("hello")) - require.NoError(t, err) - defer resp.Body.Close() - body, _ := io.ReadAll(resp.Body) - assert.Equal(t, "ok", string(body)) - assert.Equal(t, "hello", resp.Header.Get("X-Echo")) - - assert.Equal(t, []string{hostOf(hop1.URL)}, hop0.sawConnects(), "hop 0 only tunnels to hop 1") - assert.Equal(t, []string{hostOf(dest.URL)}, hop1.sawConnects(), "hop 1 tunnels to the destination") -} - -func TestChainDialer_TwoHops_HTTPDestination(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop1 := newConnectProxy(t, false) - dest := newDestination(t, false) - - client := newChainClient(t, hop0.URL+" "+withCreds(hop1.URL, "last", "secret"), nil, nil) - resp, err := client.Get(dest.URL) - require.NoError(t, err) - resp.Body.Close() - assert.Equal(t, http.StatusOK, resp.StatusCode) - - assert.Equal(t, []string{hostOf(hop1.URL)}, hop0.sawConnects()) - assert.Empty(t, hop1.sawConnects(), "plain-http target is forwarded absolute-URI, no CONNECT at the last hop") -} - -func TestChainDialer_ThreeHops(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop1 := newConnectProxy(t, false) - hop2 := newConnectProxy(t, false) - dest := newDestination(t, true) - - client := newChainClient(t, strings.Join([]string{hop0.URL, hop1.URL, hop2.URL}, " "), rootPool(dest), nil) - resp, err := client.Get(dest.URL) - require.NoError(t, err) - resp.Body.Close() - - assert.Equal(t, []string{hostOf(hop1.URL)}, hop0.sawConnects()) - assert.Equal(t, []string{hostOf(hop2.URL)}, hop1.sawConnects()) - assert.Equal(t, []string{hostOf(dest.URL)}, hop2.sawConnects()) -} - -func TestChainDialer_HTTPSFirstHop(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, true) - hop1 := newConnectProxy(t, false) - dest := newDestination(t, true) - - client := newChainClient(t, hop0.URL+" "+hop1.URL, rootPool(hop0.Server, dest), nil) - resp, err := client.Get(dest.URL) - require.NoError(t, err) - resp.Body.Close() - assert.Equal(t, []string{hostOf(hop1.URL)}, hop0.sawConnects()) - assert.Equal(t, []string{hostOf(dest.URL)}, hop1.sawConnects()) -} - -func TestChainDialer_HTTPSIntermediateHop(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop1 := newConnectProxy(t, true) - hop2 := newConnectProxy(t, false) - dest := newDestination(t, true) - - client := newChainClient(t, strings.Join([]string{hop0.URL, hop1.URL, hop2.URL}, " "), rootPool(hop1.Server, dest), nil) - resp, err := client.Get(dest.URL) - require.NoError(t, err) - resp.Body.Close() - assert.Equal(t, []string{hostOf(hop2.URL)}, hop1.sawConnects(), "TLS to hop 1 runs inside hop 0's tunnel") -} - -func TestChainDialer_CredentialsPerHop(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop1 := newConnectProxy(t, false) - dest := newDestination(t, true) - - chain := withCreds(hop0.URL, "first", "pw0") + " " + withCreds(hop1.URL, "last", "pw1") - client := newChainClient(t, chain, rootPool(dest), nil) - resp, err := client.Get(dest.URL) - require.NoError(t, err) - resp.Body.Close() - - assert.Equal(t, []string{"Basic Zmlyc3Q6cHcw"}, hop0.sawAuths(), "first:pw0") - assert.Equal(t, []string{"Basic bGFzdDpwdzE="}, hop1.sawAuths(), "last:pw1, written by Go's transport") -} - -func TestChainDialer_TunnelReused(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop1 := newConnectProxy(t, false) - dest := newDestination(t, true) - - var reused []bool - var mu sync.Mutex - client := newChainClient(t, hop0.URL+" "+hop1.URL, rootPool(dest), func(r bool) { - mu.Lock() - reused = append(reused, r) - mu.Unlock() - }) - for range 2 { - resp, err := client.Get(dest.URL) - require.NoError(t, err) - _, _ = io.Copy(io.Discard, resp.Body) - resp.Body.Close() - } - assert.Equal(t, []bool{false, true}, reused) - assert.Len(t, hop0.sawConnects(), 1, "one tunnel serves both requests") -} - -func TestChainDialer_FirstHopUnreachable(t *testing.T) { - t.Parallel() - dead := httptest.NewServer(http.NotFoundHandler()) - deadURL := dead.URL - dead.Close() - hop1 := newConnectProxy(t, false) - - client := newChainClient(t, withCreds(deadURL, "u", "topsecret")+" "+hop1.URL, nil, nil) - _, err := client.Get("https://example.invalid/") - require.Error(t, err) - var opErr *net.OpError - require.True(t, errors.As(err, &opErr)) - assert.Equal(t, "proxyconnect", opErr.Op) - assert.NotContains(t, err.Error(), "topsecret") -} - -func TestChainDialer_IntermediateHopRejects(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop0.reject = func(string) (int, http.Header) { - return http.StatusServiceUnavailable, http.Header{"X-Envoy-Response-Flags": {"UF"}} - } - hop1 := newConnectProxy(t, false) - - client := newChainClient(t, withCreds(hop0.URL, "u", "topsecret")+" "+hop1.URL, nil, nil) - _, err := client.Get("https://example.invalid/") - require.Error(t, err) - - var connectErr *destregistry.ProxyConnectError - require.True(t, errors.As(err, &connectErr), "got %v", err) - assert.Equal(t, http.StatusServiceUnavailable, connectErr.Status) - assert.Equal(t, "UF", connectErr.Header.Get("X-Envoy-Response-Flags")) - assert.Equal(t, hostOf(hop1.URL), connectErr.Next) - assert.Equal(t, "http://"+hostOf(hop0.URL), connectErr.Hop) - assert.NotContains(t, err.Error(), "topsecret") - assert.Empty(t, hop1.sawConnects()) -} - -func TestChainDialer_ContextTimeoutDuringConnect(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - hop0.hold = make(chan struct{}) - defer close(hop0.hold) - hop1 := newConnectProxy(t, false) - - client := newChainClient(t, hop0.URL+" "+hop1.URL, nil, nil) - ctx, cancel := context.WithTimeout(context.Background(), 200*time.Millisecond) - defer cancel() - req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "https://example.invalid/", nil) - start := time.Now() - _, err := client.Do(req) - require.Error(t, err) - assert.Less(t, time.Since(start), 5*time.Second) - assert.True(t, errors.Is(err, context.DeadlineExceeded) || strings.Contains(err.Error(), "deadline"), "got %v", err) -} - -func TestChainDialer_SingleHopUnchanged(t *testing.T) { - t.Parallel() - hop0 := newConnectProxy(t, false) - dest := newDestination(t, true) - - client := newChainClient(t, hop0.URL, rootPool(dest), nil) - resp, err := client.Get(dest.URL) - require.NoError(t, err) - resp.Body.Close() - tr := client.Transport.(*http.Transport) - assert.NotNil(t, tr.Proxy) - assert.Equal(t, []string{hostOf(dest.URL)}, hop0.sawConnects()) -} diff --git a/internal/mqs/queue_rabbitmq.go b/internal/mqs/queue_rabbitmq.go index 610fd639e..cb3813146 100644 --- a/internal/mqs/queue_rabbitmq.go +++ b/internal/mqs/queue_rabbitmq.go @@ -2,9 +2,11 @@ package mqs import ( "context" + "net" "sync" "time" + "github.com/hookdeck/outpost/internal/proxychain" "github.com/rabbitmq/amqp091-go" "gocloud.dev/pubsub" "gocloud.dev/pubsub/rabbitpubsub" @@ -16,6 +18,9 @@ type RabbitMQConfig struct { ServerURL string Exchange string // optional Queue string + // Dial, when set, opens the broker connection in place of a direct TCP + // dial, e.g. through a proxy chain. + Dial proxychain.DialFunc } type RabbitMQQueue struct { @@ -82,7 +87,7 @@ func (q *RabbitMQQueue) ensureConnected() (*pubsub.Topic, *amqp091.Connection, e if q.lastDialErr != nil && time.Since(q.lastDialFailure) < rabbitmqRedialCooldown { return nil, nil, q.lastDialErr } - conn, err := amqp091.Dial(q.config.ServerURL) + conn, err := q.dial() if err != nil { q.lastDialFailure = time.Now() q.lastDialErr = err @@ -112,3 +117,34 @@ func (q *RabbitMQQueue) connectionLost() bool { func NewRabbitMQQueue(config *RabbitMQConfig) *RabbitMQQueue { return &RabbitMQQueue{config: config, base: newWrappedBaseQueue()} } + +func (q *RabbitMQQueue) dial() (*amqp091.Connection, error) { + if q.config.Dial == nil { + return amqp091.Dial(q.config.ServerURL) + } + uri, err := amqp091.ParseURI(q.config.ServerURL) + if err != nil { + return nil, err + } + timeout := 30 * time.Second + if uri.ConnectionTimeout != 0 { + timeout = time.Duration(uri.ConnectionTimeout) * time.Millisecond + } + return amqp091.DialConfig(q.config.ServerURL, amqp091.Config{ + Dial: func(network, addr string) (net.Conn, error) { + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + conn, err := q.config.Dial(ctx, network, addr) + if err != nil { + return nil, err + } + // Same handshake deadline as amqp091's default dialer; the + // library clears it once the connection is open. + if err := conn.SetDeadline(time.Now().Add(timeout)); err != nil { + conn.Close() + return nil, err + } + return conn, nil + }, + }) +} diff --git a/internal/mqs/queue_rabbitmq_proxy_test.go b/internal/mqs/queue_rabbitmq_proxy_test.go new file mode 100644 index 000000000..7361f33c5 --- /dev/null +++ b/internal/mqs/queue_rabbitmq_proxy_test.go @@ -0,0 +1,183 @@ +package mqs_test + +import ( + "context" + "crypto/tls" + "encoding/pem" + "errors" + "fmt" + "io" + "net" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/hookdeck/outpost/internal/mqs" + "github.com/hookdeck/outpost/internal/proxychain" + "github.com/hookdeck/outpost/internal/proxychain/proxychaintest" + "github.com/hookdeck/outpost/internal/util/testinfra" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +var amqpProtocolHeader = []byte("AMQP\x00\x00\x09\x01") + +// newFakeBroker accepts one connection, reads the AMQP protocol header the +// client sends first, reports it and hangs up. With tlsConfig set it +// terminates TLS first, so the header only arrives if the client's TLS +// session reached the broker itself. +func newFakeBroker(t *testing.T, tlsConfig *tls.Config) (string, <-chan []byte) { + t.Helper() + var ln net.Listener + var err error + if tlsConfig != nil { + ln, err = tls.Listen("tcp", "127.0.0.1:0", tlsConfig) + } else { + ln, err = net.Listen("tcp", "127.0.0.1:0") + } + require.NoError(t, err) + t.Cleanup(func() { ln.Close() }) + got := make(chan []byte, 1) + go func() { + conn, err := ln.Accept() + if err != nil { + return + } + defer conn.Close() + _ = conn.SetReadDeadline(time.Now().Add(5 * time.Second)) + buf := make([]byte, len(amqpProtocolHeader)) + if _, err := io.ReadFull(conn, buf); err == nil { + got <- buf + } + }() + return ln.Addr().String(), got +} + +func proxyDial(t *testing.T, chain string) proxychain.DialFunc { + t.Helper() + hops, err := proxychain.Parse(chain) + require.NoError(t, err) + return proxychain.NewDialer(hops, nil, nil).DialContext +} + +func initRabbitMQ(serverURL string, dial proxychain.DialFunc) error { + queue := mqs.NewRabbitMQQueue(&mqs.RabbitMQConfig{ServerURL: serverURL, Queue: "test", Dial: dial}) + cleanup, err := queue.Init(context.Background()) + if err == nil { + cleanup() + } + return err +} + +func receiveHeader(t *testing.T, got <-chan []byte) []byte { + t.Helper() + select { + case b := <-got: + return b + case <-time.After(5 * time.Second): + t.Fatal("broker never received the AMQP protocol header") + return nil + } +} + +func TestMQ_RabbitMQDialsThroughProxyChain(t *testing.T) { + t.Parallel() + for _, n := range []int{1, 2} { + t.Run(fmt.Sprintf("%d hops", n), func(t *testing.T) { + t.Parallel() + broker, got := newFakeBroker(t, nil) + hops := make([]*proxychaintest.Proxy, n) + urls := make([]string, n) + for i := range hops { + hops[i] = proxychaintest.New(t, false) + urls[i] = hops[i].URL + } + + // The fake broker hangs up after the protocol header, so the dial fails. + require.Error(t, initRabbitMQ("amqp://guest:guest@"+broker+"/", proxyDial(t, strings.Join(urls, " ")))) + assert.Equal(t, amqpProtocolHeader, receiveHeader(t, got)) + assert.Equal(t, []string{broker}, hops[n-1].Connects(), "last hop tunnels to the broker") + if n == 2 { + assert.Equal(t, []string{proxychaintest.HostOf(urls[1])}, hops[0].Connects()) + } + }) + } +} + +func TestMQ_RabbitMQProxyAMQPS(t *testing.T) { + t.Parallel() + certSrv := httptest.NewTLSServer(http.NotFoundHandler()) + certSrv.Close() + caFile := filepath.Join(t.TempDir(), "ca.pem") + require.NoError(t, os.WriteFile(caFile, pem.EncodeToMemory(&pem.Block{Type: "CERTIFICATE", Bytes: certSrv.Certificate().Raw}), 0o600)) + + broker, got := newFakeBroker(t, &tls.Config{Certificates: certSrv.TLS.Certificates}) + hop := proxychaintest.New(t, false) + + serverURL := "amqps://guest:guest@" + broker + "/?cacertfile=" + caFile + require.Error(t, initRabbitMQ(serverURL, proxyDial(t, hop.URL))) + assert.Equal(t, amqpProtocolHeader, receiveHeader(t, got), "TLS runs end to end from client to broker through the tunnel") + assert.Equal(t, []string{broker}, hop.Connects()) +} + +func TestMQ_RabbitMQProxyAuthRejected(t *testing.T) { + t.Parallel() + hop := proxychaintest.New(t, false) + hop.Reject = func(string) (int, http.Header) { return http.StatusProxyAuthRequired, nil } + + chain := proxychaintest.WithCreds(hop.URL, "u", "topsecret") + err := initRabbitMQ("amqp://guest:guest@127.0.0.1:5672/", proxyDial(t, chain)) + var connectErr *proxychain.ConnectError + require.True(t, errors.As(err, &connectErr), "got %v", err) + assert.Equal(t, http.StatusProxyAuthRequired, connectErr.Status) + assert.Equal(t, "http://"+proxychaintest.HostOf(hop.URL), connectErr.Hop) + assert.NotContains(t, err.Error(), "topsecret") +} + +func TestMQ_RabbitMQProxyHonoursConnectionTimeout(t *testing.T) { + t.Parallel() + hop := proxychaintest.New(t, false) + hop.Hold = make(chan struct{}) + t.Cleanup(func() { close(hop.Hold) }) + + start := time.Now() + err := initRabbitMQ("amqp://guest:guest@127.0.0.1:5672/?connection_timeout=200", proxyDial(t, hop.URL)) + require.Error(t, err) + assert.Less(t, time.Since(start), 5*time.Second) +} + +func TestIntegrationMQ_RabbitMQPublishThroughProxyChain(t *testing.T) { + t.Parallel() + t.Cleanup(testinfra.Start(t)) + config := testinfra.NewMQRabbitMQConfig(t) + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + config.RabbitMQ.Dial = proxyDial(t, hop0.URL+" "+hop1.URL) + + ctx := context.Background() + queue := mqs.NewQueue(&config) + cleanup, err := queue.Init(ctx) + require.NoError(t, err) + defer cleanup() + + subscription, err := queue.Subscribe(ctx) + require.NoError(t, err) + defer subscription.Shutdown(ctx) + + require.NoError(t, queue.Publish(ctx, &Msg{ID: "via-proxy"})) + receiveCtx, cancel := context.WithTimeout(ctx, 5*time.Second) + defer cancel() + msg, err := subscription.Receive(receiveCtx) + require.NoError(t, err) + msg.Ack() + parsed := &Msg{} + require.NoError(t, parsed.FromMessage(msg)) + assert.Equal(t, "via-proxy", parsed.ID) + + assert.Len(t, hop0.Connects(), 1, "one AMQP connection serves publish and subscribe") + assert.Equal(t, []string{proxychaintest.HostOf(hop1.URL)}, hop0.Connects()) +} diff --git a/internal/proxychain/dialer_test.go b/internal/proxychain/dialer_test.go new file mode 100644 index 000000000..a8625b1f0 --- /dev/null +++ b/internal/proxychain/dialer_test.go @@ -0,0 +1,113 @@ +package proxychain_test + +import ( + "context" + "crypto/tls" + "errors" + "io" + "net" + "net/http" + "testing" + "time" + + "github.com/hookdeck/outpost/internal/proxychain" + "github.com/hookdeck/outpost/internal/proxychain/proxychaintest" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// newEchoServer accepts TCP connections and echoes whatever it reads. +func newEchoServer(t *testing.T) string { + t.Helper() + ln, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + t.Cleanup(func() { ln.Close() }) + go func() { + for { + conn, err := ln.Accept() + if err != nil { + return + } + go func() { + defer conn.Close() + _, _ = io.Copy(conn, conn) + }() + } + }() + return ln.Addr().String() +} + +func dialThrough(t *testing.T, chain, addr string) (net.Conn, error) { + t.Helper() + hops, err := proxychain.Parse(chain) + require.NoError(t, err) + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + return proxychain.NewDialer(hops, nil, nil).DialContext(ctx, "tcp", addr) +} + +func assertEcho(t *testing.T, conn net.Conn) { + t.Helper() + _, err := conn.Write([]byte("ping")) + require.NoError(t, err) + buf := make([]byte, 4) + require.NoError(t, conn.SetReadDeadline(time.Now().Add(5*time.Second))) + _, err = io.ReadFull(conn, buf) + require.NoError(t, err) + assert.Equal(t, "ping", string(buf)) +} + +func TestDialer_OneHop(t *testing.T) { + t.Parallel() + target := newEchoServer(t) + hop := proxychaintest.New(t, false) + + conn, err := dialThrough(t, proxychaintest.WithCreds(hop.URL, "u", "pw"), target) + require.NoError(t, err) + defer conn.Close() + assertEcho(t, conn) + + assert.Equal(t, []string{target}, hop.Connects()) + assert.Equal(t, []string{"Basic dTpwdw=="}, hop.Auths(), "u:pw") +} + +func TestDialer_TwoHops(t *testing.T) { + t.Parallel() + target := newEchoServer(t) + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, true) + + // hop1 is https: trust its test certificate for the TLS leg inside hop0's tunnel. + hops, err := proxychain.Parse(hop0.URL + " " + hop1.URL) + require.NoError(t, err) + tlsConfig := hop1.Client().Transport.(*http.Transport).TLSClientConfig + d := proxychain.NewDialer(hops, nil, func() *tls.Config { return tlsConfig }) + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + conn, err := d.DialContext(ctx, "tcp", target) + require.NoError(t, err) + defer conn.Close() + assertEcho(t, conn) + + assert.Equal(t, []string{proxychaintest.HostOf(hop1.URL)}, hop0.Connects()) + assert.Equal(t, []string{target}, hop1.Connects()) +} + +func TestDialer_AuthRejected(t *testing.T) { + t.Parallel() + target := newEchoServer(t) + hop0 := proxychaintest.New(t, false) + hop1 := proxychaintest.New(t, false) + hop1.Reject = func(string) (int, http.Header) { return http.StatusProxyAuthRequired, nil } + + chain := hop0.URL + " " + proxychaintest.WithCreds(hop1.URL, "u", "topsecret") + _, err := dialThrough(t, chain, target) + require.Error(t, err) + + var connectErr *proxychain.ConnectError + require.True(t, errors.As(err, &connectErr), "got %v", err) + assert.Equal(t, http.StatusProxyAuthRequired, connectErr.Status) + assert.Equal(t, "http://"+proxychaintest.HostOf(hop1.URL), connectErr.Hop) + assert.Equal(t, target, connectErr.Next) + assert.NotContains(t, err.Error(), "topsecret") +} diff --git a/internal/destregistry/proxychain.go b/internal/proxychain/proxychain.go similarity index 72% rename from internal/destregistry/proxychain.go rename to internal/proxychain/proxychain.go index 4f93b1ee6..a474f4ec5 100644 --- a/internal/destregistry/proxychain.go +++ b/internal/proxychain/proxychain.go @@ -1,4 +1,5 @@ -package destregistry +// Package proxychain dials through a chain of HTTP CONNECT forward proxies. +package proxychain import ( "bufio" @@ -13,7 +14,7 @@ import ( "time" ) -// ParseProxyURL parses the proxy config value: one or more forward proxy +// Parse parses the proxy config value: one or more forward proxy // URLs separated by whitespace, nearest hop first. An unencoded space is never valid inside a URL, so a // single-proxy value parses as a one-element chain unchanged. Empty or // whitespace-only input yields nil (no proxy). @@ -21,7 +22,7 @@ import ( // Every hop must be an absolute http or https URL with a host. Errors name // the offending hop by index and never echo the value, which may carry // credentials. -func ParseProxyURL(s string) ([]*url.URL, error) { +func Parse(s string) ([]*url.URL, error) { fields := strings.Fields(s) if len(fields) == 0 { return nil, nil @@ -43,56 +44,55 @@ func ParseProxyURL(s string) ([]*url.URL, error) { return hops, nil } -// RedactedProxyURL renders a proxy hop as scheme://host[:port] for logs and +// Redact renders a proxy hop as scheme://host[:port] for logs and // error messages, dropping userinfo, path and query. -func RedactedProxyURL(u *url.URL) string { +func Redact(u *url.URL) string { if u == nil { return "" } return u.Scheme + "://" + u.Host } -// ProxyConnectError is returned by the chain dialer when an intermediate hop -// answers a CONNECT with anything but 200. Hop and Next are redacted +// ConnectError is returned by the dialer when a hop answers a CONNECT with anything but 200. Hop and Next are redacted // scheme://host:port strings; Header carries the hop's response headers so // the caller can classify (for Envoy, x-envoy-response-flags). -type ProxyConnectError struct { +type ConnectError struct { Hop string Next string Status int Header http.Header } -func (e *ProxyConnectError) Error() string { +func (e *ConnectError) Error() string { return fmt.Sprintf("proxy %s returned %d for CONNECT %s", e.Hop, e.Status, e.Next) } // DialFunc matches http.Transport.DialContext. type DialFunc func(ctx context.Context, network, addr string) (net.Conn, error) -// chainDialer tunnels through hops 0..n-2 of a proxy chain so the transport, -// whose Proxy is the last hop, ends up talking to that hop over an -// already-established CONNECT tunnel. Go's transport cannot tell the -// returned conn from a direct dial: it still sends its own CONNECT (or -// absolute-URI request) to the last hop, with that hop's credentials. -type chainDialer struct { +// Dialer reaches addr by CONNECTing through every hop in order. The returned +// conn is a raw tunnel to addr; anything the caller layers on top (TLS to +// the target, AMQP) runs end to end through it. +type Dialer struct { hops []*url.URL dial DialFunc - // tls is read per dial so TLSClientConfig set on the transport after - // construction (WrapTransport, tests) still applies to https hops. + // tls is read per dial so TLSClientConfig set on a transport after + // construction still applies to https hops. tls func() *tls.Config } -func newChainDialer(hops []*url.URL, dial DialFunc, tlsConfig func() *tls.Config) *chainDialer { +// NewDialer returns a Dialer over hops. dial opens the TCP connection to the +// first hop (nil uses a net.Dialer); tlsConfig supplies the config for https +// hops (nil uses the zero config). +func NewDialer(hops []*url.URL, dial DialFunc, tlsConfig func() *tls.Config) *Dialer { if dial == nil { dial = (&net.Dialer{Timeout: 30 * time.Second, KeepAlive: 30 * time.Second}).DialContext } - return &chainDialer{hops: hops, dial: dial, tls: tlsConfig} + return &Dialer{hops: hops, dial: dial, tls: tlsConfig} } -// DialContext receives the last hop's host:port from the transport and -// returns a conn tunneled to it through every intermediate hop. -func (d *chainDialer) DialContext(ctx context.Context, network, lastHopAddr string) (net.Conn, error) { +// DialContext returns a conn tunneled to addr through every hop. +func (d *Dialer) DialContext(ctx context.Context, network, addr string) (net.Conn, error) { first := d.hops[0] conn, err := d.dial(ctx, network, proxyHostPort(first)) if err != nil { @@ -106,7 +106,7 @@ func (d *chainDialer) DialContext(ctx context.Context, network, lastHopAddr stri for i, hop := range d.hops { var next *url.URL - nextAddr := lastHopAddr + nextAddr := addr if i+1 < len(d.hops) { next = d.hops[i+1] nextAddr = proxyHostPort(next) @@ -125,7 +125,7 @@ func (d *chainDialer) DialContext(ctx context.Context, network, lastHopAddr stri } // wrapTLS starts TLS on conn to a proxy hop. On failure the conn is closed. -func (d *chainDialer) wrapTLS(ctx context.Context, conn net.Conn, serverName string) (net.Conn, error) { +func (d *Dialer) wrapTLS(ctx context.Context, conn net.Conn, serverName string) (net.Conn, error) { var cfg *tls.Config if d.tls != nil { cfg = d.tls() @@ -174,8 +174,8 @@ func connectThrough(ctx context.Context, conn net.Conn, hop *url.URL, target str } if resp.StatusCode != http.StatusOK { _ = resp.Body.Close() - return &ProxyConnectError{ - Hop: RedactedProxyURL(hop), + return &ConnectError{ + Hop: Redact(hop), Next: target, Status: resp.StatusCode, Header: resp.Header, diff --git a/internal/destregistry/proxychain_test.go b/internal/proxychain/proxychain_test.go similarity index 70% rename from internal/destregistry/proxychain_test.go rename to internal/proxychain/proxychain_test.go index b46385c52..6a738622d 100644 --- a/internal/destregistry/proxychain_test.go +++ b/internal/proxychain/proxychain_test.go @@ -1,20 +1,20 @@ -package destregistry_test +package proxychain_test import ( "testing" - "github.com/hookdeck/outpost/internal/destregistry" + "github.com/hookdeck/outpost/internal/proxychain" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) -func TestParseProxyURL(t *testing.T) { +func TestParse(t *testing.T) { t.Parallel() t.Run("empty and whitespace-only yield no proxy", func(t *testing.T) { t.Parallel() for _, in := range []string{"", " ", "\t\n"} { - hops, err := destregistry.ParseProxyURL(in) + hops, err := proxychain.Parse(in) require.NoError(t, err) assert.Nil(t, hops) } @@ -22,7 +22,7 @@ func TestParseProxyURL(t *testing.T) { t.Run("single URL parses unchanged, including comma in password", func(t *testing.T) { t.Parallel() - hops, err := destregistry.ParseProxyURL("http://user:p,ss@proxy.example.com:3128") + hops, err := proxychain.Parse("http://user:p,ss@proxy.example.com:3128") require.NoError(t, err) require.Len(t, hops, 1) assert.Equal(t, "proxy.example.com:3128", hops[0].Host) @@ -32,7 +32,7 @@ func TestParseProxyURL(t *testing.T) { t.Run("multiple hops split on any whitespace, order preserved", func(t *testing.T) { t.Parallel() - hops, err := destregistry.ParseProxyURL("http://a:10000 \t https://b:8443\nhttp://c") + hops, err := proxychain.Parse("http://a:10000 \t https://b:8443\nhttp://c") require.NoError(t, err) require.Len(t, hops, 3) assert.Equal(t, "a:10000", hops[0].Host) @@ -52,7 +52,7 @@ func TestParseProxyURL(t *testing.T) { } for name, in := range cases { t.Run(name, func(t *testing.T) { - hops, err := destregistry.ParseProxyURL(in) + hops, err := proxychain.Parse(in) require.Error(t, err) assert.Nil(t, hops) assert.Contains(t, err.Error(), "proxy hop 1") @@ -62,10 +62,10 @@ func TestParseProxyURL(t *testing.T) { }) } -func TestRedactedProxyURL(t *testing.T) { +func TestRedact(t *testing.T) { t.Parallel() - hops, err := destregistry.ParseProxyURL("https://user:pass@proxy.example.com:8443/ignored?x=1") + hops, err := proxychain.Parse("https://user:pass@proxy.example.com:8443/ignored?x=1") require.NoError(t, err) - assert.Equal(t, "https://proxy.example.com:8443", destregistry.RedactedProxyURL(hops[0])) - assert.Equal(t, "", destregistry.RedactedProxyURL(nil)) + assert.Equal(t, "https://proxy.example.com:8443", proxychain.Redact(hops[0])) + assert.Equal(t, "", proxychain.Redact(nil)) } diff --git a/internal/proxychain/proxychaintest/proxy.go b/internal/proxychain/proxychaintest/proxy.go new file mode 100644 index 000000000..8e56e3242 --- /dev/null +++ b/internal/proxychain/proxychaintest/proxy.go @@ -0,0 +1,130 @@ +// Package proxychaintest provides an in-process HTTP CONNECT forward proxy +// for tests. +package proxychaintest + +import ( + "io" + "net" + "net/http" + "net/http/httptest" + "net/url" + "sync" + "testing" + "time" +) + +// Proxy is an httptest forward proxy: CONNECT is hijacked and piped to the +// requested authority, plain requests are forwarded absolute-URI style. It +// records every CONNECT authority and Proxy-Authorization it saw. +type Proxy struct { + *httptest.Server + mu sync.Mutex + connects []string + auths []string + // Reject, if set, is consulted for each CONNECT; a non-zero status short + // circuits with that status and headers. + Reject func(target string) (int, http.Header) + // Hold, if set, is closed by the test to release a CONNECT that is + // deliberately left unanswered. + Hold chan struct{} +} + +// New starts a Proxy, closed on test cleanup. +func New(t *testing.T, useTLS bool) *Proxy { + t.Helper() + p := &Proxy{} + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.Method != http.MethodConnect { + out, err := http.DefaultTransport.RoundTrip(&http.Request{ + Method: r.Method, URL: r.URL, Header: r.Header, Body: r.Body, Host: r.Host, + }) + if err != nil { + http.Error(w, err.Error(), http.StatusBadGateway) + return + } + defer out.Body.Close() + for k, v := range out.Header { + w.Header()[k] = v + } + w.WriteHeader(out.StatusCode) + _, _ = io.Copy(w, out.Body) + return + } + p.mu.Lock() + p.connects = append(p.connects, r.Host) + p.auths = append(p.auths, r.Header.Get("Proxy-Authorization")) + p.mu.Unlock() + + if p.Hold != nil { + <-p.Hold + } + if p.Reject != nil { + if status, h := p.Reject(r.Host); status != 0 { + for k, v := range h { + w.Header()[k] = v + } + w.WriteHeader(status) + return + } + } + upstream, err := net.DialTimeout("tcp", r.Host, 5*time.Second) + if err != nil { + w.WriteHeader(http.StatusBadGateway) + return + } + defer upstream.Close() + hj, ok := w.(http.Hijacker) + if !ok { + t.Error("proxychaintest: response writer is not a Hijacker") + return + } + w.WriteHeader(http.StatusOK) + conn, buf, err := hj.Hijack() + if err != nil { + t.Errorf("proxychaintest: hijack: %v", err) + return + } + defer conn.Close() + _ = buf.Flush() + done := make(chan struct{}, 2) + // Read through buf: the server may already hold the client's first + // post-CONNECT bytes there, and reading the raw conn would drop them. + go func() { _, _ = io.Copy(upstream, buf); done <- struct{}{} }() + go func() { _, _ = io.Copy(conn, upstream); done <- struct{}{} }() + <-done + }) + if useTLS { + p.Server = httptest.NewTLSServer(handler) + } else { + p.Server = httptest.NewServer(handler) + } + t.Cleanup(p.Close) + return p +} + +// Connects returns every CONNECT authority seen so far. +func (p *Proxy) Connects() []string { + p.mu.Lock() + defer p.mu.Unlock() + return append([]string(nil), p.connects...) +} + +// Auths returns the Proxy-Authorization header of every CONNECT seen so far. +func (p *Proxy) Auths() []string { + p.mu.Lock() + defer p.mu.Unlock() + return append([]string(nil), p.auths...) +} + +// WithCreds rewrites a server URL to carry userinfo. +func WithCreds(rawURL, user, pass string) string { + u, _ := url.Parse(rawURL) + u.User = url.UserPassword(user, pass) + return u.String() +} + +// HostOf returns the host:port of a URL. +func HostOf(rawURL string) string { + u, _ := url.Parse(rawURL) + return u.Host +} diff --git a/internal/services/builder.go b/internal/services/builder.go index e82f730fb..e9b5c4cff 100644 --- a/internal/services/builder.go +++ b/internal/services/builder.go @@ -240,8 +240,12 @@ func (b *ServiceBuilder) BuildAPIWorkers(baseRouter *gin.Engine) error { b.supervisor.Register(retryWorker) // Worker 2: PublishMQ Consumer (optional) - if b.cfg.PublishMQ.GetQueueConfig() != nil { - publishMQ := publishmq.New(publishmq.WithQueue(b.cfg.PublishMQ.GetQueueConfig())) + if publishQueueConfig := b.cfg.PublishMQ.GetQueueConfig(); publishQueueConfig != nil { + if b.cfg.PublishMQ.ProxyIgnored() { + b.logger.Info("PUBLISH_PROXY_URL is ignored: only the RabbitMQ publish queue connects through a proxy", + zap.String("publishmq_type", b.cfg.PublishMQ.GetInfraType())) + } + publishMQ := publishmq.New(publishmq.WithQueue(publishQueueConfig)) messageHandler := publishmq.NewMessageHandler(eventHandler) publishMQWorker := NewConsumerWorker( "publishmq-consumer", From 68d6214f6fe1c47791ad7f95d91604a463c0a4b1 Mon Sep 17 00:00:00 2001 From: Alex Luong Date: Thu, 24 Sep 2026 00:14:33 +0700 Subject: [PATCH 3/3] fix(mqs): resubscribe RabbitMQ subscription after connection loss (#1087) * fix(mqs): resubscribe RabbitMQ subscription after connection loss A RabbitMQ subscription was bound to the connection it was opened on. Once that connection closed (broker restart, closed at the broker, proxy restart), every Receive failed until the consumer hit max consecutive errors and the worker stopped. Receive now redials and reopens the subscription when its connection is closed, then returns the original error so consumer backoff still applies. Co-Authored-By: Claude Opus 5.5 * fix(mqs): don't redial RabbitMQ after queue cleanup Co-Authored-By: Claude Opus 5.5 --------- Co-authored-by: Claude Opus 5.5 --- internal/mqs/export_test.go | 4 ++ internal/mqs/queue_rabbitmq.go | 73 ++++++++++++++++++++++- internal/mqs/queue_rabbitmq_test.go | 92 +++++++++++++++++++++++++++++ 3 files changed, 167 insertions(+), 2 deletions(-) diff --git a/internal/mqs/export_test.go b/internal/mqs/export_test.go index 9afce0c3d..fb43bd13f 100644 --- a/internal/mqs/export_test.go +++ b/internal/mqs/export_test.go @@ -10,3 +10,7 @@ func ForceCloseRabbitMQConnection(q Queue) error { } return conn.Close() } + +func RabbitMQConnectionClosed(q Queue) bool { + return q.(*RabbitMQQueue).connectionLost() +} diff --git a/internal/mqs/queue_rabbitmq.go b/internal/mqs/queue_rabbitmq.go index cb3813146..ed9a01452 100644 --- a/internal/mqs/queue_rabbitmq.go +++ b/internal/mqs/queue_rabbitmq.go @@ -2,6 +2,7 @@ package mqs import ( "context" + "errors" "net" "sync" "time" @@ -14,6 +15,8 @@ import ( const rabbitmqRedialCooldown = 5 * time.Second +var errRabbitMQQueueClosed = errors.New("rabbitmq queue closed") + type RabbitMQConfig struct { ServerURL string Exchange string // optional @@ -31,6 +34,7 @@ type RabbitMQQueue struct { mu sync.Mutex lastDialFailure time.Time lastDialErr error + closed bool } var _ Queue = &RabbitMQQueue{} @@ -41,6 +45,7 @@ func (q *RabbitMQQueue) Init(ctx context.Context) (func(), error) { } return func() { q.mu.Lock() + q.closed = true conn, topic := q.conn, q.topic q.mu.Unlock() if conn != nil { @@ -74,13 +79,19 @@ func (q *RabbitMQQueue) Subscribe(ctx context.Context, opts ...SubscribeOption) if err != nil { return nil, err } - subscription := rabbitpubsub.OpenSubscription(conn, q.config.Queue, nil) - return q.base.Subscribe(ctx, subscription) + return &rabbitMQSubscription{ + queue: q, + conn: conn, + subscription: rabbitpubsub.OpenSubscription(conn, q.config.Queue, nil), + }, nil } func (q *RabbitMQQueue) ensureConnected() (*pubsub.Topic, *amqp091.Connection, error) { q.mu.Lock() defer q.mu.Unlock() + if q.closed { + return nil, nil, errRabbitMQQueueClosed + } if q.conn != nil && !q.conn.IsClosed() { return q.topic, q.conn, nil } @@ -114,6 +125,64 @@ func (q *RabbitMQQueue) connectionLost() bool { return q.conn == nil || q.conn.IsClosed() } +// rabbitMQSubscription reopens the underlying subscription after its connection +// closes, since a gocloud subscription stays in a permanent error state once its +// connection is gone. +type rabbitMQSubscription struct { + queue *RabbitMQQueue + mu sync.Mutex + conn *amqp091.Connection + subscription *pubsub.Subscription + shutdown bool +} + +var _ Subscription = &rabbitMQSubscription{} + +// Receive returns the error that revealed a dropped connection after +// resubscribing, so the caller's backoff still applies to the reconnect. +func (s *rabbitMQSubscription) Receive(ctx context.Context) (*Message, error) { + s.mu.Lock() + conn, subscription := s.conn, s.subscription + s.mu.Unlock() + + msg, err := subscription.Receive(ctx) + if err != nil { + if conn.IsClosed() { + s.resubscribe(subscription) + } + return nil, err + } + return &Message{ + QueueMessage: msg, + LoggableID: msg.LoggableID, + Body: msg.Body, + }, nil +} + +func (s *rabbitMQSubscription) resubscribe(dead *pubsub.Subscription) { + s.mu.Lock() + defer s.mu.Unlock() + // Another Receive may have already replaced it. + if s.shutdown || s.subscription != dead { + return + } + _, conn, err := s.queue.ensureConnected() + if err != nil { + return + } + s.conn = conn + s.subscription = rabbitpubsub.OpenSubscription(conn, s.queue.config.Queue, nil) + go dead.Shutdown(context.Background()) +} + +func (s *rabbitMQSubscription) Shutdown(ctx context.Context) error { + s.mu.Lock() + s.shutdown = true + subscription := s.subscription + s.mu.Unlock() + return subscription.Shutdown(ctx) +} + func NewRabbitMQQueue(config *RabbitMQConfig) *RabbitMQQueue { return &RabbitMQQueue{config: config, base: newWrappedBaseQueue()} } diff --git a/internal/mqs/queue_rabbitmq_test.go b/internal/mqs/queue_rabbitmq_test.go index daac3fc2a..4dd29b8c1 100644 --- a/internal/mqs/queue_rabbitmq_test.go +++ b/internal/mqs/queue_rabbitmq_test.go @@ -5,6 +5,7 @@ import ( "testing" "time" + "github.com/hookdeck/outpost/internal/consumer" "github.com/hookdeck/outpost/internal/mqs" "github.com/hookdeck/outpost/internal/util/testinfra" "github.com/stretchr/testify/require" @@ -63,3 +64,94 @@ func TestIntegrationMQ_RabbitMQPublishReconnects(t *testing.T) { require.NoError(t, queue.Publish(ctx, &Msg{ID: "after-disconnect"})) require.Equal(t, "after-disconnect", receive(t).ID) } + +func TestIntegrationMQ_RabbitMQSubscriptionReconnects(t *testing.T) { + t.Parallel() + t.Cleanup(testinfra.Start(t)) + config := testinfra.NewMQRabbitMQConfig(t) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + queue := mqs.NewQueue(&config) + cleanup, err := queue.Init(ctx) + require.NoError(t, err) + defer cleanup() + + subscription, err := queue.Subscribe(ctx) + require.NoError(t, err) + + received := make(chan string, 10) + csm := consumer.New(subscription, handlerFunc(func(ctx context.Context, msg *mqs.Message) error { + msg.Ack() + parsed := &Msg{} + if err := parsed.FromMessage(msg); err != nil { + return err + } + received <- parsed.ID + return nil + }), + consumer.WithConcurrency(5), + consumer.WithMaxConsecutiveErrors(3), + consumer.WithInitialBackoff(50*time.Millisecond), + ) + runErr := make(chan error, 1) + go func() { runErr <- csm.Run(ctx) }() + + // Messages whose ack was lost with the connection are redelivered, so + // skip anything that isn't the expected ID. + awaitMessage := func(id string) { + t.Helper() + timeout := time.After(10 * time.Second) + for { + select { + case got := <-received: + if got == id { + return + } + case err := <-runErr: + t.Fatalf("consumer exited: %v", err) + case <-timeout: + t.Fatalf("timed out waiting for %s", id) + } + } + } + + require.NoError(t, queue.Publish(ctx, &Msg{ID: "before-disconnect"})) + awaitMessage("before-disconnect") + + // Simulate the broker dropping the connection. + require.NoError(t, mqs.ForceCloseRabbitMQConnection(queue)) + + require.NoError(t, queue.Publish(ctx, &Msg{ID: "after-disconnect"})) + awaitMessage("after-disconnect") + + cancel() + require.ErrorIs(t, <-runErr, context.Canceled) +} + +type handlerFunc func(ctx context.Context, msg *mqs.Message) error + +func (f handlerFunc) Handle(ctx context.Context, msg *mqs.Message) error { return f(ctx, msg) } + +func TestIntegrationMQ_RabbitMQNoRedialAfterCleanup(t *testing.T) { + t.Parallel() + t.Cleanup(testinfra.Start(t)) + config := testinfra.NewMQRabbitMQConfig(t) + + ctx := context.Background() + queue := mqs.NewQueue(&config) + cleanup, err := queue.Init(ctx) + require.NoError(t, err) + + subscription, err := queue.Subscribe(ctx) + require.NoError(t, err) + defer subscription.Shutdown(ctx) + + cleanup() + + receiveCtx, cancel := context.WithTimeout(ctx, 5*time.Second) + defer cancel() + _, err = subscription.Receive(receiveCtx) + require.Error(t, err) + require.True(t, mqs.RabbitMQConnectionClosed(queue), "queue redialed after cleanup") +}