PAYMENTS-11727 Proof: the fork delivery specs fail on 0.8.3 as released

.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:

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

spec/integration/resque_fork_delivery_spec.rb

@@ -0,0 +1,147 @@
+# frozen_string_literal: true
+
+# Copyright (c) 2019-present, BigCommerce Pty. Ltd. All rights reserved
+#
+# Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated
+# documentation files (the "Software"), to deal in the Software without restriction, including without limitation the
+# rights to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the Software, and to permit
+# persons to whom the Software is furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included in all copies or substantial portions of the
+# Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE
+# WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+# COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR
+# OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+#
+require 'spec_helper'
+require 'resque'
+
+##
+# Pushes a metric as the final statement of the job, with nothing after it.
+#
+# This is the worst case and the shape that broke in production: once the push returns there is no further work, so
+# Resque's `exit!` follows immediately and anything relying on the background delivery thread is lost.
+#
+class ForkDeliveryProbeJob
+  METRIC_NAME = 'fork_delivery_probe_counter'
+  @queue = :bc_prometheus_fork_delivery
+
+  def self.perform(_payload)
+    Bigcommerce::Prometheus.client.send_json(
+      type: 'fork_delivery_probe',
+      name: METRIC_NAME,
+      value: 1.0
+    )
+  end
+end
+
+##
+# Black box: N jobs run, N observations arrive, and instrumentation does not blow out job time.
+#
+# Deliberately says nothing about queues, threads or forks. Both properties have been broken by past changes from
+# opposite directions. PAYMENTS-11567 met completeness by adding 480ms per job. PAYMENTS-11727 kept job time flat by
+# silently dropping the metrics. A change that satisfies one at the expense of the other should fail here.
+#
+# Forks real children and needs a redis, so it is excluded from the default run. To run it:
+#
+#   FORK_INTEGRATION=1 REDIS_URL=redis://127.0.0.1:6379/15 bundle exec rspec spec/integration
+#
+describe 'metric delivery from Resque forked children', :fork_integration do
+  JOB_COUNT = 100
+
+  # Per-job overhead the instrumentation is allowed to add, measured against an identical run with metrics off so the
+  # machine's own speed cancels out.
+  #
+  # Measured cost is 0.90ms per job, against 2.5ms for the same jobs with metrics disabled, so the budget sits about
+  # 27x above what this should take and about 19x below the 480ms regression it exists to catch. Wide on both sides,
+  # because a latency assertion on CI hardware has to be.
+  OVERHEAD_BUDGET_SECONDS = 0.025
+
+  let(:exporter) { CountingExporter.new.start }
+  let(:queue) { ForkDeliveryProbeJob.instance_variable_get(:@queue) }
+
+  before do
+    skip "redis unavailable at #{redis_url}" unless redis_available?
+
+    Resque.redis = Redis.new(url: redis_url)
+    Resque.redis.redis.flushdb
+    Resque.logger = Logger.new(File::NULL)
+
+    Bigcommerce::Prometheus.configure do |config|
+      config.enabled = true
+      config.logger = Logger.new(File::NULL)
+      config.server_host = '127.0.0.1'
+      config.server_port = exporter.port
+    end
+
+    # The client is a singleton that captures host and port when it is first built, which earlier specs in the run may
+    # already have done. Point the existing instance at this run's exporter and drop anything they left queued, so the
+    # result does not depend on spec ordering.
+    client = Bigcommerce::Prometheus.client
+    client.instance_variable_set(:@host, '127.0.0.1')
+    client.instance_variable_set(:@port, exporter.port)
+    # 0.8.3 has no `reset_after_fork!`. Clearing the queue directly is the only part of it this setup needs.
+    client.instance_variable_get(:@queue).clear
+
+    Bigcommerce::Prometheus::Integrations::Resque.start(client: client)
+  end
+
+  after { exporter.stop }
+
+  describe 'completeness' do
+    it 'delivers one observation for every job that pushed one' do
+      run_jobs(JOB_COUNT)
+
+      expect(exporter.count_for(ForkDeliveryProbeJob::METRIC_NAME)).to eq JOB_COUNT
+    end
+  end
+
+  describe 'overhead' do
+    it 'adds less than the per-job budget over an identical run with metrics disabled' do
+      expect(measured_overhead_per_job).to be < OVERHEAD_BUDGET_SECONDS
+    end
+  end
+
+  # --- helpers -----------------------------------------------------------
+
+  # Drains the queue synchronously, one job at a time, so the run has no timers or sleeps in it. Each call still forks,
+  # runs the after_fork hooks and exits the child exactly as a live worker does.
+  #
+  # @param [Integer] count
+  # @return [Float] seconds elapsed
+  def run_jobs(count)
+    count.times { Resque::Job.create(queue, ForkDeliveryProbeJob, 'n' => 1) }
+    worker = Resque::Worker.new(queue)
+
+    # Monotonic clock rather than Benchmark: benchmark stopped being a default gem in Ruby 4.0, and requiring it here
+    # would break every job in the suite, not just this one. RSpec loads all spec files before it applies tag filters,
+    # so a top-level require in an excluded file still runs.
+    started_at = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+    count.times { worker.work_one_job }
+    Process.clock_gettime(Process::CLOCK_MONOTONIC) - started_at
+  end
+
+  # @return [Float] seconds of instrumentation cost per job
+  def measured_overhead_per_job
+    Bigcommerce::Prometheus.enabled = false
+    without_metrics = run_jobs(JOB_COUNT)
+
+    Bigcommerce::Prometheus.enabled = true
+    with_metrics = run_jobs(JOB_COUNT)
+
+    (with_metrics - without_metrics) / JOB_COUNT
+  end
+
+  def redis_url
+    ENV.fetch('REDIS_URL', 'redis://127.0.0.1:6379/15')
+  end
+
+  def redis_available?
+    Redis.new(url: redis_url, timeout: 0.5).ping
+    true
+  rescue StandardError
+    false
+  end
+end

spec/spec_helper.rb

@@ -26,4 +26,8 @@
     mocks.allow_message_expectations_on_nil = true
   end
   config.color = true
+
+  # Specs tagged :fork_integration fork real Resque children and need a redis, so they are opt-in rather than part of
+  # the default run. Enable with FORK_INTEGRATION=1.
+  config.filter_run_excluding(:fork_integration) unless ENV.fetch('FORK_INTEGRATION', nil)
 end

spec/support/counting_exporter.rb

@@ -0,0 +1,97 @@
+# frozen_string_literal: true
+
+# Copyright (c) 2019-present, BigCommerce Pty. Ltd. All rights reserved
+#
+# Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated
+# documentation files (the "Software"), to deal in the Software without restriction, including without limitation the
+# rights to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the Software, and to permit
+# persons to whom the Software is furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included in all copies or substantial portions of the
+# Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE
+# WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+# COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR
+# OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+#
+require 'json'
+require 'socket'
+
+##
+# Stands in for the exporter server and counts what arrives at /send-metrics.
+#
+# The fork-integration specs assert on how many observations actually crossed the process boundary, so they need a real
+# listener rather than a stubbed client. Counting envelopes here keeps those assertions independent of type collector
+# registration and of the exposition format.
+#
+class CountingExporter
+  # @return [Integer] the ephemeral port the exporter bound to
+  attr_reader :port
+
+  def initialize
+    @server = TCPServer.new('127.0.0.1', 0)
+    @port = @server.addr[1]
+    @envelopes = []
+    @mutex = Mutex.new
+  end
+
+  def start
+    @thread = Thread.new do
+      loop do
+        connection = @server.accept
+        Thread.new(connection) { |socket| serve(socket) }
+      end
+    end
+    self
+  end
+
+  def stop
+    @thread&.kill
+    begin
+      @server.close
+    rescue StandardError
+      nil
+    end
+  end
+
+  ##
+  # @param [String] name only count envelopes for this metric, ignoring anything the collectors also push
+  # @return [Integer]
+  #
+  def count_for(name)
+    @mutex.synchronize { @envelopes.count { |envelope| envelope['name'] == name } }
+  end
+
+  private
+
+  def serve(socket)
+    request_line = socket.gets
+    body = read_body(socket)
+    record(body) if request_line.to_s.include?('/send-metrics')
+    socket.write("HTTP/1.1 200 OK\r\nContent-Length: 2\r\nConnection: close\r\n\r\nOK")
+  rescue StandardError
+    nil
+  ensure
+    begin
+      socket.close
+    rescue StandardError
+      nil
+    end
+  end
+
+  def read_body(socket)
+    content_length = 0
+    while (line = socket.gets) && line != "\r\n"
+      content_length = line.split(':', 2).last.to_i if line.downcase.start_with?('content-length:')
+    end
+    content_length.positive? ? socket.read(content_length).to_s : ''
+  end
+
+  def record(body)
+    envelope = JSON.parse(body)
+    @mutex.synchronize { @envelopes << envelope }
+  rescue JSON::ParserError
+    nil
+  end
+end