fix(platform): PAYMENTS-11727 Deliver metrics pushed from inside a Resque job

.circleci/config.yml

@@ -51,6 +51,22 @@ workflows:
           <<: *ruby_3_4_defaults
           name: ruby-3_4-rspec_unit
           db: false
+      # Forks real Resque children against a redis, so it is opt-in and excluded from the run above. The ruby executor
+      # already provides redis on localhost:6379, which is where the specs look by default.
+      #
+      # One ruby version is enough: what it exercises is fork and HTTP behaviour rather than anything version
+      # specific, and forking a few hundred children per version buys nothing. 3.4 matches the consuming service.
+      - ruby/rspec-unit:
+          <<: *ruby_3_4_defaults
+          name: ruby-3_4-rspec_fork_integration
+          db: false
+          code-climate: false
+          report-code-coverage: false
+          additional_args: "spec/integration"
+          pre-exec-hooks:
+            - run:
+                name: Enable the fork integration specs
+                command: echo 'export FORK_INTEGRATION=1' >> "$BASH_ENV"
   ruby_4_0:
     jobs:
       - ruby/bundle-audit:

.rubocop.yml

@@ -20,6 +20,11 @@ Lint/AmbiguousOperator:
 Layout/LineLength:
   Enabled: false
 
+# Client carries the delivery path: the queue, the lock, the timeouts and the reporting. Cohesive rather than long,
+# and splitting it would mean handing a collaborator most of the client's state.
+Metrics/ClassLength:
+  Max: 120
+
 Metrics/MethodLength:
   Max: 20
 

CHANGELOG.md

@@ -1,5 +1,14 @@
 Changelog for the bc-prometheus-ruby gem.
 
+## 0.8.4
+
+- Reset the Prometheus client in forked Resque children via `Resque.after_fork`. A child previously inherited a copy of the parent's undrained outbound queue and had to re-send every message in it before reaching its own, which Resque's `exit!` cut short. Observations pushed from inside a job were dropped as a result.
+- Deliver a forked Resque child's own queued metrics before the child exits, by wrapping `Resque::Worker#perform`. Pushing only queues, and `exit!` does not wait for the thread that would deliver it, so metrics pushed from inside a job were unreliable regardless of the above. Costs one request per job that pushed something and nothing for jobs that did not. Disable with `PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=0`.
+- Serialise delivery to the collector on its own mutex, so a flush cannot return while the background thread still has a message in flight. An empty queue is not an empty wire: the worker thread pops before it sends, and a child exiting in that window destroyed the request. Also removes a hang where both threads saw one queued message, both called `pop`, and the loser blocked forever.
+- Bound the connect, response and write timeouts when delivering to the collector, configurable via `PROMETHEUS_CLIENT_OPEN_TIMEOUT`, `PROMETHEUS_CLIENT_READ_TIMEOUT` and `PROMETHEUS_CLIENT_WRITE_TIMEOUT`. `Net::HTTP` defaults all three to 60 seconds, which an unhealthy collector could previously impose on the caller.
+- Bound a flush to `PROMETHEUS_CLIENT_FLUSH_TIMEOUT`, 20ms by default, covering the wait for the delivery lock as well as the requests. A forked child holds up real work while it delivers, so an unhealthy collector now costs it a known amount rather than however long the network takes to give up. Past the deadline the observations are abandoned, because availability of the work matters more than completeness of its metrics.
+- Report abandoned observations, and push the warning out of the process before `exit!` destroys it. A line written to a buffered STDOUT in a Resque child never reaches the log, so the buffers are flushed after warning rather than left to an exit that runs no handlers.
+
 ## 0.8.3
 
 - Add opt-in per-Resque-job histograms `resque_job_queue_latency_seconds` and `resque_job_perform_duration_seconds`, labelled by `job_class`.

Gemfile

@@ -26,4 +26,13 @@ gem 'rubocop-performance', '>= 1.5'
 gem 'rubocop-rspec'
 gem 'simplecov', '>= 0.16'
 
+# Resque is an optional integration, but its fork-per-job lifecycle is the one thing the client has to survive, so the
+# integration needs real coverage rather than stubs.
+#
+# Resque depends on sinatra for its web UI with a loose `>= 0.9.2`. There is no Gemfile.lock in this repo, so CI
+# resolves cold and the resolver is free to pick an old sinatra that caps `rack < 3`, which conflicts with the
+# gemspec's `rack >= 3.0`. Pinning sinatra forward keeps the resolution rack-3 compatible.
+gem 'resque', '>= 2.0'
+gem 'sinatra', '>= 4.0'
+
 gemspec

README.md

@@ -43,6 +43,60 @@ require 'bigcommerce/prometheus'
 Bigcommerce::Prometheus::Instrumentors::Resque.new(app: Rails.application).start
 ```
 
+### Metrics pushed from inside a job
+
+Resque runs each job in a forked child that ends with `exit!`, which runs no at_exit handlers and does not wait for
+threads. Pushing a metric only queues it; delivery happens on a background thread that wakes every
+`client_thread_sleep` seconds. A child that pushes and then returns is normally torn down before that thread runs, so
+the observation is silently discarded.
+
+Two things are done automatically to make an in-child push arrive:
+
+- The child is given a clean client queue at fork time, via `Resque.after_fork`. Without this it would inherit a copy
+  of whatever the parent had not yet drained and have to re-send all of it before reaching its own message.
+- The child delivers its own queue on the calling thread before the job returns, by wrapping
+  `Resque::Worker#perform`. Delivery is serialised against the background thread, so a request already in progress
+  finishes before the child exits rather than being destroyed with it.
+
+Cost is one request to the local collector per job that pushed something, and nothing at all for jobs that pushed
+nothing. Disable with `PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=0` if a service would rather have the throughput and can
+accept the loss.
+
+A job is real work, and it should not wait on the metrics pipeline for long. Delivery is therefore bounded by
+`PROMETHEUS_CLIENT_FLUSH_TIMEOUT`, 20ms by default, covering the wait for the delivery lock as well as the requests
+themselves. An unhealthy collector costs a job that much and no more. Past the deadline the observations are abandoned
+and a warning is logged saying how many, which is the only signal you will get, since the metric that would have
+reported the outage is the one being lost.
+
+Note that this applies to metrics your application code pushes from inside a job. The per-job histograms below are
+recorded in the parent and never pay this cost.
+
+### Measuring delivery and cost
+
+`bin/resque_fork_bench` forks real children against a real redis and a real listener, and reports how many of the
+observations pushed inside a job arrived and how much slower the job got. It needs a redis and takes tens of seconds, so
+it is a manual tool rather than part of `script/test`.
+
+```bash
+redis-server --port 6399 --save '' --appendonly no --daemonize yes
+
+REDIS_URL=redis://127.0.0.1:6399/15 bin/resque_fork_bench --smoke-test
+```
+
+`--smoke-test` sweeps a representative spread of job shapes. A single shape can be measured directly instead, varying
+how many metrics the job pushes, how much work separates them, and how much work follows the last one:
+
+```bash
+bin/resque_fork_bench --pushes 2 --gap 0.05      # two pushes, 50ms apart
+bin/resque_fork_bench --pushes 1 --trailing 0.01 # one push, then 10ms of work
+bin/resque_fork_bench --smoke-test --no-child-flush
+```
+
+Read the total column rather than the overhead column. Overhead subtracts a control run that performed the same sleeps,
+so it hides any part of a wait that overlapped the job's own work. `--help` lists the rest, including
+`--thread-sleep` for the drain cadence and `--redis-url`. Exits non-zero if any row lost an observation or exceeded the
+overhead budget the integration specs enforce.
+
 ### Per-job metrics (opt-in)
 
 Set `PROMETHEUS_RESQUE_PER_JOB_METRICS_ENABLED=1` on Resque worker pods to enable two additional histograms recorded from the parent worker process.
@@ -67,13 +121,18 @@ After requiring the main file, you can further configure with:
 | client_custom_labels | A hash of custom labels to send with each client request | `{}` | None |
 | client_max_queue_size | The max amount of metrics to send before flushing | `10000` | `ENV['PROMETHEUS_CLIENT_MAX_QUEUE_SIZE']` |
 | client_thread_sleep | How often to sleep the worker thread that manages the client buffer (seconds) | `0.5` | `ENV['PROMETHEUS_CLIENT_THREAD_SLEEP']` |
+| client_open_timeout | Connect timeout when delivering to the collector (seconds) | `0.5` | `ENV['PROMETHEUS_CLIENT_OPEN_TIMEOUT']` |
+| client_read_timeout | Response timeout when delivering to the collector (seconds) | `1.0` | `ENV['PROMETHEUS_CLIENT_READ_TIMEOUT']` |
+| client_write_timeout | Send timeout when delivering to the collector (seconds) | `0.5` | `ENV['PROMETHEUS_CLIENT_WRITE_TIMEOUT']` |
+| client_flush_timeout | Total a synchronous flush will spend before abandoning what is queued (seconds) | `0.02` | `ENV['PROMETHEUS_CLIENT_FLUSH_TIMEOUT']` |
 | puma_collection_frequency | How often to poll puma collection metrics (seconds) | `30` | `ENV['PROMETHEUS_PUMA_COLLECTION_FREQUENCY']` |
 | server_host | The host to run the exporter on | `"0.0.0.0"` | `ENV['PROMETHEUS_SERVER_HOST']` |
 | server_port | The port to run the exporter on | `9394` | `ENV['PROMETHEUS_SERVER_PORT']` |
 | server_thread_pool_size | The number of threads used for the exporter server | `3` | `ENV['PROMETHEUS_SERVER_THREAD_POOL_SIZE']` |
 | process_name | What the current process name is (used in logging) | `"unknown"` | `ENV['PROCESS']` |
 | railtie_disabled | Opt out flag for Railtie; use `Bigcommerce::Prometheus::Instrumentors::Web.new(app: Rails.application).start` in your app's code to start it up yourself  | `0` | `ENV['PROMETHEUS_DISABLE_RAILTIE']` |
 | resque_per_job_metrics_enabled | Enable per-job queue-latency and perform-duration histograms (parent-side, no synchronous flush) | `0` | `ENV['PROMETHEUS_RESQUE_PER_JOB_METRICS_ENABLED']` |
+| resque_child_flush_enabled | Deliver a forked child's own queued metrics before Resque exits it | `1` | `ENV['PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED']` |
 
 ## Custom Collectors