feat(rate_limit): log the rule name when a check fails open (058806ab) · Commits · GitLab.org / ruby / gems / labkit-ruby

lib/labkit/rate_limit/evaluator.rb

+31 −8

Original line number	Diff line number	Diff line
		@@ -12,6 +12,12 @@ module Labkit
		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.
		@@ -68,12 +74,13 @@ module Labkit
		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

		@@ -81,10 +88,11 @@ module Labkit
		# 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

		@@ -117,11 +125,14 @@ module Labkit
		# 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
		@@ -141,6 +152,9 @@ module Labkit
		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
		@@ -152,10 +166,12 @@ module Labkit
		# 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
		@@ -164,6 +180,8 @@ module Labkit
		return result if result.block?
		end

		cursor.rule = nil

		result
		end

		@@ -319,9 +337,14 @@ module Labkit
		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,

spec/labkit/rate_limit/evaluator_spec.rb

+67 −0

Original line number	Diff line number	Diff line
		@@ -587,6 +587,73 @@ RSpec.describe Labkit::RateLimit::Evaluator do

		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