Merge pull request #58 from epimorphics/spike/update-logging-params

Task: Release v2.0.2

CHANGELOG.md

@@ -1,5 +1,13 @@
 # Changelog for the JSON Rails Logger gem
 
+## 2.0.2 - 2025-02
+
+- (Jon) Added new required keys for logging: message, method, path, etc.
+- (Jon) Moved some keys to optional and updated their handling.
+- (Jon) Improved payload formatting based on log severity in development.
+- (Jon) Introduced a new method for fetching request parameters.
+- (Jon) Enhanced duration normalisation logic.
+
 ## 2.0.1 - 2024-12
 
 - (Bogdan) Regenerated `Gemfile.lock`

Gemfile.lock

@@ -1,10 +1,10 @@
 PATH
   remote: .
   specs:
-    json_rails_logger (2.0.1)
+    json_rails_logger (2.0.2)
       json
       lograge
-      railties (~> 7.0)
+      railties
 
 GEM
   remote: https://rubygems.org/

json_rails_logger.gemspec

@@ -29,5 +29,5 @@ Gem::Specification.new do |spec|
 
   spec.add_dependency 'json'
   spec.add_dependency 'lograge'
-  spec.add_dependency 'railties', '~> 7.0'
+  spec.add_dependency 'railties'
 end

lib/json_rails_logger/constants.rb

@@ -6,6 +6,7 @@ module JsonRailsLogger
   EXCEPTION = :exception
   MESSAGE = :message
   METHOD = :method
+  PARAMS = :request_params # Alias for REQUEST_PARAMS
   PATH = :request_path # Alias for REQUEST_PATH
   QUERY_STRING = :query_string
   REQUEST_ID = :request_id
@@ -14,6 +15,7 @@ module JsonRailsLogger
   REQUEST_STATUS = :request_status
   REQUEST_URI = :request_uri
   STATUS = :status
+  USER_AGENT = :user_agent
   # * THE FOLLOWING ARE NOT CURRENTLY USED BUT AVAILABLE FOR USE * #
   # ACCEPT = :accept
   # ACTION = :action
@@ -42,5 +44,4 @@ module JsonRailsLogger
   # SERVER_PORT = :server_port
   # SERVER_PROTOCOL = :server_protocol
   # SERVER_SOFTWARE = :server_software
-  # USER_AGENT = :user_agent
 end

lib/json_rails_logger/json_formatter.rb

@@ -6,12 +6,29 @@ class JsonFormatter < ::Logger::Formatter # rubocop:disable Metrics/ClassLength
     ## Required keys to be logged to the output
     REQUIRED_KEYS = %w[
       accept
-      action
       backtrace
       body
-      controller
       duration
+      message
+      method
+      path
+      query_string
+      request_id
+      request_params
+      request_path
+      request_status
+      request_time
+      status
+      user_agent
+    ].freeze
+
+    ## Optional keys to be ignored from the output for the time being
+    OPTIONAL_KEYS = %w[
+      action
       encoding
+      exception
+      exception_object
+      format
       forwarded_for
       gateway
       http_accept_charset
@@ -25,28 +42,17 @@ class JsonFormatter < ::Logger::Formatter # rubocop:disable Metrics/ClassLength
       http_origin
       http_referer
       keep_alive
-      message
-      method
-      path
-      query_string
+      params
       remote_addr
-      request_id
-      request_params
-      request_path
-      request_status
       request_uri
       request_url
       server_name
       server_port
       server_protocol
       server_software
-      status
-      user_agent
+      view
     ].freeze
 
-    ## Optional keys to be ignored from the output for the time being
-    OPTIONAL_KEYS = %w[format exception exception_object view].freeze
-
     ## Request methods to check for in the message
     REQUEST_METHODS = %w[GET POST PUT DELETE PATCH].freeze
 
@@ -57,12 +63,22 @@ def call(severity, timestamp, _progname, raw_msg) # rubocop:disable Metrics/AbcS
       msg = process_message(raw_msg)
       new_msg = format_message(msg)
 
+      # if Rails.logger.debug?
+      #   puts "\n\e[31m> received raw_msg: #{raw_msg}\e[0m"
+      #   puts "\e[32m> processed msg: #{msg}\e[0m"
+      #   puts "\e[33m> formatted msg: #{new_msg}\e[0m\n\n"
+      # end
+
+      # ! DO NOT DISPLAY THIS MESSAGE FROM WEBPACKER
+      return nil if new_msg[:message] == "[Webpacker] Everything's up-to-date. Nothing to do"
+
       payload = {
         ts: timestp,
         level: sev
       }
 
       payload.merge!(query_string.to_h) unless query_string.nil?
+      payload.merge!(request_params.to_h) unless request_params.nil?
       payload.merge!(request_id.to_h)
       payload.merge!(new_msg.to_h.except!(:optional).compact)
 
@@ -90,6 +106,12 @@ def query_string
       { query_string: query_string } if query_string.present?
     end
 
+    def request_params
+      request_params = Thread.current[JsonRailsLogger::REQUEST_PARAMS]
+      request_params ||= Thread.current[JsonRailsLogger::PARAMS]
+      { query_string: request_params } if request_params.present? && query_string.empty
+    end
+
     def process_message(raw_msg)
       msg = normalize_message(raw_msg)
 
@@ -98,6 +120,10 @@ def process_message(raw_msg)
       return request_type(msg) if request_type?(msg)
       return user_agent_message(msg) if user_agent_message?(msg)
 
+      # squish is better than strip as it still returns the string, but first
+      # removing all whitespace on both ends of the string, and then changing
+      # remaining consecutive whitespace groups into one space each. strip only
+      # removes white spaces only at the leading and trailing ends.
       { message: msg.squish }
     end
 
@@ -113,10 +139,9 @@ def format_message(msg)
       split_msg = msg.partition { |k, _v| REQUIRED_KEYS.include?(k.to_s) }.map(&:to_h)
       # If the returned hash is empty, check if the message is a hash with optional keys
       if split_msg[0].empty?
-        split_msg = msg.partition do |k, _v|
-          OPTIONAL_KEYS.exclude?(k.to_s)
-        end.map(&:to_h)
+        split_msg = msg.partition { |k, _v| OPTIONAL_KEYS.include?(k.to_s) }.map(&:to_h)
       end
+
       # Check if the message contains a duration key and normalise it
       split_msg[0] = normalise_duration(split_msg[0]) if includes_duration?(split_msg[0])
 
@@ -178,12 +203,21 @@ def user_agent_message(msg)
     end
 
     def includes_duration?(msg)
-      msg.key?('duration')
+      msg.key?('duration') ||
+        msg.key?(:duration) ||
+        msg.key?('request_time') ||
+        msg.key?(:request_time)
     end
 
     # If duration is a float, convert it to an integer as milliseconds µs -> ms
     def normalise_duration(msg)
-      msg.to_h { |k, v| k.to_s == 'duration' && v.is_a?(Float) ? [k, v.round(0)] : [k, v] }
+      msg.to_h do |k, v|
+        if %w[duration request_time].include?(k.to_s) && v.is_a?(Float)
+          [:request_time, v.round(0)]
+        else
+          [k, v]
+        end
+      end
     end
   end
 end

lib/json_rails_logger/version.rb

@@ -3,7 +3,7 @@
 module JsonRailsLogger
   MAJOR = 2
   MINOR = 0
-  PATCH = 1
+  PATCH = 2
   SUFFIX = nil
   VERSION = "#{MAJOR}.#{MINOR}.#{PATCH}#{SUFFIX && "-#{SUFFIX}"}".freeze
 end

test/formatter_test.rb

@@ -56,7 +56,7 @@
   end
 
   it 'should correctly format the timestamp' do
-    message = "[Webpacker] Everything's up-to-date. Nothing to do"
+    message = "Everything's up-to-date. Nothing to do"
 
     log_output = fixture.call('INFO', timestamp, progname, message)
     _(log_output).must_be_kind_of(String)
@@ -80,7 +80,7 @@
   end
 
   it 'should correctly add the request id to returning json' do
-    message = "[Webpacker] Everything's up-to-date. Nothing to do"
+    message = "Everything's up-to-date. Nothing to do"
     request_id_fixture = { 'request_id' => 'example-8a3fb0-request-30dgh0e-id' }
 
     fixture.stub :request_id, request_id_fixture do
@@ -93,12 +93,12 @@
   end
 
   it 'should correctly format a microsecond duration into milliseconds' do
-    message = '{"duration": 1234567.89}'
+    message = '{"request_time": 1234567.89}'
 
     log_output = fixture.call('INFO', timestamp, progname, message)
     _(log_output).must_be_kind_of(String)
 
     json_output = JSON.parse(log_output)
-    _(json_output['duration']).must_equal(1_234_568)
+    _(json_output['request_time']).must_equal(1_234_568)
   end
 end