Commit d6eb679b authored by Matthias Käppler's avatar Matthias Käppler 3️⃣
Browse files

Merge branch 'fix/do-not-auto-format-time' into 'master' 

fix: Do not auto format time in JsonLogger

See merge request !227

Merged-by: Matthias Käppler's avatarMatthias Käppler <mkaeppler@gitlab.com>
Approved-by: Matthias Käppler's avatarMatthias Käppler <mkaeppler@gitlab.com>
Co-authored-by: Hercules Merscher's avatarHercules Merscher <hmerscher@gitlab.com>
parents 7107b03e 25d73cd2

lib/labkit/logging/json_logger.rb

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

        when Hash

          reject_reserved_log_keys!(message)

          format_time!(message)

          data.merge!(message)

        end
@@ -85,28 +84,6 @@ 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|

          hash[key] = convert_time_value(value)

        end

      end



      def convert_time_value(value)

        case value

        when Time

          value.utc.iso8601(3)

        when DateTime

          value.to_time.utc.iso8601(3)

        when Hash

          format_time!(value)

          value

        when Array

          value.map { |v| convert_time_value(v) }

        else

          value

        end

      end

    end

  end

end

lib/labkit/user_experience_sli/experience.rb

+3 −3
Original line number Diff line number Diff line
@@ -236,9 +236,9 @@ module Labkit 
          user_experience_id: id,

          feature_category: @definition.feature_category,

          urgency: @definition.urgency,

          start_time: @start_time,

          checkpoint_time: @checkpoint_time,

          end_time: @end_time,

          start_time: @start_time&.iso8601(3),

          checkpoint_time: @checkpoint_time&.iso8601(3),

          end_time: @end_time&.iso8601(3),

          elapsed_time_s: elapsed_time,

          urgency_threshold_s: urgency_threshold

        )

spec/labkit/logging/json_logger_spec.rb

+0 −127
Original line number Diff line number Diff line
@@ -176,133 +176,6 @@ RSpec.describe Labkit::Logging::JsonLogger do 
    end

  end



  describe "time formatting" do

    let(:time_value) { Time.utc(2024, 1, 15, 10, 30, 45, 123456) }

    let(:datetime_value) { DateTime.new(2024, 1, 15, 10, 30, 45.123456, '+00:00') }

    let(:expected_iso8601) { "2024-01-15T10:30:45.123Z" }



    it "formats Time values to iso8601(3)" do

      output = subject.format_message("INFO", now, "test", { timestamp: time_value })

      data = JSON.parse(output)



      expect(data["timestamp"]).to eq(expected_iso8601)

    end



    it "formats DateTime values to iso8601(3)" do

      output = subject.format_message("INFO", now, "test", { timestamp: datetime_value })

      data = JSON.parse(output)



      expect(data["timestamp"]).to eq(expected_iso8601)

    end



    it "formats Time objects in hash messages to ISO8601" do

      time_value = Time.now

      output = subject.format_message("INFO", now, "test", { event_time: time_value })

      data = JSON.parse(output)



      expect(data["event_time"]).to eq(time_value.utc.iso8601(3))

      expect(data["event_time"]).to be_a(String)

    end



    it "formats nested Time objects in hash messages" do

      time_value = Time.now

      output = subject.format_message("INFO", now, "test", { nested: { event_time: time_value } })

      data = JSON.parse(output)



      expect(data["nested"]["event_time"]).to eq(time_value.utc.iso8601(3))

      expect(data["nested"]["event_time"]).to be_a(String)

    end



    it "formats nested DateTime objects in hash messages" do

      time_value = DateTime.now

      output = subject.format_message("INFO", now, "test", { nested: { event_time: time_value } })

      data = JSON.parse(output)



      expect(data["nested"]["event_time"]).to eq(time_value.to_time.utc.iso8601(3))

      expect(data["nested"]["event_time"]).to be_a(String)

    end



    it "formats Time values in arrays" do

      output = subject.format_message("INFO", now, "test", {

        timestamps: [time_value, time_value]

      })

      data = JSON.parse(output)



      expect(data["timestamps"]).to eq([expected_iso8601, expected_iso8601])

    end



    it "formats DateTime values in arrays" do

      output = subject.format_message("INFO", now, "test", {

        timestamps: [datetime_value, datetime_value]

      })

      data = JSON.parse(output)



      expect(data["timestamps"]).to eq([expected_iso8601, expected_iso8601])

    end



    it "formats Time values in nested arrays" do

      output = subject.format_message("INFO", now, "test", {

        events: [

          { created_at: time_value },

          { created_at: time_value }

        ]

      })

      data = JSON.parse(output)



      expect(data["events"][0]["created_at"]).to eq(expected_iso8601)

      expect(data["events"][1]["created_at"]).to eq(expected_iso8601)

    end



    it "handles mixed types in arrays" do

      output = subject.format_message("INFO", now, "test", {

        mixed: [time_value, "string", 42, { nested_time: datetime_value }]

      })

      data = JSON.parse(output)



      expect(data["mixed"][0]).to eq(expected_iso8601)

      expect(data["mixed"][1]).to eq("string")

      expect(data["mixed"][2]).to eq(42)

      expect(data["mixed"][3]["nested_time"]).to eq(expected_iso8601)

    end



    it "preserves non-time values" do

      output = subject.format_message("INFO", now, "test", {

        string: "hello",

        number: 42,

        boolean: true,

        null: nil,

        timestamp: time_value

      })

      data = JSON.parse(output)



      expect(data["string"]).to eq("hello")

      expect(data["number"]).to eq(42)

      expect(data["boolean"]).to be(true)

      expect(data["null"]).to be_nil

      expect(data["timestamp"]).to eq(expected_iso8601)

    end



    it "converts Time values with different timezones to UTC" do

      local_time = Time.new(2024, 1, 15, 15, 30, 45.123456, "+05:00")

      output = subject.format_message("INFO", now, "test", { timestamp: local_time })

      data = JSON.parse(output)



      expect(data["timestamp"]).to eq("2024-01-15T10:30:45.123Z")

    end



    it "does not corrupt context when formatting hash messages with Time values" do

      time_value = Time.now

      Labkit::Context.with_context("request_id" => "12345") do

        output = subject.format_message("INFO", now, "test", { event_time: time_value })

        data = JSON.parse(output)



        expect(data["#{Labkit::Context::LOG_KEY}.request_id"]).to eq("12345")

        expect(data["time"]).to eq(now.utc.iso8601(3))

        expect(data["event_time"]).to eq(time_value.utc.iso8601(3))

      end

    end

  end



  describe "reserved log keys" do

    let(:reserved_key_data) { described_class::RESERVED_LOG_KEYS.to_h { |k| [k, 42] } }

    let(:expected_error) { /^The following log keys used are reserved: #{described_class::RESERVED_LOG_KEYS.join(", ")}.*/ }

spec/labkit/user_experience_sli/experience_spec.rb

+8 −8
Original line number Diff line number Diff line
@@ -14,9 +14,9 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do 


  let(:event_info) do

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

      start_time: a_kind_of(Time),

      elapsed_time_s: a_kind_of(Numeric),

      urgency_threshold_s: a_kind_of(Integer),

      start_time: be_a(String),

      elapsed_time_s: be_a(Numeric),

      urgency_threshold_s: be_a(Integer),

    )

  end
@@ -62,7 +62,7 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do 
          user_experience_id: 'testing_sample',

          feature_category: 'source_code_management',

          urgency: 'sync_fast',

          start_time: be_a(Time),

          start_time: be_a(String),

          elapsed_time_s: be_a(Numeric),

          urgency_threshold_s: 2,

        )
@@ -170,7 +170,7 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do 
          .and_call_original



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

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

          .with(hash_including(**event_info, checkpoint: 'end', end_time: be_a(String)))

          .ordered

          .and_call_original
@@ -245,7 +245,7 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do 
            .and_call_original



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

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

            .with(hash_including(**event_info, checkpoint: 'end', end_time: be_a(String)))

            .ordered

            .and_call_original
@@ -296,7 +296,7 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do 
      it { expect { checkpoint }.to checkpoint_user_experience(:testing_sample) }



      it 'logs checkpoint time' do

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

        checkpoint_event_info = event_info.merge(checkpoint: 'intermediate', checkpoint_time: be_a(String))



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

          .with(hash_including(**checkpoint_event_info))
@@ -327,7 +327,7 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do 
      it { expect { complete }.to complete_user_experience(:testing_sample) }



      it 'logs completion time' do

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

        complete_event_info = event_info.merge(checkpoint: 'end', end_time: be_a(String))



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

          .with(hash_including(**complete_event_info))