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

fix: JsonLogger should not automatically format time

parent 7107b03e
Loading
Loading
Loading
Loading
+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
+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(", ")}.*/ }