Merge branch 'nindurkar/log-rule-name-on-error' into 'master'

      CHAR_VALUE_MAX_LENGTH = 200

      MISSING_VALUE_SENTINEL = "_unknown_"

      # Carries the rule in flight out of the rule loop and into the rescue in

      # #check/#peek, where the error is seen but the rule is out of scope.

      # Per call, not instance state: one Evaluator serves concurrent requests.

      # Only read while an exception unwinds; nil means no rule was in flight.

      RuleCursor = Struct.new(:rule)

      # Atomic increment-with-TTL Lua script. The whole script runs as one

      # operation from Redis's perspective, so there is no window between

      # the increment and EXPIRE that can leak a key without TTL.

      end

      def check(identifier, cost: 1, rule_context: nil)

        check_rules(identifier, cost, rule_context)

        cursor = RuleCursor.new

        check_rules(identifier, cost, rule_context, cursor)

      rescue StandardError => e

        # Intentionally broad: fail-open applies to any unexpected error (network,

        # timeout, OOM) not only Redis protocol errors.

        report_error_metrics

        log_error(e, identifier)

        log_error(e, identifier, cursor.rule)

        Result.error

      end

      # shape; the underlying Redis counter is not mutated and the TTL is not

      # extended. A missing Redis key is treated as count=0 (matched, not exceeded).

      def peek(identifier, rule_context: nil)

        peek_rules(identifier, rule_context)

        cursor = RuleCursor.new

        peek_rules(identifier, rule_context, cursor)

      rescue StandardError => e

        report_error_metrics

        log_error(e, identifier)

        log_error(e, identifier, cursor.rule)

        Result.error

      end

      # counters were incremented. No blocking verdict is lost that way - a

      # :limit rule over its limit returns before any later rule can raise -

      # but a rule declared after the failing one loses its chance to block.

      # The request is counted and allowed.

      def check_rules(identifier, cost, rule_context)

      # The request is counted and allowed. +cursor+ is set before the match, so

      # a raise from the match itself (e.g. Regexp::TimeoutError) is attributed.

      def check_rules(identifier, cost, rule_context, cursor)

        result = Result.new

        @rules.each do |rule|

          cursor.rule = rule

          next unless rule_matches?(rule, identifier)

          if rule.action == :skip

          return result if result.block?

        end

        # The loop is done, so anything raised from here on belongs to no rule.

        cursor.rule = nil

        report_unmatched_metrics unless result.matched?

        result

      end

      # peek does not need the count_distinct identifier key - it reads SCARD on

      # the rule-keyed compound key, which contains the cardinality across all

      # members. So missing-key fail-open does not apply here.

      def peek_rules(identifier, rule_context)

      def peek_rules(identifier, rule_context, cursor)

        result = Result.new

        @rules.each do |rule|

          cursor.rule = rule

          next unless rule_matches?(rule, identifier)

          return result.skip!(rule) if rule.action == :skip

          return result if result.block?

        end

        cursor.rule = nil

        result

      end

        end

      end

      def log_error(error, identifier)

      # rule is nil when the error was raised with no rule in flight - before the

      # loop reached one, or after it finished - so the field is logged as null

      # rather than omitted, the same way identifier is. A named rule is the rule

      # whose match or evaluation raised.

      def log_error(error, identifier, rule = nil)

        @logger.warn(

          name: @name,

          rule: rule&.name,

          Labkit::Fields::ERROR_TYPE => "rate_limit_error",

          Labkit::Fields::CLASS_NAME => error.class.to_s,

          Labkit::Fields::ERROR_MESSAGE => error.message,

      expect(elapsed).to be < (Labkit::RateLimit::Matcher::MATCH_TIMEOUT_SECONDS * 20)

    end

    # A limiter can carry a dozen-plus rules, so the limiter name alone does not

    # say which rule's Redis call or match regex raised. Each case below puts a

    # non-matching rule first, so a passing assertion means the logged rule is

    # the one in flight rather than the only one present.

    it "logs the rule whose Redis evaluation raised" do

      faulty = Class.new do

        def with

          yield self

        end

        def evalsha(*)

          raise "connection refused"

        end

      end.new

      logger = instance_double(Labkit::Logging::JsonLogger)

      expect(logger).to receive(:warn).with(hash_including(rule: "err_rule"))

      rules = [make_rule(name: "other_rule", match: { user: 999 }), make_rule(name: "err_rule")]

      described_class.new(name: "rack_request", rules: rules, redis: faulty, logger: logger).check(identifier)

    end

    it "logs the rule whose match regex timed out" do

      logger = instance_double(Labkit::Logging::JsonLogger)

      expect(logger).to receive(:warn).with(hash_including(rule: "slow_regex"))

      rules = [

        make_rule(name: "other_rule", match: { user: 999 }),

        make_rule(name: "slow_regex", match: { ip: { re: '(a+)+\1$' } })

      ]

      id = Labkit::RateLimit::Identifier.new(user: 42, ip: "#{'a' * 60}!")

      described_class.new(name: "rack_request", rules: rules, redis: redis, logger: logger).check(id)

    end

    it "logs a nil rule when the error is raised with no rule in flight" do

      logger = instance_double(Labkit::Logging::JsonLogger)

      expect(logger).to receive(:warn).with(hash_including(rule: nil))

      # report_unmatched_metrics runs after the loop, so the raise lands where no

      # rule can be blamed. errors_total is left alone: the rescue still uses it.

      allow(Labkit::RateLimit::Metrics).to receive(:calls_total).and_raise("metrics down")

      rule = make_rule(name: "other_rule", match: { user: 999 })

      result = described_class.new(name: "rack_request", rules: [rule], redis: redis, logger: logger).check(identifier)

      expect(result.error?).to be(true)

    end

    it "logs the rule whose peek raised" do

      faulty = Class.new do

        def with

          yield self

        end

        def pipelined

          raise "connection refused"

        end

      end.new

      logger = instance_double(Labkit::Logging::JsonLogger)

      expect(logger).to receive(:warn).with(hash_including(rule: "err_rule"))

      rules = [make_rule(name: "other_rule", match: { user: 999 }), make_rule(name: "err_rule")]

      described_class.new(name: "rack_request", rules: rules, redis: faulty, logger: logger).peek(identifier)

    end

  end

  describe "Metrics emission", :with_metrics_config do