Optimize trace and debug logging (#332)

lib/openhab/core.rb

@@ -38,7 +38,7 @@ class << self
       def wait_till_openhab_ready
         logger.trace("Checking readiness of openHAB")
         until automation_manager
-          logger.trace("Automation manager not loaded, checking again in #{CHECK_DELAY} seconds.")
+          logger.trace { "Automation manager not loaded, checking again in #{CHECK_DELAY} seconds." }
           sleep CHECK_DELAY
         end
         logger.trace "Automation manager instantiated, openHAB ready for rule processing."

lib/openhab/core/actions.rb

@@ -37,7 +37,7 @@ module Actions
                  else
                    (java_import action_class.ruby_class).first
                  end
-        logger.trace("Loaded ACTION: #{action_class}")
+        logger.trace { "Loaded ACTION: #{action_class}" }
         Object.const_set(module_name, action)
       end
 

lib/openhab/core/items.rb

@@ -44,7 +44,7 @@ def def_predicate_methods(klass)
             _command_predicate, state_predicate = Types::PREDICATE_ALIASES[state.to_s]
             next if klass.instance_methods.include?(state_predicate)
 
-            logger.trace("Defining #{klass}##{state_predicate} for #{state}")
+            logger.trace { "Defining #{klass}##{state_predicate} for #{state}" }
             klass.class_eval <<~RUBY, __FILE__, __LINE__ + 1
               def #{state_predicate}                                                  # def on?
                 raw_state.as(#{state.class.java_class.simple_name}).equal?(#{state})  #   raw_state.as(OnOffType) == ON
@@ -61,7 +61,7 @@ def def_command_methods(klass)
             next if klass.instance_methods.include?(command)
 
             if value.is_a?(Types::State)
-              logger.trace("Defining #{klass}/Enumerable##{command}/#{command}! for #{value}")
+              logger.trace { "Defining #{klass}/Enumerable##{command}/#{command}! for #{value}" }
 
               klass.class_eval <<~RUBY, __FILE__, __LINE__ + 1
                 ruby2_keywords def #{command}(*args, &block)   # ruby2_keywords def on(*args, &block)
@@ -83,7 +83,7 @@ def #{command}!        # def on!
                 end                    # end
               RUBY
             else
-              logger.trace("Defining #{klass}/Enumerable##{command} for #{value}")
+              logger.trace { "Defining #{klass}/Enumerable##{command} for #{value}" }
 
               klass.class_eval <<~RUBY, __FILE__, __LINE__ + 1
                 ruby2_keywords def #{command}(*args, &block)  # ruby2_keywords def refresh(*args, &block)
@@ -98,7 +98,7 @@ def #{command}        # def refresh
               RUBY
             end
 
-            logger.trace("Defining ItemCommandEvent##{command}? for #{value}")
+            logger.trace { "Defining ItemCommandEvent##{command}? for #{value}" }
             Events::ItemCommandEvent.class_eval <<~RUBY, __FILE__, __LINE__ + 1
               def #{command}?                                                       # def refresh?
                 command.as(#{value.class.java_class.simple_name}).equal?(#{value})  #   command.as(RefreshType).equal?(REFRESH)

lib/openhab/core/items/generic_item.rb

@@ -276,7 +276,7 @@ def modify(force: false)
               raise FrozenError, "Cannot modify item #{name} from provider #{provider.inspect}." unless force
 
               provider = nil
-              logger.debug("Forcing modifications to non-managed item #{name}")
+              logger.debug { "Forcing modifications to non-managed item #{name}" }
             end
             @modified = false
             @modifying = true

lib/openhab/core/items/image_item.rb

@@ -55,7 +55,7 @@ def update_from_file(file, mime_type: nil)
         #
         #
         def update_from_url(uri)
-          logger.trace("Downloading image from #{uri}")
+          logger.trace { "Downloading image from #{uri}" }
           response = Net::HTTP.get_response(URI(uri))
           mime_type = response["content-type"]
           bytes = response.body

lib/openhab/core/items/metadata/namespace_hash.rb

@@ -73,7 +73,7 @@ def fetch(key, *default_value, &block)
               raise ArgumentError, "Wrong number of arguments (given #{default_value.length + 1}, expected 1..2)"
             end
 
-            logger.trace("Getting metadata for item: #{@item_name}, namespace '#{key}'")
+            logger.trace { "Getting metadata for item: #{@item_name}, namespace '#{key}'" }
             if (m = Provider.registry.get(MetadataKey.new(key, @item_name)))
               Hash.new(m)
             elsif block

lib/openhab/core/items/semantics.rb

@@ -251,7 +251,7 @@ def lookup(id, locale = java.util.Locale.default)
           #
           # @!visibility private
           def const_missing(sym)
-            logger.trace("const missing, performing Semantics Lookup for: #{sym}")
+            logger.trace { "const missing, performing Semantics Lookup for: #{sym}" }
             lookup(sym)&.tap { |tag| const_set(sym, tag) } || super
           end
         end

lib/openhab/core/profile_factory.rb

@@ -86,7 +86,9 @@ def onTimeSeriesFromHandler(time_series)
         private
 
         def process_event(event, **params)
-          logger.trace("Handling event #{event.inspect} in profile #{@uid} with param #{params.values.first.inspect}.")
+          logger.trace do
+            "Handling event #{event.inspect} in profile #{@uid} with param #{params.values.first.inspect}."
+          end
 
           params[:callback] = @callback
           params[:context] = @context

lib/openhab/core/script_handling.rb

@@ -119,7 +119,7 @@ def scriptUnloaded # rubocop:disable Naming/MethodName method name dictated by o
       # Executed when openHAB loads a script file
       #
       def scriptLoaded(filename) # rubocop:disable Naming/MethodName method name dictated by openHAB
-        logger.trace("Script loaded: #{filename}")
+        logger.trace { "Script loaded: #{filename}" }
         ScriptHandlingCallbacks.script_loaded_hooks.each do |hook|
           hook.call
         rescue => e

lib/openhab/core/things/thing.rb

@@ -256,7 +256,7 @@ def method_missing(method, *args, &block)
 
         # @!visibility private
         def respond_to_missing?(method_name, _include_private = false)
-          logger.trace("Checking if Thing #{uid} supports #{method_name} action")
+          logger.trace { "Checking if Thing #{uid} supports #{method_name} action" }
           return true if actions.respond_to?(method_name)
 
           super

lib/openhab/core/types.rb

@@ -55,7 +55,7 @@ module Types
           states = Types::PREDICATE_ALIASES[value.to_s]
 
           ([command] | states).each do |method|
-            logger.trace("Defining #{klass}##{method} for #{value}")
+            logger.trace { "Defining #{klass}##{method} for #{value}" }
             klass.class_eval <<~RUBY, __FILE__, __LINE__ + 1
               def #{method}                                                 # def on?
                 as(#{value.class.java_class.simple_name}).equal?(#{value})  #   as(OnOffType).equal?(ON)

lib/openhab/core/types/date_time_type.rb

@@ -113,7 +113,7 @@ def eql?(other)
         #   `nil` is returned if the two values are incomparable.
         #
         def <=>(other)
-          logger.trace("(#{self.class}) #{self} <=> #{other} (#{other.class})")
+          logger.trace { "(#{self.class}) #{self} <=> #{other} (#{other.class})" }
           if other.is_a?(self.class)
             zoned_date_time <=> other.zoned_date_time
           elsif other.respond_to?(:to_time)
@@ -135,7 +135,7 @@ def <=>(other)
         # @return [[DateTimeType, DateTimeType], nil]
         #
         def coerce(other)
-          logger.trace("Coercing #{self} as a request from #{other.class}")
+          logger.trace { "Coercing #{self} as a request from #{other.class}" }
           return [other, zoned_date_time] if other.respond_to?(:to_zoned_date_time)
 
           [DateTimeType.new(other), self] if other.respond_to?(:to_time)

lib/openhab/core/types/decimal_type.rb

@@ -91,7 +91,7 @@ def |(other)
         #   `nil` is returned if the two values are incomparable.
         #
         def <=>(other)
-          logger.trace("(#{self.class}) #{self} <=> #{other} (#{other.class})")
+          logger.trace { "(#{self.class}) #{self} <=> #{other} (#{other.class})" }
           if other.is_a?(QuantityType) || other.is_a?(HSBType)
             (other <=> self)&.-@
           elsif other.is_a?(self.class)
@@ -115,7 +115,7 @@ def <=>(other)
         # @return [Array<(DecimalType, DecimalType)>, nil]
         #
         def coerce(other)
-          logger.trace("Coercing #{self} as a request from #{other.class}")
+          logger.trace { "Coercing #{self} as a request from #{other.class}" }
           return unless other.respond_to?(:to_d)
 
           [self.class.new(other.to_d), self]

lib/openhab/core/types/hsb_type.rb

@@ -65,7 +65,7 @@ def new(*args)
               # in this case, HTML hex format for rgb
               if (match = value.match(/^#(\h{2})(\h{2})(\h{2})$/))
                 rgb = match.to_a[1..3].map { |v| v.to_i(16) }
-                logger.trace("creating from rgb #{rgb.inspect}")
+                logger.trace { "creating from rgb #{rgb.inspect}" }
                 return from_rgb(*rgb)
               end
             end
@@ -110,7 +110,7 @@ def new(*args)
         #   `nil` is returned if the two values are incomparable.
         #
         def <=>(other)
-          logger.trace("(#{self.class}) #{self} <=> #{other} (#{other.class})")
+          logger.trace { "(#{self.class}) #{self} <=> #{other} (#{other.class})" }
           if other.is_a?(HSBType)
             [brightness, hue, saturation] <=> [other.brightness, other.hue, other.saturation]
           else

lib/openhab/core/types/point_type.rb

@@ -103,7 +103,7 @@ def altitude
         #
         # @return [QuantityType]
         def distance_from(other)
-          logger.trace("(#{self}).distance_from(#{other} (#{other.class})")
+          logger.trace { "(#{self}).distance_from(#{other} (#{other.class})" }
           raise TypeError, "#{other.class} can't be coerced into #{self.class}" unless other.is_a?(PointType)
 
           QuantityType.new(raw_distance_from(other), SIUnits::METRE)

lib/openhab/core/types/quantity_type.rb

@@ -132,7 +132,7 @@ class QuantityType
         #   `nil` is returned if the two values are incomparable.
         #
         def <=>(other)
-          logger.trace("(#{self.class}) #{self} <=> #{other} (#{other.class})")
+          logger.trace { "(#{self.class}) #{self} <=> #{other} (#{other.class})" }
           case other
           when self.class
             return unitize(other.unit).compare_to(other) if unit == Units::ONE
@@ -161,7 +161,7 @@ def <=>(other)
         #
         # @return [Array<(QuantityType, QuantityType)>, nil]
         def coerce(other)
-          logger.trace("Coercing #{self} as a request from #{other.class}")
+          logger.trace { "Coercing #{self} as a request from #{other.class}" }
           return unless other.respond_to?(:to_d)
 
           [QuantityType.new(other.to_d.to_java, Units::ONE), self]
@@ -178,7 +178,7 @@ def coerce(other)
 
           class_eval( # rubocop:disable Style/DocumentDynamicEvalDefinition https://github.com/rubocop/rubocop/issues/10179
             # def +(other)
-            #   logger.trace("#{self} + #{other} (#{other.class})")
+            #   logger.trace { "#{self} + #{other} (#{other.class})" }
             #   other = other.state if other.is_a?(Core::Items::Persistence::PersistedState)
             #   if other.is_a?(QuantityType)
             #     add_quantity(other)
@@ -203,7 +203,7 @@ def coerce(other)
             # end
             <<~RUBY, __FILE__, __LINE__ + 1
               def #{ruby_op}(other)
-                logger.trace("\#{self} #{ruby_op} \#{other} (\#{other.class})")
+                logger.trace { "\#{self} #{ruby_op} \#{other} (\#{other.class})" }
                 other = other.state if other.is_a?(Core::Items::Persistence::PersistedState)
                 if other.is_a?(QuantityType)
                   #{java_op}_quantity(other)
@@ -236,7 +236,7 @@ def #{ruby_op}(other)
         }.each do |java_op, ruby_op|
           class_eval( # rubocop:disable Style/DocumentDynamicEvalDefinition https://github.com/rubocop/rubocop/issues/10179
             # def *(other)
-            #   logger.trace("#{self} * #{other} (#{other.class})")
+            #   logger.trace { "#{self} * #{other} (#{other.class})" }
             #   other = other.state if other.is_a?(Core::Items::Persistence::PersistedState)
             #   if other.is_a?(QuantityType)
             #     multiply_quantity(other)
@@ -254,7 +254,7 @@ def #{ruby_op}(other)
             # end
             <<~RUBY, __FILE__, __LINE__ + 1
               def #{ruby_op}(other)
-                logger.trace("\#{self} #{ruby_op} \#{other} (\#{other.class})")
+                logger.trace { "\#{self} #{ruby_op} \#{other} (\#{other.class})" }
                 other = other.state if other.is_a?(Core::Items::Persistence::PersistedState)
                 if other.is_a?(QuantityType)
                   #{java_op}_quantity(other).unitize
@@ -279,7 +279,7 @@ def #{ruby_op}(other)
         def unitize(other_unit = unit, relative: false)
           # prefer converting to the thread-specified unit if there is one
           other_unit = DSL.unit(dimension) || other_unit
-          logger.trace("Converting #{self} to #{other_unit}")
+          logger.trace { "Converting #{self} to #{other_unit}" }
 
           case unit
           when Units::ONE

lib/openhab/core/types/string_type.rb

@@ -41,7 +41,7 @@ def eql?(other)
         #   `nil` is returned if the two values are incomparable.
         #
         def <=>(other)
-          logger.trace("(#{self.class}) #{self} <=> #{other} (#{other.class})")
+          logger.trace { "(#{self.class}) #{self} <=> #{other} (#{other.class})" }
           if other.respond_to?(:to_str)
             to_str <=> other.to_str
           elsif other.respond_to?(:coerce)
@@ -61,7 +61,7 @@ def <=>(other)
         # @return [[StringType, StringType], nil]
         #
         def coerce(other)
-          logger.trace("Coercing #{self} as a request from #{other.class}")
+          logger.trace { "Coercing #{self} as a request from #{other.class}" }
           [other.to_str, self] if other.respond_to?(:to_str)
         end
 

lib/openhab/core_ext/java/month_day.rb

@@ -20,7 +20,7 @@ class << self
           # @return [MonthDay]
           #
           def parse(string)
-            logger.trace("#{self.class}.parse #{string} (#{string.class})")
+            logger.trace { "#{self.class}.parse #{string} (#{string.class})" }
             java_send(:parse,
                       [java.lang.CharSequence, java.time.format.DateTimeFormatter],
                       string.to_s,

lib/openhab/dsl.rb

@@ -1106,10 +1106,10 @@ def try_parse_time_like(string)
       return super unless args.empty? && !block_given?
 
       if (context = Thread.current[:openhab_context]) && context.key?(method)
-        logger.trace("DSL#method_missing found context variable: '#{method}'")
+        logger.trace { "DSL#method_missing found context variable: '#{method}'" }
         return context[method]
       elsif Core.ui_context&.key?(method)
-        logger.trace("DSL#method_missing found UI context variable: '#{method}'")
+        logger.trace { "DSL#method_missing found UI context variable: '#{method}'" }
         return Core.ui_context[method]
       end
       super

lib/openhab/dsl/rules/automation_rule.rb

@@ -104,7 +104,7 @@ def listen_for_removal
           @listener ||= org.openhab.core.common.registry.RegistryChangeListener.impl do |method, element|
             next unless method == :removed
 
-            logger.trace("Rule #{element.inspect} removed from registry")
+            logger.trace { "Rule #{element.inspect} removed from registry" }
             next unless element.uid == uid
 
             cleanup
@@ -225,7 +225,7 @@ def check_guards(event:)
 
           return true if @guard.should_run?(event)
 
-          logger.trace("Skipped execution of rule '#{name}' because of guard #{@guard}")
+          logger.trace { "Skipped execution of rule '#{name}' because of guard #{@guard}" }
           false
         end
 

lib/openhab/dsl/rules/guard.rb

@@ -37,7 +37,7 @@ def to_s
         # @return [true,false] True if guard is satisfied, false otherwise
         #
         def should_run?(event)
-          logger.trace("Checking guards #{self}")
+          logger.trace { "Checking guards #{self}" }
           return false unless check_only_if(event)
           return false unless check_not_if(event)
 

lib/openhab/dsl/rules/rule_triggers.rb

@@ -44,7 +44,7 @@ def initialize
         def append_trigger(type:, config:, attach: nil, conditions: nil, label: nil)
           config.transform_keys!(&:to_s)
           RuleTriggers.trigger(type: type, config: config, label: label).tap do |trigger|
-            logger.trace("Appending trigger (#{trigger.inspect}) attach (#{attach}) conditions(#{conditions})")
+            logger.trace { "Appending trigger (#{trigger.inspect}) attach (#{attach}) conditions(#{conditions})" }
             @triggers << trigger
             @attachments[trigger.id] = attach if attach
             @trigger_conditions[trigger.id] = conditions if conditions
@@ -61,7 +61,7 @@ def append_trigger(type:, config:, attach: nil, conditions: nil, label: nil)
         # @return [org.openhab.core.automation.Trigger] configured by type and supplied config
         #
         def self.trigger(type:, config:, label: nil)
-          logger.trace("Creating trigger of type '#{type}' config: #{config}")
+          logger.trace { "Creating trigger of type '#{type}' config: #{config}" }
           org.openhab.core.automation.util.TriggerBuilder.create
              .with_id(uuid)
              .with_type_uid(type)

lib/openhab/dsl/rules/triggers/conditions/duration.rb

@@ -22,8 +22,10 @@ def initialize(to:, from:, duration:)
               @conditions = Generic.new(to: to, from: from)
               @duration = duration
               @timers = {}
-              logger.trace "Created Duration Condition To(#{to}) From(#{from}) " \
-                           "Conditions(#{@conditions}) Duration(#{@duration})"
+              logger.trace do
+                "Created Duration Condition To(#{to}) From(#{from}) " \
+                  "Conditions(#{@conditions}) Duration(#{@duration})"
+              end
             end
 
             # Process rule
@@ -34,13 +36,13 @@ def process(mod:, inputs:, &block)
               if timer&.active?
                 process_active_timer(timer, inputs, mod, &block)
               elsif @conditions.process(mod: mod, inputs: inputs)
-                logger.trace("Trigger Guards Matched for #{self}, delaying rule execution")
+                logger.trace { "Trigger Guards Matched for #{self}, delaying rule execution" }
                 # Add timer and attach timer to delay object, and also state being tracked to so
                 # timer can be cancelled if state changes
                 # Also another timer should not be created if changed to same value again but instead rescheduled
                 create_trigger_delay_timer(inputs, mod, &block)
               else
-                logger.trace("Trigger Guards did not match for #{self}, ignoring trigger.")
+                logger.trace { "Trigger Guards did not match for #{self}, ignoring trigger." }
               end
             end
 
@@ -61,10 +63,10 @@ def cleanup
             #
             #
             def create_trigger_delay_timer(inputs, _mod)
-              logger.trace("Creating timer for trigger delay #{self}")
+              logger.trace { "Creating timer for trigger delay #{self}" }
               item_name = inputs["triggeringItem"]&.name
               @timers[item_name] = DSL.after(@duration) do
-                logger.trace("Delay Complete for #{self}, executing rule")
+                logger.trace { "Delay Complete for #{self}, executing rule" }
                 @timers.delete(item_name)
                 yield
               end
@@ -83,9 +85,9 @@ def process_active_timer(timer, inputs, mod, &block)
               new_state = Conditions.new_state_from(inputs)
               if @conditions.from? && new_state != @tracking_from &&
                  @conditions.process(mod: nil, inputs: { "state" => new_state })
-                logger.trace("Item changed from #{old_state} to #{new_state} for #{self}, keep waiting.")
+                logger.trace { "Item changed from #{old_state} to #{new_state} for #{self}, keep waiting." }
               else
-                logger.trace("Item changed from #{old_state} to #{new_state} for #{self}, canceling timer.")
+                logger.trace { "Item changed from #{old_state} to #{new_state} for #{self}, canceling timer." }
                 timer.cancel
                 # Reprocess trigger delay after canceling to track new state (if guards matched, etc)
                 process(mod: mod, inputs: inputs, &block)