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

feat: Automatically format time in structured JSON log messages

parent 2ac4a073

lib/labkit/covered_experience/experience.rb

+5 −6
Original line number Diff line number Diff line
@@ -161,18 +161,17 @@ module Labkit 
      end



      def build_log_data(event_type, **extra)

        extra ||= {}

        log_data = extra.merge(

        log_data = (extra || {}).merge(

          checkpoint: event_type,

          covered_experience: @definition.covered_experience,

          feature_category: @definition.feature_category,

          urgency: @definition.urgency,

          start_time: @start_time.utc.iso8601(3),

          start_time: @start_time,

          checkpoint_time: @checkpoint_time,

          end_time: @end_time,

          elapsed: elapsed,

          urgency_threshold_in_seconds: urgency_threshold

        )

        log_data[:checkpoint_time] = @checkpoint_time.utc.iso8601(3) if @checkpoint_time

        log_data[:end_time] = @end_time.utc.iso8601(3) if @end_time

        ).compact



        if has_error?

          log_data[:error] = true

lib/labkit/logging/json_logger.rb

+11 −0
Original line number Diff line number Diff line
@@ -52,6 +52,7 @@ module Labkit 
          data[:message] = message

        when Hash

          reject_reserved_log_keys!(message)

          format_time!(data)

          data.merge!(message)

        end
@@ -77,6 +78,16 @@ module Labkit 
                  "\n\nUse key names that are descriptive e.g. by using a prefix."

        end

      end



      def format_time!(hash)

        hash.each do |key, value|

          if value.is_a?(Time)

            hash[key] = value.utc.iso8601(3)

          elsif value.is_a?(Hash)

            format_time(value)

          end

        end

      end

    end

  end

end

lib/labkit/rspec/matchers/covered_experience_matchers.rb

+3 −3
Original line number Diff line number Diff line
@@ -47,7 +47,7 @@ module Labkit 
            checkpoint: checkpoint_type,

            # always present values

            **attributes(covered_experience_id),

            start_time: be_a(String),

            start_time: be_a(Time),

            elapsed: be_a(Numeric),

            urgency_threshold_in_seconds: be_a(Numeric)

          }
@@ -120,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", checkpoint_time: be_a(String))

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



    actual.call
@@ -182,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 = { end_time: be_a(String) }

    attrs = { end_time: be_a(Time) }

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

    allow_logger_call(covered_experience_id, "end", attrs)