PAYMENTS-11727 Deliver metrics recorded inside Resque jobs

[WillemHoman]

Jira: PAYMENTS-11727

Replaces #42, which was opened on a misspelled branch and closes as won't-merge.

What? Why?

Metrics recorded inside a Resque job were being dropped. Bigpay released 0.8.3 with
PROMETHEUS_RESQUE_PER_JOB_METRICS_ENABLED=1 and ruby_webhooks_published_counter fell to about 8% of normal on every
worker pod, recovering exactly on rollback. No webhooks were lost, no jobs failed and the queue never backed up. Only
the recording broke.

The fix everyone gets: the child no longer inherits the parent's queue

The client is a singleton and its queue is ordinary process memory, so fork copies it.
JobMetrics.record_queue_latency enqueues in the parent on the line immediately before super, which is the fork, so
every child inherited that message and had to re-send it, and anything else pending, before reaching its own. That
moved the survival threshold from about 2ms of post-record life to 25-50ms, and the webhook job sat between the two.

A Resque.after_fork hook now hands each child a clean client. Nothing is lost: the parent still holds the originals
and sends them on its own schedule. Unconditional, no configuration, no cost. This is the incident fix, and it is
the reason to take the bump even if you read no further.

The opt-in part: delivering what a job records

Recording only queues; delivery happens on a background thread that wakes every client_thread_sleep seconds. A Resque
child ends with exit!, which runs no at_exit handlers and kills threads outright, so an observation recorded near the
end of a job is destroyed with the child. That predates 0.8.3 and has always been costing observations quietly.

A prepend on Resque::Worker#perform, the in-child boundary, drains on the calling thread before the job returns.

Off by default. It costs one request per job that records something, and bumping this gem should not change how long
anybody's jobs take. Jobs that record nothing pay nothing either way. Enable with
PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=1, or by assigning resque_child_flush_enabled.

That default is a position rather than caution waiting to be undone: turning it on for everyone would change other
people's job latency, which is breaking and wants a version bump to match, as 0.4.0 did when the thread pool default
went from 20 to 3.

An empty queue is not an empty wire

Found by the bench below, on its first run. The flush originally returned early when nothing was queued, and the queue
reads as empty the instant the background thread pops the last message, well before it reaches the collector. exit!
then destroyed the request: roughly 0.1% to 0.3% of in-child records, silently, because the process that would have
logged it was already gone.

Confirmed at the socket layer, where the listener accepted every connection but read fewer complete requests, and the
shortfall matched its count of connections opened and then closed with no request line. Both drain paths are now
serialised on a delivery mutex, so a flush cannot return while a send is in flight. That also closes a hang where both
threads saw one queued message, both called pop, and the loser blocked forever.

A job should not wait long on the metrics pipeline

Making the child wait for delivery means it now waits for a collector that is not answering, and 0.8.3 has no such
exposure because nothing in a job's code path ever touched the network. Delivery is bounded by
PROMETHEUS_CLIENT_FLUSH_TIMEOUT, 20ms by default, covering the wait for the lock as well as the requests. Past it the
observations are abandoned, because availability of the work beats completeness of its metrics, and a warning says how
many.

Turning it on and off without a restart

resque_child_flush_enabled also accepts anything callable, asked in the parent before every fork. The child
inherits the answer through the fork, so a feature flag client never has to survive one, and nothing in a child ever
evaluates anything:

config.resque_child_flush_enabled = lambda do |job|
  MyFeatureFlags.enabled?('resque_child_metric_flush', queue: job.queue)
end

A callable taking an argument receives the Resque::Job, so a rollout can be gated per job as well as per process.
Anything it raises is treated as "do not flush", since it runs as a Resque.before_fork hook where an escaping
exception would stop the worker.

The env var supplies the default and an assignment overrides it, as with all 30 settings here, so a callable replaces
the env var rather than layering on top of it.

Also in here

• Bounded connect, response and write timeouts when delivering. Net::HTTP defaults all three to 60 seconds,
  survivable on a background thread and not survivable inline in a job.
• bin/resque_fork_bench, a manual tool that forks real children and reports both what arrived and what it cost, with
  a --smoke-test sweep and --collector healthy|stalled|down. Every measurement below came from it.
• resque and sinatra >= 4.0 as dev dependencies, the work deferred from PAYMENTS-11727 Resque latency metrics #31. Resque pulls sinatra with a loose
  constraint and, with no Gemfile.lock here, a cold CI resolve was free to pick a sinatra capping rack < 3 against
  the gemspec's rack >= 3.0.
• A boot log stating whether the flush is installed and whether it is static or resolved per fork, so the state can be
  confirmed during an incident rather than inferred.
• Release 0.8.4.

How was it tested?

spec/bigcommerce/prometheus/client_spec.rb covers #flush! and #reset_after_fork!: delivery on the calling
thread, never raising into the caller, waiting for an in-flight send, giving up on the deadline, bounded timeouts on
both paths, and clearing of the queue, worker thread, both mutexes and socket state. One example binds a real socket
that accepts and never answers, because a timeout cannot be asserted against a stub.

spec/bigcommerce/prometheus/integrations/resque_spec.rb covers resolving the setting in the parent: a plain
value, an arity-0 callable, an arity-1 callable receiving the job, an object with a #call method, and a raising
callable that returns false without propagating.

spec/bigcommerce/prometheus/integrations/resque/child_flush_spec.rb covers the in-child wrapper: flushes when the
parent enabled it, does not when it did not, does not on a non-forking worker, and still flushes when the job raises.

spec/integration/resque_fork_delivery_spec.rb is black box, forking real Resque children against a real listener.
It asserts two properties and deliberately mentions neither queues nor forks, because past changes have broken each
from opposite directions:

• Completeness. 100 jobs run, 100 observations arrive.
• Overhead. Per-job cost stays under budget, measured against an identical run with metrics disabled so machine speed
  cancels out.

Excluded from the default run and given its own job, ruby-3_4-rspec_fork_integration. The ruby executor already
provides redis, so no service needed adding.

None of it is vacuous, and each was checked by removing the fix:

property	without the fix
completeness	0 of 100 with the flush off
waits for an in-flight send	fails, the flusher thread is already dead
gives up on the deadline	5.01s against a stalled collector, fails < 1.0
accepts a callable object	fails, arity raises NoMethodError and is swallowed
overhead	56ms on the PAYMENTS-11567 approach, fails < 25ms

Measurements

The default is genuinely off, and the env var genuinely reaches the gem. 40 jobs recording one metric each:

configuration	delivered	per-job overhead
default	0/40	0.1 ms
PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=1	40/40	1.1 ms

Cost of serialising delivery, A/B on the same machine, medians of five runs at one push and three at five:

metrics recorded per job	before	after
1	1.4 ms	1.9 ms
5	3.2 ms	4.7 ms

Roughly half a millisecond on the shape bigpay runs. That is the calling thread paying for a request it previously
handed to a thread that was about to be killed.

Cost when the collector is not healthy, 50 jobs recording one metric each:

collector	per job	delivered
healthy	6.1 ms	50/50
dead, connection refused	5.1 ms	0/50
saturated, 20ms bound	27.8 ms	0/50
saturated, 1s bound	1011.8 ms	0/15

The last row is what the per-request timeouts alone would give. A dead collector costs nothing, since ECONNREFUSED is
immediate. Only a saturated one is expensive, and that is what the bound exists for.

The live switch, one process, 40 forks, callable flipped at job 20:

jobs run:            40
flush on for first:  20
observations landed: 20

Delivery followed the flag mid-run with no restart. The probe records and returns immediately, so nothing but the flush
could have delivered those 20.

Ruled out: was the collector simply overloaded?

Worth asking, because enabling per-job metrics makes the parent record two extra envelopes per job, so the endpoint
takes roughly three times the requests, and the fork reset does nothing about that.

sum(rate(ruby_collector_sessions_total{job="bigpay-worker"}[5m])) peaked at 85.7 requests per second across the
whole fleet, against 60 worker exporter instances, each with its own Puma pool of three threads. Under two
requests per second each. Even if one instance had absorbed the entire fleet's traffic it would still be under a tenth
of one thread. And ruby_collector_working reads 1 across all 46,252 samples, minimum and maximum identical.

On rollout, ruby_collector_sessions_total should roughly triple, from about one request per job to three. That rise is
the feature working. It is a symptom only if ruby_collector_working leaves 1 or ruby_collector_bad_metrics_total
starts climbing.

Proof against the two prior regressions

Two draft PRs run these specs against the releases they exist to catch, one property failing on each. Both are expected
to be red and are not for merge. Both need rebasing onto this branch name:

• PAYMENTS-11727 Proof: the fork delivery specs fail on 0.8.3 as released #43, 0.8.3 as released. Completeness fails at 0 of 100, overhead passes. This incident's signature: job time
  stayed flat while the observations went nowhere.
• PAYMENTS-11727 Proof: the fork delivery specs fail on the PAYMENTS-11567 flush approach #44, the PAYMENTS-11567 approach reconstructed. Completeness passes, overhead fails at 56ms. The mirror image:
  the observations arrived, they were just unaffordable.

Not covered

The specs cannot show loss caused by overloading the collector. CountingExporter is a bare TCPServer with a thread
per connection, so it absorbs far more than the real exporter. Acceptable at the rates above, and if that changes the
answer is to bind a real Bigcommerce::Prometheus::Server with a counting type collector rather than to teach the fake
one to imitate a thread pool.

A connection-reuse optimisation was written and measured, then dropped: the difference was inside run-to-run noise.