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

feat: Custom logger for Covered Experience matchers

parent f4a655e2

lib/labkit/rspec/matchers/covered_experience_matchers.rb

+64 −21
Original line number Diff line number Diff line
@@ -9,6 +9,16 @@ 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
@@ -33,15 +43,22 @@ module Labkit 
          Labkit::Metrics::Client.get(:gitlab_covered_experience_apdex_total)

        end



        def logger

          Labkit::CoveredExperience.configuration.logger

        # 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



        def expect_log_for(covered_experience_id, event_type, extra_args = {})

          # Get the current logger's output (assumes StringIO for testing)

          log_output = logger.instance_variable_get(:@logdev).dev

          raise 'Logger does not using StringIO for test' unless log_output.respond_to?(:string)

            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 = {
@@ -55,7 +72,7 @@ module Labkit 


          # Parse each log line and check if the log line with the set of expected attributes

          # is present and matches the expected attributes

          log_content.split("\n").any? do |line|

          logged = log_content.split("\n").any? do |line|

            next if line.strip.empty?



            begin
@@ -78,6 +95,8 @@ module Labkit 
              false

            end

          end



          [logged, log_content]

        end

      end

    end
@@ -91,7 +110,10 @@ end 
#

# This matcher verifies that the following metric is incremented:

# - gitlab_covered_experience_checkpoint_total (with checkpoint=start)

# - logger is called with the covered experience attributes and context

#

# 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')
@@ -112,12 +134,15 @@ RSpec::Matchers.define :start_covered_experience do |covered_experience_id| 


    @checkpoint_change = checkpoint_after - checkpoint_before



    @checkpoint_change == 1 && expect_log_for(covered_experience_id, "start")

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



    @checkpoint_change == 1 && is_logged

  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}"

      "expected checkpoint='start' counter to increase by 1, but increased by #{@checkpoint_change}\n" \

      "expected to log start, but log output is \"#{@log_output}\""

  end

end
@@ -128,7 +153,11 @@ end 
#

# This matcher verifies that the following metric is incremented:

# - gitlab_covered_experience_checkpoint_total (with checkpoint=intermediate)

# - logger is called with the covered experience attributes and context

#

# 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')
@@ -148,12 +177,15 @@ 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



    @checkpoint_change == 1 && expect_log_for(covered_experience_id, "intermediate", checkpoint_time: be_a(String))

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



    @checkpoint_change == 1 && is_logged

  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}"

      "expected checkpoint='intermediate' counter to increase by 1, but increased by #{@checkpoint_change}\n" \

      "expected to log checkpoint, but log output is \"#{@log_output}\""

  end



  match_when_negated do |actual|
@@ -184,7 +216,12 @@ end 
# - gitlab_covered_experience_checkpoint_total (with checkpoint=end)

# - gitlab_covered_experience_total (with error=false)

# - gitlab_covered_experience_apdex_total (with success=true)

# - logger is called with the covered experience attributes and context

#

# 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')
@@ -215,17 +252,17 @@ RSpec::Matchers.define :complete_covered_experience do |covered_experience_id, e 
    expected_log_attrs = { end_time: be_a(String) }

    expected_log_attrs[:error] = true if error



    @checkpoint_change == 1 &&

      @total_change == 1 &&

      @apdex_change == (error ? 0 : 1) &&

      expect_log_for(covered_experience_id, "end", expected_log_attrs)

    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

  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}"

      "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}\""

  end



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

    @apdex_change = apdex_after - apdex_before



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

    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

  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}"

      "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}\""

  end

end

spec/labkit/covered_experience_spec.rb

+0 −4
Original line number Diff line number Diff line
@@ -8,10 +8,6 @@ require 'labkit/rspec/matchers/covered_experience_matchers' 
RSpec.describe Labkit::CoveredExperience, :with_metrics_config do

  include StubENV



  after do

    described_class.instance_variable_set(:@configuration, nil)

  end



  describe '.configuration' do

    it 'returns a Configuration instance' do

      expect(described_class.configuration).to be_a(described_class::Configuration)

spec/support/covered_experience_test_config.rb

+2 −4
Original line number Diff line number Diff line 
# frozen_string_literal: true



# Test configuration for Labkit::CoveredExperience to capture logs during tests

# Test configuration for Labkit::CoveredExperience to ignore logs by default in tests

RSpec.configure do |config|

  config.before do

    # Configure CoveredExperience with a logger that captures logs in memory for testing

    Labkit::CoveredExperience.configure do |config|

      # Use StringIO to capture logs in memory (useful for testing)

      config.logger = Labkit::Logging::JsonLogger.new(StringIO.new)

      config.logger = Labkit::Logging::JsonLogger.new("/dev/null")

    end

  end