Add debug logging to derivative (#152489)

homeassistant/components/derivative/sensor.py

@@ -227,15 +227,28 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
             weight = calculate_weight(start, end, current_time)
             derivative = derivative + (value * Decimal(weight))
 
+        _LOGGER.debug(
+            "%s: Calculated new derivative as %f from %d segments",
+            self.entity_id,
+            derivative,
+            len(self._state_list),
+        )
+
         return derivative
 
     def _prune_state_list(self, current_time: datetime) -> None:
         # filter out all derivatives older than `time_window` from our window list
+        old_len = len(self._state_list)
         self._state_list = [
             (time_start, time_end, state)
             for time_start, time_end, state in self._state_list
             if (current_time - time_end).total_seconds() < self._time_window
         ]
+        _LOGGER.debug(
+            "%s: Pruned %d elements from state list",
+            self.entity_id,
+            old_len - len(self._state_list),
+        )
 
     def _handle_invalid_source_state(self, state: State | None) -> bool:
         # Check the source state for unknown/unavailable condition. If unusable, write unknown/unavailable state and return false.
@@ -292,6 +305,10 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
                 ) -> None:
                     """Calculate derivative based on time and reschedule."""
 
+                    _LOGGER.debug(
+                        "%s: Recalculating derivative due to max_sub_interval time elapsed",
+                        self.entity_id,
+                    )
                     self._prune_state_list(now)
                     derivative = self._calc_derivative_from_state_list(now)
                     self._write_native_value(derivative)
@@ -300,6 +317,11 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
                     if derivative != 0:
                         schedule_max_sub_interval_exceeded(source_state)
 
+                _LOGGER.debug(
+                    "%s: Scheduling max_sub_interval_callback in %s",
+                    self.entity_id,
+                    self._max_sub_interval,
+                )
                 self._cancel_max_sub_interval_exceeded_callback = async_call_later(
                     self.hass,
                     self._max_sub_interval,
@@ -309,6 +331,9 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
         @callback
         def on_state_reported(event: Event[EventStateReportedData]) -> None:
             """Handle constant sensor state."""
+            _LOGGER.debug(
+                "%s: New state reported event: %s", self.entity_id, event.data
+            )
             self._cancel_max_sub_interval_exceeded_callback()
             new_state = event.data["new_state"]
             if not self._handle_invalid_source_state(new_state):
@@ -330,6 +355,7 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
         @callback
         def on_state_changed(event: Event[EventStateChangedData]) -> None:
             """Handle changed sensor state."""
+            _LOGGER.debug("%s: New state changed event: %s", self.entity_id, event.data)
             self._cancel_max_sub_interval_exceeded_callback()
             new_state = event.data["new_state"]
             if not self._handle_invalid_source_state(new_state):
@@ -382,15 +408,32 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
                     / Decimal(self._unit_prefix)
                     * Decimal(self._unit_time)
                 )
+                _LOGGER.debug(
+                    "%s: Calculated new derivative segment as %f / %f / %f * %f = %f",
+                    self.entity_id,
+                    delta_value,
+                    elapsed_time,
+                    self._unit_prefix,
+                    self._unit_time,
+                    new_derivative,
+                )
 
             except ValueError as err:
-                _LOGGER.warning("While calculating derivative: %s", err)
+                _LOGGER.warning(
+                    "%s: While calculating derivative: %s", self.entity_id, err
+                )
             except DecimalException as err:
                 _LOGGER.warning(
-                    "Invalid state (%s > %s): %s", old_value, new_state.state, err
+                    "%s: Invalid state (%s > %s): %s",
+                    self.entity_id,
+                    old_value,
+                    new_state.state,
+                    err,
                 )
             except AssertionError as err:
-                _LOGGER.error("Could not calculate derivative: %s", err)
+                _LOGGER.error(
+                    "%s: Could not calculate derivative: %s", self.entity_id, err
+                )
 
             # For total inreasing sensors, the value is expected to continuously increase.
             # A negative derivative for a total increasing sensor likely indicates the
@@ -400,6 +443,10 @@ class DerivativeSensor(RestoreSensor, SensorEntity):
                 == SensorStateClass.TOTAL_INCREASING
                 and new_derivative < 0
             ):
+                _LOGGER.debug(
+                    "%s: Dropping sample as source total_increasing sensor decreased",
+                    self.entity_id,
+                )
                 return
 
             # add latest derivative to the window list