✨ Added time_formatter_proc, add_time_format

.rubocop_gradual.lock

@@ -1,25 +1,25 @@
 {
-  "README.md:3009712128": [
+  "README.md:3801622303": [
     [240, 10, 27, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2226893134],
     [243, 3, 37, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 4163348045],
     [247, 3, 37, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2420123939],
     [251, 3, 45, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 3568969579],
     [264, 3, 43, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 235184892],
-    [354, 12, 27, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2226893134],
-    [357, 3, 37, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 4163348045],
-    [361, 3, 37, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2420123939],
-    [365, 3, 45, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 3568969579],
-    [378, 3, 45, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 637514124]
+    [375, 12, 27, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2226893134],
+    [378, 3, 37, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 4163348045],
+    [382, 3, 37, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2420123939],
+    [386, 3, 45, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 3568969579],
+    [399, 3, 45, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 637514124]
   ],
   "bin/bundle:1543177218": [
     [63, 5, 20, "ThreadSafety/InstanceVariableInClassMethod: Avoid instance variables in class methods.", 2485198147]
   ],
   "lib/debug_logging.rb:2647816515": [
     [124, 5, 42, "ThreadSafety/ClassAndModuleAttributes: Avoid mutating class and module attributes.", 1265699560]
   ],
-  "lib/debug_logging/argument_printer.rb:3334736513": [
+  "lib/debug_logging/argument_printer.rb:268366549": [
     [11, 7, 49, "Style/UnlessLogicalOperators: Do not use mixed logical operators in an `unless`.", 24710009],
-    [60, 7, 49, "Style/UnlessLogicalOperators: Do not use mixed logical operators in an `unless`.", 24710009]
+    [66, 7, 49, "Style/UnlessLogicalOperators: Do not use mixed logical operators in an `unless`.", 24710009]
   ],
   "lib/debug_logging/finalize.rb:2519216288": [
     [5, 5, 299, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2506770293]
@@ -28,20 +28,20 @@
     [6, 5, 61, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 62321122],
     [10, 5, 59, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 2109073884]
   ],
-  "lib/debug_logging/log_subscriber.rb:1842174884": [
+  "lib/debug_logging/log_subscriber.rb:2124920356": [
     [10, 7, 20, "ThreadSafety/ClassAndModuleAttributes: Avoid mutating class and module attributes.", 1853072198],
     [16, 5, 368, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 479488482],
     [17, 7, 6, "ThreadSafety/InstanceVariableInClassMethod: Avoid instance variables in class methods.", 2741946345],
-    [28, 5, 558, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 4277533184]
+    [28, 5, 570, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 4277533184]
   ],
-  "lib/debug_logging/util.rb:1177721888": [
-    [62, 9, 5, "Style/IdenticalConditionalBranches: Move `proxy` out of the conditional.", 187023241],
-    [77, 9, 5, "Style/IdenticalConditionalBranches: Move `proxy` out of the conditional.", 187023241]
+  "lib/debug_logging/util.rb:1422248835": [
+    [78, 9, 5, "Style/IdenticalConditionalBranches: Move `proxy` out of the conditional.", 187023241],
+    [93, 9, 5, "Style/IdenticalConditionalBranches: Move `proxy` out of the conditional.", 187023241]
   ],
   "lib/simple_debug_logging.rb:1035783295": [
     [71, 5, 688, "Style/ClassMethodsDefinitions: Use `class << self` to define a class method.", 790702810]
   ],
-  "spec/debug_logging/argument_printer_spec.rb:2145628744": [
+  "spec/debug_logging/argument_printer_spec.rb:2820935729": [
     [12, 17, 35, "RSpec/VerifiedDoubles: Prefer using verifying doubles over normal doubles.", 864840599],
     [50, 33, 35, "Style/DateTime: Prefer `Time` over `DateTime`.", 2193634500],
     [98, 13, 23, "RSpec/ContextWording: Context description should match /^when\\b/, /^with\\b/, or /^without\\b/.", 2254666317],
@@ -284,7 +284,7 @@
     [7, 7, 7, "RSpec/InstanceVariable: Avoid instance variables - use let, a method call, or a local variable (if possible).", 289916282],
     [11, 11, 55, "RSpec/ContextWording: Context description should match /^when\\b/, /^with\\b/, or /^without\\b/.", 2011841710]
   ],
-  "spec/debug_logging_spec.rb:3914205660": [
+  "spec/debug_logging_spec.rb:2514057238": [
     [10, 44, 7, "RSpec/MessageSpies: Prefer `have_received` for setting message expectations. Setup `simple_klass.debug_config` as a spy using `allow` or `instance_spy`.", 1384559950],
     [11, 25, 7, "RSpec/MessageSpies: Prefer `have_received` for setting message expectations. Setup `logger` as a spy using `allow` or `instance_spy`.", 1384559950],
     [20, 44, 7, "RSpec/MessageSpies: Prefer `have_received` for setting message expectations. Setup `simple_klass.debug_config` as a spy using `allow` or `instance_spy`.", 1384559950],

CHANGELOG.md

@@ -8,6 +8,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [Unreleased]
 ### Added
 - Support for all Numeric types to be used as monotonic timestamps for ActiveSupport::Notifications
+- `time_formatter_proc` - used to format timestamp added to beginning of log lines
+- `add_timestamp` - Add timestamp to front of each log line
 ### Changed
 - `DebugLogging::ArgumentPrinter.debug_time_to_s` => `DebugLogging::ArgumentPrinter.debug_event_time_to_s`
 ### Fixed

README.md

@@ -208,7 +208,7 @@ Just send along a hash of the config options, similar to the following:
 
 See the example class below, and the specs.
 
-**NOTE ON** `Rails.logger` - It will probably be nil in your initializer, so setting the `config.logger` to `Rails.logger` there will result in setting it to `nil`, which means the default will end up being used: `Logger.new(STDOUT)`. Instead just config the logger in your application.rb, or anytime later, but *before your classes get loaded* and start inheriting the config:
+**NOTE ON** `Rails.logger` - It will probably be nil in your initializer, so setting the `config.logger` to `Rails.logger` there will result in setting it to `nil`, which means the default will end up being used: `Logger.new($stdout)`. Instead just config the logger in your application.rb, or anytime later, but *before your classes get loaded* and start inheriting the config:
 
 ```ruby
 DebugLogging.configuration.logger = Rails.logger
@@ -294,7 +294,28 @@ class Car
   # Override configuration options for any instance method(s), by passing a hash as the last argument
   # In the last hash any non-Configuration keys will be data that gets logged,
   #     and also made available to last_hash_to_s_proc
-  i_logged [:faster], {add_invocation_id: false}
+  # Here's an example that sets every possible option, while also showing what the default values are!
+  i_logged [:faster], {
+    logger: Logger.new($stdout), # probably want to override to be the Rails.logger
+    log_level: :debug, # at what level do the messages created by this gem sent at?
+    multiple_last_hashes: false,
+    last_hash_to_s_proc: nil, # e.g. ->(hash) { "keys: #{hash.keys}" }
+    last_hash_max_length: 1_000,
+    args_to_s_proc: nil, # e.g. ->(*record) { "record id: #{record.first.id}" }
+    args_max_length: 1_000,
+    colorized_chain_for_method: false, # e.g. ->(colorized_string) { colorized_string.red.on_blue.underline }
+    colorized_chain_for_class: false,  # e.g. ->(colorized_string) { colorized_string.colorize(:light_blue ).colorize( :background => :red) }
+    add_invocation_id: true, # allows unique identification of method call; association of entry and exit log lines
+    ellipsis: " ✂️ …".freeze,
+    mark_scope_exit: false,
+    add_payload: true, # Can also be a proc returning a string, which will be called when printing the payload
+    payload_max_length: 1_000,
+    error_handler_proc: nil,
+    time_formatter_proc: DebugLogging::Constants::DEFAULT_TIME_FORMATTER,
+    add_time_format: false,
+    instance_benchmarks: false,
+    class_benchmarks: false,
+  }
 
   # You can also use `i_logged` as a true method decorator:
   i_logged def slower

lib/debug_logging/argument_printer.rb

@@ -7,11 +7,13 @@ def debug_benchmark_to_s(tms:)
       "completed in #{format("%f", tms.real)}s (#{format("%f", tms.total)}s CPU)"
     end
 
-    def debug_invocation_id_to_s(args: nil, kwargs: nil, config_proxy: nil)
+    def debug_invocation_id_to_s(args: nil, kwargs: nil, start_at: nil, config_proxy: nil)
       return "" unless (args || kwargs) && config_proxy
 
       if config_proxy.debug_add_invocation_id
-        invocation = " ~#{args.object_id}|#{kwargs.object_id}@#{(Time.now.to_f.to_s % "%#-21a")[4..-4]}~"
+        time = start_at ? Util.debug_time(start_at) : Time.now
+        unique_id = (time.to_f.to_s % "%#-21a")[4..-4]
+        invocation = " ~#{args.object_id}|#{kwargs.object_id}@#{unique_id}~"
         case config_proxy.debug_add_invocation_id
         when true
           invocation
@@ -23,22 +25,25 @@ def debug_invocation_id_to_s(args: nil, kwargs: nil, config_proxy: nil)
       end
     end
 
+    # @return [String]
+    def debug_time_to_s(time_or_monotonic, config_proxy: nil)
+      return "" unless config_proxy&.add_timestamp
+      return config_proxy.time_formatter_proc.call(Time.now) unless time_or_monotonic
+
+      time = Util.debug_time(time_or_monotonic)
+
+      config_proxy.time_formatter_proc.call(time)
+    end
+
     # A custom time format will never apply here, because ActiveSupport::Notifications have a required time format
     def debug_event_time_to_s(time_or_monotonic)
       # Time format must match:
       #   \d{4,}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} [-+]\d{4}
       #   YYYY-MM-DD HH:mm:ss +00:00
       #   strftime("%F %T %z")
-      case time_or_monotonic
-      when Numeric
-        Time.at(time_or_monotonic).strftime("%F %T %z")
-      when Time, DateTime
-        time_or_monotonic.strftime("%F %T %z")
-      when String
-        Time.parse(time_or_monotonic).strftime("%F %T %z")
-      else
-        time_or_monotonic
-      end
+      time_or_monotonic = Time.now if time_or_monotonic.nil? || (time_or_monotonic.respond_to?(:empty?) && time_or_monotonic.empty?)
+      time = Util.debug_time(time_or_monotonic)
+      DebugLogging::Constants::EVENT_TIME_FORMATTER.call(time)
     end
 
     def debug_invocation_to_s(klass: nil, separator: nil, method_to_log: nil, config_proxy: nil)
@@ -197,10 +202,10 @@ def debug_payload_to_s(payload: nil, config_proxy: nil)
       end
     end
 
+    module_function
+
     def debug_event_name_to_s(method_to_notify: nil)
       "#{method_to_notify}.log"
     end
-
-    module_function
   end
 end

lib/debug_logging/configuration.rb

@@ -12,16 +12,25 @@ class Configuration
     #     extend DebugLogging::InstanceLogger
     #     i_logged [:drive, :stop],
     #       {
-    #         logger: Logger.new(STDOUT) # probably want to override to be the Rails.logger
-    #         log_level: :debug # at what level do the messages created by this gem sent at?
-    #         last_hash_to_s_proc: nil # e.g. ->(hash) { "keys: #{hash.keys}" }
-    #         last_hash_max_length: 1_000
-    #         args_to_s_proc: nil # e.g. ->(*record) { "record id: #{record.first.id}" }
-    #         args_max_length: 1_000
-    #         instance_benchmarks: false
-    #         class_benchmarks: false
-    #         add_invocation_id: true # invocation id allows you to identify a method call uniquely in a log
-    #         ellipsis: " ✂️ …".freeze
+    #         logger: Logger.new($stdout), # probably want to override to be the Rails.logger
+    #         log_level: :debug, # at what level do the messages created by this gem sent at?
+    #         multiple_last_hashes: false,
+    #         last_hash_to_s_proc: nil, # e.g. ->(hash) { "keys: #{hash.keys}" }
+    #         last_hash_max_length: 1_000,
+    #         args_to_s_proc: nil, # e.g. ->(*record) { "record id: #{record.first.id}" }
+    #         args_max_length: 1_000,
+    #         colorized_chain_for_method: false, # e.g. ->(colorized_string) { colorized_string.red.on_blue.underline }
+    #         colorized_chain_for_class: false,  # e.g. ->(colorized_string) { colorized_string.colorize(:light_blue ).colorize( :background => :red) }
+    #         add_invocation_id: true, # allows unique identification of method call; association of entry and exit log lines
+    #         ellipsis: " ✂️ …".freeze,
+    #         mark_scope_exit: false,
+    #         add_payload: true, # Can also be a proc returning a string, which will be called when printing the payload
+    #         payload_max_length: 1_000,
+    #         error_handler_proc: nil,
+    #         time_formatter_proc: DebugLogging::Constants::DEFAULT_TIME_FORMATTER,
+    #         add_timestamp: false,
+    #         instance_benchmarks: false,
+    #         class_benchmarks: false,
     #       }
     #
     CONFIG_KEYS.each do |key|

lib/debug_logging/constants.rb

@@ -1,23 +1,27 @@
 module DebugLogging
   module Constants
     DEFAULT_ELLIPSIS = " ✂️ …"
+    DEFAULT_TIME_FORMATTER = ->(time) { "[#{time.strftime("%Y%m%d %H-%M-%S")}] " }
+    EVENT_TIME_FORMATTER = ->(time) { time.strftime("%F %T %z") }
     CONFIG_ATTRS_DEFAULTS = {
       enabled: true,
-      logger: Logger.new($stdout),
-      log_level: :debug,
+      logger: Logger.new($stdout), # probably want to override to be the Rails.logger
+      log_level: :debug, # at what level do the messages created by this gem sent at?
       multiple_last_hashes: false,
-      last_hash_to_s_proc: nil,
+      last_hash_to_s_proc: nil, # e.g. ->(hash) { "keys: #{hash.keys}" }
       last_hash_max_length: 1_000,
-      args_to_s_proc: nil,
+      args_to_s_proc: nil, # e.g. ->(*record) { "record id: #{record.first.id}" }
       args_max_length: 1_000,
-      colorized_chain_for_method: false,
-      colorized_chain_for_class: false,
-      add_invocation_id: true,
+      colorized_chain_for_method: false, # e.g. ->(colorized_string) { colorized_string.red.on_blue.underline }
+      colorized_chain_for_class: false,  # e.g. ->(colorized_string) { colorized_string.colorize(:light_blue ).colorize( :background => :red) }
+      add_invocation_id: true, # allows unique identification of method call; association of entry and exit log lines
       ellipsis: DEFAULT_ELLIPSIS,
       mark_scope_exit: false,
       add_payload: true, # Can also be a proc returning a string, which will be called when printing the payload
       payload_max_length: 1_000,
       error_handler_proc: nil,
+      time_formatter_proc: DEFAULT_TIME_FORMATTER,
+      add_timestamp: false,
     }.freeze
     CONFIG_ATTRS = CONFIG_ATTRS_DEFAULTS.keys
     CONFIG_READERS_DEFAULTS = {

lib/debug_logging/instance_logger.rb

@@ -1,5 +1,27 @@
 module DebugLogging
   module InstanceLogger
+    # NOTE: These params can be passed in / hidden in a last hash of *args
+    # NOTE: They can also be passed in discretely for each method, by passing *args as an array of arrays
+    # TODO: Refactor to use modern Ruby 3 *args, **kwargs instead
+    # @param logger [Logger] Logger.new($stdout), # probably want to override to be the Rails.logger
+    # @param log_level [Symbol] default: :debug, at what level do the messages created by this gem sent at?
+    # @param multiple_last_hashes [true, false] default: false,
+    # @param last_hash_to_s_proc [nil, Proc] default: nil, e.g. ->(hash) { "keys: #{hash.keys}" }
+    # @param last_hash_max_length [Integer] default: 1_000,
+    # @param args_to_s_proc [nil, Proc] default: nil, e.g. ->(*record) { "record id: #{record.first.id}" }
+    # @param args_max_length [Integer] default: 1_000,
+    # @param colorized_chain_for_method [false, Proc] default: false, e.g. ->(colorized_string) { colorized_string.red.on_blue.underline }
+    # @param colorized_chain_for_class [false, Proc] default: false, e.g. ->(colorized_string) { colorized_string.colorize(:light_blue ).colorize( :background => :red) }
+    # @param add_invocation_id [true, false] default: true, allows unique identification of method call; association of entry and exit log lines
+    # @param ellipsis [String] default: " ✂️ …".freeze,
+    # @param mark_scope_exit [true, false] default: false,
+    # @param add_payload [true, false, Proc] default: true, # Can also be a proc returning a string, which will be called when printing the payload
+    # @param payload_max_length [Integer] default: 1_000,
+    # @param error_handler_proc [nil, Proc] default: nil,
+    # @param time_formatter_proc [nil, Proc] default: DebugLogging::Constants::DEFAULT_TIME_FORMATTER,
+    # @param add_timestamp [true, false] default: false,
+    # @param instance_benchmarks [true, false] default: false,
+    # @param class_benchmarks [true, false] default: false,
     def i_logged(*methods_to_log)
       methods_to_log, payload, config_opts = DebugLogging::Util.extract_payload_and_config(
         method_names: methods_to_log,

lib/debug_logging/instance_logger_modulizer.rb

@@ -28,19 +28,22 @@ def to_mod(methods_to_log: nil, payload: nil, config: nil)
                 method_to_log: method_to_log,
                 config_proxy: config_proxy,
               )
-              invocation_id = self.class.debug_invocation_id_to_s(args:, kwargs:, config_proxy:)
+              start_at = Time.now
+              start_timestamp = self.class.debug_time_to_s(start_at, config_proxy:)
+              invocation_id = self.class.debug_invocation_id_to_s(args:, kwargs:, start_at:, config_proxy:)
               config_proxy.log do
                 paydirt = DebugLogging::Util.payload_instance_variable_hydration(scope: self, payload: method_payload)
                 signature = self.class.debug_signature_to_s(args:, kwargs:, config_proxy:)
                 paymud = debug_payload_to_s(payload: paydirt, config_proxy:)
-                "#{log_prefix}#{signature}#{invocation_id} debug: #{paymud}"
+                "#{start_timestamp}#{log_prefix}#{signature}#{invocation_id} debug: #{paymud}"
               end
               if config_proxy.benchmarkable_for?(:debug_instance_benchmarks)
                 tms = Benchmark.measure do
                   method_return_value = super(*args, **kwargs, &block)
                 end
+                end_timestamp = self.class.debug_time_to_s(Time.now, config_proxy:)
                 config_proxy.log do
-                  "#{log_prefix} #{self.class.debug_benchmark_to_s(tms: tms)}#{invocation_id}"
+                  "#{end_timestamp}#{log_prefix} #{self.class.debug_benchmark_to_s(tms: tms)}#{invocation_id}"
                 end
               else
                 begin
@@ -53,8 +56,9 @@ def to_mod(methods_to_log: nil, payload: nil, config: nil)
                   end
                 end
                 if config_proxy.exit_scope_markable? && invocation_id && !invocation_id.empty?
+                  end_timestamp = self.class.debug_time_to_s(Time.now, config_proxy:)
                   config_proxy.log do
-                    "#{log_prefix} completed#{invocation_id}"
+                    "#{end_timestamp}#{log_prefix} completed#{invocation_id}"
                   end
                 end
               end