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

feat: Ensuring all log messages have time tracking

parent cea318df

lib/labkit/covered_experience/experience.rb

+23 −16
Original line number Diff line number Diff line
@@ -40,9 +40,9 @@ module Labkit 
      #  experience.checkpoint

      #  experience.complete

      def start

        @started = Time.now.utc

        @start_time = Time.now.utc

        checkpoint_counter.increment(checkpoint: "start")

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

        log_event("start")



        return self unless block_given?
@@ -64,8 +64,9 @@ module Labkit 
      def checkpoint

        return unless ensure_started!



        @checkpoint_time = Time.now.utc

        checkpoint_counter.increment(checkpoint: "intermediate")

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

        log_event("intermediate")



        self

      end
@@ -78,20 +79,12 @@ module Labkit 
        return unless ensure_started!



        begin

          end_time = Time.now.utc

          elapsed = end_time - @started

          @end_time = Time.now.utc

        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)

          apdex_counter.increment(success: success?) unless has_error?

          log_event("end")

        end



        self
@@ -117,7 +110,7 @@ module Labkit 
      end



      def ensure_started!

        return @started unless @started.nil?

        return @start_time unless @start_time.nil?



        err = UnstartedError.new("Covered Experience #{@definition.covered_experience} not started")
@@ -129,6 +122,15 @@ module Labkit 
        URGENCY_THRESHOLDS_IN_SECONDS[@definition.urgency.to_sym]

      end



      def elapsed

        last_time = @end_time || @checkpoint_time || @start_time

        last_time - @start_time

      end



      def success?

        elapsed <= urgency_threshold

      end



      def checkpoint_counter

        @checkpoint_counter ||= Labkit::Metrics::Client.counter(

          :gitlab_covered_experience_checkpoint_total,
@@ -164,8 +166,13 @@ module Labkit 
          checkpoint: event_type,

          covered_experience: @definition.covered_experience,

          feature_category: @definition.feature_category,

          urgency: @definition.urgency

          urgency: @definition.urgency,

          start_time: @start_time.iso8601,

          elapsed: elapsed,

          urgency_threshold_in_seconds: urgency_threshold

        )

        log_data[:checkpoint_time] = @checkpoint_time.iso8601 if @checkpoint_time

        log_data[:end_time] = @end_time.iso8601 if @end_time



        if has_error?

          log_data[:error] = true

lib/labkit/rspec/matchers/covered_experience_matchers.rb

+12 −5
Original line number Diff line number Diff line
@@ -42,8 +42,15 @@ module Labkit 
        def allow_logger_call(covered_experience_id, checkpoint_type, extra = {})

          return unless logger



          attrs = attributes(covered_experience_id)

          expected_log_data = { **extra, **attrs, checkpoint: checkpoint_type }

          expected_log_data = {

            **extra,

            checkpoint: checkpoint_type,

            # always present values

            **attributes(covered_experience_id),

            start_time: be_a(String),

            elapsed: be_a(Numeric),

            urgency_threshold_in_seconds: be_a(Numeric)

          }



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

        end
@@ -74,7 +81,7 @@ RSpec::Matchers.define :start_covered_experience do |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))

    allow_logger_call(covered_experience_id, "start")



    actual.call
@@ -113,7 +120,7 @@ RSpec::Matchers.define :checkpoint_covered_experience do |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))

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



    actual.call
@@ -175,7 +182,7 @@ RSpec::Matchers.define :complete_covered_experience do |covered_experience_id, e 
    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 = { end_time: be_a(String) }

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

    allow_logger_call(covered_experience_id, "end", attrs)