diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml new file mode 100644 index 0000000..713e182 --- /dev/null +++ b/.github/workflows/ci.yml @@ -0,0 +1,57 @@ +name: CI + +on: + push: + branches: [main] + pull_request: + workflow_dispatch: + +jobs: + lint: + runs-on: ubuntu-latest + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Set up Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: "3.1" + bundler-cache: true + + - name: Run linter + run: bundle exec standardrb + + test: + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + ruby: ["3.1", "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 tests + run: bundle exec rake test + + package: + runs-on: ubuntu-latest + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Set up Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: "4.0" + 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/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..74bc6e9 --- /dev/null +++ b/Gemfile.lock @@ -0,0 +1,120 @@ +PATH + remote: . + specs: + yabeda-rack-queue (0.1.0) + yabeda (>= 0.14, < 1.0) + +GEM + remote: https://rubygems.org/ + specs: + 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) + 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) + ast (~> 2.4.1) + racc + prism (1.9.0) + puma (7.2.0) + nio4r (~> 2.0) + racc (1.8.1) + rainbow (3.1.1) + rake (13.3.1) + regexp_parser (2.11.3) + 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 + dry-initializer + +PLATFORMS + arm64-darwin-24 + ruby + +DEPENDENCIES + benchmark (>= 0.4, < 1.0) + benchmark-ips (>= 2.14, < 3.0) + minitest (>= 5.22, < 6.0) + puma (>= 6, < 8) + rake (>= 13.0) + standard (~> 1.44) + yabeda-rack-queue! + +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 + 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 + rainbow (3.1.1) sha256=039491aa3a89f42efa1d6dec2fc4e62ede96eb6acd95e52f1ad581182b79bc6a + rake (13.3.1) sha256=8c9e89d09f66a26a01264e7e3480ec0607f0c497a861ef16063604b1b08eb19c + regexp_parser (2.11.3) sha256=ca13f381a173b7a93450e53459075c9b76a10433caadcb2f1180f2c741fc55a4 + 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) + +BUNDLED WITH + 4.0.3 diff --git a/README.md b/README.md new file mode 100644 index 0000000..67cbd9d --- /dev/null +++ b/README.md @@ -0,0 +1,132 @@ +# yabeda-rack-queue + +Rack middleware that measures HTTP request queue time. It reports the result to [Yabeda](https://github.com/yabeda-rb/yabeda) as a histogram. + +## What is queue time? + +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 to your Gemfile: + +```ruby +gem "yabeda-rack-queue" +``` + +Then run: + +```bash +bundle install +``` + +## 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" +require "yabeda/prometheus" + +Yabeda.configure! + +use Yabeda::Rack::Queue::Middleware +run MyRackApp +``` + +For Rails, add it in `config/application.rb`: + +```ruby +config.middleware.use Yabeda::Rack::Queue::Middleware +``` + +## Metric + +| 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 + +Run tests: + +```bash +bundle exec rake test +``` + +Run the linter: + +```bash +bundle exec standardrb +``` + +## Contributing + +Bug reports and pull requests are welcome at . + +## License + +MIT. See [LICENSE.txt](LICENSE.txt). diff --git a/Rakefile b/Rakefile new file mode 100644 index 0000000..6bd32f4 --- /dev/null +++ b/Rakefile @@ -0,0 +1,15 @@ +# frozen_string_literal: true + +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: %i[lint test] diff --git a/SPEC.md b/SPEC.md index 9a382de..859c68d 100644 --- a/SPEC.md +++ b/SPEC.md @@ -6,6 +6,17 @@ 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. + +## Testing Framework + +The test suite uses Minitest. + +## Linting + +Linting uses standardrb. + ## Metric | Name | Type | Group | Unit | Description | @@ -40,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 @@ -136,4 +154,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/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..2e14a9a --- /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+)/ + T_EQUALS_PATTERN = /t\s*=\s*(#{NUMBER_PATTERN.source})/i + + 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..e219710 --- /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..fb3ae12 --- /dev/null +++ b/lib/yabeda/rack/queue/middleware.rb @@ -0,0 +1,85 @@ +# 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) + Kernel.warn(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) + x_request_start = env[HEADER_KEYS[0]] + x_queue_start = env[HEADER_KEYS[1]] + + 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(x_request_start, x_queue_start, now) + parsed = parse_header_timestamp(x_request_start, now) + return parsed if parsed + + parse_header_timestamp(x_queue_start, now) + end + + 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) + 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/test/e2e/puma_integration_test.rb b/test/e2e/puma_integration_test.rb new file mode 100644 index 0000000..def0420 --- /dev/null +++ b/test/e2e/puma_integration_test.rb @@ -0,0 +1,75 @@ +# frozen_string_literal: true + +require "test_helper" +require "net/http" +require "puma" +require "socket" +require "timeout" + +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 + socket = TCPSocket.new("127.0.0.1", port) + socket.close + break + rescue Errno::ECONNREFUSED + sleep 0.01 + end + end + end +end + +class PumaIntegrationTest < Minitest::Test + def setup + super + rack_app = Yabeda::Rack::Queue::Middleware.new( + ->(_env) { [200, {"content-type" => "text/plain"}, ["ok"]] } + ) + @server = PumaServerHarness.new(rack_app) + @server.start + end + + def teardown + @server&.stop + super + end + + 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}/") + 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) } + + assert_equal "200", response.code + + metric = Yabeda.rack_queue.rack_queue_duration + measured = Yabeda::TestAdapter.instance.histograms.fetch(metric).fetch({}) + + assert_kind_of Float, measured + assert_operator measured, :>=, requested_queue_time_seconds + end +end diff --git a/test/test_helper.rb b/test/test_helper.rb new file mode 100644 index 0000000..8c434cc --- /dev/null +++ b/test/test_helper.rb @@ -0,0 +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? + +class Minitest::Test + def setup + super + Yabeda::TestAdapter.instance.reset! + end +end 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 new file mode 100644 index 0000000..a83e83f --- /dev/null +++ b/test/yabeda/rack/queue/header_timestamp_parser_test.rb @@ -0,0 +1,61 @@ +# 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 + + 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/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_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 new file mode 100644 index 0000000..5f22ccc --- /dev/null +++ b/test/yabeda/rack/queue/middleware_test.rb @@ -0,0 +1,199 @@ +# 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) + observed_clock_ids = [] + clock_gettime_stub = lambda do |clock_id| + observed_clock_ids << clock_id + @now + end + + 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 + + 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 new file mode 100644 index 0000000..c95452b --- /dev/null +++ b/yabeda-rack-queue.gemspec @@ -0,0 +1,43 @@ +# 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 = ["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/speedshop/yabeda-rack-queue" + spec.license = "MIT" + spec.required_ruby_version = ">= 3.1" + + spec.metadata = { + "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/speedshop/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 "yabeda", ">= 0.14", "< 1.0" + + 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