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

feat: Checking log events

parent c41b23c7

lib/labkit/covered_experience/experience.rb

+2 −2
Original line number Diff line number Diff line
@@ -39,7 +39,7 @@ module Labkit 
      #  experience.start

      #  experience.checkpoint

      #  experience.complete

      def start(**extra)

      def start(**extra, &)

        @start_time = Time.now.utc

        checkpoint_counter.increment(checkpoint: "start")

        log_event("start", **extra)
@@ -53,7 +53,7 @@ module Labkit 
          error!(e)

          raise

        ensure

          complete

          complete(**extra)

        end

      end

lib/labkit/rspec/matchers/covered_experience_matchers.rb

+1 −1
Original line number Diff line number Diff line
@@ -16,7 +16,7 @@ module Labkit 
          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)

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

        end



        def checkpoint_counter

spec/labkit/covered_experience/experience_spec.rb

+107 −44
Original line number Diff line number Diff line
@@ -12,6 +12,14 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
    Labkit::CoveredExperience::Registry.new[:testing_sample]

  end



  let(:event_info) do

    definition.to_h.slice(:covered_experience, :feature_category, :urgency).merge(

      start_time: a_kind_of(Time),

      elapsed_time_s: a_kind_of(Numeric),

      urgency_threshold_s: a_kind_of(Integer),

    )

  end



  let(:user_id) { 123 }

  let(:project_id) { 456 }

  let(:context) { { user_id: user_id, project_id: project_id } }
@@ -45,6 +53,20 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
        .and start_covered_experience(:testing_sample)

        .and complete_covered_experience(:testing_sample, error: true)

      end



      it 'logs start and end times' do

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(**event_info, checkpoint: 'start'))

          .ordered

          .and_call_original



        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(**event_info, checkpoint: 'end', end_time: a_kind_of(Time)))

          .ordered

          .and_call_original



        experience.start { |_xp| 1 + 1 }

      end

    end



    context 'when block is not given' do
@@ -53,6 +75,14 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
      it { is_expected.to be(experience) }

      it { expect { start }.to start_covered_experience(:testing_sample) }

      it { expect { start }.not_to complete_covered_experience(:testing_sample) }



      it 'logs only start time' do

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(event_info.merge(checkpoint: 'start')))

          .and_call_original



        start

      end

    end

  end
@@ -66,6 +96,16 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 


      it { is_expected.to be(experience) }

      it { expect { checkpoint }.to checkpoint_covered_experience(:testing_sample) }



      it 'logs checkpoint time' do

        checkpoint_event_info = event_info.merge(checkpoint: 'intermediate', checkpoint_time: a_kind_of(Time))



        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(**checkpoint_event_info))

          .and_call_original



        checkpoint

      end

    end



    context 'when not started' do
@@ -106,6 +146,16 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
      it { is_expected.to be(experience) }

      it { expect { complete }.to complete_covered_experience(:testing_sample) }



      it 'logs completion time' do

        complete_event_info = event_info.merge(checkpoint: 'end', end_time: a_kind_of(Time))



        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(**complete_event_info))

          .and_call_original



        complete

      end



      it 'ends with error when marked as error' do

        expect do

          experience.error!('boom!').complete
@@ -159,44 +209,41 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
  end



  describe 'extra arguments in log events' do

    let(:logger) { Labkit::Logging::JsonLogger.new(StringIO.new) }



    before do

      Labkit::CoveredExperience.configure do |config|

        config.logger = logger

      end

    end



    def log_entries

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

      log_output.string.split("\n").filter_map do |line|

        next if line.strip.empty?



        JSON.parse(line, symbolize_names: true)

      rescue JSON::ParserError

        nil

      end

    end



    describe '#start with extra arguments' do

      it 'includes extra arguments in the log event' do

        experience.start(user_id: 123, request_id: 'abc-123')



        start_log = log_entries.find { |entry| entry[:checkpoint] == 'start' }

        expect(start_log).to include(

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(

            **event_info,

            checkpoint: 'start',

            user_id: 123,

            request_id: 'abc-123'

        )

          ))

          .and_call_original



        experience.start(user_id: 123, request_id: 'abc-123')

      end



      it 'works with block and includes extra arguments' do

        experience.start(session_id: 'session-456') { |_xp| 1 + 1 }

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(

            **event_info,

            checkpoint: 'start',

            session_id: 'session-456'

          ))

          .ordered

          .and_call_original



        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(

            **event_info,

            checkpoint: 'end',

            end_time: a_kind_of(Time),

            session_id: 'session-456'

          ))

          .ordered

          .and_call_original



        start_log = log_entries.find { |entry| entry[:checkpoint] == 'start' }

        end_log = log_entries.find { |entry| entry[:checkpoint] == 'end' }



        expect(start_log).to include(session_id: 'session-456')

        expect(end_log).not_to include(:session_id) # end doesn't get start's extra args

        experience.start(session_id: 'session-456') { |_xp| 1 + 1 }

      end

    end
@@ -206,13 +253,19 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
      end



      it 'includes extra arguments in the log event' do

        experience.checkpoint(step: 'validation', items_processed: 50)

        event_info.merge(checkpoint: 'intermediate', checkpoint_time: a_kind_of(Time))



        checkpoint_log = log_entries.find { |entry| entry[:checkpoint] == 'intermediate' }

        expect(checkpoint_log).to include(

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(

            **event_info,

            checkpoint: 'intermediate',

            checkpoint_time: a_kind_of(Time),

            step: 'validation',

            items_processed: 50

        )

          ))

          .and_call_original



        experience.checkpoint(step: 'validation', items_processed: 50)

      end

    end
@@ -222,24 +275,34 @@ RSpec.describe Labkit::CoveredExperience::Experience, :with_metrics_config do 
      end



      it 'includes extra arguments in the log event' do

        experience.complete(total_items: 100, success_rate: 0.95)



        complete_log = log_entries.find { |entry| entry[:checkpoint] == 'end' }

        expect(complete_log).to include(

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(

            **event_info,

            checkpoint: 'end',

            end_time: a_kind_of(Time),

            total_items: 100,

            success_rate: 0.95

        )

          ))

          .and_call_original



        experience.complete(total_items: 100, success_rate: 0.95)

      end



      it 'includes extra arguments even when there is an error' do

        experience.error!('Something went wrong')

        experience.complete(cleanup_performed: true)



        complete_log = log_entries.find { |entry| entry[:checkpoint] == 'end' }

        expect(complete_log).to include(

        expect(Labkit::CoveredExperience.configuration.logger).to receive(:info)

          .with(hash_including(

            **event_info,

            checkpoint: 'end',

            end_time: a_kind_of(Time),

            cleanup_performed: true,

          error: true

        )

            error: true,

            error_message: a_kind_of(String)

          ))

          .and_call_original



        experience.complete(cleanup_performed: true)

      end

    end

  end