discourse/spec/lib/middleware/request_tracker_spec.rb

# frozen_string_literal: true

RSpec.describe Middleware::RequestTracker do
  def env(opts = {})
    path = opts.delete(:path) || "/path?bla=1"
    create_request_env(path: path).merge(
      "HTTP_HOST" => "http://test.com",
      "HTTP_USER_AGENT" =>
        "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2228.0 Safari/537.36",
      "REQUEST_METHOD" => "GET",
      "HTTP_ACCEPT" =>
        "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8",
      "rack.input" => StringIO.new,
    ).merge(opts)
  end

  before do
    ApplicationRequest.enable
    CachedCounting.reset
    CachedCounting.enable
  end

  after do
    CachedCounting.reset
    ApplicationRequest.disable
    CachedCounting.disable
  end

  describe "full request" do
    it "can handle rogue user agents" do
      agent = (+"Evil Googlebot String \xc3\x28").force_encoding("Windows-1252")

      middleware =
        Middleware::RequestTracker.new(->(env) { ["200", { "Content-Type" => "text/html" }, [""]] })
      middleware.call(env("HTTP_USER_AGENT" => agent))

      CachedCounting.flush

      expect(WebCrawlerRequest.where(user_agent: agent.encode("utf-8")).count).to eq(1)
    end
  end

  describe "log_request" do
    before do
      freeze_time
      ApplicationRequest.clear_cache!
    end

    def log_tracked_view(val)
      data =
        Middleware::RequestTracker.get_data(
          env("HTTP_DISCOURSE_TRACK_VIEW" => val),
          ["200", { "Content-Type" => "text/html" }],
          0.2,
        )

      Middleware::RequestTracker.log_request(data)
    end

    it "can exclude/include based on custom header" do
      log_tracked_view("true")
      log_tracked_view("1")
      log_tracked_view("false")
      log_tracked_view("0")

      CachedCounting.flush

      expect(ApplicationRequest.page_view_anon.first.count).to eq(2)
      expect(ApplicationRequest.page_view_anon_browser.first.count).to eq(2)
    end

    it "can log requests correctly" do
      data =
        Middleware::RequestTracker.get_data(
          env("HTTP_USER_AGENT" => "AdsBot-Google (+http://www.google.com/adsbot.html)"),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      data =
        Middleware::RequestTracker.get_data(
          env("HTTP_DISCOURSE_TRACK_VIEW" => "1"),
          ["200", {}],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      data =
        Middleware::RequestTracker.get_data(
          env(
            "HTTP_USER_AGENT" =>
              "Mozilla/5.0 (iPhone; CPU iPhone OS 8_1 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko) Version/8.0 Mobile/12B410 Safari/600.1.4",
          ),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      # /srv/status is never a tracked view because content-type is text/plain
      data =
        Middleware::RequestTracker.get_data(
          env("HTTP_USER_AGENT" => "kube-probe/1.18", "REQUEST_URI" => "/srv/status?shutdown_ok=1"),
          ["200", { "Content-Type" => "text/plain" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      CachedCounting.flush

      expect(ApplicationRequest.http_total.first.count).to eq(4)
      expect(ApplicationRequest.http_2xx.first.count).to eq(4)

      expect(ApplicationRequest.page_view_anon.first.count).to eq(2)
      expect(ApplicationRequest.page_view_crawler.first.count).to eq(1)
      expect(ApplicationRequest.page_view_anon_mobile.first.count).to eq(1)

      expect(ApplicationRequest.page_view_crawler.first.count).to eq(1)

      expect(ApplicationRequest.page_view_anon_browser.first.count).to eq(1)
    end

    it "logs deferred pageviews correctly" do
      data =
        Middleware::RequestTracker.get_data(
          env(:path => "/message-bus/abcde/poll", "HTTP_DISCOURSE_DEFERRED_TRACK_VIEW" => "1"),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )
      Middleware::RequestTracker.log_request(data)

      expect(data[:deferred_track]).to eq(true)
      CachedCounting.flush

      expect(ApplicationRequest.page_view_anon_browser.first.count).to eq(1)
    end

    it "logs API requests correctly" do
      data =
        Middleware::RequestTracker.get_data(
          env("_DISCOURSE_API" => "1"),
          ["200", { "Content-Type" => "text/json" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      data =
        Middleware::RequestTracker.get_data(
          env("_DISCOURSE_API" => "1"),
          ["404", { "Content-Type" => "text/json" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      data =
        Middleware::RequestTracker.get_data(env("_DISCOURSE_USER_API" => "1"), ["200", {}], 0.1)

      Middleware::RequestTracker.log_request(data)
      CachedCounting.flush

      expect(ApplicationRequest.http_total.first.count).to eq(3)
      expect(ApplicationRequest.http_2xx.first.count).to eq(2)

      expect(ApplicationRequest.api.first.count).to eq(2)
      expect(ApplicationRequest.user_api.first.count).to eq(1)
    end

    it "can log Discourse user agent requests correctly" do
      # log discourse api agents as crawlers for page view stats...
      data =
        Middleware::RequestTracker.get_data(
          env("HTTP_USER_AGENT" => "DiscourseAPI Ruby Gem 0.19.0"),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      CachedCounting.flush
      CachedCounting.reset

      expect(ApplicationRequest.page_view_crawler.first.count).to eq(1)

      # ...but count our mobile app user agents as regular visits
      data =
        Middleware::RequestTracker.get_data(
          env("HTTP_USER_AGENT" => "Mozilla/5.0 AppleWebKit/605.1.15 Mobile/15E148 DiscourseHub)"),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )

      Middleware::RequestTracker.log_request(data)

      CachedCounting.flush

      expect(ApplicationRequest.page_view_crawler.first.count).to eq(1)
      expect(ApplicationRequest.page_view_anon.first.count).to eq(1)
    end

    context "when ignoring anonymous page views" do
      let(:anon_data) do
        Middleware::RequestTracker.get_data(
          env(
            "HTTP_USER_AGENT" =>
              "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.72 Safari/537.36",
          ),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )
      end

      let(:logged_in_data) do
        user = Fabricate(:user, active: true)
        token = UserAuthToken.generate!(user_id: user.id)
        cookie =
          create_auth_cookie(
            token: token.unhashed_auth_token,
            user_id: user.id,
            trust_level: user.trust_level,
            issued_at: 5.minutes.ago,
          )
        Middleware::RequestTracker.get_data(
          env(
            "HTTP_USER_AGENT" =>
              "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.72 Safari/537.36",
            "HTTP_COOKIE" => "_t=#{cookie};",
          ),
          ["200", { "Content-Type" => "text/html" }],
          0.1,
        )
      end

      it "does not ignore anonymous requests for public sites" do
        SiteSetting.login_required = false

        Middleware::RequestTracker.log_request(anon_data)
        Middleware::RequestTracker.log_request(logged_in_data)

        CachedCounting.flush

        expect(ApplicationRequest.http_total.first.count).to eq(2)
        expect(ApplicationRequest.http_2xx.first.count).to eq(2)

        expect(ApplicationRequest.page_view_logged_in.first.count).to eq(1)
        expect(ApplicationRequest.page_view_anon.first.count).to eq(1)
      end

      it "ignores anonymous requests for private sites" do
        SiteSetting.login_required = true

        Middleware::RequestTracker.log_request(anon_data)
        Middleware::RequestTracker.log_request(logged_in_data)

        CachedCounting.flush

        expect(ApplicationRequest.http_total.first.count).to eq(2)
        expect(ApplicationRequest.http_2xx.first.count).to eq(2)

        expect(ApplicationRequest.page_view_logged_in.first.count).to eq(1)
        expect(ApplicationRequest.page_view_anon.first).to eq(nil)
      end
    end
  end

  describe "rate limiting" do
    before do
      RateLimiter.enable
      RateLimiter.clear_all_global!

      @orig_logger = Rails.logger
      Rails.logger = @fake_logger = FakeLogger.new

      # rate limiter tests depend on checks for retry-after
      # they can be sensitive to clock skew during test runs
      freeze_time_safe
    end

    use_redis_snapshotting

    after { Rails.logger = @orig_logger }

    let :middleware do
      app = lambda { |env| [200, {}, ["OK"]] }

      Middleware::RequestTracker.new(app)
    end

    it "does nothing if configured to do nothing" do
      global_setting :max_reqs_per_ip_mode, "none"
      global_setting :max_reqs_per_ip_per_10_seconds, 1

      status, _ = middleware.call(env)
      status, _ = middleware.call(env)

      expect(status).to eq(200)
    end

    it "blocks private IPs if not skipped" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "warn+block"
      global_setting :max_reqs_rate_limit_on_private, true

      addresses = %w[
        127.1.2.3
        127.0.0.2
        192.168.1.2
        10.0.1.2
        172.16.9.8
        172.19.1.2
        172.20.9.8
        172.29.1.2
        172.30.9.8
        172.31.1.2
      ]
      warn_count = 1
      addresses.each do |addr|
        env1 = env("REMOTE_ADDR" => addr)

        status, _ = middleware.call(env1)
        status, _ = middleware.call(env1)

        expect(@fake_logger.warnings.count { |w| w.include?("Global rate limit exceeded") }).to eq(
          warn_count,
        )
        expect(status).to eq(429)
        warn_count += 1
      end
    end

    it "blocks if the ip isn't static skipped" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "block"

      env1 = env("REMOTE_ADDR" => "1.1.1.1")
      status, _ = middleware.call(env1)
      status, _ = middleware.call(env1)
      expect(status).to eq(429)
    end

    it "doesn't block if rate limiter is enabled but IP is on the static exception list" do
      stub_const(
        Middleware::RequestTracker,
        "STATIC_IP_SKIPPER",
        "177.33.14.73 191.209.88.192/30".split.map { |ip| IPAddr.new(ip) },
      ) do
        global_setting :max_reqs_per_ip_per_10_seconds, 1
        global_setting :max_reqs_per_ip_mode, "block"

        env1 = env("REMOTE_ADDR" => "177.33.14.73")
        env2 = env("REMOTE_ADDR" => "191.209.88.194")

        status, _ = middleware.call(env1)
        expect(status).to eq(200)

        status, _ = middleware.call(env1)
        expect(status).to eq(200)

        status, _ = middleware.call(env2)
        expect(status).to eq(200)

        status, _ = middleware.call(env2)
        expect(status).to eq(200)
      end
    end

    describe "register_ip_skipper" do
      before do
        Middleware::RequestTracker.register_ip_skipper { |ip| ip == "1.1.1.2" }
        global_setting :max_reqs_per_ip_per_10_seconds, 1
        global_setting :max_reqs_per_ip_mode, "block"
      end

      after { Middleware::RequestTracker.unregister_ip_skipper }

      it "won't block if the ip is skipped" do
        env1 = env("REMOTE_ADDR" => "1.1.1.2")
        status, _ = middleware.call(env1)
        status, _ = middleware.call(env1)
        expect(status).to eq(200)
      end

      it "blocks if the ip isn't skipped" do
        env1 = env("REMOTE_ADDR" => "1.1.1.1")
        status, _ = middleware.call(env1)
        status, _ = middleware.call(env1)
        expect(status).to eq(429)
      end
    end

    it "does nothing for private IPs if skipped" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "warn+block"
      global_setting :max_reqs_rate_limit_on_private, false

      addresses = %w[
        127.1.2.3
        127.0.3.1
        192.168.1.2
        10.0.1.2
        172.16.9.8
        172.19.1.2
        172.20.9.8
        172.29.1.2
        172.30.9.8
        172.31.1.2
      ]
      addresses.each do |addr|
        env1 = env("REMOTE_ADDR" => addr)

        status, _ = middleware.call(env1)
        status, _ = middleware.call(env1)

        expect(@fake_logger.warnings.count { |w| w.include?("Global rate limit exceeded") }).to eq(
          0,
        )
        expect(status).to eq(200)
      end
    end

    it "does warn if rate limiter is enabled via warn+block" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "warn+block"

      status, _ = middleware.call(env)
      status, headers = middleware.call(env)

      expect(@fake_logger.warnings.count { |w| w.include?("Global rate limit exceeded") }).to eq(1)
      expect(status).to eq(429)
      expect(headers["Retry-After"]).to eq("10")
    end

    it "does warn if rate limiter is enabled" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "warn"

      status, _ = middleware.call(env)
      status, _ = middleware.call(env)

      expect(@fake_logger.warnings.count { |w| w.include?("Global rate limit exceeded") }).to eq(1)
      expect(status).to eq(200)
    end

    it "allows assets for more requests" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "block"
      global_setting :max_asset_reqs_per_ip_per_10_seconds, 3

      env1 = env("REMOTE_ADDR" => "1.1.1.1", "DISCOURSE_IS_ASSET_PATH" => 1)

      status, _ = middleware.call(env1)
      expect(status).to eq(200)
      status, _ = middleware.call(env1)
      expect(status).to eq(200)
      status, _ = middleware.call(env1)
      expect(status).to eq(200)
      status, headers = middleware.call(env1)
      expect(status).to eq(429)
      expect(headers["Retry-After"]).to eq("10")

      env2 = env("REMOTE_ADDR" => "1.1.1.1")

      status, headers = middleware.call(env2)
      expect(status).to eq(429)
      expect(headers["Retry-After"]).to eq("10")
    end

    it "does block if rate limiter is enabled" do
      global_setting :max_reqs_per_ip_per_10_seconds, 1
      global_setting :max_reqs_per_ip_mode, "block"

      env1 = env("REMOTE_ADDR" => "1.1.1.1")
      env2 = env("REMOTE_ADDR" => "1.1.1.2")

      status, _ = middleware.call(env1)
      expect(status).to eq(200)

      status, headers = middleware.call(env1)
      expect(status).to eq(429)
      expect(headers["Retry-After"]).to eq("10")

      status, _ = middleware.call(env2)
      expect(status).to eq(200)
    end

    describe "diagnostic information" do
      it "is included when the requests-per-10-seconds limit is reached" do
        global_setting :max_reqs_per_ip_per_10_seconds, 1
        called = 0
        app =
          lambda do |_|
            called += 1
            [200, {}, ["OK"]]
          end
        env = env("REMOTE_ADDR" => "1.1.1.1")
        middleware = Middleware::RequestTracker.new(app)
        status, = middleware.call(env)
        expect(status).to eq(200)
        expect(called).to eq(1)

        env = env("REMOTE_ADDR" => "1.1.1.1")
        middleware = Middleware::RequestTracker.new(app)
        status, headers, response = middleware.call(env)
        expect(status).to eq(429)
        expect(called).to eq(1)
        expect(headers["Discourse-Rate-Limit-Error-Code"]).to eq("ip_10_secs_limit")
        expect(response.first).to include("too many requests from this IP address")
        expect(response.first).to include("Error code: ip_10_secs_limit.")
      end

      it "is included when the requests-per-minute limit is reached" do
        global_setting :max_reqs_per_ip_per_minute, 1
        called = 0
        app =
          lambda do |_|
            called += 1
            [200, {}, ["OK"]]
          end
        env = env("REMOTE_ADDR" => "1.1.1.1")
        middleware = Middleware::RequestTracker.new(app)
        status, = middleware.call(env)
        expect(status).to eq(200)
        expect(called).to eq(1)

        env = env("REMOTE_ADDR" => "1.1.1.1")
        middleware = Middleware::RequestTracker.new(app)
        status, headers, response = middleware.call(env)
        expect(status).to eq(429)
        expect(called).to eq(1)
        expect(headers["Discourse-Rate-Limit-Error-Code"]).to eq("ip_60_secs_limit")
        expect(response.first).to include("too many requests from this IP address")
        expect(response.first).to include("Error code: ip_60_secs_limit.")
      end

      it "is included when the assets-requests-per-10-seconds limit is reached" do
        global_setting :max_asset_reqs_per_ip_per_10_seconds, 1
        called = 0
        app =
          lambda do |env|
            called += 1
            env["DISCOURSE_IS_ASSET_PATH"] = true
            [200, {}, ["OK"]]
          end
        env = env("REMOTE_ADDR" => "1.1.1.1")
        middleware = Middleware::RequestTracker.new(app)
        status, = middleware.call(env)
        expect(status).to eq(200)
        expect(called).to eq(1)

        env = env("REMOTE_ADDR" => "1.1.1.1")
        middleware = Middleware::RequestTracker.new(app)
        status, headers, response = middleware.call(env)
        expect(status).to eq(429)
        expect(called).to eq(1)
        expect(headers["Discourse-Rate-Limit-Error-Code"]).to eq("ip_assets_10_secs_limit")
        expect(response.first).to include("too many requests from this IP address")
        expect(response.first).to include("Error code: ip_assets_10_secs_limit.")
      end
    end

    it "users with high enough trust level are not rate limited per ip" do
      global_setting :max_reqs_per_ip_per_minute, 1
      global_setting :skip_per_ip_rate_limit_trust_level, 3

      envs =
        3.times.map do |n|
          user = Fabricate(:user, trust_level: 3)
          token = UserAuthToken.generate!(user_id: user.id)
          cookie =
            create_auth_cookie(
              token: token.unhashed_auth_token,
              user_id: user.id,
              trust_level: user.trust_level,
              issued_at: 5.minutes.ago,
            )
          env("HTTP_COOKIE" => "_t=#{cookie}", "REMOTE_ADDR" => "1.1.1.1")
        end

      called = 0
      app =
        lambda do |env|
          called += 1
          [200, {}, ["OK"]]
        end
      envs.each do |env|
        middleware = Middleware::RequestTracker.new(app)
        status, = middleware.call(env)
        expect(status).to eq(200)
      end
      expect(called).to eq(3)

      envs.each do |env|
        middleware = Middleware::RequestTracker.new(app)
        status, headers, response = middleware.call(env)
        expect(status).to eq(429)
        expect(headers["Discourse-Rate-Limit-Error-Code"]).to eq("id_60_secs_limit")
        expect(response.first).to include("too many requests from this user")
        expect(response.first).to include("Error code: id_60_secs_limit.")
      end
      expect(called).to eq(3)
    end

    it "falls back to IP rate limiting if the cookie is too old" do
      unfreeze_time
      global_setting :max_reqs_per_ip_per_minute, 1
      global_setting :skip_per_ip_rate_limit_trust_level, 3
      user = Fabricate(:user, trust_level: 3)
      token = UserAuthToken.generate!(user_id: user.id)
      cookie =
        create_auth_cookie(
          token: token.unhashed_auth_token,
          user_id: user.id,
          trust_level: user.trust_level,
          issued_at: 5.minutes.ago,
        )
      env = env("HTTP_COOKIE" => "_t=#{cookie}", "REMOTE_ADDR" => "1.1.1.1")

      called = 0
      app =
        lambda do |_|
          called += 1
          [200, {}, ["OK"]]
        end
      freeze_time(12.minutes.from_now) do
        middleware = Middleware::RequestTracker.new(app)
        status, = middleware.call(env)
        expect(status).to eq(200)

        middleware = Middleware::RequestTracker.new(app)
        status, headers, response = middleware.call(env)
        expect(status).to eq(429)
        expect(headers["Discourse-Rate-Limit-Error-Code"]).to eq("ip_60_secs_limit")
        expect(response.first).to include("too many requests from this IP address")
        expect(response.first).to include("Error code: ip_60_secs_limit.")
      end
    end

    it "falls back to IP rate limiting if the cookie is tampered with" do
      unfreeze_time
      global_setting :max_reqs_per_ip_per_minute, 1
      global_setting :skip_per_ip_rate_limit_trust_level, 3
      user = Fabricate(:user, trust_level: 3)
      token = UserAuthToken.generate!(user_id: user.id)
      cookie =
        create_auth_cookie(
          token: token.unhashed_auth_token,
          user_id: user.id,
          trust_level: user.trust_level,
          issued_at: Time.zone.now,
        )
      cookie = swap_2_different_characters(cookie)
      env = env("HTTP_COOKIE" => "_t=#{cookie}", "REMOTE_ADDR" => "1.1.1.1")

      called = 0
      app =
        lambda do |_|
          called += 1
          [200, {}, ["OK"]]
        end

      middleware = Middleware::RequestTracker.new(app)
      status, = middleware.call(env)
      expect(status).to eq(200)

      middleware = Middleware::RequestTracker.new(app)
      status, headers, response = middleware.call(env)
      expect(status).to eq(429)
      expect(headers["Discourse-Rate-Limit-Error-Code"]).to eq("ip_60_secs_limit")
      expect(response.first).to include("too many requests from this IP address")
      expect(response.first).to include("Error code: ip_60_secs_limit.")
    end
  end

  describe "callbacks" do
    def app(result, sql_calls: 0, redis_calls: 0)
      lambda do |env|
        sql_calls.times { User.where(id: -100).pluck(:id) }
        redis_calls.times { Discourse.redis.get("x") }
        yield if block_given?
        result
      end
    end

    let(:logger) do
      ->(env, data) do
        @env = env
        @data = data
      end
    end

    before { Middleware::RequestTracker.register_detailed_request_logger(logger) }

    after { Middleware::RequestTracker.unregister_detailed_request_logger(logger) }

    it "can report data from anon cache" do
      Middleware::AnonymousCache.enable_anon_cache

      cache = Middleware::AnonymousCache.new(app([200, {}, ["i am a thing"]]))
      tracker = Middleware::RequestTracker.new(cache)

      uri = "/path?#{SecureRandom.hex}"

      request_params = { "a" => "b", "action" => "bob", "controller" => "jane" }

      tracker.call(
        env(
          "REQUEST_URI" => uri,
          "ANON_CACHE_DURATION" => 60,
          "action_dispatch.request.parameters" => request_params,
        ),
      )
      expect(@data[:cache]).to eq("skip")

      tracker.call(
        env(
          "REQUEST_URI" => uri,
          "ANON_CACHE_DURATION" => 60,
          "action_dispatch.request.parameters" => request_params,
        ),
      )
      expect(@data[:cache]).to eq("store")

      tracker.call(env("REQUEST_URI" => uri, "ANON_CACHE_DURATION" => 60))
      expect(@data[:cache]).to eq("true")

      # not allowlisted
      request_params.delete("a")

      expect(@env["action_dispatch.request.parameters"]).to eq(request_params)
    end

    it "can correctly log detailed data" do
      global_setting :enable_performance_http_headers, true

      # ensure pg is warmed up with the select 1 query
      User.where(id: -100).pluck(:id)

      freeze_time
      start = Time.now.to_f

      freeze_time 1.minute.from_now

      tracker = Middleware::RequestTracker.new(app([200, {}, []], sql_calls: 2, redis_calls: 2))
      _, headers, _ = tracker.call(env("HTTP_X_REQUEST_START" => "t=#{start}"))

      expect(@data[:queue_seconds]).to eq(60)

      timing = @data[:timing]
      expect(timing[:total_duration]).to be > 0

      expect(timing[:sql][:duration]).to be > 0
      expect(timing[:sql][:calls]).to eq 2

      expect(timing[:redis][:duration]).to be > 0
      expect(timing[:redis][:calls]).to eq 2

      expect(headers["X-Queue-Time"]).to eq("60.000000")

      expect(headers["X-Redis-Calls"]).to eq("2")
      expect(headers["X-Redis-Time"].to_f).to be > 0

      expect(headers["X-Sql-Calls"]).to eq("2")
      expect(headers["X-Sql-Time"].to_f).to be > 0

      expect(headers["X-Runtime"].to_f).to be > 0
    end

    it "correctly logs GC stats when `instrument_gc_stat_per_request` site setting has been enabled" do
      tracker =
        Middleware::RequestTracker.new(
          app([200, {}, []]) do
            GC.start(full_mark: true) # Major GC
            GC.start(full_mark: false) # Minor GC
          end,
        )

      tracker.call(env)

      expect(@data[:timing][:gc]).to eq(nil)

      SiteSetting.instrument_gc_stat_per_request = true

      tracker =
        Middleware::RequestTracker.new(
          app([200, {}, []]) do
            GC.start(full_mark: true) # Major GC
            GC.start(full_mark: false) # Minor GC
          end,
        )

      tracker.call(env)

      expect(@data[:timing][:gc][:time]).to be > 0.0
      expect(@data[:timing][:gc][:major_count]).to eq(1)
      expect(@data[:timing][:gc][:minor_count]).to eq(1)
    end

    it "can correctly log messagebus request types" do
      tracker = Middleware::RequestTracker.new(app([200, {}, []]))

      tracker.call(env(path: "/message-bus/abcde/poll"))
      expect(@data[:is_background]).to eq(true)
      expect(@data[:background_type]).to eq("message-bus")

      tracker.call(env(path: "/message-bus/abcde/poll?dlp=t"))
      expect(@data[:is_background]).to eq(true)
      expect(@data[:background_type]).to eq("message-bus-dlp")

      tracker.call(env("HTTP_DONT_CHUNK" => "True", :path => "/message-bus/abcde/poll"))
      expect(@data[:is_background]).to eq(true)
      expect(@data[:background_type]).to eq("message-bus-dontchunk")
    end
  end
end