Commit 01fa96e4 authored by Bob Van Landuyt's avatar Bob Van Landuyt 💬
Browse files

Merge branch 'fix/datetime-json-format' into 'master' 

fix: Converts time to use rfc3339 w/ 3 precision on json logs

See merge request !219

Merged-by: Bob Van Landuyt's avatarBob Van Landuyt <bob@gitlab.com>
Approved-by: Bob Van Landuyt's avatarBob Van Landuyt <bob@gitlab.com>
Co-authored-by: Hercules Merscher's avatarHercules Merscher <hmerscher@gitlab.com>
parents 7601ef00 d7bdd1f5

lib/labkit/logging/json_logger.rb

+18 −5
Original line number Diff line number Diff line 
# frozen_string_literal: true

require "time"

require "date"

require "logger"

require "json"
@@ -52,7 +53,7 @@ module Labkit 
          data[:message] = message

        when Hash

          reject_reserved_log_keys!(message)

          format_time!(data)

          format_time!(message)

          data.merge!(message)

        end
@@ -81,11 +82,23 @@ module Labkit 


      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)

          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

spec/labkit/logging/json_logger_spec.rb

+127 −0
Original line number Diff line number Diff line
@@ -176,6 +176,133 @@ 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(", ")}.*/ }