From f87af5e503d8eecd3026d66af93ce440d8d9ed45 Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Tue, 23 Jun 2026 17:51:16 -0400 Subject: [PATCH 1/8] test: producer-to-collector routing on pg_stat_ch.block_format MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes the producer-side contract gap: the unified Arrow exporter emits pg_stat_ch.block_format=arrow_events_raw on its OTLP envelope, while the legacy ArrowBatchBuilder path emits arrow_ipc. The central OTel collector's routingconnector is supposed to fan batches between the legacy query_logs_arrow target and the new events_raw target based on that marker. This test pins the producer half of the contract. New TAP test t/037_arrow_routing.pl exercises both arms: - arm 1 (unified=off, arrow_passthrough=on): legacy.jsonl grows, events_raw.jsonl and default.jsonl don't. - arm 2 (unified=on): events_raw.jsonl grows with arrow_events_raw in the routed payload, legacy.jsonl and default.jsonl don't. Stock otelcol-contrib image (matches existing t/024 setup, version 0.120.0). Routingconnector keyed on the resource attribute (where pg_stat_ch.block_format lives via PopulateResource), two file exporters writing JSONL to a bind-mounted dir the test reads from. No CH receiver — the events_raw column-set contract isn't validated here; that's covered by t/036 (producer Arrow IPC -> direct CH ingest) and by a separate receiver-faithful test in clickgres-platform. New helpers in t/psch.pm (psch_routing_collector_available, psch_start_routing_collector, psch_stop_routing_collector) live on a separate compose profile + container/ports so the new test can coexist with t/024's collector if both fire in the same suite. Co-Authored-By: Claude Opus 4.7 (1M context) --- docker/docker-compose.arrow-route.yml | 23 +++ docker/otel-routing/collector-config.yaml | 69 +++++++++ docker/otel-routing/output/.gitignore | 2 + t/037_arrow_routing.pl | 178 ++++++++++++++++++++++ t/psch.pm | 45 ++++++ 5 files changed, 317 insertions(+) create mode 100644 docker/docker-compose.arrow-route.yml create mode 100644 docker/otel-routing/collector-config.yaml create mode 100644 docker/otel-routing/output/.gitignore create mode 100644 t/037_arrow_routing.pl diff --git a/docker/docker-compose.arrow-route.yml b/docker/docker-compose.arrow-route.yml new file mode 100644 index 0000000..bc487fc --- /dev/null +++ b/docker/docker-compose.arrow-route.yml @@ -0,0 +1,23 @@ +# Standalone collector profile for t/037_arrow_routing.pl. Kept separate +# from docker-compose.otel.yml (which serves t/024_otel_export.pl) so the +# two tests can run concurrently — different ports + container names. +# +# Output JSONL files land in ./otel-routing/output/, bind-mounted into the +# container at /output. The test cleans this directory before each run. + +services: + routing-otelcol: + image: otel/opentelemetry-collector-contrib:0.120.0 + container_name: psch-routing-otelcol + command: ["--config=/etc/otelcol-contrib/config.yaml"] + volumes: + - ./otel-routing/collector-config.yaml:/etc/otelcol-contrib/config.yaml + - ./otel-routing/output:/output + ports: + - "14317:4317" # gRPC OTLP receiver (host:14317 so it doesn't clash with otel-test's 4317) + - "23133:13133" # Health check HTTP endpoint + healthcheck: + test: ["CMD", "wget", "--no-verbose", "--tries=1", "--spider", "http://localhost:13133/"] + interval: 5s + timeout: 5s + retries: 10 diff --git a/docker/otel-routing/collector-config.yaml b/docker/otel-routing/collector-config.yaml new file mode 100644 index 0000000..aab82ae --- /dev/null +++ b/docker/otel-routing/collector-config.yaml @@ -0,0 +1,69 @@ +# Minimum-faithful OTel collector config for the producer-to-collector +# routing test (t/037_arrow_routing.pl). +# +# Mirrors the SHAPE of the prod datagres-otelcol pipeline (routing connector +# fanning Arrow batches between the legacy query_logs_arrow target and the new +# events_raw target based on the pg_stat_ch.block_format resource attribute) +# but with stdout/file sinks instead of real receivers. The test asserts that +# routing decisions match the producer-side marker emission contract — it does +# NOT validate any downstream wire format. That's covered by: +# - t/036_unified_arrow_e2e.pl (producer Arrow IPC -> direct curl into CH) +# - clickgres-platform's receiver-faithful e2e test (producer -> real +# datagres-arrow-exporter -> CH events_raw) + +receivers: + otlp: + protocols: + grpc: + endpoint: 0.0.0.0:4317 + +connectors: + routing: + # Default pipeline catches anything that doesn't match a routing rule. + # In the test we treat hits on the default pipeline as routing failures + # (the producer should always emit one of the two known marker values). + default_pipelines: [logs/default] + error_mode: ignore + table: + - context: resource + statement: route() where attributes["pg_stat_ch.block_format"] == "arrow_events_raw" + pipelines: [logs/events_raw] + - context: resource + statement: route() where attributes["pg_stat_ch.block_format"] == "arrow_ipc" + pipelines: [logs/legacy] + +exporters: + # JSONL sinks — one file per route. Tests parse these directly to assert + # that batches landed on the expected pipeline. + file/legacy: + path: /output/legacy.jsonl + file/events_raw: + path: /output/events_raw.jsonl + file/default: + path: /output/default.jsonl + # Keep one stdout sink for easier debugging when a test fails locally. + debug: + verbosity: basic + +extensions: + health_check: + endpoint: 0.0.0.0:13133 + +service: + extensions: [health_check] + pipelines: + # Ingress: receive OTLP gRPC and hand off to the routing connector. + logs/in: + receivers: [otlp] + exporters: [routing] + # Routed legs. Each pipeline takes its input from the connector and + # writes to a dedicated file plus the shared debug stdout. + logs/legacy: + receivers: [routing] + exporters: [file/legacy, debug] + logs/events_raw: + receivers: [routing] + exporters: [file/events_raw, debug] + logs/default: + receivers: [routing] + exporters: [file/default, debug] diff --git a/docker/otel-routing/output/.gitignore b/docker/otel-routing/output/.gitignore new file mode 100644 index 0000000..d6b7ef3 --- /dev/null +++ b/docker/otel-routing/output/.gitignore @@ -0,0 +1,2 @@ +* +!.gitignore diff --git a/t/037_arrow_routing.pl b/t/037_arrow_routing.pl new file mode 100644 index 0000000..cd92319 --- /dev/null +++ b/t/037_arrow_routing.pl @@ -0,0 +1,178 @@ +#!/usr/bin/env perl +# Test: producer-to-collector routing on pg_stat_ch.block_format. +# +# Validates the producer-side half of the Arrow exporter migration contract: +# the central OTel collector's routingconnector must be able to fan batches +# between the legacy (query_logs_arrow) receiver path and the new (events_raw) +# receiver path based on a self-identifying attribute the producer emits. +# +# This is the "generic" routing test — no CH receiver, no datagres-arrow-exporter. +# Stock otelcol-contrib with two file sinks instead. Catches: +# - Producer-side regression in pg_stat_ch.block_format emission +# (e.g. unified path accidentally falling back to "arrow_ipc") +# - Routingconnector config-shape drift (e.g. attribute name typo, OTTL +# statement that no longer matches) +# - OTLP-side serialization regressions that would make the marker +# unreachable to a routing connector matching on resource attributes +# +# Does NOT validate the events_raw column-set contract or the receiver's +# wire-format expectations — those live behind the datagres-arrow-exporter +# in clickgres-platform and are covered by a separate test there. +# +# Flow: +# 1. Spin up the routing collector via docker compose (otel-routing profile). +# 2. Start a node configured to ship to it; first with the unified GUC OFF, +# then OFF + with otel_arrow_passthrough so the legacy ArrowBatchBuilder +# path fires; finally with the unified GUC ON. +# 3. Wait for JSONL files in docker/otel-routing/output/ and assert each +# arm landed where expected based on the marker value. + +use strict; +use warnings; +use lib 't'; +use Test::More; +use Time::HiRes qw(sleep time); + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use psch; + +if (!psch_routing_collector_available()) { + # Try to bring it up; the helper dies if Docker isn't available. + eval { psch_start_routing_collector() }; + if ($@) { + plan skip_all => "Docker / routing collector not available: $@"; + } +} + +my $project_dir = $ENV{PROJECT_DIR} // '.'; +my $output_dir = "$project_dir/docker/otel-routing/output"; + +# ---------------------------------------------------------------------------- +# Helper: spin up a pg_stat_ch node configured to ship to the routing +# collector. Caller picks which GUC combination to enable. +# ---------------------------------------------------------------------------- +sub start_node { + my ($name, %opts) = @_; + my $arrow_passthrough = $opts{arrow_passthrough} // 'off'; + my $unified = $opts{unified} // 'off'; + + my $node = PostgreSQL::Test::Cluster->new($name); + $node->init(); + $node->append_conf('postgresql.conf', qq{ +shared_preload_libraries = 'pg_stat_ch' +pg_stat_ch.enabled = on +pg_stat_ch.queue_capacity = 65536 +pg_stat_ch.flush_interval_ms = 100 +pg_stat_ch.batch_max = 100 +pg_stat_ch.use_otel = on +pg_stat_ch.otel_endpoint = 'localhost:14317' +pg_stat_ch.otel_arrow_passthrough = $arrow_passthrough +pg_stat_ch.use_unified_arrow_exporter = $unified +pg_stat_ch.hostname = 'routing-test-host' +}); + $node->start(); + $node->safe_psql('postgres', 'CREATE EXTENSION pg_stat_ch'); + return $node; +} + +# Truncate-equivalent: remove any JSONL the collector wrote on a previous arm +# of this test. The collector keeps writing into the same file across pg +# clusters, so we have to snapshot byte-offsets per arm and only consider the +# tail. +sub current_size { + my ($path) = @_; + return -e $path ? (-s $path) : 0; +} + +# Wait until file size at $path grows past $baseline, or timeout. Returns the +# new size on success, undef on timeout. +sub wait_for_growth { + my ($path, $baseline, $timeout_s) = @_; + my $deadline = time() + $timeout_s; + while (time() < $deadline) { + my $size = current_size($path); + return $size if $size > $baseline; + sleep(0.2); + } + return undef; +} + +# ---------------------------------------------------------------------------- +# Arm 1: legacy ArrowBatchBuilder path (unified=off, arrow_passthrough=on). +# Producer should emit pg_stat_ch.block_format=arrow_ipc; routingconnector +# fans to logs/legacy -> file/legacy. Other files should NOT grow. +# ---------------------------------------------------------------------------- +{ + my $legacy_before = current_size("$output_dir/legacy.jsonl"); + my $events_raw_before = current_size("$output_dir/events_raw.jsonl"); + my $default_before = current_size("$output_dir/default.jsonl"); + + my $node = start_node('routing_legacy_arm', + arrow_passthrough => 'on', unified => 'off'); + $node->safe_psql('postgres', 'SELECT 1 AS legacy_arm_marker'); + $node->safe_psql('postgres', 'SELECT pg_stat_ch_flush()'); + + my $legacy_after = wait_for_growth("$output_dir/legacy.jsonl", $legacy_before, 15); + ok(defined $legacy_after, + 'arm 1 (arrow_ipc): legacy.jsonl received bytes after producer flush'); + + my $events_raw_after = current_size("$output_dir/events_raw.jsonl"); + is($events_raw_after, $events_raw_before, + 'arm 1 (arrow_ipc): events_raw.jsonl did NOT grow (routing kept it isolated)'); + + my $default_after = current_size("$output_dir/default.jsonl"); + is($default_after, $default_before, + 'arm 1 (arrow_ipc): default.jsonl did NOT grow (no unmatched batches)'); + + $node->stop(); +} + +# ---------------------------------------------------------------------------- +# Arm 2: unified path (unified=on). Producer should emit +# pg_stat_ch.block_format=arrow_events_raw; routingconnector fans to +# logs/events_raw -> file/events_raw. Legacy file should NOT grow. +# ---------------------------------------------------------------------------- +{ + my $legacy_before = current_size("$output_dir/legacy.jsonl"); + my $events_raw_before = current_size("$output_dir/events_raw.jsonl"); + my $default_before = current_size("$output_dir/default.jsonl"); + + my $node = start_node('routing_unified_arm', + arrow_passthrough => 'on', unified => 'on'); + $node->safe_psql('postgres', 'SELECT 2 AS unified_arm_marker'); + $node->safe_psql('postgres', 'SELECT pg_stat_ch_flush()'); + + my $events_raw_after = + wait_for_growth("$output_dir/events_raw.jsonl", $events_raw_before, 15); + ok(defined $events_raw_after, + 'arm 2 (arrow_events_raw): events_raw.jsonl received bytes after producer flush'); + + my $legacy_after = current_size("$output_dir/legacy.jsonl"); + is($legacy_after, $legacy_before, + 'arm 2 (arrow_events_raw): legacy.jsonl did NOT grow (routing kept it isolated)'); + + my $default_after = current_size("$output_dir/default.jsonl"); + is($default_after, $default_before, + 'arm 2 (arrow_events_raw): default.jsonl did NOT grow (no unmatched batches)'); + + # Spot-check the JSONL: extract the new bytes since this arm started and + # confirm the marker value appears. Catches a producer-side regression + # that emits the right ATTRIBUTE NAME but the wrong value (which + # routingconnector would catch by falling through to default — already + # asserted above — but the explicit content check pins the contract). + open my $fh, '<', "$output_dir/events_raw.jsonl" + or die "open events_raw.jsonl: $!"; + seek($fh, $events_raw_before, 0); + my $tail = do { local $/; <$fh> }; + close $fh; + like($tail, qr/arrow_events_raw/, + 'arm 2: marker value "arrow_events_raw" appears in the routed JSONL'); + unlike($tail, qr/arrow_ipc/, + 'arm 2: legacy marker "arrow_ipc" does NOT appear in events_raw arm'); + + $node->stop(); +} + +psch_stop_routing_collector(); +done_testing(); diff --git a/t/psch.pm b/t/psch.pm index 0fdf6cd..e6a3a53 100644 --- a/t/psch.pm +++ b/t/psch.pm @@ -25,6 +25,9 @@ our @EXPORT = qw( psch_init_node_with_otel psch_get_otel_histogram_total psch_otel_metric_has_label + psch_routing_collector_available + psch_start_routing_collector + psch_stop_routing_collector ); # Initialize a PostgreSQL node with pg_stat_ch loaded @@ -240,6 +243,48 @@ sub psch_stop_otelcol { system("docker compose -f $compose_file down -v"); } +# ============================================================================ +# Routing-collector helpers (t/037_arrow_routing.pl) +# ============================================================================ +# Separate from psch_*_otelcol because the routing test runs a distinct +# collector deployment (different ports, different config, file sinks +# instead of Prometheus). Both collectors can coexist if tests overlap. + +sub psch_routing_collector_available { + return 0 unless system("docker ps >/dev/null 2>&1") == 0; + my $result = `curl -sf 'http://localhost:23133/' 2>/dev/null`; + return $result =~ /Server available/; +} + +sub psch_start_routing_collector { + my $project_dir = $ENV{PROJECT_DIR} // '.'; + my $compose_file = "$project_dir/docker/docker-compose.arrow-route.yml"; + my $output_dir = "$project_dir/docker/otel-routing/output"; + + # Wipe the output directory so we don't read stale JSONL from a prior + # run. The directory itself is gitignored (with .gitignore preserved). + for my $f (glob("$output_dir/*.jsonl")) { + unlink $f; + } + + system("docker compose -f $compose_file up -d") == 0 + or die "Failed to start routing collector container"; + + for my $i (1..30) { + my $result = `curl -sf 'http://localhost:23133/' 2>/dev/null`; + return 1 if $result =~ /Server available/; + sleep(1); + } + die "Routing collector container failed to become healthy"; +} + +sub psch_stop_routing_collector { + my $project_dir = $ENV{PROJECT_DIR} // '.'; + my $compose_file = "$project_dir/docker/docker-compose.arrow-route.yml"; + + system("docker compose -f $compose_file down -v"); +} + # Initialize a node with OTel export enabled sub psch_init_node_with_otel { my ($name, %opts) = @_; From 4ca10bc5e1c0056ea93801d81ac0a4f5185959fc Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Thu, 23 Jul 2026 12:25:51 -0400 Subject: [PATCH 2/8] test: extend TLS reconnect timeout to cover worst-case backoff MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit t/013_clickhouse_tls.pl's reconnect subtest polled for the resumed export within 30s of restarting the ClickHouse container. The exporter's reconnect backoff (stats_exporter.cc PschGetRetryDelayMs) is exponential — base 1s, doubling per consecutive failure, capped at 60s. Failed flush attempts start accumulating as soon as CH goes down, well before the container finishes restarting, and the cumulative wait before the Nth retry is the sum of all prior delays: 1, 3, 7, 15, 31, 63, 123s. A restart slow enough to rack up 5-6 failures — plausible under a loaded CI runner — pushes the bgworker's next attempt past the 30s mark even though ClickHouse itself came back much sooner. Observed exactly this on CI twice in a row while rebasing PR #117 onto post-#116 main: identical assertion, identical 'got 0' failure, while the same commit had passed cleanly on a less-loaded run days earlier. Not a regression — the backoff constants and this test's timeout have coexisted; it just needed a slow enough runner to surface. Bump to 90s, comfortably past the 6-failure (63s) cumulative-backoff case plus round-trip margin. Co-Authored-By: Claude Opus 4.7 (1M context) --- t/013_clickhouse_tls.pl | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/t/013_clickhouse_tls.pl b/t/013_clickhouse_tls.pl index 18f4cde..8657d17 100644 --- a/t/013_clickhouse_tls.pl +++ b/t/013_clickhouse_tls.pl @@ -88,8 +88,18 @@ sub ch_tls_ready { $node->safe_psql('postgres', 'SELECT 200'); $node->safe_psql('postgres', 'SELECT pg_stat_ch_flush()'); + # 90s, not 30s: the exporter's reconnect backoff (stats_exporter.cc, + # PschGetRetryDelayMs) is exponential — base 1s, doubling per + # consecutive failure, capped at 60s. Failed flush attempts start + # accumulating the moment CH goes down (well before docker restart's + # container comes back), and the cumulative wait before the Nth retry + # is the sum of all prior delays: 1, 3, 7, 15, 31, 63, 123s... A CH + # restart slow enough to rack up 5-6 failures (very plausible under a + # loaded CI runner) pushes the bgworker's next attempt past the 30s + # mark even though CH itself came back much sooner. 90s comfortably + # covers the 63s (6-failure) cumulative-backoff case plus round-trip. my $after = psch_wait_for_clickhouse_query( - 'SELECT count() FROM pg_stat_ch.events_raw', sub { $_[0] >= 1 }, 30); + 'SELECT count() FROM pg_stat_ch.events_raw', sub { $_[0] >= 1 }, 90); cmp_ok($after, '>=', 1, "export resumed over TLS after reconnect (got $after)"); }; From 71ecff9bd05b58c86a7e327d22f108a75a66654b Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Thu, 23 Jul 2026 13:38:11 -0400 Subject: [PATCH 3/8] test: fix collector lifecycle leaks and strengthen routing assertions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Addresses review feedback (1 Copilot + 4 Cursor comments) on t/037_arrow_routing.pl, verified live via prove against a real build (not just code review): - Track whether this run started the routing collector ($started_routing_collector, set before the eval'd start attempt so a partial startup still counts). Only tear it down if so — a developer's manually-started collector, or one left behind by a crashed prior run, is left alone. - Move teardown into an END block (with 'local $?' to stop system() inside END from clobbering the script's exit code) so cleanup runs on every exit path: normal completion, plan skip_all, or a die() anywhere in the test body. Previously a die (e.g. the open-or-die below) skipped cleanup entirely, leaking the container and its fixed host ports (14317, 23133) -- ports t/026_arrow_dump.pl and t/036_unified_arrow_e2e.pl rely on being unbound. - Replace the bare 'open ... or die' on arm 2's spot-check with a Test::More SKIP block gated on whether the file actually grew, so a growth timeout produces a clean failed assertion instead of aborting the script mid-run. - Add per-arm producer-side bookkeeping (psch_wait_for_export + psch_get_stats asserting exported/send_failures), matching the existing t/024_otel_export.pl idiom, before the JSONL-growth checks. On failure this distinguishes 'producer never exported' from 'producer exported but routing/collector dropped it'. - Document the fixed-host-port single-instance-per-machine constraint in the header rather than parameterizing container/output naming: CI runs the TAP suite sequentially (prove without -j, single TAP job), and parameterizing names without also parameterizing the ports (14317/23133) wouldn't actually fix concurrent local runs while risking t/026 and t/036's assumption that those ports are unbound. Live-run verification surfaced a genuine pre-existing race unrelated to the above: the otelcol fileexporter writes a JSON line and its trailing newline as separate writes, and arm 1's node can flush trailing batches right up through stop(). If arm 2 snapshots its baselines mid-write, those late bytes get mis-attributed. Added wait_for_quiet() (polls combined JSONL size across all three files until stable for 1.5s, 15s cap) before arm 2's baselines to close the window. Confirmed via 3 live prove runs against a real build: one initial 11/12 run caught the race, then 12/12 with the collector auto-started (and torn down after), and 12/12 with the collector pre-started manually (and correctly left running after). Co-Authored-By: Claude Opus 4.7 (1M context) Co-Authored-By: Claude Fable 5 --- t/037_arrow_routing.pl | 105 ++++++++++++++++++++++++++++++++++++----- 1 file changed, 92 insertions(+), 13 deletions(-) diff --git a/t/037_arrow_routing.pl b/t/037_arrow_routing.pl index cd92319..f0c6f04 100644 --- a/t/037_arrow_routing.pl +++ b/t/037_arrow_routing.pl @@ -21,11 +21,18 @@ # # Flow: # 1. Spin up the routing collector via docker compose (otel-routing profile). -# 2. Start a node configured to ship to it; first with the unified GUC OFF, -# then OFF + with otel_arrow_passthrough so the legacy ArrowBatchBuilder -# path fires; finally with the unified GUC ON. +# 2. Start a node configured to ship to it, two arms: +# arm 1: unified GUC off + otel_arrow_passthrough on (legacy +# ArrowBatchBuilder path) +# arm 2: unified GUC on (new typed-column path) # 3. Wait for JSONL files in docker/otel-routing/output/ and assert each # arm landed where expected based on the marker value. +# +# Constraint: the routing collector binds fixed host ports (14317 OTLP gRPC, +# 23133 health) and a fixed output directory, so at most one instance of this +# test can run per machine. CI runs the TAP suite sequentially (prove without +# -j); two concurrent local runs of the suite would collide here regardless +# of container/output naming, because the port bindings are fixed. use strict; use warnings; @@ -37,14 +44,33 @@ use PostgreSQL::Test::Utils; use psch; +# Track whether THIS run started the collector. If it was already up (e.g. a +# developer brought it up manually for debugging, or a crashed prior run left +# it behind), leave it alone on exit. The flag is set before the start attempt +# so a partial startup (compose up succeeded, health check timed out) is still +# torn down. +my $started_routing_collector = 0; + if (!psch_routing_collector_available()) { # Try to bring it up; the helper dies if Docker isn't available. + $started_routing_collector = 1; eval { psch_start_routing_collector() }; if ($@) { plan skip_all => "Docker / routing collector not available: $@"; } } +# Runs on every exit path — normal completion, plan skip_all above, or a die() +# anywhere in the test body. Without this, a mid-test failure would leak the +# collector and its host ports (14317, 23133); t/026_arrow_dump.pl and +# t/036_unified_arrow_e2e.pl rely on nothing listening on 14317. +END { + # system() inside END sets $?, which would clobber the script's exit + # code; preserve it. + local $?; + psch_stop_routing_collector() if $started_routing_collector; +} + my $project_dir = $ENV{PROJECT_DIR} // '.'; my $output_dir = "$project_dir/docker/otel-routing/output"; @@ -85,6 +111,31 @@ sub current_size { return -e $path ? (-s $path) : 0; } +# Wait until the combined size of @paths has been stable for $stable_s +# seconds (returns 1), or $timeout_s elapsed (returns 0). Used between arms: +# the previous arm's node can flush trailing batches right up through its +# stop(), and the collector writes them asynchronously — the fileexporter +# even emits the JSON line and its trailing newline as separate writes. If +# the next arm snapshots its baselines mid-write, those late bytes get +# mis-attributed to it. +sub wait_for_quiet { + my ($stable_s, $timeout_s, @paths) = @_; + my $total = sub { my $t = 0; $t += current_size($_) for @paths; return $t }; + my $deadline = time() + $timeout_s; + my $last_size = $total->(); + my $stable_since = time(); + while (time() < $deadline) { + sleep(0.2); + my $size = $total->(); + if ($size != $last_size) { + $last_size = $size; + $stable_since = time(); + } + return 1 if time() - $stable_since >= $stable_s; + } + return 0; +} + # Wait until file size at $path grows past $baseline, or timeout. Returns the # new size on success, undef on timeout. sub wait_for_growth { @@ -113,6 +164,15 @@ sub wait_for_growth { $node->safe_psql('postgres', 'SELECT 1 AS legacy_arm_marker'); $node->safe_psql('postgres', 'SELECT pg_stat_ch_flush()'); + # Producer-side bookkeeping first: on failure this distinguishes + # "producer never exported" from "producer exported but the collector / + # routing dropped it" (same pattern as t/024_otel_export.pl). + my $exported = psch_wait_for_export($node, 1, 10); + cmp_ok($exported, '>=', 1, + 'arm 1 (arrow_ipc): producer reported exported events'); + my $stats = psch_get_stats($node); + is($stats->{send_failures}, 0, 'arm 1 (arrow_ipc): no send failures'); + my $legacy_after = wait_for_growth("$output_dir/legacy.jsonl", $legacy_before, 15); ok(defined $legacy_after, 'arm 1 (arrow_ipc): legacy.jsonl received bytes after producer flush'); @@ -134,6 +194,11 @@ sub wait_for_growth { # logs/events_raw -> file/events_raw. Legacy file should NOT grow. # ---------------------------------------------------------------------------- { + # Let arm 1's trailing collector writes settle before snapshotting this + # arm's baselines (see wait_for_quiet). + wait_for_quiet(1.5, 15, + map { "$output_dir/$_.jsonl" } qw(legacy events_raw default)); + my $legacy_before = current_size("$output_dir/legacy.jsonl"); my $events_raw_before = current_size("$output_dir/events_raw.jsonl"); my $default_before = current_size("$output_dir/default.jsonl"); @@ -143,6 +208,13 @@ sub wait_for_growth { $node->safe_psql('postgres', 'SELECT 2 AS unified_arm_marker'); $node->safe_psql('postgres', 'SELECT pg_stat_ch_flush()'); + # Producer-side bookkeeping first (see arm 1). + my $exported = psch_wait_for_export($node, 1, 10); + cmp_ok($exported, '>=', 1, + 'arm 2 (arrow_events_raw): producer reported exported events'); + my $stats = psch_get_stats($node); + is($stats->{send_failures}, 0, 'arm 2 (arrow_events_raw): no send failures'); + my $events_raw_after = wait_for_growth("$output_dir/events_raw.jsonl", $events_raw_before, 15); ok(defined $events_raw_after, @@ -161,18 +233,25 @@ sub wait_for_growth { # that emits the right ATTRIBUTE NAME but the wrong value (which # routingconnector would catch by falling through to default — already # asserted above — but the explicit content check pins the contract). - open my $fh, '<', "$output_dir/events_raw.jsonl" - or die "open events_raw.jsonl: $!"; - seek($fh, $events_raw_before, 0); - my $tail = do { local $/; <$fh> }; - close $fh; - like($tail, qr/arrow_events_raw/, - 'arm 2: marker value "arrow_events_raw" appears in the routed JSONL'); - unlike($tail, qr/arrow_ipc/, - 'arm 2: legacy marker "arrow_ipc" does NOT appear in events_raw arm'); + # Only meaningful if the file actually grew; on timeout the ok() above + # already failed and there is no tail to inspect. + SKIP: { + skip 'events_raw.jsonl never grew; no tail to spot-check', 2 + unless defined $events_raw_after; + open my $fh, '<', "$output_dir/events_raw.jsonl" + or die "open events_raw.jsonl: $!"; + seek($fh, $events_raw_before, 0); + my $tail = do { local $/; <$fh> }; + close $fh; + like($tail, qr/arrow_events_raw/, + 'arm 2: marker value "arrow_events_raw" appears in the routed JSONL'); + unlike($tail, qr/arrow_ipc/, + 'arm 2: legacy marker "arrow_ipc" does NOT appear in events_raw arm'); + } $node->stop(); } -psch_stop_routing_collector(); +# Collector teardown happens in the END block above (only if this run +# started it). done_testing(); From 8fe8ca907a5a6a01ac241f02e67a76d09ee057ff Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Tue, 28 Jul 2026 14:23:21 -0700 Subject: [PATCH 4/8] test: diagnose why the routing collector fails healthcheck in CI MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit t/037_arrow_routing.pl has skipped in every GitHub Actions CI run so far with only 'Routing collector container failed to become healthy' and no further detail. Locally, the exact same compose config starts and reports healthy in well under a second, and 'docker compose ... components' confirms the routing connector exists in this image version — ruling out a config bug or missing component. The failure appears specific to the GH-hosted runner environment, but there's been no way to tell why from the CI log alone. Dump 'docker compose ps' and 'docker compose logs' into the die message on healthcheck timeout, so the next occurrence (this one, on this push) actually carries diagnostic evidence instead of a bare 'failed to become healthy'. Also fixes a latent (currently harmless) bug found along the way: the service's Docker-level healthcheck used 'wget', which doesn't exist in the distroless otel/opentelemetry-collector-contrib image — it would always report unhealthy regardless of actual readiness. Doesn't affect today's behavior (psch_start_routing_collector polls host-side HTTP directly, independent of Docker's own healthcheck), but is misleading in 'docker compose ps' and would hang forever if anyone later adds '--wait' to the start command. Co-Authored-By: Claude Opus 4.7 (1M context) --- docker/docker-compose.arrow-route.yml | 13 ++++++++----- t/psch.pm | 12 +++++++++++- 2 files changed, 19 insertions(+), 6 deletions(-) diff --git a/docker/docker-compose.arrow-route.yml b/docker/docker-compose.arrow-route.yml index bc487fc..cdcd78d 100644 --- a/docker/docker-compose.arrow-route.yml +++ b/docker/docker-compose.arrow-route.yml @@ -16,8 +16,11 @@ services: ports: - "14317:4317" # gRPC OTLP receiver (host:14317 so it doesn't clash with otel-test's 4317) - "23133:13133" # Health check HTTP endpoint - healthcheck: - test: ["CMD", "wget", "--no-verbose", "--tries=1", "--spider", "http://localhost:13133/"] - interval: 5s - timeout: 5s - retries: 10 + # No Docker-level healthcheck: otel/opentelemetry-collector-contrib is a + # distroless image with no wget/curl/shell, so a CMD-based healthcheck + # can never succeed and would always report "unhealthy" regardless of + # actual readiness — misleading in `docker compose ps`, and a landmine + # for anyone who later adds `--wait` to the start command (would hang + # forever). Readiness is checked from the host via a real HTTP request + # in psch_start_routing_collector (t/psch.pm), independent of Docker's + # own healthcheck machinery. diff --git a/t/psch.pm b/t/psch.pm index e6a3a53..e805f8b 100644 --- a/t/psch.pm +++ b/t/psch.pm @@ -275,7 +275,17 @@ sub psch_start_routing_collector { return 1 if $result =~ /Server available/; sleep(1); } - die "Routing collector container failed to become healthy"; + + # Diagnostic dump before dying: this failure has been silent and + # reproducible in CI (not a flake) with no clue why, since the only + # prior signal was "container failed to become healthy" and nothing + # else. Capture container status + logs so the next occurrence is + # actually debuggable from the CI log alone. + my $ps = `docker compose -f $compose_file ps 2>&1`; + my $logs = `docker compose -f $compose_file logs 2>&1`; + die "Routing collector container failed to become healthy\n" . + "--- docker compose ps ---\n$ps" . + "--- docker compose logs ---\n$logs"; } sub psch_stop_routing_collector { From 2af93aa383f3bfab9f5efca7bd220491edac1277 Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Tue, 28 Jul 2026 14:33:24 -0700 Subject: [PATCH 5/8] fix: route routing-collector diagnostics through warn, not die message MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The prior commit folded 'docker compose ps'/'docker compose logs' output into the die message on healthcheck timeout, but that die message becomes the reason string for t/037_arrow_routing.pl's 'plan skip_all' — and TAP's protocol doesn't tolerate embedded newlines there. Test::More silently dropped everything past the first line, so the CI run that should have shown the diagnostics showed nothing new at all (confirmed: this exact commit's SHA ran in CI, zero trace of the dump anywhere in the log). Emit the dump via warn (STDERR) immediately before the die instead, decoupled from the skip reason string entirely. prove -v interleaves STDERR with STDOUT per test file, so this should show up inline in the CI log this time. Co-Authored-By: Claude Opus 4.7 (1M context) --- t/psch.pm | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/t/psch.pm b/t/psch.pm index e805f8b..cb7dee2 100644 --- a/t/psch.pm +++ b/t/psch.pm @@ -281,11 +281,17 @@ sub psch_start_routing_collector { # prior signal was "container failed to become healthy" and nothing # else. Capture container status + logs so the next occurrence is # actually debuggable from the CI log alone. + # + # Emitted via warn (STDERR), NOT folded into the die message: the die + # message becomes the reason string for the caller's `plan skip_all`, + # and TAP's protocol doesn't tolerate embedded newlines there — + # Test::More silently drops everything past the first line, which is + # exactly what ate the first attempt at this diagnostic. my $ps = `docker compose -f $compose_file ps 2>&1`; my $logs = `docker compose -f $compose_file logs 2>&1`; - die "Routing collector container failed to become healthy\n" . - "--- docker compose ps ---\n$ps" . - "--- docker compose logs ---\n$logs"; + warn "--- docker compose ps ($compose_file) ---\n$ps" . + "--- docker compose logs ($compose_file) ---\n$logs"; + die "Routing collector container failed to become healthy"; } sub psch_stop_routing_collector { From 0d06dff5133386db444e8d26af29b355ea048251 Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Tue, 28 Jul 2026 14:45:51 -0700 Subject: [PATCH 6/8] fix: use Test::More::diag for routing-collector diagnostics, not warn MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit warn (STDERR) didn't work either: confirmed empirically across two CI runs that plain STDERR output from a test ending in SKIP (rather than FAIL) never appears in prove -v's displayed output, even though the warn() call itself executes. diag() writes through Test::Builder's own output handle instead of raw STDERR, and prove -v documents showing diag() output regardless of the subtest's pass/fail/skip outcome. Verified locally with a throwaway script: a plan-skip_all test emitting a multi-line diag() shows every line, '#'-prefixed, under prove -v — exactly the behavior needed here. Co-Authored-By: Claude Opus 4.7 (1M context) --- t/psch.pm | 22 +++++++++++++++------- 1 file changed, 15 insertions(+), 7 deletions(-) diff --git a/t/psch.pm b/t/psch.pm index cb7dee2..a0b85e3 100644 --- a/t/psch.pm +++ b/t/psch.pm @@ -5,6 +5,7 @@ use strict; use warnings; use Exporter 'import'; use PostgreSQL::Test::Cluster; +use Test::More (); use Time::HiRes qw(sleep time); our @EXPORT = qw( @@ -282,15 +283,22 @@ sub psch_start_routing_collector { # else. Capture container status + logs so the next occurrence is # actually debuggable from the CI log alone. # - # Emitted via warn (STDERR), NOT folded into the die message: the die - # message becomes the reason string for the caller's `plan skip_all`, - # and TAP's protocol doesn't tolerate embedded newlines there — - # Test::More silently drops everything past the first line, which is - # exactly what ate the first attempt at this diagnostic. + # Two things ruled out before landing on Test::More::diag: + # 1. Folding this into the die message doesn't work: the die message + # becomes the reason string for the caller's `plan skip_all`, and + # TAP doesn't tolerate embedded newlines there — Test::More + # silently drops everything past the first line. + # 2. Plain `warn` (STDERR) doesn't show either: prove -v evidently + # doesn't surface a subtest's STDERR for one that ends in SKIP + # rather than FAIL. Confirmed empirically — a prior commit tried + # both and produced zero trace of the dump in two separate CI runs. + # diag() writes through Test::Builder's own output handle, which + # `prove -v` (verbose mode, already in use here) documents showing + # regardless of the subtest's pass/fail/skip outcome. my $ps = `docker compose -f $compose_file ps 2>&1`; my $logs = `docker compose -f $compose_file logs 2>&1`; - warn "--- docker compose ps ($compose_file) ---\n$ps" . - "--- docker compose logs ($compose_file) ---\n$logs"; + Test::More::diag("--- docker compose ps ($compose_file) ---\n$ps" . + "--- docker compose logs ($compose_file) ---\n$logs"); die "Routing collector container failed to become healthy"; } From f0eb1d13b1bdb70dda7010040920fb205136d58e Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Tue, 28 Jul 2026 14:57:54 -0700 Subject: [PATCH 7/8] fix: chmod routing collector output dir before starting the container MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Root cause found via the new Test::More::diag diagnostic: the otelcol-contrib container (runs as UID 10001 by default) crashed immediately on startup in every GitHub Actions CI run with error: open /output/legacy.jsonl: permission denied Error: cannot start pipelines: open /output/legacy.jsonl: permission denied On a fresh CI checkout, docker/otel-routing/output/ is owned by the runner account with default 0755 permissions. UID 10001 falls into the 'other' bucket, which gets r-x but not w on the bind-mounted directory, so the file exporter can't even create legacy.jsonl / events_raw.jsonl / default.jsonl. This is why t/037_arrow_routing.pl has skipped in literally every CI run since it was added: the collector never gets far enough to open its health-check port, so the 30x1s host-side curl poll always times out. Never reproduced locally: confirmed macOS's Docker Desktop/colima VM bind-mount layer doesn't enforce the same UID-based permission checks a real Linux host does (verified by force-running the container with --user 10001:10001 against a 0755-owned directory locally — started fine, unlike the real failure). The GH Actions runner is a real Linux host where these semantics apply for real. Fix: chmod the output dir to 0777 in psch_start_routing_collector right before 'docker compose up', rather than committing directory permission bits (which don't reliably survive git checkout across platforms/configs anyway). Self-healing every run; no risk since the directory holds only gitignored scratch test output. Co-Authored-By: Claude Opus 4.7 (1M context) --- t/psch.pm | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/t/psch.pm b/t/psch.pm index a0b85e3..aa6b4e1 100644 --- a/t/psch.pm +++ b/t/psch.pm @@ -268,6 +268,19 @@ sub psch_start_routing_collector { unlink $f; } + # otel/opentelemetry-collector-contrib runs as UID 10001 by default. On + # a fresh checkout the bind-mounted output dir is owned by whatever + # user checked the repo out (e.g. the CI runner account) with default + # 0755 permissions — UID 10001 falls into "other", which gets r-x but + # not w, so the container can't even create the .jsonl files (fails + # with "permission denied" and crashes before ever serving its health + # endpoint). chmod here rather than committing directory permissions: + # self-healing every run, and doesn't depend on guessing the CI + # runner's UID. The directory holds only scratch test output (gitignored, + # recreated every run), so world-writable carries no real risk. + chmod 0777, $output_dir + or die "Failed to chmod routing collector output dir ($output_dir): $!"; + system("docker compose -f $compose_file up -d") == 0 or die "Failed to start routing collector container"; From db1f9be67e6c72354af2ad99a3e3fdc52ed46031 Mon Sep 17 00:00:00 2001 From: Josh Ventura Date: Tue, 28 Jul 2026 16:01:07 -0700 Subject: [PATCH 8/8] test: address remaining Copilot/Cursor findings on the routing test MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three real, still-open findings from the review pass: 1. (Copilot) Header comment called the collector startup a compose 'profile' — it's a dedicated compose file, no --profile flag involved anywhere. Corrected the wording. 2. (Copilot + Cursor, duplicate findings) wait_for_quiet's return value was ignored at its one call site (settling between arm 1 and arm 2). If settling timed out, the test proceeded with unstable baselines instead of failing loudly. Wrapped in ok() so a timeout is now an explicit, attributable failure. 3. (Cursor) Isolation checks raced async writes: each arm calls wait_for_growth on its OWN expected file, then immediately snapshots the OTHER two files for the 'did NOT grow' assertions — with no settle time in between. A genuine misrouting bug whose erroneous write to another sink landed a moment late could race that snapshot and produce a false pass, defeating the entire point of the isolation check. Added a short wait_for_quiet on just the other two files (1s stable / 5s cap — narrower than the between-arms settle, since this is guarding against a fast erroneous write, not accommodating a slow legitimate one) before taking those snapshots, in both arms. Also fixed, Low severity (Cursor): arm 2's marker spot-check used 'open ... or die', so a transient reopen failure (the file's existence was already confirmed by the growth check, so this really would mean something changed underneath us) aborted the whole script instead of recording a failed assertion. Restructured as nested SKIP blocks — ok(open) now records pass/fail explicitly, and only the content checks that depend on a successful open get skipped if it fails. One further Copilot finding (t/psch.pm:315, healthcheck 30s vs compose's 50s) is now moot: the compose-level healthcheck it refers to was removed entirely in an earlier commit (wget doesn't exist in the distroless otelcol-contrib image, so it could never succeed regardless of timing) — replied and resolved on GitHub rather than included here since there's no code left for it to apply to. Syntax-checked (perl -c); could not get a live prove run in this local environment (pg_regress binary missing from a stale local install_tap tree, unrelated to this diff) — relying on CI, which has been the working verification loop all session for this file. Co-Authored-By: Claude Opus 4.7 (1M context) --- t/037_arrow_routing.pl | 58 ++++++++++++++++++++++++++++++++---------- 1 file changed, 44 insertions(+), 14 deletions(-) diff --git a/t/037_arrow_routing.pl b/t/037_arrow_routing.pl index f0c6f04..89c1e48 100644 --- a/t/037_arrow_routing.pl +++ b/t/037_arrow_routing.pl @@ -20,7 +20,9 @@ # in clickgres-platform and are covered by a separate test there. # # Flow: -# 1. Spin up the routing collector via docker compose (otel-routing profile). +# 1. Spin up the routing collector via docker compose +# (docker-compose.arrow-route.yml — a dedicated compose file, not a +# compose "profile"). # 2. Start a node configured to ship to it, two arms: # arm 1: unified GUC off + otel_arrow_passthrough on (legacy # ArrowBatchBuilder path) @@ -177,6 +179,14 @@ sub wait_for_growth { ok(defined $legacy_after, 'arm 1 (arrow_ipc): legacy.jsonl received bytes after producer flush'); + # Give a hypothetical misrouted write to the OTHER sinks a chance to + # land before asserting isolation. Without this, a genuine routing bug + # that writes to events_raw/default slightly after legacy.jsonl could + # race the snapshot below and produce a false pass. Only wait on the + # other two files — legacy already confirmed growth above. + ok(wait_for_quiet(1.0, 5, "$output_dir/events_raw.jsonl", "$output_dir/default.jsonl"), + 'arm 1: other sinks quiesced before isolation check'); + my $events_raw_after = current_size("$output_dir/events_raw.jsonl"); is($events_raw_after, $events_raw_before, 'arm 1 (arrow_ipc): events_raw.jsonl did NOT grow (routing kept it isolated)'); @@ -195,9 +205,13 @@ sub wait_for_growth { # ---------------------------------------------------------------------------- { # Let arm 1's trailing collector writes settle before snapshotting this - # arm's baselines (see wait_for_quiet). - wait_for_quiet(1.5, 15, - map { "$output_dir/$_.jsonl" } qw(legacy events_raw default)); + # arm's baselines (see wait_for_quiet). Asserted, not just called: if + # settling times out, the baselines below are unreliable and any + # isolation check built on them is meaningless — better to fail loudly + # here than produce a confusing downstream flake. + ok(wait_for_quiet(1.5, 15, + map { "$output_dir/$_.jsonl" } qw(legacy events_raw default)), + 'output files settled before arm 2 baselines'); my $legacy_before = current_size("$output_dir/legacy.jsonl"); my $events_raw_before = current_size("$output_dir/events_raw.jsonl"); @@ -220,6 +234,11 @@ sub wait_for_growth { ok(defined $events_raw_after, 'arm 2 (arrow_events_raw): events_raw.jsonl received bytes after producer flush'); + # See arm 1: give a hypothetical misrouted write to the other sinks a + # chance to land before asserting isolation. + ok(wait_for_quiet(1.0, 5, "$output_dir/legacy.jsonl", "$output_dir/default.jsonl"), + 'arm 2: other sinks quiesced before isolation check'); + my $legacy_after = current_size("$output_dir/legacy.jsonl"); is($legacy_after, $legacy_before, 'arm 2 (arrow_events_raw): legacy.jsonl did NOT grow (routing kept it isolated)'); @@ -236,17 +255,28 @@ sub wait_for_growth { # Only meaningful if the file actually grew; on timeout the ok() above # already failed and there is no tail to inspect. SKIP: { - skip 'events_raw.jsonl never grew; no tail to spot-check', 2 + skip 'events_raw.jsonl never grew; no tail to spot-check', 3 unless defined $events_raw_after; - open my $fh, '<', "$output_dir/events_raw.jsonl" - or die "open events_raw.jsonl: $!"; - seek($fh, $events_raw_before, 0); - my $tail = do { local $/; <$fh> }; - close $fh; - like($tail, qr/arrow_events_raw/, - 'arm 2: marker value "arrow_events_raw" appears in the routed JSONL'); - unlike($tail, qr/arrow_ipc/, - 'arm 2: legacy marker "arrow_ipc" does NOT appear in events_raw arm'); + + # A transient reopen failure here (permissions blip, filesystem + # hiccup) should record a failed assertion, not abort the whole + # script — the file's existence was already confirmed by the + # growth check above, so getting here means something changed + # between then and now, which is itself worth surfacing as a + # failure rather than a fatal die. + my $opened = open my $fh, '<', "$output_dir/events_raw.jsonl"; + SKIP2: { + ok($opened, 'arm 2: reopened events_raw.jsonl to spot-check marker'); + skip "could not reopen events_raw.jsonl: $!", 2 unless $opened; + + seek($fh, $events_raw_before, 0); + my $tail = do { local $/; <$fh> }; + close $fh; + like($tail, qr/arrow_events_raw/, + 'arm 2: marker value "arrow_events_raw" appears in the routed JSONL'); + unlike($tail, qr/arrow_ipc/, + 'arm 2: legacy marker "arrow_ipc" does NOT appear in events_raw arm'); + } } $node->stop();