From 7db7b1c2d725c77d84fff7d918eb4344f694245d Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 10:44:38 +0900 Subject: [PATCH 1/8] Implement rack queue middleware, specs, and CI --- .github/workflows/ci.yml | 42 +++++ .gitignore | 3 + .rspec | 2 + Gemfile | 3 + Gemfile.lock | 69 ++++++++ README.md | 28 +++ Rakefile | 8 + lib/yabeda-rack-queue.rb | 3 + lib/yabeda/rack/queue.rb | 6 + .../rack/queue/header_timestamp_parser.rb | 51 ++++++ lib/yabeda/rack/queue/metric.rb | 27 +++ lib/yabeda/rack/queue/middleware.rb | 80 +++++++++ lib/yabeda/rack/queue/version.rb | 9 + spec/e2e/puma_integration_spec.rb | 79 +++++++++ spec/spec_helper.rb | 17 ++ .../queue/header_timestamp_parser_spec.rb | 58 +++++++ spec/yabeda/rack/queue/metric_spec.rb | 18 ++ spec/yabeda/rack/queue/middleware_spec.rb | 161 ++++++++++++++++++ yabeda-rack-queue.gemspec | 41 +++++ 19 files changed, 705 insertions(+) create mode 100644 .github/workflows/ci.yml create mode 100644 .gitignore create mode 100644 .rspec create mode 100644 Gemfile create mode 100644 Gemfile.lock create mode 100644 README.md create mode 100644 Rakefile create mode 100644 lib/yabeda-rack-queue.rb create mode 100644 lib/yabeda/rack/queue.rb create mode 100644 lib/yabeda/rack/queue/header_timestamp_parser.rb create mode 100644 lib/yabeda/rack/queue/metric.rb create mode 100644 lib/yabeda/rack/queue/middleware.rb create mode 100644 lib/yabeda/rack/queue/version.rb create mode 100644 spec/e2e/puma_integration_spec.rb create mode 100644 spec/spec_helper.rb create mode 100644 spec/yabeda/rack/queue/header_timestamp_parser_spec.rb create mode 100644 spec/yabeda/rack/queue/metric_spec.rb create mode 100644 spec/yabeda/rack/queue/middleware_spec.rb create mode 100644 yabeda-rack-queue.gemspec diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml new file mode 100644 index 0000000..a11df93 --- /dev/null +++ b/.github/workflows/ci.yml @@ -0,0 +1,42 @@ +name: CI + +on: + push: + branches: ["**"] + pull_request: + workflow_dispatch: + +jobs: + spec: + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + ruby: ["3.2", "3.3", "3.4"] + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Set up Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: ${{ matrix.ruby }} + bundler-cache: true + + - name: Run specs + run: bundle exec rspec + + package: + runs-on: ubuntu-latest + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Set up Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: "3.3" + bundler-cache: true + + - name: Verify gem can be built + run: bundle exec rake build diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..76747df --- /dev/null +++ b/.gitignore @@ -0,0 +1,3 @@ +/.bundle/ +/pkg/ +*.gem diff --git a/.rspec b/.rspec new file mode 100644 index 0000000..5be63fc --- /dev/null +++ b/.rspec @@ -0,0 +1,2 @@ +--require spec_helper +--format documentation diff --git a/Gemfile b/Gemfile new file mode 100644 index 0000000..b4e2a20 --- /dev/null +++ b/Gemfile @@ -0,0 +1,3 @@ +source "https://rubygems.org" + +gemspec diff --git a/Gemfile.lock b/Gemfile.lock new file mode 100644 index 0000000..73294b5 --- /dev/null +++ b/Gemfile.lock @@ -0,0 +1,69 @@ +PATH + remote: . + specs: + yabeda-rack-queue (0.1.0) + rack (>= 2.2, < 4.0) + yabeda (>= 0.14, < 1.0) + +GEM + remote: https://rubygems.org/ + specs: + anyway_config (2.8.0) + ruby-next-core (~> 1.0) + concurrent-ruby (1.3.6) + diff-lcs (1.6.2) + dry-initializer (3.2.0) + nio4r (2.7.5) + puma (7.2.0) + nio4r (~> 2.0) + rack (3.2.5) + rake (13.3.1) + rspec (3.13.2) + rspec-core (~> 3.13.0) + rspec-expectations (~> 3.13.0) + rspec-mocks (~> 3.13.0) + rspec-core (3.13.6) + rspec-support (~> 3.13.0) + rspec-expectations (3.13.5) + diff-lcs (>= 1.2.0, < 2.0) + rspec-support (~> 3.13.0) + rspec-mocks (3.13.7) + diff-lcs (>= 1.2.0, < 2.0) + rspec-support (~> 3.13.0) + rspec-support (3.13.7) + ruby-next-core (1.2.0) + yabeda (0.14.0) + anyway_config (>= 1.0, < 3) + concurrent-ruby + dry-initializer + +PLATFORMS + arm64-darwin-24 + ruby + +DEPENDENCIES + puma (>= 6, < 8) + rake (>= 13.0) + rspec (~> 3.13) + yabeda-rack-queue! + +CHECKSUMS + anyway_config (2.8.0) + concurrent-ruby (1.3.6) + diff-lcs (1.6.2) + dry-initializer (3.2.0) + nio4r (2.7.5) + puma (7.2.0) + rack (3.2.5) + rake (13.3.1) + rspec (3.13.2) + rspec-core (3.13.6) + rspec-expectations (3.13.5) + rspec-mocks (3.13.7) + rspec-support (3.13.7) + ruby-next-core (1.2.0) + yabeda (0.14.0) + yabeda-rack-queue (0.1.0) + +BUNDLED WITH + 4.0.3 diff --git a/README.md b/README.md new file mode 100644 index 0000000..b609c8d --- /dev/null +++ b/README.md @@ -0,0 +1,28 @@ +# yabeda-rack-queue + +Rack middleware for reporting HTTP request queue time to Yabeda. + +## Installation + +Add to your Gemfile: + +```ruby +gem "yabeda-rack-queue" +``` + +Then bundle install. + +## Usage + +```ruby +require "yabeda/rack/queue" +require "yabeda/prometheus" + +Yabeda.configure! + +use Yabeda::Rack::Queue::Middleware +run MyRackApp +``` + +The middleware inspects `X-Request-Start` / `X-Queue-Start` headers and records +`rack_queue.rack_queue_duration` histogram values in seconds. diff --git a/Rakefile b/Rakefile new file mode 100644 index 0000000..b6ae734 --- /dev/null +++ b/Rakefile @@ -0,0 +1,8 @@ +# frozen_string_literal: true + +require "bundler/gem_tasks" +require "rspec/core/rake_task" + +RSpec::Core::RakeTask.new(:spec) + +task default: :spec diff --git a/lib/yabeda-rack-queue.rb b/lib/yabeda-rack-queue.rb new file mode 100644 index 0000000..ca9e43f --- /dev/null +++ b/lib/yabeda-rack-queue.rb @@ -0,0 +1,3 @@ +# frozen_string_literal: true + +require "yabeda/rack/queue" diff --git a/lib/yabeda/rack/queue.rb b/lib/yabeda/rack/queue.rb new file mode 100644 index 0000000..445d14d --- /dev/null +++ b/lib/yabeda/rack/queue.rb @@ -0,0 +1,6 @@ +# frozen_string_literal: true + +require_relative "queue/version" +require_relative "queue/metric" +require_relative "queue/header_timestamp_parser" +require_relative "queue/middleware" diff --git a/lib/yabeda/rack/queue/header_timestamp_parser.rb b/lib/yabeda/rack/queue/header_timestamp_parser.rb new file mode 100644 index 0000000..54b2593 --- /dev/null +++ b/lib/yabeda/rack/queue/header_timestamp_parser.rb @@ -0,0 +1,51 @@ +# frozen_string_literal: true + +module Yabeda + module Rack + module Queue + class HeaderTimestampParser + MIN_EPOCH_SECONDS = Time.utc(2000, 1, 1).to_f + FUTURE_TOLERANCE_SECONDS = 30.0 + NORMALIZATION_DIVISORS = [1_000_000.0, 1_000.0, 1.0].freeze + NUMBER_PATTERN = /[+-]?(?:\d+(?:\.\d+)?|\.\d+)/.freeze + T_EQUALS_PATTERN = /t\s*=\s*(#{NUMBER_PATTERN.source})/i.freeze + + def parse(value, now:) + first_value = first_header_value(value) + return nil if first_value.empty? + + token = extract_numeric_token(first_value) + return nil if token.nil? + + normalize(Float(token), now) + rescue ArgumentError, TypeError + nil + end + + private + + def first_header_value(value) + value.to_s.split(",", 2).first.to_s.strip + end + + def extract_numeric_token(value) + value[T_EQUALS_PATTERN, 1] || value[NUMBER_PATTERN, 0] + end + + def normalize(raw_timestamp, now) + max_allowed = now + FUTURE_TOLERANCE_SECONDS + + NORMALIZATION_DIVISORS.each do |divisor| + candidate = raw_timestamp / divisor + next if candidate < MIN_EPOCH_SECONDS + next if candidate > max_allowed + + return candidate + end + + nil + end + end + end + end +end diff --git a/lib/yabeda/rack/queue/metric.rb b/lib/yabeda/rack/queue/metric.rb new file mode 100644 index 0000000..39be6f4 --- /dev/null +++ b/lib/yabeda/rack/queue/metric.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +require "yabeda" + +module Yabeda + module Rack + module Queue + HISTOGRAM_BUCKETS = [ + 0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60 + ].freeze + + METRIC_NAME = :rack_queue_duration + METRIC_GROUP = :rack_queue + METRIC_UNIT = :seconds + METRIC_DESCRIPTION = "Time a request waited in the upstream queue before reaching the application" + end + end +end + +Yabeda.configure do + group Yabeda::Rack::Queue::METRIC_GROUP do + histogram Yabeda::Rack::Queue::METRIC_NAME, + comment: Yabeda::Rack::Queue::METRIC_DESCRIPTION, + unit: Yabeda::Rack::Queue::METRIC_UNIT, + buckets: Yabeda::Rack::Queue::HISTOGRAM_BUCKETS + end +end diff --git a/lib/yabeda/rack/queue/middleware.rb b/lib/yabeda/rack/queue/middleware.rb new file mode 100644 index 0000000..37cc177 --- /dev/null +++ b/lib/yabeda/rack/queue/middleware.rb @@ -0,0 +1,80 @@ +# frozen_string_literal: true + +module Yabeda + module Rack + module Queue + class Middleware + HEADER_KEYS = %w[HTTP_X_REQUEST_START HTTP_X_QUEUE_START].freeze + REQUEST_BODY_WAIT_KEY = "puma.request_body_wait" + + class StderrLogger + def warn(message) + $stderr.puts(message) + end + end + + class YabedaReporter + def observe(value) + Yabeda.rack_queue.rack_queue_duration.measure({}, value) + end + end + + def initialize(app, reporter: YabedaReporter.new, parser: HeaderTimestampParser.new, logger: nil, clock: nil) + @app = app + @reporter = reporter + @parser = parser + @logger = logger || StderrLogger.new + @clock = clock || -> { Process.clock_gettime(Process::CLOCK_REALTIME) } + end + + def call(env) + now = @clock.call + request_start = request_start_timestamp(env, now) + + report_queue_time(env, now, request_start) if request_start + + @app.call(env) + end + + private + + def request_start_timestamp(env, now) + HEADER_KEYS.each do |header_key| + header_value = env[header_key] + next if header_value.nil? + + parsed = @parser.parse(header_value, now: now) + return parsed if parsed + end + + nil + end + + def report_queue_time(env, now, request_start) + queue_time = now - request_start + if queue_time.negative? + @logger.warn("Negative rack queue duration (#{queue_time}) observed; dropping measurement") + return + end + + body_wait = parse_request_body_wait(env[REQUEST_BODY_WAIT_KEY]) + queue_time -= body_wait if body_wait + queue_time = 0.0 if queue_time.negative? + + @reporter.observe(queue_time) + end + + def parse_request_body_wait(value) + return nil if value.nil? + + milliseconds = Float(value) + return nil if milliseconds.negative? + + milliseconds / 1_000.0 + rescue ArgumentError, TypeError + nil + end + end + end + end +end diff --git a/lib/yabeda/rack/queue/version.rb b/lib/yabeda/rack/queue/version.rb new file mode 100644 index 0000000..7797fd7 --- /dev/null +++ b/lib/yabeda/rack/queue/version.rb @@ -0,0 +1,9 @@ +# frozen_string_literal: true + +module Yabeda + module Rack + module Queue + VERSION = "0.1.0" + end + end +end diff --git a/spec/e2e/puma_integration_spec.rb b/spec/e2e/puma_integration_spec.rb new file mode 100644 index 0000000..0e62c63 --- /dev/null +++ b/spec/e2e/puma_integration_spec.rb @@ -0,0 +1,79 @@ +# frozen_string_literal: true + +require "spec_helper" +require "net/http" +require "puma" +require "socket" +require "timeout" + +RSpec.describe "Puma E2E queue time reporting" do + class PumaServerHarness + attr_reader :port + + def initialize(app) + @app = app + end + + def start + @server = Puma::Server.new(@app, nil, min_threads: 0, max_threads: 4) + @server.add_tcp_listener("127.0.0.1", 0) + @port = @server.connected_ports.first + @server.run(true, thread_name: "puma-e2e") + wait_until_ready + end + + def stop + @server&.stop(true) + end + + private + + def wait_until_ready + Timeout.timeout(5) do + loop do + begin + socket = TCPSocket.new("127.0.0.1", port) + socket.close + break + rescue Errno::ECONNREFUSED + sleep 0.01 + end + end + end + end + end + + let(:rack_app) do + Yabeda::Rack::Queue::Middleware.new( + ->(_env) { [200, { "content-type" => "text/plain" }, ["ok"]] } + ) + end + let(:server) { PumaServerHarness.new(rack_app) } + + before do + server.start + rescue Errno::EPERM + skip "Socket binding is not permitted in this environment" + end + + after do + server.stop + end + + it "records rack_queue_duration histogram via Yabeda on a real HTTP request" do + request_start_ms = ((Time.now.to_f - 0.12) * 1_000).to_i + uri = URI("http://127.0.0.1:#{server.port}/") + request = Net::HTTP::Get.new(uri) + request["X-Request-Start"] = request_start_ms.to_s + + response = Net::HTTP.start(uri.host, uri.port) { |http| http.request(request) } + + expect(response.code).to eq("200") + + metric = Yabeda.rack_queue.rack_queue_duration + measured = Yabeda::TestAdapter.instance.histograms.fetch(metric).fetch({}) + + expect(measured).to be_a(Float) + expect(measured).to be >= 0.0 + end +end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb new file mode 100644 index 0000000..b9a3bc5 --- /dev/null +++ b/spec/spec_helper.rb @@ -0,0 +1,17 @@ +# frozen_string_literal: true + +require "bundler/setup" +require "yabeda/test_adapter" +require "yabeda/rack/queue" + +Yabeda.register_adapter(:test, Yabeda::TestAdapter.instance) +Yabeda.configure! unless Yabeda.configured? + +RSpec.configure do |config| + config.disable_monkey_patching! + config.expect_with(:rspec) { |c| c.syntax = :expect } + + config.before do + Yabeda::TestAdapter.instance.reset! + end +end diff --git a/spec/yabeda/rack/queue/header_timestamp_parser_spec.rb b/spec/yabeda/rack/queue/header_timestamp_parser_spec.rb new file mode 100644 index 0000000..e2e3488 --- /dev/null +++ b/spec/yabeda/rack/queue/header_timestamp_parser_spec.rb @@ -0,0 +1,58 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Yabeda::Rack::Queue::HeaderTimestampParser do + subject(:parser) { described_class.new } + + let(:now) { 1_700_000_000.0 } + + describe "#parse" do + it "accepts known valid values from the truth table" do + expectations = { + "t=1512379167.574" => 1_512_379_167.574, + "1512379167.574" => 1_512_379_167.574, + "t=1512379167574" => 1_512_379_167.574, + "1512379167574" => 1_512_379_167.574, + "t=1570633834463123" => 1_570_633_834.463123, + "1570633834463123" => 1_570_633_834.463123, + "t=1512379167" => 1_512_379_167.0, + "1512379167" => 1_512_379_167.0, + " t=1512379167.574 " => 1_512_379_167.574, + "t=1512379167.574, t=1512379168.000" => 1_512_379_167.574 + } + + expectations.each do |header_value, expected| + actual = parser.parse(header_value, now: now) + expect(actual).to be_within(1e-9).of(expected) + end + end + + it "rejects known invalid values from the truth table" do + [ + "invalid", + "t=", + "t=0", + "t=915148800", + "t=1700000035" + ].each do |header_value| + expect(parser.parse(header_value, now: now)).to be_nil + end + end + + it "prefers t= token over plain token when both are present" do + value = parser.parse("1512370000 t=1512379167.574", now: now) + expect(value).to be_within(1e-9).of(1_512_379_167.574) + end + + it "returns nil for non-string values that cannot be parsed" do + expect(parser.parse(nil, now: now)).to be_nil + expect(parser.parse(Object.new, now: now)).to be_nil + end + + it "rejects values more than 30 seconds in the future" do + header_value = "t=#{now + 30.001}" + expect(parser.parse(header_value, now: now)).to be_nil + end + end +end diff --git a/spec/yabeda/rack/queue/metric_spec.rb b/spec/yabeda/rack/queue/metric_spec.rb new file mode 100644 index 0000000..ddf1f1c --- /dev/null +++ b/spec/yabeda/rack/queue/metric_spec.rb @@ -0,0 +1,18 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe "rack_queue metric registration" do + it "registers rack_queue_duration histogram with required metadata" do + metric = Yabeda.rack_queue.rack_queue_duration + + expect(metric).to be_a(Yabeda::Histogram) + expect(metric.group).to eq(:rack_queue) + expect(metric.unit).to eq(:seconds) + expect(metric.comment).to eq("Time a request waited in the upstream queue before reaching the application") + expect(metric.tags).to eq([]) + expect(metric.buckets).to eq( + [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60] + ) + end +end diff --git a/spec/yabeda/rack/queue/middleware_spec.rb b/spec/yabeda/rack/queue/middleware_spec.rb new file mode 100644 index 0000000..446bf73 --- /dev/null +++ b/spec/yabeda/rack/queue/middleware_spec.rb @@ -0,0 +1,161 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Yabeda::Rack::Queue::Middleware do + class CapturingReporter + attr_reader :values + + def initialize + @values = [] + end + + def observe(value) + @values << value + end + end + + class CapturingLogger + attr_reader :warnings + + def initialize + @warnings = [] + end + + def warn(message) + @warnings << message + end + end + + let(:response) { [201, { "content-type" => "text/plain" }, ["ok"]] } + let(:app) { ->(_env) { response } } + let(:reporter) { CapturingReporter.new } + let(:now) { 1_700_000_000.0 } + let(:clock) { -> { now } } + let(:logger) { CapturingLogger.new } + let(:middleware) { described_class.new(app, reporter: reporter, clock: clock, logger: logger) } + + describe "#call" do + it "always calls the downstream app and returns the downstream response unchanged" do + env = {} + expect(app).to receive(:call).with(env).and_call_original + + result = middleware.call(env) + + expect(result).to equal(response) + end + + it "does not mutate rack env" do + env = { "HTTP_X_REQUEST_START" => "t=1699999999.9", "custom.key" => "value" } + original = env.dup + + middleware.call(env) + + expect(env).to eq(original) + end + + it "records nothing when neither header is present" do + middleware.call({}) + expect(reporter.values).to be_empty + end + + it "uses HTTP_X_REQUEST_START before HTTP_X_QUEUE_START when both are valid" do + env = { + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "HTTP_X_QUEUE_START" => "t=1699999999.8" + } + + middleware.call(env) + + expect(reporter.values.last).to be_within(1e-4).of(0.1) + end + + it "falls back to HTTP_X_QUEUE_START when HTTP_X_REQUEST_START is invalid" do + env = { + "HTTP_X_REQUEST_START" => "invalid", + "HTTP_X_QUEUE_START" => "t=1699999999.9" + } + + middleware.call(env) + + expect(reporter.values.last).to be_within(1e-4).of(0.1) + end + + it "computes queue time before calling downstream app" do + sleeping_app = ->(_env) do + sleep 0.05 + response + end + test_middleware = described_class.new(sleeping_app, reporter: reporter, clock: clock, logger: logger) + + test_middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") + + expect(reporter.values.last).to be_within(1e-4).of(0.1) + end + + it "uses Process.clock_gettime(Process::CLOCK_REALTIME) by default" do + default_clock_middleware = described_class.new(app, reporter: reporter, logger: logger) + expect(Process).to receive(:clock_gettime).with(Process::CLOCK_REALTIME).and_return(now) + + default_clock_middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") + end + + it "never raises on invalid header values" do + expect do + middleware.call("HTTP_X_REQUEST_START" => Object.new, "HTTP_X_QUEUE_START" => "") + end.not_to raise_error + end + + it "drops negative queue times and logs warning" do + middleware.call("HTTP_X_REQUEST_START" => "t=1700000000.1") + + expect(reporter.values).to be_empty + expect(logger.warnings.join("\n")).to include("Negative rack queue duration") + end + + it "subtracts puma.request_body_wait milliseconds from queue time" do + middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => 40 + ) + + expect(reporter.values.last).to be_within(1e-4).of(0.06) + end + + it "coerces string puma.request_body_wait values" do + middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => "40" + ) + + expect(reporter.values.last).to be_within(1e-4).of(0.06) + end + + it "ignores non-numeric puma.request_body_wait values" do + middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => "not-a-number" + ) + + expect(reporter.values.last).to be_within(1e-4).of(0.1) + end + + it "ignores negative puma.request_body_wait values" do + middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => -40 + ) + + expect(reporter.values.last).to be_within(1e-4).of(0.1) + end + + it "clamps to zero after puma.request_body_wait subtraction" do + middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => 200 + ) + + expect(reporter.values.last).to eq(0.0) + end + end +end diff --git a/yabeda-rack-queue.gemspec b/yabeda-rack-queue.gemspec new file mode 100644 index 0000000..23f76b0 --- /dev/null +++ b/yabeda-rack-queue.gemspec @@ -0,0 +1,41 @@ +# frozen_string_literal: true + +require_relative "lib/yabeda/rack/queue/version" + +Gem::Specification.new do |spec| + spec.name = "yabeda-rack-queue" + spec.version = Yabeda::Rack::Queue::VERSION + spec.authors = ["Yabeda Contributors"] + spec.email = ["maintainers@yabeda.dev"] + + spec.summary = "Yabeda middleware for HTTP request queue duration" + spec.description = <<~DESCRIPTION + Rack middleware that measures HTTP request queue duration from upstream + headers and reports it to Yabeda as a histogram metric. + DESCRIPTION + spec.homepage = "https://github.com/yabeda-rb/yabeda-rack-queue" + spec.license = "MIT" + spec.required_ruby_version = ">= 3.1" + + spec.metadata = { + "bug_tracker_uri" => "https://github.com/yabeda-rb/yabeda-rack-queue/issues", + "changelog_uri" => "https://github.com/yabeda-rb/yabeda-rack-queue/releases", + "homepage_uri" => spec.homepage, + "source_code_uri" => "https://github.com/yabeda-rb/yabeda-rack-queue", + "rubygems_mfa_required" => "true" + } + + spec.files = Dir.chdir(__dir__) do + `git ls-files -z`.split("\x0").reject do |file| + file.start_with?(".github/", ".pi/") + end + end + spec.require_paths = ["lib"] + + spec.add_dependency "rack", ">= 2.2", "< 4.0" + spec.add_dependency "yabeda", ">= 0.14", "< 1.0" + + spec.add_development_dependency "puma", ">= 6", "< 8" + spec.add_development_dependency "rake", ">= 13.0" + spec.add_development_dependency "rspec", "~> 3.13" +end From 01e2f2859ab0f369ae883299c53119ab2482d990 Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 10:45:45 +0900 Subject: [PATCH 2/8] Fix lockfile checksums for CI frozen mode --- Gemfile.lock | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/Gemfile.lock b/Gemfile.lock index 73294b5..958e463 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -48,21 +48,21 @@ DEPENDENCIES yabeda-rack-queue! CHECKSUMS - anyway_config (2.8.0) - concurrent-ruby (1.3.6) - diff-lcs (1.6.2) - dry-initializer (3.2.0) - nio4r (2.7.5) - puma (7.2.0) - rack (3.2.5) - rake (13.3.1) - rspec (3.13.2) - rspec-core (3.13.6) - rspec-expectations (3.13.5) - rspec-mocks (3.13.7) - rspec-support (3.13.7) - ruby-next-core (1.2.0) - yabeda (0.14.0) + anyway_config (2.8.0) sha256=f6797a7231f81202dcd3d0c07284e836e45713e761d320180348b13a5c7c9306 + concurrent-ruby (1.3.6) sha256=6b56837e1e7e5292f9864f34b69c5a2cbc75c0cf5338f1ce9903d10fa762d5ab + diff-lcs (1.6.2) sha256=9ae0d2cba7d4df3075fe8cd8602a8604993efc0dfa934cff568969efb1909962 + dry-initializer (3.2.0) sha256=37d59798f912dc0a1efe14a4db4a9306989007b302dcd5f25d0a2a20c166c4e3 + nio4r (2.7.5) sha256=6c90168e48fb5f8e768419c93abb94ba2b892a1d0602cb06eef16d8b7df1dca1 + puma (7.2.0) sha256=bf8ef4ab514a4e6d4554cb4326b2004eba5036ae05cf765cfe51aba9706a72a8 + rack (3.2.5) sha256=4cbd0974c0b79f7a139b4812004a62e4c60b145cba76422e288ee670601ed6d3 + rake (13.3.1) sha256=8c9e89d09f66a26a01264e7e3480ec0607f0c497a861ef16063604b1b08eb19c + rspec (3.13.2) sha256=206284a08ad798e61f86d7ca3e376718d52c0bc944626b2349266f239f820587 + rspec-core (3.13.6) sha256=a8823c6411667b60a8bca135364351dda34cd55e44ff94c4be4633b37d828b2d + rspec-expectations (3.13.5) sha256=33a4d3a1d95060aea4c94e9f237030a8f9eae5615e9bd85718fe3a09e4b58836 + rspec-mocks (3.13.7) sha256=0979034e64b1d7a838aaaddf12bf065ea4dc40ef3d4c39f01f93ae2c66c62b1c + rspec-support (3.13.7) sha256=0640e5570872aafefd79867901deeeeb40b0c9875a36b983d85f54fb7381c47c + ruby-next-core (1.2.0) sha256=f6a7d00bb5186cecbb02f7f1845a0f3a2c9788d35b6ccff5c9be3f0d46799b86 + yabeda (0.14.0) sha256=bc517bf22d692ebd80a29fc9fd2246c257aaf92d10b2735a775e2419351a43bf yabeda-rack-queue (0.1.0) BUNDLED WITH From 01ad1d7ffbc04b6cf17b98f1637f222a7ba09eee Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 10:52:18 +0900 Subject: [PATCH 3/8] Add standardrb linting and update CI Ruby matrix --- .github/workflows/ci.yml | 23 ++++++- Gemfile.lock | 66 +++++++++++++++++++ .../rack/queue/header_timestamp_parser.rb | 4 +- lib/yabeda/rack/queue/metric.rb | 6 +- lib/yabeda/rack/queue/middleware.rb | 2 +- spec/e2e/puma_integration_spec.rb | 61 +++++++++-------- spec/yabeda/rack/queue/middleware_spec.rb | 50 +++++++------- yabeda-rack-queue.gemspec | 1 + 8 files changed, 149 insertions(+), 64 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index a11df93..32551e8 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -7,12 +7,31 @@ on: workflow_dispatch: jobs: + lint: + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + ruby: ["3.4", "4.0"] + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Set up Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: ${{ matrix.ruby }} + bundler-cache: true + + - name: Run linter + run: bundle exec standardrb + spec: runs-on: ubuntu-latest strategy: fail-fast: false matrix: - ruby: ["3.2", "3.3", "3.4"] + ruby: ["3.4", "4.0"] steps: - name: Checkout uses: actions/checkout@v4 @@ -35,7 +54,7 @@ jobs: - name: Set up Ruby uses: ruby/setup-ruby@v1 with: - ruby-version: "3.3" + ruby-version: "4.0" bundler-cache: true - name: Verify gem can be built diff --git a/Gemfile.lock b/Gemfile.lock index 958e463..69341d5 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -10,14 +10,26 @@ GEM specs: anyway_config (2.8.0) ruby-next-core (~> 1.0) + ast (2.4.3) concurrent-ruby (1.3.6) diff-lcs (1.6.2) dry-initializer (3.2.0) + json (2.18.1) + language_server-protocol (3.17.0.5) + lint_roller (1.1.0) nio4r (2.7.5) + parallel (1.27.0) + parser (3.3.10.2) + ast (~> 2.4.1) + racc + prism (1.9.0) puma (7.2.0) nio4r (~> 2.0) + racc (1.8.1) rack (3.2.5) + rainbow (3.1.1) rake (13.3.1) + regexp_parser (2.11.3) rspec (3.13.2) rspec-core (~> 3.13.0) rspec-expectations (~> 3.13.0) @@ -31,7 +43,41 @@ GEM diff-lcs (>= 1.2.0, < 2.0) rspec-support (~> 3.13.0) rspec-support (3.13.7) + rubocop (1.84.2) + json (~> 2.3) + language_server-protocol (~> 3.17.0.2) + lint_roller (~> 1.1.0) + parallel (~> 1.10) + parser (>= 3.3.0.2) + rainbow (>= 2.2.2, < 4.0) + regexp_parser (>= 2.9.3, < 3.0) + rubocop-ast (>= 1.49.0, < 2.0) + ruby-progressbar (~> 1.7) + unicode-display_width (>= 2.4.0, < 4.0) + rubocop-ast (1.49.0) + parser (>= 3.3.7.2) + prism (~> 1.7) + rubocop-performance (1.26.1) + lint_roller (~> 1.1) + rubocop (>= 1.75.0, < 2.0) + rubocop-ast (>= 1.47.1, < 2.0) ruby-next-core (1.2.0) + ruby-progressbar (1.13.0) + standard (1.54.0) + language_server-protocol (~> 3.17.0.2) + lint_roller (~> 1.0) + rubocop (~> 1.84.0) + standard-custom (~> 1.0.0) + standard-performance (~> 1.8) + standard-custom (1.0.2) + lint_roller (~> 1.0) + rubocop (~> 1.50) + standard-performance (1.9.0) + lint_roller (~> 1.1) + rubocop-performance (~> 1.26.0) + unicode-display_width (3.2.0) + unicode-emoji (~> 4.1) + unicode-emoji (4.2.0) yabeda (0.14.0) anyway_config (>= 1.0, < 3) concurrent-ruby @@ -45,23 +91,43 @@ DEPENDENCIES puma (>= 6, < 8) rake (>= 13.0) rspec (~> 3.13) + standard (~> 1.44) yabeda-rack-queue! CHECKSUMS anyway_config (2.8.0) sha256=f6797a7231f81202dcd3d0c07284e836e45713e761d320180348b13a5c7c9306 + ast (2.4.3) sha256=954615157c1d6a382bc27d690d973195e79db7f55e9765ac7c481c60bdb4d383 concurrent-ruby (1.3.6) sha256=6b56837e1e7e5292f9864f34b69c5a2cbc75c0cf5338f1ce9903d10fa762d5ab diff-lcs (1.6.2) sha256=9ae0d2cba7d4df3075fe8cd8602a8604993efc0dfa934cff568969efb1909962 dry-initializer (3.2.0) sha256=37d59798f912dc0a1efe14a4db4a9306989007b302dcd5f25d0a2a20c166c4e3 + json (2.18.1) sha256=fe112755501b8d0466b5ada6cf50c8c3f41e897fa128ac5d263ec09eedc9f986 + language_server-protocol (3.17.0.5) sha256=fd1e39a51a28bf3eec959379985a72e296e9f9acfce46f6a79d31ca8760803cc + lint_roller (1.1.0) sha256=2c0c845b632a7d172cb849cc90c1bce937a28c5c8ccccb50dfd46a485003cc87 nio4r (2.7.5) sha256=6c90168e48fb5f8e768419c93abb94ba2b892a1d0602cb06eef16d8b7df1dca1 + parallel (1.27.0) sha256=4ac151e1806b755fb4e2dc2332cbf0e54f2e24ba821ff2d3dcf86bf6dc4ae130 + parser (3.3.10.2) sha256=6f60c84aa4bdcedb6d1a2434b738fe8a8136807b6adc8f7f53b97da9bc4e9357 + prism (1.9.0) sha256=7b530c6a9f92c24300014919c9dcbc055bf4cdf51ec30aed099b06cd6674ef85 puma (7.2.0) sha256=bf8ef4ab514a4e6d4554cb4326b2004eba5036ae05cf765cfe51aba9706a72a8 + racc (1.8.1) sha256=4a7f6929691dbec8b5209a0b373bc2614882b55fc5d2e447a21aaa691303d62f rack (3.2.5) sha256=4cbd0974c0b79f7a139b4812004a62e4c60b145cba76422e288ee670601ed6d3 + rainbow (3.1.1) sha256=039491aa3a89f42efa1d6dec2fc4e62ede96eb6acd95e52f1ad581182b79bc6a rake (13.3.1) sha256=8c9e89d09f66a26a01264e7e3480ec0607f0c497a861ef16063604b1b08eb19c + regexp_parser (2.11.3) sha256=ca13f381a173b7a93450e53459075c9b76a10433caadcb2f1180f2c741fc55a4 rspec (3.13.2) sha256=206284a08ad798e61f86d7ca3e376718d52c0bc944626b2349266f239f820587 rspec-core (3.13.6) sha256=a8823c6411667b60a8bca135364351dda34cd55e44ff94c4be4633b37d828b2d rspec-expectations (3.13.5) sha256=33a4d3a1d95060aea4c94e9f237030a8f9eae5615e9bd85718fe3a09e4b58836 rspec-mocks (3.13.7) sha256=0979034e64b1d7a838aaaddf12bf065ea4dc40ef3d4c39f01f93ae2c66c62b1c rspec-support (3.13.7) sha256=0640e5570872aafefd79867901deeeeb40b0c9875a36b983d85f54fb7381c47c + rubocop (1.84.2) sha256=5692cea54168f3dc8cb79a6fe95c5424b7ea893c707ad7a4307b0585e88dbf5f + rubocop-ast (1.49.0) sha256=49c3676d3123a0923d333e20c6c2dbaaae2d2287b475273fddee0c61da9f71fd + rubocop-performance (1.26.1) sha256=cd19b936ff196df85829d264b522fd4f98b6c89ad271fa52744a8c11b8f71834 ruby-next-core (1.2.0) sha256=f6a7d00bb5186cecbb02f7f1845a0f3a2c9788d35b6ccff5c9be3f0d46799b86 + ruby-progressbar (1.13.0) sha256=80fc9c47a9b640d6834e0dc7b3c94c9df37f08cb072b7761e4a71e22cff29b33 + standard (1.54.0) sha256=7a4b08f83d9893083c8f03bc486f0feeb6a84d48233b40829c03ef4767ea0100 + standard-custom (1.0.2) sha256=424adc84179a074f1a2a309bb9cf7cd6bfdb2b6541f20c6bf9436c0ba22a652b + standard-performance (1.9.0) sha256=49483d31be448292951d80e5e67cdcb576c2502103c7b40aec6f1b6e9c88e3f2 + unicode-display_width (3.2.0) sha256=0cdd96b5681a5949cdbc2c55e7b420facae74c4aaf9a9815eee1087cb1853c42 + unicode-emoji (4.2.0) sha256=519e69150f75652e40bf736106cfbc8f0f73aa3fb6a65afe62fefa7f80b0f80f yabeda (0.14.0) sha256=bc517bf22d692ebd80a29fc9fd2246c257aaf92d10b2735a775e2419351a43bf yabeda-rack-queue (0.1.0) diff --git a/lib/yabeda/rack/queue/header_timestamp_parser.rb b/lib/yabeda/rack/queue/header_timestamp_parser.rb index 54b2593..2e14a9a 100644 --- a/lib/yabeda/rack/queue/header_timestamp_parser.rb +++ b/lib/yabeda/rack/queue/header_timestamp_parser.rb @@ -7,8 +7,8 @@ class HeaderTimestampParser MIN_EPOCH_SECONDS = Time.utc(2000, 1, 1).to_f FUTURE_TOLERANCE_SECONDS = 30.0 NORMALIZATION_DIVISORS = [1_000_000.0, 1_000.0, 1.0].freeze - NUMBER_PATTERN = /[+-]?(?:\d+(?:\.\d+)?|\.\d+)/.freeze - T_EQUALS_PATTERN = /t\s*=\s*(#{NUMBER_PATTERN.source})/i.freeze + NUMBER_PATTERN = /[+-]?(?:\d+(?:\.\d+)?|\.\d+)/ + T_EQUALS_PATTERN = /t\s*=\s*(#{NUMBER_PATTERN.source})/i def parse(value, now:) first_value = first_header_value(value) diff --git a/lib/yabeda/rack/queue/metric.rb b/lib/yabeda/rack/queue/metric.rb index 39be6f4..e219710 100644 --- a/lib/yabeda/rack/queue/metric.rb +++ b/lib/yabeda/rack/queue/metric.rb @@ -20,8 +20,8 @@ module Queue Yabeda.configure do group Yabeda::Rack::Queue::METRIC_GROUP do histogram Yabeda::Rack::Queue::METRIC_NAME, - comment: Yabeda::Rack::Queue::METRIC_DESCRIPTION, - unit: Yabeda::Rack::Queue::METRIC_UNIT, - buckets: Yabeda::Rack::Queue::HISTOGRAM_BUCKETS + comment: Yabeda::Rack::Queue::METRIC_DESCRIPTION, + unit: Yabeda::Rack::Queue::METRIC_UNIT, + buckets: Yabeda::Rack::Queue::HISTOGRAM_BUCKETS end end diff --git a/lib/yabeda/rack/queue/middleware.rb b/lib/yabeda/rack/queue/middleware.rb index 37cc177..fd3bebb 100644 --- a/lib/yabeda/rack/queue/middleware.rb +++ b/lib/yabeda/rack/queue/middleware.rb @@ -9,7 +9,7 @@ class Middleware class StderrLogger def warn(message) - $stderr.puts(message) + Kernel.warn(message) end end diff --git a/spec/e2e/puma_integration_spec.rb b/spec/e2e/puma_integration_spec.rb index 0e62c63..3d2077b 100644 --- a/spec/e2e/puma_integration_spec.rb +++ b/spec/e2e/puma_integration_spec.rb @@ -6,46 +6,44 @@ require "socket" require "timeout" -RSpec.describe "Puma E2E queue time reporting" do - class PumaServerHarness - attr_reader :port +class PumaServerHarness + attr_reader :port - def initialize(app) - @app = app - end + def initialize(app) + @app = app + end - def start - @server = Puma::Server.new(@app, nil, min_threads: 0, max_threads: 4) - @server.add_tcp_listener("127.0.0.1", 0) - @port = @server.connected_ports.first - @server.run(true, thread_name: "puma-e2e") - wait_until_ready - end + def start + @server = Puma::Server.new(@app, nil, min_threads: 0, max_threads: 4) + @server.add_tcp_listener("127.0.0.1", 0) + @port = @server.connected_ports.first + @server.run(true, thread_name: "puma-e2e") + wait_until_ready + end - def stop - @server&.stop(true) - end + def stop + @server&.stop(true) + end - private + private - def wait_until_ready - Timeout.timeout(5) do - loop do - begin - socket = TCPSocket.new("127.0.0.1", port) - socket.close - break - rescue Errno::ECONNREFUSED - sleep 0.01 - end - end + def wait_until_ready + Timeout.timeout(5) do + loop do + socket = TCPSocket.new("127.0.0.1", port) + socket.close + break + rescue Errno::ECONNREFUSED + sleep 0.01 end end end +end +RSpec.describe "Puma E2E queue time reporting" do let(:rack_app) do Yabeda::Rack::Queue::Middleware.new( - ->(_env) { [200, { "content-type" => "text/plain" }, ["ok"]] } + ->(_env) { [200, {"content-type" => "text/plain"}, ["ok"]] } ) end let(:server) { PumaServerHarness.new(rack_app) } @@ -61,7 +59,8 @@ def wait_until_ready end it "records rack_queue_duration histogram via Yabeda on a real HTTP request" do - request_start_ms = ((Time.now.to_f - 0.12) * 1_000).to_i + requested_queue_time_seconds = 0.12 + request_start_ms = ((Time.now.to_f - requested_queue_time_seconds) * 1_000).to_i uri = URI("http://127.0.0.1:#{server.port}/") request = Net::HTTP::Get.new(uri) request["X-Request-Start"] = request_start_ms.to_s @@ -74,6 +73,6 @@ def wait_until_ready measured = Yabeda::TestAdapter.instance.histograms.fetch(metric).fetch({}) expect(measured).to be_a(Float) - expect(measured).to be >= 0.0 + expect(measured).to be >= (requested_queue_time_seconds - 0.005) end end diff --git a/spec/yabeda/rack/queue/middleware_spec.rb b/spec/yabeda/rack/queue/middleware_spec.rb index 446bf73..0edaf22 100644 --- a/spec/yabeda/rack/queue/middleware_spec.rb +++ b/spec/yabeda/rack/queue/middleware_spec.rb @@ -3,36 +3,36 @@ require "spec_helper" RSpec.describe Yabeda::Rack::Queue::Middleware do - class CapturingReporter - attr_reader :values + let(:response) { [201, {"content-type" => "text/plain"}, ["ok"]] } + let(:app) { ->(_env) { response } } + let(:reporter) do + Class.new do + attr_reader :values - def initialize - @values = [] - end + def initialize + @values = [] + end - def observe(value) - @values << value - end + def observe(value) + @values << value + end + end.new end + let(:now) { 1_700_000_000.0 } + let(:clock) { -> { now } } + let(:logger) do + Class.new do + attr_reader :warnings - class CapturingLogger - attr_reader :warnings - - def initialize - @warnings = [] - end + def initialize + @warnings = [] + end - def warn(message) - @warnings << message - end + def warn(message) + @warnings << message + end + end.new end - - let(:response) { [201, { "content-type" => "text/plain" }, ["ok"]] } - let(:app) { ->(_env) { response } } - let(:reporter) { CapturingReporter.new } - let(:now) { 1_700_000_000.0 } - let(:clock) { -> { now } } - let(:logger) { CapturingLogger.new } let(:middleware) { described_class.new(app, reporter: reporter, clock: clock, logger: logger) } describe "#call" do @@ -46,7 +46,7 @@ def warn(message) end it "does not mutate rack env" do - env = { "HTTP_X_REQUEST_START" => "t=1699999999.9", "custom.key" => "value" } + env = {"HTTP_X_REQUEST_START" => "t=1699999999.9", "custom.key" => "value"} original = env.dup middleware.call(env) diff --git a/yabeda-rack-queue.gemspec b/yabeda-rack-queue.gemspec index 23f76b0..12b1ca6 100644 --- a/yabeda-rack-queue.gemspec +++ b/yabeda-rack-queue.gemspec @@ -38,4 +38,5 @@ Gem::Specification.new do |spec| spec.add_development_dependency "puma", ">= 6", "< 8" spec.add_development_dependency "rake", ">= 13.0" spec.add_development_dependency "rspec", "~> 3.13" + spec.add_development_dependency "standard", "~> 1.44" end From 7b8f90453ed219c891da56733b7600c3d721f5da Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 11:01:26 +0900 Subject: [PATCH 4/8] Migrate to Minitest and drop rack gem dependency --- .github/workflows/ci.yml | 14 +- .rspec | 2 - Gemfile.lock | 27 +-- README.md | 53 ++++- Rakefile | 9 +- SPEC.md | 4 +- .../queue/header_timestamp_parser_spec.rb | 58 ------ spec/yabeda/rack/queue/metric_spec.rb | 18 -- spec/yabeda/rack/queue/middleware_spec.rb | 161 --------------- .../e2e/puma_integration_test.rb | 31 ++- spec/spec_helper.rb => test/test_helper.rb | 9 +- .../queue/header_timestamp_parser_test.rb | 52 +++++ test/yabeda/rack/queue/metric_test.rb | 16 ++ test/yabeda/rack/queue/middleware_test.rb | 191 ++++++++++++++++++ yabeda-rack-queue.gemspec | 15 +- 15 files changed, 349 insertions(+), 311 deletions(-) delete mode 100644 .rspec delete mode 100644 spec/yabeda/rack/queue/header_timestamp_parser_spec.rb delete mode 100644 spec/yabeda/rack/queue/metric_spec.rb delete mode 100644 spec/yabeda/rack/queue/middleware_spec.rb rename spec/e2e/puma_integration_spec.rb => test/e2e/puma_integration_test.rb (71%) rename spec/spec_helper.rb => test/test_helper.rb (66%) create mode 100644 test/yabeda/rack/queue/header_timestamp_parser_test.rb create mode 100644 test/yabeda/rack/queue/metric_test.rb create mode 100644 test/yabeda/rack/queue/middleware_test.rb diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 32551e8..dfc64c4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -9,10 +9,6 @@ on: jobs: lint: runs-on: ubuntu-latest - strategy: - fail-fast: false - matrix: - ruby: ["3.4", "4.0"] steps: - name: Checkout uses: actions/checkout@v4 @@ -20,18 +16,18 @@ jobs: - name: Set up Ruby uses: ruby/setup-ruby@v1 with: - ruby-version: ${{ matrix.ruby }} + ruby-version: "3.1" bundler-cache: true - name: Run linter run: bundle exec standardrb - spec: + test: runs-on: ubuntu-latest strategy: fail-fast: false matrix: - ruby: ["3.4", "4.0"] + ruby: ["3.1", "3.4", "4.0"] steps: - name: Checkout uses: actions/checkout@v4 @@ -42,8 +38,8 @@ jobs: ruby-version: ${{ matrix.ruby }} bundler-cache: true - - name: Run specs - run: bundle exec rspec + - name: Run tests + run: bundle exec rake test package: runs-on: ubuntu-latest diff --git a/.rspec b/.rspec deleted file mode 100644 index 5be63fc..0000000 --- a/.rspec +++ /dev/null @@ -1,2 +0,0 @@ ---require spec_helper ---format documentation diff --git a/Gemfile.lock b/Gemfile.lock index 69341d5..27a2b28 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -2,7 +2,6 @@ PATH remote: . specs: yabeda-rack-queue (0.1.0) - rack (>= 2.2, < 4.0) yabeda (>= 0.14, < 1.0) GEM @@ -12,11 +11,11 @@ GEM ruby-next-core (~> 1.0) ast (2.4.3) concurrent-ruby (1.3.6) - diff-lcs (1.6.2) dry-initializer (3.2.0) json (2.18.1) language_server-protocol (3.17.0.5) lint_roller (1.1.0) + minitest (5.27.0) nio4r (2.7.5) parallel (1.27.0) parser (3.3.10.2) @@ -26,23 +25,9 @@ GEM puma (7.2.0) nio4r (~> 2.0) racc (1.8.1) - rack (3.2.5) rainbow (3.1.1) rake (13.3.1) regexp_parser (2.11.3) - rspec (3.13.2) - rspec-core (~> 3.13.0) - rspec-expectations (~> 3.13.0) - rspec-mocks (~> 3.13.0) - rspec-core (3.13.6) - rspec-support (~> 3.13.0) - rspec-expectations (3.13.5) - diff-lcs (>= 1.2.0, < 2.0) - rspec-support (~> 3.13.0) - rspec-mocks (3.13.7) - diff-lcs (>= 1.2.0, < 2.0) - rspec-support (~> 3.13.0) - rspec-support (3.13.7) rubocop (1.84.2) json (~> 2.3) language_server-protocol (~> 3.17.0.2) @@ -88,9 +73,9 @@ PLATFORMS ruby DEPENDENCIES + minitest (>= 5.22, < 6.0) puma (>= 6, < 8) rake (>= 13.0) - rspec (~> 3.13) standard (~> 1.44) yabeda-rack-queue! @@ -98,26 +83,20 @@ CHECKSUMS anyway_config (2.8.0) sha256=f6797a7231f81202dcd3d0c07284e836e45713e761d320180348b13a5c7c9306 ast (2.4.3) sha256=954615157c1d6a382bc27d690d973195e79db7f55e9765ac7c481c60bdb4d383 concurrent-ruby (1.3.6) sha256=6b56837e1e7e5292f9864f34b69c5a2cbc75c0cf5338f1ce9903d10fa762d5ab - diff-lcs (1.6.2) sha256=9ae0d2cba7d4df3075fe8cd8602a8604993efc0dfa934cff568969efb1909962 dry-initializer (3.2.0) sha256=37d59798f912dc0a1efe14a4db4a9306989007b302dcd5f25d0a2a20c166c4e3 json (2.18.1) sha256=fe112755501b8d0466b5ada6cf50c8c3f41e897fa128ac5d263ec09eedc9f986 language_server-protocol (3.17.0.5) sha256=fd1e39a51a28bf3eec959379985a72e296e9f9acfce46f6a79d31ca8760803cc lint_roller (1.1.0) sha256=2c0c845b632a7d172cb849cc90c1bce937a28c5c8ccccb50dfd46a485003cc87 + minitest (5.27.0) sha256=2d3b17f8a36fe7801c1adcffdbc38233b938eb0b4966e97a6739055a45fa77d5 nio4r (2.7.5) sha256=6c90168e48fb5f8e768419c93abb94ba2b892a1d0602cb06eef16d8b7df1dca1 parallel (1.27.0) sha256=4ac151e1806b755fb4e2dc2332cbf0e54f2e24ba821ff2d3dcf86bf6dc4ae130 parser (3.3.10.2) sha256=6f60c84aa4bdcedb6d1a2434b738fe8a8136807b6adc8f7f53b97da9bc4e9357 prism (1.9.0) sha256=7b530c6a9f92c24300014919c9dcbc055bf4cdf51ec30aed099b06cd6674ef85 puma (7.2.0) sha256=bf8ef4ab514a4e6d4554cb4326b2004eba5036ae05cf765cfe51aba9706a72a8 racc (1.8.1) sha256=4a7f6929691dbec8b5209a0b373bc2614882b55fc5d2e447a21aaa691303d62f - rack (3.2.5) sha256=4cbd0974c0b79f7a139b4812004a62e4c60b145cba76422e288ee670601ed6d3 rainbow (3.1.1) sha256=039491aa3a89f42efa1d6dec2fc4e62ede96eb6acd95e52f1ad581182b79bc6a rake (13.3.1) sha256=8c9e89d09f66a26a01264e7e3480ec0607f0c497a861ef16063604b1b08eb19c regexp_parser (2.11.3) sha256=ca13f381a173b7a93450e53459075c9b76a10433caadcb2f1180f2c741fc55a4 - rspec (3.13.2) sha256=206284a08ad798e61f86d7ca3e376718d52c0bc944626b2349266f239f820587 - rspec-core (3.13.6) sha256=a8823c6411667b60a8bca135364351dda34cd55e44ff94c4be4633b37d828b2d - rspec-expectations (3.13.5) sha256=33a4d3a1d95060aea4c94e9f237030a8f9eae5615e9bd85718fe3a09e4b58836 - rspec-mocks (3.13.7) sha256=0979034e64b1d7a838aaaddf12bf065ea4dc40ef3d4c39f01f93ae2c66c62b1c - rspec-support (3.13.7) sha256=0640e5570872aafefd79867901deeeeb40b0c9875a36b983d85f54fb7381c47c rubocop (1.84.2) sha256=5692cea54168f3dc8cb79a6fe95c5424b7ea893c707ad7a4307b0585e88dbf5f rubocop-ast (1.49.0) sha256=49c3676d3123a0923d333e20c6c2dbaaae2d2287b475273fddee0c61da9f71fd rubocop-performance (1.26.1) sha256=cd19b936ff196df85829d264b522fd4f98b6c89ad271fa52744a8c11b8f71834 diff --git a/README.md b/README.md index b609c8d..aacf67f 100644 --- a/README.md +++ b/README.md @@ -1,18 +1,30 @@ # yabeda-rack-queue -Rack middleware for reporting HTTP request queue time to Yabeda. +Rack middleware that measures HTTP request queue time and reports it to +[Yabeda core](https://github.com/yabeda-rb/yabeda) as a histogram. + +## Features + +- Reports upstream queue wait time before your app starts handling the request +- Reads common queue headers (`X-Request-Start`, `X-Queue-Start`) +- Exposes `rack_queue.rack_queue_duration` (seconds) +- Supports Puma request body wait adjustment (`puma.request_body_wait`) ## Installation -Add to your Gemfile: +Add the gem: ```ruby gem "yabeda-rack-queue" ``` -Then bundle install. +Then install dependencies: -## Usage +```bash +bundle install +``` + +## Quickstart ```ruby require "yabeda/rack/queue" @@ -24,5 +36,34 @@ use Yabeda::Rack::Queue::Middleware run MyRackApp ``` -The middleware inspects `X-Request-Start` / `X-Queue-Start` headers and records -`rack_queue.rack_queue_duration` histogram values in seconds. +Send a request with an upstream queue header (for example `X-Request-Start`) and +the middleware will record `rack_queue.rack_queue_duration`. + +## Metric + +- Name: `rack_queue_duration` +- Group: `rack_queue` +- Type: histogram +- Unit: seconds + +## Development + +Run tests: + +```bash +bundle exec rake test +``` + +Run lint: + +```bash +bundle exec standardrb +``` + +## Contributing + +Issues and pull requests are welcome. + +## License + +MIT, see [LICENSE.txt](LICENSE.txt). diff --git a/Rakefile b/Rakefile index b6ae734..e1e4c5a 100644 --- a/Rakefile +++ b/Rakefile @@ -1,8 +1,11 @@ # frozen_string_literal: true require "bundler/gem_tasks" -require "rspec/core/rake_task" +require "rake/testtask" -RSpec::Core::RakeTask.new(:spec) +Rake::TestTask.new(:test) do |test| + test.libs << "test" + test.pattern = "test/**/*_test.rb" +end -task default: :spec +task default: :test diff --git a/SPEC.md b/SPEC.md index 9a382de..429c037 100644 --- a/SPEC.md +++ b/SPEC.md @@ -6,6 +6,9 @@ This gem measures HTTP request queue time — the duration between when a revers proxy or load balancer first receives a request and when the Ruby application begins processing it. It reports this as a Yabeda histogram metric. +The gem follows the Rack SPEC and uses Rack env/request-response conventions, +but it should not declare `rack` as a gem dependency. + ## Metric | Name | Type | Group | Unit | Description | @@ -136,4 +139,3 @@ Assumptions used below: | `1699999999.900` | `1700000000.000` | `0.100` | `"40"` (ms) | `0.060` | | `1700000000.050` | `1700000000.000` | `-0.050` | _absent_ | dropped (clock skew, WARN logged) | | `1699999999.900` | `1700000000.000` | `0.100` | `200` (ms) | `0.000` (post-subtraction clamp) | - diff --git a/spec/yabeda/rack/queue/header_timestamp_parser_spec.rb b/spec/yabeda/rack/queue/header_timestamp_parser_spec.rb deleted file mode 100644 index e2e3488..0000000 --- a/spec/yabeda/rack/queue/header_timestamp_parser_spec.rb +++ /dev/null @@ -1,58 +0,0 @@ -# frozen_string_literal: true - -require "spec_helper" - -RSpec.describe Yabeda::Rack::Queue::HeaderTimestampParser do - subject(:parser) { described_class.new } - - let(:now) { 1_700_000_000.0 } - - describe "#parse" do - it "accepts known valid values from the truth table" do - expectations = { - "t=1512379167.574" => 1_512_379_167.574, - "1512379167.574" => 1_512_379_167.574, - "t=1512379167574" => 1_512_379_167.574, - "1512379167574" => 1_512_379_167.574, - "t=1570633834463123" => 1_570_633_834.463123, - "1570633834463123" => 1_570_633_834.463123, - "t=1512379167" => 1_512_379_167.0, - "1512379167" => 1_512_379_167.0, - " t=1512379167.574 " => 1_512_379_167.574, - "t=1512379167.574, t=1512379168.000" => 1_512_379_167.574 - } - - expectations.each do |header_value, expected| - actual = parser.parse(header_value, now: now) - expect(actual).to be_within(1e-9).of(expected) - end - end - - it "rejects known invalid values from the truth table" do - [ - "invalid", - "t=", - "t=0", - "t=915148800", - "t=1700000035" - ].each do |header_value| - expect(parser.parse(header_value, now: now)).to be_nil - end - end - - it "prefers t= token over plain token when both are present" do - value = parser.parse("1512370000 t=1512379167.574", now: now) - expect(value).to be_within(1e-9).of(1_512_379_167.574) - end - - it "returns nil for non-string values that cannot be parsed" do - expect(parser.parse(nil, now: now)).to be_nil - expect(parser.parse(Object.new, now: now)).to be_nil - end - - it "rejects values more than 30 seconds in the future" do - header_value = "t=#{now + 30.001}" - expect(parser.parse(header_value, now: now)).to be_nil - end - end -end diff --git a/spec/yabeda/rack/queue/metric_spec.rb b/spec/yabeda/rack/queue/metric_spec.rb deleted file mode 100644 index ddf1f1c..0000000 --- a/spec/yabeda/rack/queue/metric_spec.rb +++ /dev/null @@ -1,18 +0,0 @@ -# frozen_string_literal: true - -require "spec_helper" - -RSpec.describe "rack_queue metric registration" do - it "registers rack_queue_duration histogram with required metadata" do - metric = Yabeda.rack_queue.rack_queue_duration - - expect(metric).to be_a(Yabeda::Histogram) - expect(metric.group).to eq(:rack_queue) - expect(metric.unit).to eq(:seconds) - expect(metric.comment).to eq("Time a request waited in the upstream queue before reaching the application") - expect(metric.tags).to eq([]) - expect(metric.buckets).to eq( - [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60] - ) - end -end diff --git a/spec/yabeda/rack/queue/middleware_spec.rb b/spec/yabeda/rack/queue/middleware_spec.rb deleted file mode 100644 index 0edaf22..0000000 --- a/spec/yabeda/rack/queue/middleware_spec.rb +++ /dev/null @@ -1,161 +0,0 @@ -# frozen_string_literal: true - -require "spec_helper" - -RSpec.describe Yabeda::Rack::Queue::Middleware do - let(:response) { [201, {"content-type" => "text/plain"}, ["ok"]] } - let(:app) { ->(_env) { response } } - let(:reporter) do - Class.new do - attr_reader :values - - def initialize - @values = [] - end - - def observe(value) - @values << value - end - end.new - end - let(:now) { 1_700_000_000.0 } - let(:clock) { -> { now } } - let(:logger) do - Class.new do - attr_reader :warnings - - def initialize - @warnings = [] - end - - def warn(message) - @warnings << message - end - end.new - end - let(:middleware) { described_class.new(app, reporter: reporter, clock: clock, logger: logger) } - - describe "#call" do - it "always calls the downstream app and returns the downstream response unchanged" do - env = {} - expect(app).to receive(:call).with(env).and_call_original - - result = middleware.call(env) - - expect(result).to equal(response) - end - - it "does not mutate rack env" do - env = {"HTTP_X_REQUEST_START" => "t=1699999999.9", "custom.key" => "value"} - original = env.dup - - middleware.call(env) - - expect(env).to eq(original) - end - - it "records nothing when neither header is present" do - middleware.call({}) - expect(reporter.values).to be_empty - end - - it "uses HTTP_X_REQUEST_START before HTTP_X_QUEUE_START when both are valid" do - env = { - "HTTP_X_REQUEST_START" => "t=1699999999.9", - "HTTP_X_QUEUE_START" => "t=1699999999.8" - } - - middleware.call(env) - - expect(reporter.values.last).to be_within(1e-4).of(0.1) - end - - it "falls back to HTTP_X_QUEUE_START when HTTP_X_REQUEST_START is invalid" do - env = { - "HTTP_X_REQUEST_START" => "invalid", - "HTTP_X_QUEUE_START" => "t=1699999999.9" - } - - middleware.call(env) - - expect(reporter.values.last).to be_within(1e-4).of(0.1) - end - - it "computes queue time before calling downstream app" do - sleeping_app = ->(_env) do - sleep 0.05 - response - end - test_middleware = described_class.new(sleeping_app, reporter: reporter, clock: clock, logger: logger) - - test_middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") - - expect(reporter.values.last).to be_within(1e-4).of(0.1) - end - - it "uses Process.clock_gettime(Process::CLOCK_REALTIME) by default" do - default_clock_middleware = described_class.new(app, reporter: reporter, logger: logger) - expect(Process).to receive(:clock_gettime).with(Process::CLOCK_REALTIME).and_return(now) - - default_clock_middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") - end - - it "never raises on invalid header values" do - expect do - middleware.call("HTTP_X_REQUEST_START" => Object.new, "HTTP_X_QUEUE_START" => "") - end.not_to raise_error - end - - it "drops negative queue times and logs warning" do - middleware.call("HTTP_X_REQUEST_START" => "t=1700000000.1") - - expect(reporter.values).to be_empty - expect(logger.warnings.join("\n")).to include("Negative rack queue duration") - end - - it "subtracts puma.request_body_wait milliseconds from queue time" do - middleware.call( - "HTTP_X_REQUEST_START" => "t=1699999999.9", - "puma.request_body_wait" => 40 - ) - - expect(reporter.values.last).to be_within(1e-4).of(0.06) - end - - it "coerces string puma.request_body_wait values" do - middleware.call( - "HTTP_X_REQUEST_START" => "t=1699999999.9", - "puma.request_body_wait" => "40" - ) - - expect(reporter.values.last).to be_within(1e-4).of(0.06) - end - - it "ignores non-numeric puma.request_body_wait values" do - middleware.call( - "HTTP_X_REQUEST_START" => "t=1699999999.9", - "puma.request_body_wait" => "not-a-number" - ) - - expect(reporter.values.last).to be_within(1e-4).of(0.1) - end - - it "ignores negative puma.request_body_wait values" do - middleware.call( - "HTTP_X_REQUEST_START" => "t=1699999999.9", - "puma.request_body_wait" => -40 - ) - - expect(reporter.values.last).to be_within(1e-4).of(0.1) - end - - it "clamps to zero after puma.request_body_wait subtraction" do - middleware.call( - "HTTP_X_REQUEST_START" => "t=1699999999.9", - "puma.request_body_wait" => 200 - ) - - expect(reporter.values.last).to eq(0.0) - end - end -end diff --git a/spec/e2e/puma_integration_spec.rb b/test/e2e/puma_integration_test.rb similarity index 71% rename from spec/e2e/puma_integration_spec.rb rename to test/e2e/puma_integration_test.rb index 3d2077b..0139fd9 100644 --- a/spec/e2e/puma_integration_spec.rb +++ b/test/e2e/puma_integration_test.rb @@ -1,6 +1,6 @@ # frozen_string_literal: true -require "spec_helper" +require "test_helper" require "net/http" require "puma" require "socket" @@ -40,39 +40,38 @@ def wait_until_ready end end -RSpec.describe "Puma E2E queue time reporting" do - let(:rack_app) do - Yabeda::Rack::Queue::Middleware.new( +class PumaIntegrationTest < Minitest::Test + def setup + super + rack_app = Yabeda::Rack::Queue::Middleware.new( ->(_env) { [200, {"content-type" => "text/plain"}, ["ok"]] } ) - end - let(:server) { PumaServerHarness.new(rack_app) } - - before do - server.start + @server = PumaServerHarness.new(rack_app) + @server.start rescue Errno::EPERM skip "Socket binding is not permitted in this environment" end - after do - server.stop + def teardown + @server&.stop + super end - it "records rack_queue_duration histogram via Yabeda on a real HTTP request" do + def test_records_rack_queue_duration_histogram_via_yabeda_on_real_http_request requested_queue_time_seconds = 0.12 request_start_ms = ((Time.now.to_f - requested_queue_time_seconds) * 1_000).to_i - uri = URI("http://127.0.0.1:#{server.port}/") + uri = URI("http://127.0.0.1:#{@server.port}/") request = Net::HTTP::Get.new(uri) request["X-Request-Start"] = request_start_ms.to_s response = Net::HTTP.start(uri.host, uri.port) { |http| http.request(request) } - expect(response.code).to eq("200") + assert_equal "200", response.code metric = Yabeda.rack_queue.rack_queue_duration measured = Yabeda::TestAdapter.instance.histograms.fetch(metric).fetch({}) - expect(measured).to be_a(Float) - expect(measured).to be >= (requested_queue_time_seconds - 0.005) + assert_kind_of Float, measured + assert_operator measured, :>=, requested_queue_time_seconds end end diff --git a/spec/spec_helper.rb b/test/test_helper.rb similarity index 66% rename from spec/spec_helper.rb rename to test/test_helper.rb index b9a3bc5..8c434cc 100644 --- a/spec/spec_helper.rb +++ b/test/test_helper.rb @@ -1,17 +1,16 @@ # frozen_string_literal: true require "bundler/setup" +require "minitest/autorun" require "yabeda/test_adapter" require "yabeda/rack/queue" Yabeda.register_adapter(:test, Yabeda::TestAdapter.instance) Yabeda.configure! unless Yabeda.configured? -RSpec.configure do |config| - config.disable_monkey_patching! - config.expect_with(:rspec) { |c| c.syntax = :expect } - - config.before do +class Minitest::Test + def setup + super Yabeda::TestAdapter.instance.reset! end end diff --git a/test/yabeda/rack/queue/header_timestamp_parser_test.rb b/test/yabeda/rack/queue/header_timestamp_parser_test.rb new file mode 100644 index 0000000..a4617bd --- /dev/null +++ b/test/yabeda/rack/queue/header_timestamp_parser_test.rb @@ -0,0 +1,52 @@ +# frozen_string_literal: true + +require "test_helper" + +class HeaderTimestampParserTest < Minitest::Test + def setup + super + @parser = Yabeda::Rack::Queue::HeaderTimestampParser.new + @now = 1_700_000_000.0 + end + + def test_accepts_known_valid_values_from_truth_table + expectations = { + "t=1512379167.574" => 1_512_379_167.574, + "1512379167.574" => 1_512_379_167.574, + "t=1512379167574" => 1_512_379_167.574, + "1512379167574" => 1_512_379_167.574, + "t=1570633834463123" => 1_570_633_834.463123, + "1570633834463123" => 1_570_633_834.463123, + "t=1512379167" => 1_512_379_167.0, + "1512379167" => 1_512_379_167.0, + " t=1512379167.574 " => 1_512_379_167.574, + "t=1512379167.574, t=1512379168.000" => 1_512_379_167.574 + } + + expectations.each do |header_value, expected| + actual = @parser.parse(header_value, now: @now) + assert_in_delta expected, actual, 1e-9, header_value + end + end + + def test_rejects_known_invalid_values_from_truth_table + ["invalid", "t=", "t=0", "t=915148800", "t=1700000035"].each do |header_value| + assert_nil @parser.parse(header_value, now: @now), header_value + end + end + + def test_prefers_t_equals_token_over_plain_token_when_both_are_present + value = @parser.parse("1512370000 t=1512379167.574", now: @now) + assert_in_delta 1_512_379_167.574, value, 1e-9 + end + + def test_returns_nil_for_non_string_values_that_cannot_be_parsed + assert_nil @parser.parse(nil, now: @now) + assert_nil @parser.parse(Object.new, now: @now) + end + + def test_rejects_values_more_than_30_seconds_in_the_future + header_value = "t=#{@now + 30.001}" + assert_nil @parser.parse(header_value, now: @now) + end +end diff --git a/test/yabeda/rack/queue/metric_test.rb b/test/yabeda/rack/queue/metric_test.rb new file mode 100644 index 0000000..370dbab --- /dev/null +++ b/test/yabeda/rack/queue/metric_test.rb @@ -0,0 +1,16 @@ +# frozen_string_literal: true + +require "test_helper" + +class MetricTest < Minitest::Test + def test_registers_rack_queue_duration_histogram_with_required_metadata + metric = Yabeda.rack_queue.rack_queue_duration + + assert_instance_of Yabeda::Histogram, metric + assert_equal :rack_queue, metric.group + assert_equal :seconds, metric.unit + assert_equal "Time a request waited in the upstream queue before reaching the application", metric.comment + assert_equal [], metric.tags + assert_equal [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60], metric.buckets + end +end diff --git a/test/yabeda/rack/queue/middleware_test.rb b/test/yabeda/rack/queue/middleware_test.rb new file mode 100644 index 0000000..e27e6b4 --- /dev/null +++ b/test/yabeda/rack/queue/middleware_test.rb @@ -0,0 +1,191 @@ +# frozen_string_literal: true + +require "test_helper" + +class CapturingReporter + attr_reader :values + + def initialize + @values = [] + end + + def observe(value) + @values << value + end +end + +class CapturingLogger + attr_reader :warnings + + def initialize + @warnings = [] + end + + def warn(message) + @warnings << message + end +end + +class AppSpy + attr_reader :called_count, :last_env + + def initialize(response) + @response = response + @called_count = 0 + end + + def call(env) + @called_count += 1 + @last_env = env + @response + end +end + +class MiddlewareTest < Minitest::Test + def setup + super + @response = [201, {"content-type" => "text/plain"}, ["ok"]] + @app = AppSpy.new(@response) + @reporter = CapturingReporter.new + @now = 1_700_000_000.0 + @clock = -> { @now } + @logger = CapturingLogger.new + @middleware = Yabeda::Rack::Queue::Middleware.new( + @app, + reporter: @reporter, + clock: @clock, + logger: @logger + ) + end + + def test_always_calls_downstream_app_and_returns_response_unchanged + env = {} + + result = @middleware.call(env) + + assert_same @response, result + assert_equal 1, @app.called_count + assert_same env, @app.last_env + end + + def test_does_not_mutate_rack_env + env = {"HTTP_X_REQUEST_START" => "t=1699999999.9", "custom.key" => "value"} + original = env.dup + + @middleware.call(env) + + assert_equal original, env + end + + def test_records_nothing_when_neither_header_is_present + @middleware.call({}) + + assert_empty @reporter.values + end + + def test_uses_x_request_start_before_x_queue_start_when_both_are_valid + env = { + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "HTTP_X_QUEUE_START" => "t=1699999999.8" + } + + @middleware.call(env) + + assert_in_delta 0.1, @reporter.values.last, 1e-4 + end + + def test_falls_back_to_x_queue_start_when_x_request_start_is_invalid + env = { + "HTTP_X_REQUEST_START" => "invalid", + "HTTP_X_QUEUE_START" => "t=1699999999.9" + } + + @middleware.call(env) + + assert_in_delta 0.1, @reporter.values.last, 1e-4 + end + + def test_computes_queue_time_before_calling_downstream_app + sleeping_app = lambda do |_env| + sleep 0.05 + @response + end + test_middleware = Yabeda::Rack::Queue::Middleware.new( + sleeping_app, + reporter: @reporter, + clock: @clock, + logger: @logger + ) + + test_middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") + + assert_in_delta 0.1, @reporter.values.last, 1e-4 + end + + def test_uses_process_clock_gettime_realtime_by_default + middleware = Yabeda::Rack::Queue::Middleware.new(@app, reporter: @reporter, logger: @logger) + + Process.stub(:clock_gettime, @now) do + middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") + end + + refute_empty @reporter.values + end + + def test_never_raises_on_invalid_header_values + @middleware.call("HTTP_X_REQUEST_START" => Object.new, "HTTP_X_QUEUE_START" => "") + assert_equal 1, @app.called_count + end + + def test_drops_negative_queue_times_and_logs_warning + @middleware.call("HTTP_X_REQUEST_START" => "t=1700000000.1") + + assert_empty @reporter.values + assert_includes @logger.warnings.join("\n"), "Negative rack queue duration" + end + + def test_subtracts_puma_request_body_wait_milliseconds_from_queue_time + @middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => 40 + ) + + assert_in_delta 0.06, @reporter.values.last, 1e-4 + end + + def test_coerces_string_puma_request_body_wait_values + @middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => "40" + ) + + assert_in_delta 0.06, @reporter.values.last, 1e-4 + end + + def test_ignores_non_numeric_puma_request_body_wait_values + @middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => "not-a-number" + ) + + assert_in_delta 0.1, @reporter.values.last, 1e-4 + end + + def test_ignores_negative_puma_request_body_wait_values + @middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => -40 + ) + + assert_in_delta 0.1, @reporter.values.last, 1e-4 + end + + def test_clamps_to_zero_after_puma_request_body_wait_subtraction + @middleware.call( + "HTTP_X_REQUEST_START" => "t=1699999999.9", + "puma.request_body_wait" => 200 + ) + + assert_equal 0.0, @reporter.values.last + end +end diff --git a/yabeda-rack-queue.gemspec b/yabeda-rack-queue.gemspec index 12b1ca6..1bf9cb0 100644 --- a/yabeda-rack-queue.gemspec +++ b/yabeda-rack-queue.gemspec @@ -5,23 +5,23 @@ require_relative "lib/yabeda/rack/queue/version" Gem::Specification.new do |spec| spec.name = "yabeda-rack-queue" spec.version = Yabeda::Rack::Queue::VERSION - spec.authors = ["Yabeda Contributors"] - spec.email = ["maintainers@yabeda.dev"] + spec.authors = ["Nate Berkopec"] + spec.email = ["nate.berkopec@speedshop.co"] spec.summary = "Yabeda middleware for HTTP request queue duration" spec.description = <<~DESCRIPTION Rack middleware that measures HTTP request queue duration from upstream headers and reports it to Yabeda as a histogram metric. DESCRIPTION - spec.homepage = "https://github.com/yabeda-rb/yabeda-rack-queue" + spec.homepage = "https://github.com/speedshop/yabeda-rack-queue" spec.license = "MIT" spec.required_ruby_version = ">= 3.1" spec.metadata = { - "bug_tracker_uri" => "https://github.com/yabeda-rb/yabeda-rack-queue/issues", - "changelog_uri" => "https://github.com/yabeda-rb/yabeda-rack-queue/releases", + "bug_tracker_uri" => "https://github.com/speedshop/yabeda-rack-queue/issues", + "changelog_uri" => "https://github.com/speedshop/yabeda-rack-queue/releases", "homepage_uri" => spec.homepage, - "source_code_uri" => "https://github.com/yabeda-rb/yabeda-rack-queue", + "source_code_uri" => "https://github.com/speedshop/yabeda-rack-queue", "rubygems_mfa_required" => "true" } @@ -32,11 +32,10 @@ Gem::Specification.new do |spec| end spec.require_paths = ["lib"] - spec.add_dependency "rack", ">= 2.2", "< 4.0" spec.add_dependency "yabeda", ">= 0.14", "< 1.0" spec.add_development_dependency "puma", ">= 6", "< 8" spec.add_development_dependency "rake", ">= 13.0" - spec.add_development_dependency "rspec", "~> 3.13" + spec.add_development_dependency "minitest", ">= 5.22", "< 6.0" spec.add_development_dependency "standard", "~> 1.44" end From 74ec5ecee2ec6d57aa3fdb280a0d4ad39916ca06 Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 11:11:27 +0900 Subject: [PATCH 5/8] Tighten spec compliance tests and enforce perf target --- .github/workflows/ci.yml | 2 +- Gemfile.lock | 6 +++++ SPEC.md | 15 +++++++++++ lib/yabeda/rack/queue/middleware.rb | 27 +++++++++++-------- test/yabeda/rack/queue/gemspec_test.rb | 13 +++++++++ .../queue/header_timestamp_parser_test.rb | 9 +++++++ .../rack/queue/middleware_performance_test.rb | 23 ++++++++++++++++ test/yabeda/rack/queue/middleware_test.rb | 10 ++++++- yabeda-rack-queue.gemspec | 2 ++ 9 files changed, 94 insertions(+), 13 deletions(-) create mode 100644 test/yabeda/rack/queue/gemspec_test.rb create mode 100644 test/yabeda/rack/queue/middleware_performance_test.rb diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index dfc64c4..713e182 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -2,7 +2,7 @@ name: CI on: push: - branches: ["**"] + branches: [main] pull_request: workflow_dispatch: diff --git a/Gemfile.lock b/Gemfile.lock index 27a2b28..74bc6e9 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -10,6 +10,8 @@ GEM anyway_config (2.8.0) ruby-next-core (~> 1.0) ast (2.4.3) + benchmark (0.5.0) + benchmark-ips (2.14.0) concurrent-ruby (1.3.6) dry-initializer (3.2.0) json (2.18.1) @@ -73,6 +75,8 @@ PLATFORMS ruby DEPENDENCIES + benchmark (>= 0.4, < 1.0) + benchmark-ips (>= 2.14, < 3.0) minitest (>= 5.22, < 6.0) puma (>= 6, < 8) rake (>= 13.0) @@ -82,6 +86,8 @@ DEPENDENCIES CHECKSUMS anyway_config (2.8.0) sha256=f6797a7231f81202dcd3d0c07284e836e45713e761d320180348b13a5c7c9306 ast (2.4.3) sha256=954615157c1d6a382bc27d690d973195e79db7f55e9765ac7c481c60bdb4d383 + benchmark (0.5.0) sha256=465df122341aedcb81a2a24b4d3bd19b6c67c1530713fd533f3ff034e419236c + benchmark-ips (2.14.0) sha256=b72bc8a65d525d5906f8cd94270dccf73452ee3257a32b89fbd6684d3e8a9b1d concurrent-ruby (1.3.6) sha256=6b56837e1e7e5292f9864f34b69c5a2cbc75c0cf5338f1ce9903d10fa762d5ab dry-initializer (3.2.0) sha256=37d59798f912dc0a1efe14a4db4a9306989007b302dcd5f25d0a2a20c166c4e3 json (2.18.1) sha256=fe112755501b8d0466b5ada6cf50c8c3f41e897fa128ac5d263ec09eedc9f986 diff --git a/SPEC.md b/SPEC.md index 429c037..859c68d 100644 --- a/SPEC.md +++ b/SPEC.md @@ -9,6 +9,14 @@ begins processing it. It reports this as a Yabeda histogram metric. The gem follows the Rack SPEC and uses Rack env/request-response conventions, but it should not declare `rack` as a gem dependency. +## Testing Framework + +The test suite uses Minitest. + +## Linting + +Linting uses standardrb. + ## Metric | Name | Type | Group | Unit | Description | @@ -43,6 +51,13 @@ unaffected. (wall clock, not monotonic — necessary because the header timestamp comes from a different process). +## Performance Requirement + +For a no-op Rack app (for example, one that returns `hello world`), middleware +throughput MUST exceed `1_000_000` calls/second. + +This requirement is enforced with a `benchmark-ips` benchmark test. + ## Header Value Parsing Header values are parsed for compatibility with common reverse proxies and APM diff --git a/lib/yabeda/rack/queue/middleware.rb b/lib/yabeda/rack/queue/middleware.rb index fd3bebb..fb3ae12 100644 --- a/lib/yabeda/rack/queue/middleware.rb +++ b/lib/yabeda/rack/queue/middleware.rb @@ -28,26 +28,31 @@ def initialize(app, reporter: YabedaReporter.new, parser: HeaderTimestampParser. end def call(env) - now = @clock.call - request_start = request_start_timestamp(env, now) + x_request_start = env[HEADER_KEYS[0]] + x_queue_start = env[HEADER_KEYS[1]] - report_queue_time(env, now, request_start) if request_start + if x_request_start || x_queue_start + now = @clock.call + request_start = request_start_timestamp(x_request_start, x_queue_start, now) + report_queue_time(env, now, request_start) if request_start + end @app.call(env) end private - def request_start_timestamp(env, now) - HEADER_KEYS.each do |header_key| - header_value = env[header_key] - next if header_value.nil? + def request_start_timestamp(x_request_start, x_queue_start, now) + parsed = parse_header_timestamp(x_request_start, now) + return parsed if parsed - parsed = @parser.parse(header_value, now: now) - return parsed if parsed - end + parse_header_timestamp(x_queue_start, now) + end - nil + def parse_header_timestamp(value, now) + return nil if value.nil? + + @parser.parse(value, now: now) end def report_queue_time(env, now, request_start) diff --git a/test/yabeda/rack/queue/gemspec_test.rb b/test/yabeda/rack/queue/gemspec_test.rb new file mode 100644 index 0000000..b8b3b84 --- /dev/null +++ b/test/yabeda/rack/queue/gemspec_test.rb @@ -0,0 +1,13 @@ +# frozen_string_literal: true + +require "test_helper" + +class GemspecTest < Minitest::Test + def test_does_not_declare_rack_runtime_dependency + gemspec_path = File.expand_path("../../../../yabeda-rack-queue.gemspec", __dir__) + spec = Gem::Specification.load(gemspec_path) + + refute_nil spec + assert_nil spec.runtime_dependencies.find { |dependency| dependency.name == "rack" } + end +end diff --git a/test/yabeda/rack/queue/header_timestamp_parser_test.rb b/test/yabeda/rack/queue/header_timestamp_parser_test.rb index a4617bd..a83e83f 100644 --- a/test/yabeda/rack/queue/header_timestamp_parser_test.rb +++ b/test/yabeda/rack/queue/header_timestamp_parser_test.rb @@ -49,4 +49,13 @@ def test_rejects_values_more_than_30_seconds_in_the_future header_value = "t=#{@now + 30.001}" assert_nil @parser.parse(header_value, now: @now) end + + def test_accepts_values_exactly_30_seconds_in_the_future + header_value = "t=#{@now + 30.0}" + assert_in_delta @now + 30.0, @parser.parse(header_value, now: @now), 1e-9 + end + + def test_uses_only_first_comma_separated_value + assert_nil @parser.parse("invalid, t=1512379167.574", now: @now) + end end diff --git a/test/yabeda/rack/queue/middleware_performance_test.rb b/test/yabeda/rack/queue/middleware_performance_test.rb new file mode 100644 index 0000000..f104e09 --- /dev/null +++ b/test/yabeda/rack/queue/middleware_performance_test.rb @@ -0,0 +1,23 @@ +# frozen_string_literal: true + +require "test_helper" +require "benchmark/ips" + +class MiddlewarePerformanceTest < Minitest::Test + MINIMUM_IPS = 1_000_000.0 + + def test_processes_noop_rack_app_above_one_million_calls_per_second + response = [200, {"content-type" => "text/plain"}, ["hello world"]].freeze + app = ->(_env) { response } + middleware = Yabeda::Rack::Queue::Middleware.new(app) + env = {}.freeze + + report = Benchmark.ips do |x| + x.config(time: 1, warmup: 0.5) + x.report("middleware noop call") { middleware.call(env) } + end + + observed_ips = report.entries.fetch(0).ips + assert_operator observed_ips, :>, MINIMUM_IPS + end +end diff --git a/test/yabeda/rack/queue/middleware_test.rb b/test/yabeda/rack/queue/middleware_test.rb index e27e6b4..5f22ccc 100644 --- a/test/yabeda/rack/queue/middleware_test.rb +++ b/test/yabeda/rack/queue/middleware_test.rb @@ -124,22 +124,30 @@ def test_computes_queue_time_before_calling_downstream_app def test_uses_process_clock_gettime_realtime_by_default middleware = Yabeda::Rack::Queue::Middleware.new(@app, reporter: @reporter, logger: @logger) + observed_clock_ids = [] + clock_gettime_stub = lambda do |clock_id| + observed_clock_ids << clock_id + @now + end - Process.stub(:clock_gettime, @now) do + Process.stub(:clock_gettime, clock_gettime_stub) do middleware.call("HTTP_X_REQUEST_START" => "t=1699999999.9") end refute_empty @reporter.values + assert_equal [Process::CLOCK_REALTIME], observed_clock_ids end def test_never_raises_on_invalid_header_values @middleware.call("HTTP_X_REQUEST_START" => Object.new, "HTTP_X_QUEUE_START" => "") assert_equal 1, @app.called_count + assert_empty @reporter.values end def test_drops_negative_queue_times_and_logs_warning @middleware.call("HTTP_X_REQUEST_START" => "t=1700000000.1") + assert_equal 1, @app.called_count assert_empty @reporter.values assert_includes @logger.warnings.join("\n"), "Negative rack queue duration" end diff --git a/yabeda-rack-queue.gemspec b/yabeda-rack-queue.gemspec index 1bf9cb0..c95452b 100644 --- a/yabeda-rack-queue.gemspec +++ b/yabeda-rack-queue.gemspec @@ -37,5 +37,7 @@ Gem::Specification.new do |spec| spec.add_development_dependency "puma", ">= 6", "< 8" spec.add_development_dependency "rake", ">= 13.0" spec.add_development_dependency "minitest", ">= 5.22", "< 6.0" + spec.add_development_dependency "benchmark", ">= 0.4", "< 1.0" + spec.add_development_dependency "benchmark-ips", ">= 2.14", "< 3.0" spec.add_development_dependency "standard", "~> 1.44" end From 4763af4308b8968f1d7cd74525a0f13eb190a796 Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 11:14:20 +0900 Subject: [PATCH 6/8] Remove EPERM rescue from Puma integration setup --- test/e2e/puma_integration_test.rb | 2 -- 1 file changed, 2 deletions(-) diff --git a/test/e2e/puma_integration_test.rb b/test/e2e/puma_integration_test.rb index 0139fd9..def0420 100644 --- a/test/e2e/puma_integration_test.rb +++ b/test/e2e/puma_integration_test.rb @@ -48,8 +48,6 @@ def setup ) @server = PumaServerHarness.new(rack_app) @server.start - rescue Errno::EPERM - skip "Socket binding is not permitted in this environment" end def teardown From 0b4151e7f64360679b3c73f51588694d742acada Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 11:21:35 +0900 Subject: [PATCH 7/8] Revise README for clarity and readability Rewrites the README to explain queue time for new users, documents all middleware configuration options, header formats, and Puma adjustment. Targets Flesch-Kincaid grade 8.9. Co-Authored-By: Claude Sonnet 4.6 --- README.md | 101 ++++++++++++++++++++++++++++++++++++++++++++---------- 1 file changed, 82 insertions(+), 19 deletions(-) diff --git a/README.md b/README.md index aacf67f..67cbd9d 100644 --- a/README.md +++ b/README.md @@ -1,30 +1,39 @@ # yabeda-rack-queue -Rack middleware that measures HTTP request queue time and reports it to -[Yabeda core](https://github.com/yabeda-rb/yabeda) as a histogram. +Rack middleware that measures HTTP request queue time. It reports the result to [Yabeda](https://github.com/yabeda-rb/yabeda) as a histogram. -## Features +## What is queue time? -- Reports upstream queue wait time before your app starts handling the request -- Reads common queue headers (`X-Request-Start`, `X-Queue-Start`) -- Exposes `rack_queue.rack_queue_duration` (seconds) -- Supports Puma request body wait adjustment (`puma.request_body_wait`) +A request may wait before your app handles it. A proxy or load balancer (like Nginx or Heroku) causes this wait. This is called queue time. + +High queue time means your app is too busy. It cannot take new requests. That is a sign you need more capacity. + +## How it works + +Load balancers can add a header to each request. The header records when the request arrived. Common headers are `X-Request-Start` and `X-Queue-Start`. + +This middleware reads that header. It subtracts the header's timestamp from the current time. Then it reports that value as `rack_queue.rack_queue_duration`. + +> [!NOTE] +> If neither header is present, no measurement is taken. The request passes through unchanged. ## Installation -Add the gem: +Add to your Gemfile: ```ruby gem "yabeda-rack-queue" ``` -Then install dependencies: +Then run: ```bash bundle install ``` -## Quickstart +## Usage + +Add the middleware to your Rack stack. You also need a Yabeda adapter. For example, use [yabeda-prometheus](https://github.com/yabeda-rb/yabeda-prometheus). ```ruby require "yabeda/rack/queue" @@ -36,15 +45,69 @@ use Yabeda::Rack::Queue::Middleware run MyRackApp ``` -Send a request with an upstream queue header (for example `X-Request-Start`) and -the middleware will record `rack_queue.rack_queue_duration`. +For Rails, add it in `config/application.rb`: + +```ruby +config.middleware.use Yabeda::Rack::Queue::Middleware +``` ## Metric -- Name: `rack_queue_duration` -- Group: `rack_queue` -- Type: histogram -- Unit: seconds +| Name | Group | Type | Unit | +|------|-------|------|------| +| `rack_queue_duration` | `rack_queue` | histogram | seconds | + +Access it in code: + +```ruby +Yabeda.rack_queue.rack_queue_duration +``` + +Histogram buckets: 1 ms, 5 ms, 10 ms, 25 ms, 50 ms, 100 ms, 250 ms, 500 ms, 1 s, 2.5 s, 5 s, 10 s, 30 s, 60 s. + +## Header formats + +The middleware checks `X-Request-Start` first. If that header is absent, it tries `X-Queue-Start`. + +Supported timestamp formats: + +| Format | Example | +|--------|---------| +| Seconds (float) | `1609459200.123` | +| Milliseconds | `1609459200123` | +| Microseconds | `1609459200123456` | +| `t=` prefix | `t=1609459200.123` | + +The middleware auto-detects the unit. It checks if the number fits a valid recent time. + +## Puma adjustment + +Puma sets `puma.request_body_wait` (in milliseconds) in the Rack env. This records how long Puma spent reading the request body. + +The middleware subtracts this value from queue time. Without this step, large bodies make queue time appear too long. + +## Configuration + +The middleware accepts these keyword arguments: + +| Argument | Default | Purpose | +|----------|---------|---------| +| `reporter:` | `YabedaReporter.new` | Writes the value to Yabeda. | +| `parser:` | `HeaderTimestampParser.new` | Parses the header timestamp. | +| `logger:` | stderr | Gets warning messages. | +| `clock:` | `Process.clock_gettime(CLOCK_REALTIME)` | Returns current time in seconds. | + +Example with a custom logger: + +```ruby +use Yabeda::Rack::Queue::Middleware, logger: Rails.logger +``` + +## Requirements + +- Ruby >= 3.1. +- yabeda >= 0.14, < 1.0. +- A Yabeda adapter. For example: [yabeda-prometheus](https://github.com/yabeda-rb/yabeda-prometheus). ## Development @@ -54,7 +117,7 @@ Run tests: bundle exec rake test ``` -Run lint: +Run the linter: ```bash bundle exec standardrb @@ -62,8 +125,8 @@ bundle exec standardrb ## Contributing -Issues and pull requests are welcome. +Bug reports and pull requests are welcome at . ## License -MIT, see [LICENSE.txt](LICENSE.txt). +MIT. See [LICENSE.txt](LICENSE.txt). From 8eb8b2ac4bd219f6484d95f789832e688192281b Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 3 Mar 2026 11:23:38 +0900 Subject: [PATCH 8/8] Add lint task to Rakefile and include in default Co-Authored-By: Claude Sonnet 4.6 --- Rakefile | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/Rakefile b/Rakefile index e1e4c5a..6bd32f4 100644 --- a/Rakefile +++ b/Rakefile @@ -3,9 +3,13 @@ require "bundler/gem_tasks" require "rake/testtask" +task :lint do + sh "bundle exec standardrb" +end + Rake::TestTask.new(:test) do |test| test.libs << "test" test.pattern = "test/**/*_test.rb" end -task default: :test +task default: %i[lint test]