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

feat: Covered Experience logging

parent 98c2897d

lib/labkit/context.rb

+1 −0
Original line number Diff line number Diff line
@@ -5,6 +5,7 @@ require "securerandom" 
require "active_support/core_ext/module/delegation"

require "active_support/core_ext/string/starts_ends_with"

require "active_support/core_ext/string/inflections"

require "active_support/core_ext/object/blank"



module Labkit

  # A context can be used to provide structured information on what resources

lib/labkit/covered_experience/experience.rb

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



require 'labkit/logging/json_logger'

require 'labkit/context'

require 'labkit/covered_experience/error'

require 'labkit/logging/json_logger'



module Labkit

  module CoveredExperience
@@ -41,6 +42,7 @@ module Labkit 
      def start

        @started = Time.now.utc

        checkpoint_counter.increment(checkpoint: "start")

        log_event("start", start_time: @started.iso8601)



        return self unless block_given?
@@ -63,6 +65,8 @@ module Labkit 
        return unless ensure_started!



        checkpoint_counter.increment(checkpoint: "intermediate")

        log_event("intermediate", start_time: @started.iso8601, checkpoint_time: Time.now.utc.iso8601)



        self

      end
@@ -74,11 +78,20 @@ module Labkit 
        return unless ensure_started!



        begin

          elapsed = Time.now.utc - @started

          end_time = Time.now.utc

          elapsed = end_time - @started

        ensure

          checkpoint_counter.increment(checkpoint: "end")

          total_counter.increment(error: has_error?)

          apdex_counter.increment(success: elapsed <= urgency_threshold) unless has_error?



          log_attrs = {

            start_time: @started.iso8601,

            end_time: end_time.iso8601,

            elapsed: elapsed,

            urgency_threshold_in_seconds: urgency_threshold

          }

          log_event("end", **log_attrs)

        end



        self
@@ -140,6 +153,33 @@ module Labkit 
        )

      end



      def log_event(event_type, **extra)

        log_data = build_log_data(event_type, **extra)

        logger.info(log_data)

      end



      def build_log_data(event_type, **extra)

        extra ||= {}

        log_data = {

          checkpoint: event_type,

          covered_experience: @definition.covered_experience,

          feature_category: @definition.feature_category,

          urgency: @definition.urgency

        }



        context_data = Labkit::Context.current.to_h.select do |k, _|

          k == "correlation_id" || k.start_with?("meta")

        end

        log_data = extra.merge(context_data).merge(log_data)



        if has_error?

          log_data[:error] = true

          log_data[:error_message] = @error.to_s

        end



        log_data

      end



      def warn(exception)

        logger.warn(component: self.class.name, message: exception.message)

      end

lib/labkit/rspec/matchers/covered_experience_matchers.rb

+52 −14
Original line number Diff line number Diff line
@@ -10,8 +10,15 @@ raise LoadError, "RSpec is not loaded. Please require 'rspec' before requiring ' 
module Labkit

  module RSpec

    module Matchers

      # Helper module for CoveredExperience metrics access

      module CoveredExperienceMetrics

      # Helper module for CoveredExperience functionality

      module CoveredExperience

        def attributes(covered_experience_id)

          raise ArgumentError, "covered_experience_id is required" if covered_experience_id.nil?



          definition = Labkit::CoveredExperience::Registry.new[covered_experience_id]

          definition.to_h.slice(:id, :feature_category, :urgency)

        end



        def checkpoint_counter

          Labkit::Metrics::Client.get(:gitlab_covered_experience_checkpoint_total)

        end
@@ -24,11 +31,31 @@ module Labkit 
          Labkit::Metrics::Client.get(:gitlab_covered_experience_apdex_total)

        end



        def base_labels(covered_experience_id)

          raise ArgumentError, "covered_experience_id is required" if covered_experience_id.nil?

        def logger

          ::RSpec.current_example.metadata[:logger] ||= begin

            instance = Labkit::Logging::JsonLogger.new($stdout)

            allow(Labkit::Logging::JsonLogger).to receive(:new).with($stdout).and_return(instance) # rubocop:disable CodeReuse/ActiveRecord -- false positive

            instance

          end

        end



          definition = Labkit::CoveredExperience::Registry.new[covered_experience_id]

          definition.to_h.slice(:id, :feature_category, :urgency)

        def allow_logger_call(covered_experience_id, checkpoint_type, extra = {})

          return unless logger



          labels = attributes(covered_experience_id)



          context_data = Labkit::Context.current.to_h.select do |k, _|

            k == "correlation_id" || k.start_with?("meta")

          end



          expected_log_data = extra.merge(context_data).merge(

            checkpoint: checkpoint_type,

            covered_experience: covered_experience_id.to_s,

            feature_category: labels[:feature_category],

            urgency: labels[:urgency]

          )



          allow(logger).to receive(:info).with(hash_including(expected_log_data)).and_call_original # rubocop:disable CodeReuse/ActiveRecord -- false positive

        end

      end

    end
@@ -42,20 +69,23 @@ 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

#

# 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|

  include Labkit::RSpec::Matchers::CoveredExperienceMetrics

  include Labkit::RSpec::Matchers::CoveredExperience



  description { "start covered experience '#{covered_experience_id}'" }

  supports_block_expectations



  match do |actual|

    labels = base_labels(covered_experience_id)

    labels = attributes(covered_experience_id)



    checkpoint_before = checkpoint_counter&.get(labels.merge(checkpoint: "start")).to_i



    allow_logger_call(covered_experience_id, "start", start_time: be_a(String))



    actual.call



    checkpoint_after = checkpoint_counter&.get(labels.merge(checkpoint: "start")).to_i
@@ -78,20 +108,23 @@ 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

#

# 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|

  include Labkit::RSpec::Matchers::CoveredExperienceMetrics

  include Labkit::RSpec::Matchers::CoveredExperience



  description { "checkpoint covered experience '#{covered_experience_id}'" }

  supports_block_expectations



  match do |actual|

    labels = base_labels(covered_experience_id)

    labels = attributes(covered_experience_id)



    checkpoint_before = checkpoint_counter&.get(labels.merge(checkpoint: "intermediate")).to_i



    allow_logger_call(covered_experience_id, "intermediate", start_time: be_a(String), checkpoint_time: be_a(String))



    actual.call



    checkpoint_after = checkpoint_counter&.get(labels.merge(checkpoint: "intermediate")).to_i
@@ -106,7 +139,7 @@ RSpec::Matchers.define :checkpoint_covered_experience do |covered_experience_id| 
  end



  match_when_negated do |actual|

    labels = base_labels(covered_experience_id)

    labels = attributes(covered_experience_id)



    checkpoint_before = checkpoint_counter&.get(labels.merge(checkpoint: "intermediate")).to_i
@@ -133,24 +166,29 @@ 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

#

# 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)

# - success: Optional. The expected success flag for gitlab_covered_experience_apdex_total (true by default)

RSpec::Matchers.define :complete_covered_experience do |covered_experience_id, error: false, success: true|

  include Labkit::RSpec::Matchers::CoveredExperienceMetrics

  include Labkit::RSpec::Matchers::CoveredExperience



  description { "complete covered experience '#{covered_experience_id}'" }

  supports_block_expectations



  match do |actual|

    labels = base_labels(covered_experience_id)

    labels = attributes(covered_experience_id)



    checkpoint_before = checkpoint_counter&.get(labels.merge(checkpoint: "end")).to_i

    total_before = total_counter&.get(labels.merge(error: error)).to_i

    apdex_before = apdex_counter&.get(labels.merge(success: success)).to_i



    attrs = { start_time: be_a(String), end_time: be_a(String), elapsed: be_a(Numeric) }

    attrs.merge!(error: true, error_message: be_a(String)) if error

    allow_logger_call(covered_experience_id, "end", attrs)



    actual.call



    checkpoint_after = checkpoint_counter&.get(labels.merge(checkpoint: "end")).to_i
@@ -171,7 +209,7 @@ RSpec::Matchers.define :complete_covered_experience do |covered_experience_id, e 
  end



  match_when_negated do |actual|

    labels = base_labels(covered_experience_id)

    labels = attributes(covered_experience_id)



    checkpoint_before = checkpoint_counter&.get(labels.merge(checkpoint: "end")).to_i

    total_before = total_counter&.get(labels.merge(error: error)).to_i

spec/labkit/covered_experience/experience_spec.rb

+13 −2
Original line number Diff line number Diff line
@@ -12,8 +12,18 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
    Labkit::CoveredExperience::Registry.new[:testing_sample]

  end



  let(:user_id) { 123 }

  let(:project_id) { 456 }

  let(:context) { { user_id: user_id, project_id: project_id } }



  subject(:experience) { described_class.new(definition) }



  around do |example|

    Labkit::Context.with_context(**context) do

      example.run

    end

  end



  describe '#start' do

    context 'when block is given' do

      it 'returns itself' do
@@ -32,6 +42,7 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
        expect do

          experience.start { raise 'Something went wrong' }

        end.to raise_error(RuntimeError, 'Something went wrong')

        .and start_covered_experience(:testing_sample)

        .and complete_covered_experience(:testing_sample, error: true)

      end

    end
@@ -103,9 +114,9 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 


      it 'ends with apdex failure when time elapsed is too long' do

        # simulate the elapsed time in the future

        expect(Time).to receive(:now).and_return(Time.now.utc + 60)

        expect(Time).to receive(:now).and_return(Time.now.utc + 60).at_least(:once)



        expect { complete }.to complete_covered_experience(:testing_sample, success: false)

        expect { experience.complete }.to complete_covered_experience(:testing_sample, success: false)

      end

    end

spec/labkit/covered_experience_spec.rb

+1 −0
Original line number Diff line number Diff line
@@ -55,6 +55,7 @@ RSpec.describe Labkit::CoveredExperience, :with_metrics_config do 
        expect do

          described_class.start('testing_sample') { raise 'Something went wrong' }

        end.to raise_error(RuntimeError, 'Something went wrong')

        .and start_covered_experience(:testing_sample)

        .and complete_covered_experience(:testing_sample, error: true)

      end

    end