Verified Commit c41b23c7 authored by Hercules Merscher's avatar Hercules Merscher 🌴
Browse files

fix: Dropping assertions on log events inside custom matchers

parent 7a8b608a
Loading
Loading
Loading
Loading
+8 −109
Original line number Diff line number Diff line
# frozen_string_literal: true

require 'json'

# RSpec matchers for testing Labkit CoveredExperience functionality
#
# This file must be explicitly required in your test setup:
@@ -9,16 +7,6 @@ require 'json'

raise LoadError, "RSpec is not loaded. Please require 'rspec' before requiring 'labkit/rspec/matchers'" unless defined?(RSpec)

RSpec.configure do |config|
  config.before do
    Labkit::RSpec::Matchers::CoveredExperience.get_or_init_logger
  end

  config.after do
    Thread.current[:covered_experience_test_logger] = nil
  end
end

module Labkit
  module RSpec
    module Matchers
@@ -42,62 +30,6 @@ module Labkit
        def apdex_counter
          Labkit::Metrics::Client.get(:gitlab_covered_experience_apdex_total)
        end

        # Create a shared logger that persists across matcher calls in the same test
        def self.get_or_init_logger
          Thread.current[:covered_experience_test_logger] ||= begin
            logger = Labkit::Logging::JsonLogger.new(StringIO.new)

            Labkit::CoveredExperience.configure do |config|
              config.logger = logger
            end

            logger
          end
        end

        def expect_log_for(covered_experience_id, event_type, extra_args = {})
          test_logger = Labkit::RSpec::Matchers::CoveredExperience.get_or_init_logger
          log_output = test_logger.instance_variable_get(:@logdev).dev
          log_content = log_output.string

          expected_attrs = {
            checkpoint: event_type,
            start_time: be_a(String),
            elapsed_time_s: be_a(Numeric),
            urgency_threshold_s: be_a(Numeric),
            **attributes(covered_experience_id),
            **extra_args
          }

          # Parse each log line and check if the log line with the set of expected attributes
          # is present and matches the expected attributes
          logged = log_content.split("\n").any? do |line|
            next if line.strip.empty?

            begin
              log_entry = JSON.parse(line, symbolize_names: true)
              expected_attrs.all? do |key, value|
                actual_value = log_entry[key]

                case value
                when Class
                  actual_value.is_a?(value)
                when Regexp
                  actual_value&.match?(value)
                when ::RSpec::Matchers::BuiltIn::BaseMatcher
                  value.matches?(actual_value)
                else
                  actual_value == value
                end
              end
            rescue JSON::ParserError
              false
            end
          end

          [logged, log_content]
        end
      end
    end
  end
@@ -111,10 +43,6 @@ end
# This matcher verifies that the following metric is incremented:
# - gitlab_covered_experience_checkpoint_total (with checkpoint=start)
#
# Additionally, this matcher verifies that a log event is generated with:
# - checkpoint: "start"
# - Standard covered experience fields (start_time, elapsed_time_s, etc.)
#
# Parameters:
# - covered_experience_id: Required. The ID of the covered experience (e.g., 'rails_request')
RSpec::Matchers.define :start_covered_experience do |covered_experience_id|
@@ -134,15 +62,12 @@ RSpec::Matchers.define :start_covered_experience do |covered_experience_id|

    @checkpoint_change = checkpoint_after - checkpoint_before

    is_logged, @log_output = expect_log_for(covered_experience_id, "start")

    @checkpoint_change == 1 && is_logged
    @checkpoint_change == 1
  end

  failure_message do
    "Failed to checkpoint covered experience '#{covered_experience_id}':\n" \
      "expected checkpoint='start' counter to increase by 1, but increased by #{@checkpoint_change}\n" \
      "expected to log start, but log output is \"#{@log_output}\""
      "expected checkpoint='start' counter to increase by 1, but increased by #{@checkpoint_change}"
  end
end

@@ -154,11 +79,6 @@ end
# This matcher verifies that the following metric is incremented:
# - gitlab_covered_experience_checkpoint_total (with checkpoint=intermediate)
#
# Additionally, this matcher verifies that a log event is generated with:
# - checkpoint: "intermediate"
# - checkpoint_time: timestamp of the checkpoint
# - Standard covered experience fields (start_time, elapsed_time_s, etc.)
#
# Parameters:
# - covered_experience_id: Required. The ID of the covered experience (e.g., 'rails_request')
RSpec::Matchers.define :checkpoint_covered_experience do |covered_experience_id|
@@ -177,15 +97,12 @@ RSpec::Matchers.define :checkpoint_covered_experience do |covered_experience_id|
    checkpoint_after = checkpoint_counter&.get(labels.merge(checkpoint: "intermediate")).to_i
    @checkpoint_change = checkpoint_after - checkpoint_before

    is_logged, @log_output = expect_log_for(covered_experience_id, "intermediate", checkpoint_time: be_a(String))

    @checkpoint_change == 1 && is_logged
    @checkpoint_change == 1
  end

  failure_message do
    "Failed to checkpoint covered experience '#{covered_experience_id}':\n" \
      "expected checkpoint='intermediate' counter to increase by 1, but increased by #{@checkpoint_change}\n" \
      "expected to log checkpoint, but log output is \"#{@log_output}\""
      "expected checkpoint='intermediate' counter to increase by 1, but increased by #{@checkpoint_change}"
  end

  match_when_negated do |actual|
@@ -217,12 +134,6 @@ end
# - gitlab_covered_experience_total (with error=false)
# - gitlab_covered_experience_apdex_total (with success=true)
#
# Additionally, this matcher verifies that a log event is generated with:
# - checkpoint: "end"
# - end_time: timestamp of completion
# - error: true (if error=true parameter is passed)
# - Standard covered experience fields (start_time, elapsed_time_s, etc.)
#
# Parameters:
# - covered_experience_id: Required. The ID of the covered experience (e.g., 'rails_request')
# - error: Optional. The expected error flag for gitlab_covered_experience_total (false by default)
@@ -249,20 +160,14 @@ RSpec::Matchers.define :complete_covered_experience do |covered_experience_id, e
    @total_change = total_after - total_before
    @apdex_change = apdex_after - apdex_before

    expected_log_attrs = { end_time: be_a(String) }
    expected_log_attrs[:error] = true if error

    is_logged, @log_output = expect_log_for(covered_experience_id, "end", expected_log_attrs)

    @checkpoint_change == 1 && @total_change == 1 && @apdex_change == (error ? 0 : 1) && is_logged
    @checkpoint_change == 1 && @total_change == 1 && @apdex_change == (error ? 0 : 1)
  end

  failure_message do
    "Failed to complete covered experience '#{covered_experience_id}':\n" \
      "expected checkpoint='end' counter to increase by 1, but increased by #{@checkpoint_change}\n" \
      "expected total='error: #{error}' counter to increase by 1, but increased by #{@total_change}\n" \
      "expected apdex='success: #{success}' counter to increase by 1, but increased by #{@apdex_change}\n" \
      "expected to log complete, but log output is \"#{@log_output}\""
      "expected apdex='success: #{success}' counter to increase by 1, but increased by #{@apdex_change}"
  end

  match_when_negated do |actual|
@@ -281,19 +186,13 @@ RSpec::Matchers.define :complete_covered_experience do |covered_experience_id, e
    @total_change = total_after - total_before
    @apdex_change = apdex_after - apdex_before

    expected_log_attrs = { end_time: be_a(String) }
    expected_log_attrs[:error] = true if error

    is_logged, @log_output = expect_log_for(covered_experience_id, "end", expected_log_attrs)

    @checkpoint_change.zero? && @total_change.zero? && @apdex_change == (error ? 1 : 0) && !is_logged
    @checkpoint_change.zero? && @total_change.zero? && @apdex_change == (error ? 1 : 0)
  end

  failure_message_when_negated do
    "Failed covered experience '#{covered_experience_id}' NOT to complete:\n" \
      "expected checkpoint='end' counter to increase by 0, but increased by #{@checkpoint_change}\n" \
      "expected total='error: #{error}' counter to increase by 0, but increased by #{@total_change}\n" \
      "expected apdex='success: #{success}' counter to increase by 0, but increased by #{@apdex_change}\n" \
      "expected not to log complete, but log output is \"#{@log_output}\""
      "expected apdex='success: #{success}' counter to increase by 0, but increased by #{@apdex_change}"
  end
end