jpawlowski/hass.tibber_prices
1
0
Fork 0
mirror of https://github.com/jpawlowski/hass.tibber_prices.git synced 2026-03-30 05:13:40 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 2

refactor(logging): use details logger for verbose period calculation logs

Browse source 
Moved verbose debug logging to separate _LOGGER_DETAILS logger:
- core.py: Outlier flex capping messages
- outlier_filtering.py: Spike detection, context validation, smoothing details
- period_building.py: Level filter details, gap tolerance info
- relaxation.py: Per-phase iteration details, filter combination attempts

Pattern: Main _LOGGER for high-level progress, _LOGGER_DETAILS for step-by-step

Benefits:
- Users can disable verbose logs via logger configuration
- Main DEBUG log stays readable (high-level flow)
- Details available when needed for troubleshooting

Added:
- period_overlap.py: Docstring for extend_period_if_adjacent()

Impact: Cleaner log output by default. Enable details logger
(homeassistant.components.tibber_prices.coordinator.period_handlers.details)
for deep debugging.
This commit is contained in:
Julian Pawlowski 2025-11-25 20:42:29 +00:00
parent 9ae618fff9
commit 3c69807c05
5 changed files with 37 additions and 29 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
custom_components/tibber_prices/coordinator/period_handlers/core.py
View file

@ -127,9 +127,13 @@ def calculate_periods(
# High flex (>25%) makes outlier detection too permissive, accepting # High flex (>25%) makes outlier detection too permissive, accepting
# unstable price contexts as "normal". This breaks period formation. # unstable price contexts as "normal". This breaks period formation.
# User's flex setting still applies to period criteria (in_flex check). # User's flex setting still applies to period criteria (in_flex check).
# Import details logger locally (core.py imports logger locally in function)
_LOGGER_DETAILS = logging.getLogger(__name__ + ".details") # noqa: N806
outlier_flex = min(abs(flex) * 100, MAX_OUTLIER_FLEX * 100) outlier_flex = min(abs(flex) * 100, MAX_OUTLIER_FLEX * 100)
if abs(flex) * 100 > MAX_OUTLIER_FLEX * 100: if abs(flex) * 100 > MAX_OUTLIER_FLEX * 100:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sOutlier filtering: Using capped flex %.1f%% (user setting: %.1f%%)", "%sOutlier filtering: Using capped flex %.1f%% (user setting: %.1f%%)",
INDENT_L0, INDENT_L0,
outlier_flex, outlier_flex,

11
custom_components/tibber_prices/coordinator/period_handlers/outlier_filtering.py
View file

@ -18,6 +18,7 @@ import logging
from typing import NamedTuple from typing import NamedTuple
_LOGGER = logging.getLogger(__name__) _LOGGER = logging.getLogger(__name__)
_LOGGER_DETAILS = logging.getLogger(__name__ + ".details")
# Outlier filtering constants # Outlier filtering constants
MIN_CONTEXT_SIZE = 3 # Minimum intervals needed before/after for analysis MIN_CONTEXT_SIZE = 3 # Minimum intervals needed before/after for analysis
@ -52,7 +53,7 @@ def _should_skip_tail_check(
) -> bool: ) -> bool:
"""Return True when remaining intervals fall inside tail window and log why.""" """Return True when remaining intervals fall inside tail window and log why."""
if remaining_intervals < tail_window: if remaining_intervals < tail_window:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sSpike at %s: Skipping %s check (only %d intervals remaining)", "%sSpike at %s: Skipping %s check (only %d intervals remaining)",
INDENT_L0, INDENT_L0,
interval_label, interval_label,
@ -190,7 +191,7 @@ def _validate_spike_candidate(
context_diff_pct = abs(avg_after - avg_before) / avg_before if avg_before > 0 else 0 context_diff_pct = abs(avg_after - avg_before) / avg_before if avg_before > 0 else 0
if context_diff_pct > candidate.flexibility_ratio: if context_diff_pct > candidate.flexibility_ratio:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sInterval %s: Context unstable (%.1f%% change) - not a spike", "%sInterval %s: Context unstable (%.1f%% change) - not a spike",
INDENT_L0, INDENT_L0,
candidate.current.get("startsAt", "unknown interval"), candidate.current.get("startsAt", "unknown interval"),
@ -204,7 +205,7 @@ def _validate_spike_candidate(
"asymmetry", "asymmetry",
candidate.current.get("startsAt", "unknown interval"), candidate.current.get("startsAt", "unknown interval"),
) and not _check_symmetry(avg_before, avg_after, candidate.stats["std_dev"]): ) and not _check_symmetry(avg_before, avg_after, candidate.stats["std_dev"]):
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sSpike at %s rejected: Asymmetric (before=%.2f, after=%.2f ct/kWh)", "%sSpike at %s rejected: Asymmetric (before=%.2f, after=%.2f ct/kWh)",
INDENT_L0, INDENT_L0,
candidate.current.get("startsAt", "unknown interval"), candidate.current.get("startsAt", "unknown interval"),
@ -222,7 +223,7 @@ def _validate_spike_candidate(
return True return True
if _detect_zigzag_pattern(candidate.analysis_window, candidate.stats["std_dev"]): if _detect_zigzag_pattern(candidate.analysis_window, candidate.stats["std_dev"]):
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sSpike at %s rejected: Zigzag/cluster pattern detected", "%sSpike at %s rejected: Zigzag/cluster pattern detected",
INDENT_L0, INDENT_L0,
candidate.current.get("startsAt", "unknown interval"), candidate.current.get("startsAt", "unknown interval"),
@ -330,7 +331,7 @@ def filter_price_outliers(
result.append(smoothed) result.append(smoothed)
smoothed_count += 1 smoothed_count += 1
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sSmoothed spike at %s: %.2f → %.2f ct/kWh (residual: %.2f, tolerance: %.2f, trend_slope: %.4f)", "%sSmoothed spike at %s: %.2f → %.2f ct/kWh (residual: %.2f, tolerance: %.2f, trend_slope: %.4f)",
INDENT_L0, INDENT_L0,
current.get("startsAt", f"index {i}"), current.get("startsAt", f"index {i}"),

13
custom_components/tibber_prices/coordinator/period_handlers/period_building.py
View file

@ -19,6 +19,7 @@ from .level_filtering import (
from .types import TibberPricesIntervalCriteria from .types import TibberPricesIntervalCriteria
_LOGGER = logging.getLogger(__name__) _LOGGER = logging.getLogger(__name__)
_LOGGER_DETAILS = logging.getLogger(__name__ + ".details")
# Module-local log indentation (each module starts at level 0) # Module-local log indentation (each module starts at level 0)
INDENT_L0 = "" # Entry point / main function INDENT_L0 = "" # Entry point / main function
@ -92,7 +93,7 @@ def build_periods( # noqa: PLR0913, PLR0915, PLR0912 - Complex period building
level_filter_active = True level_filter_active = True
filter_direction = "≥" if reverse_sort else "≤" filter_direction = "≥" if reverse_sort else "≤"
gap_info = f", gap_tolerance={gap_count}" if gap_count > 0 else "" gap_info = f", gap_tolerance={gap_count}" if gap_count > 0 else ""
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sLevel filter active: %s (order %s, require interval level %s filter level%s)", "%sLevel filter active: %s (order %s, require interval level %s filter level%s)",
INDENT_L0, INDENT_L0,
level_filter.upper(), level_filter.upper(),
@ -102,7 +103,7 @@ def build_periods( # noqa: PLR0913, PLR0915, PLR0912 - Complex period building
) )
else: else:
status = "RELAXED to ANY" if (level_filter and level_filter.lower() == "any") else "DISABLED (not configured)" status = "RELAXED to ANY" if (level_filter and level_filter.lower() == "any") else "DISABLED (not configured)"
_LOGGER.debug("%sLevel filter: %s (accepting all levels)", INDENT_L0, status) _LOGGER_DETAILS.debug("%sLevel filter: %s (accepting all levels)", INDENT_L0, status)
periods: list[list[dict]] = [] periods: list[list[dict]] = []
current_period: list[dict] = [] current_period: list[dict] = []
@ -191,14 +192,14 @@ def build_periods( # noqa: PLR0913, PLR0915, PLR0912 - Complex period building
# Log detailed filter statistics # Log detailed filter statistics
if intervals_checked > 0: if intervals_checked > 0:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sFilter statistics: %d intervals checked", "%sFilter statistics: %d intervals checked",
INDENT_L0, INDENT_L0,
intervals_checked, intervals_checked,
) )
if intervals_filtered_by_flex > 0: if intervals_filtered_by_flex > 0:
flex_pct = (intervals_filtered_by_flex / intervals_checked) * 100 flex_pct = (intervals_filtered_by_flex / intervals_checked) * 100
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Filtered by FLEX (price too far from ref): %d/%d (%.1f%%)", "%s Filtered by FLEX (price too far from ref): %d/%d (%.1f%%)",
INDENT_L0, INDENT_L0,
intervals_filtered_by_flex, intervals_filtered_by_flex,
@ -207,7 +208,7 @@ def build_periods( # noqa: PLR0913, PLR0915, PLR0912 - Complex period building
) )
if intervals_filtered_by_min_distance > 0: if intervals_filtered_by_min_distance > 0:
distance_pct = (intervals_filtered_by_min_distance / intervals_checked) * 100 distance_pct = (intervals_filtered_by_min_distance / intervals_checked) * 100
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Filtered by MIN_DISTANCE (price too close to avg): %d/%d (%.1f%%)", "%s Filtered by MIN_DISTANCE (price too close to avg): %d/%d (%.1f%%)",
INDENT_L0, INDENT_L0,
intervals_filtered_by_min_distance, intervals_filtered_by_min_distance,
@ -216,7 +217,7 @@ def build_periods( # noqa: PLR0913, PLR0915, PLR0912 - Complex period building
) )
if level_filter_active and intervals_filtered_by_level > 0: if level_filter_active and intervals_filtered_by_level > 0:
level_pct = (intervals_filtered_by_level / intervals_checked) * 100 level_pct = (intervals_filtered_by_level / intervals_checked) * 100
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Filtered by LEVEL (wrong price level): %d/%d (%.1f%%)", "%s Filtered by LEVEL (wrong price level): %d/%d (%.1f%%)",
INDENT_L0, INDENT_L0,
intervals_filtered_by_level, intervals_filtered_by_level,

1
custom_components/tibber_prices/coordinator/period_handlers/period_overlap.py
View file

@ -9,6 +9,7 @@ if TYPE_CHECKING:
from custom_components.tibber_prices.coordinator.time_service import TibberPricesTimeService from custom_components.tibber_prices.coordinator.time_service import TibberPricesTimeService
_LOGGER = logging.getLogger(__name__) _LOGGER = logging.getLogger(__name__)
_LOGGER_DETAILS = logging.getLogger(__name__ + ".details")
# Module-local log indentation (each module starts at level 0) # Module-local log indentation (each module starts at level 0)
INDENT_L0 = "" # Entry point / main function INDENT_L0 = "" # Entry point / main function

35
custom_components/tibber_prices/coordinator/period_handlers/relaxation.py
View file

@ -24,6 +24,7 @@ from .types import (
) )
_LOGGER = logging.getLogger(__name__) _LOGGER = logging.getLogger(__name__)
_LOGGER_DETAILS = logging.getLogger(__name__ + ".details")
# Flex thresholds for warnings (see docs/development/period-calculation-theory.md) # Flex thresholds for warnings (see docs/development/period-calculation-theory.md)
# With relaxation active, high base flex is counterproductive (reduces relaxation effectiveness) # With relaxation active, high base flex is counterproductive (reduces relaxation effectiveness)
@ -204,38 +205,38 @@ def calculate_periods_with_relaxation( # noqa: PLR0913, PLR0915 - Per-day relax
# Detailed DEBUG-level context header # Detailed DEBUG-level context header
period_type_full = "PEAK PRICE (most expensive)" if config.reverse_sort else "BEST PRICE (cheapest)" period_type_full = "PEAK PRICE (most expensive)" if config.reverse_sort else "BEST PRICE (cheapest)"
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s========== %s PERIODS ==========", "%s========== %s PERIODS ==========",
INDENT_L0, INDENT_L0,
period_type_full, period_type_full,
) )
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sRelaxation: %s", "%sRelaxation: %s",
INDENT_L0, INDENT_L0,
"ENABLED (user setting: ON)" if enable_relaxation else "DISABLED by user configuration", "ENABLED (user setting: ON)" if enable_relaxation else "DISABLED by user configuration",
) )
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sBase config: flex=%.1f%%, min_length=%d min", "%sBase config: flex=%.1f%%, min_length=%d min",
INDENT_L0, INDENT_L0,
abs(config.flex) * 100, abs(config.flex) * 100,
config.min_period_length, config.min_period_length,
) )
if enable_relaxation: if enable_relaxation:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sRelaxation target: %d periods per day", "%sRelaxation target: %d periods per day",
INDENT_L0, INDENT_L0,
min_periods, min_periods,
) )
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sRelaxation strategy: 3%% fixed flex increment per step (%d flex levels x 2 filter combinations)", "%sRelaxation strategy: 3%% fixed flex increment per step (%d flex levels x 2 filter combinations)",
INDENT_L0, INDENT_L0,
max_relaxation_attempts, max_relaxation_attempts,
) )
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sEarly exit: After EACH filter combination when target reached", "%sEarly exit: After EACH filter combination when target reached",
INDENT_L0, INDENT_L0,
) )
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s=============================================", "%s=============================================",
INDENT_L0, INDENT_L0,
) )
@ -266,7 +267,7 @@ def calculate_periods_with_relaxation( # noqa: PLR0913, PLR0915 - Per-day relax
"Calculating baseline periods for %d days...", "Calculating baseline periods for %d days...",
total_days, total_days,
) )
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sProcessing ALL %d price intervals together (yesterday+today+tomorrow, allows midnight crossing)", "%sProcessing ALL %d price intervals together (yesterday+today+tomorrow, allows midnight crossing)",
INDENT_L1, INDENT_L1,
len(all_prices), len(all_prices),
@ -285,7 +286,7 @@ def calculate_periods_with_relaxation( # noqa: PLR0913, PLR0915 - Per-day relax
day_periods = periods_by_day.get(day, []) day_periods = periods_by_day.get(day, [])
period_count = len(day_periods) period_count = len(day_periods)
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sDay %s baseline: Found %d periods%s", "%sDay %s baseline: Found %d periods%s",
INDENT_L1, INDENT_L1,
day, day,
@ -302,7 +303,7 @@ def calculate_periods_with_relaxation( # noqa: PLR0913, PLR0915 - Per-day relax
if enable_relaxation and days_meeting_requirement < total_days: if enable_relaxation and days_meeting_requirement < total_days:
# At least one day doesn't have enough periods # At least one day doesn't have enough periods
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sBaseline insufficient (%d/%d days met target) - starting relaxation", "%sBaseline insufficient (%d/%d days met target) - starting relaxation",
INDENT_L1, INDENT_L1,
days_meeting_requirement, days_meeting_requirement,
@ -334,7 +335,7 @@ def calculate_periods_with_relaxation( # noqa: PLR0913, PLR0915 - Per-day relax
if period_count >= min_periods: if period_count >= min_periods:
days_meeting_requirement += 1 days_meeting_requirement += 1
elif enable_relaxation: elif enable_relaxation:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%sAll %d days met target with baseline - no relaxation needed", "%sAll %d days met target with baseline - no relaxation needed",
INDENT_L1, INDENT_L1,
total_days, total_days,
@ -422,7 +423,7 @@ def relax_all_prices( # noqa: PLR0913 - Comprehensive filter relaxation require
# Stop if we exceed hard maximum # Stop if we exceed hard maximum
if current_flex > MAX_FLEX_HARD_LIMIT: if current_flex > MAX_FLEX_HARD_LIMIT:
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Reached 50%% flex hard limit", "%s Reached 50%% flex hard limit",
INDENT_L2, INDENT_L2,
) )
@ -436,7 +437,7 @@ def relax_all_prices( # noqa: PLR0913 - Comprehensive filter relaxation require
# Try current flex with level="any" (in relaxation mode) # Try current flex with level="any" (in relaxation mode)
if original_level_filter != "any": if original_level_filter != "any":
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Flex=%.1f%%: OVERRIDING level_filter: %s → ANY", "%s Flex=%.1f%%: OVERRIDING level_filter: %s → ANY",
INDENT_L2, INDENT_L2,
current_flex * 100, current_flex * 100,
@ -450,7 +451,7 @@ def relax_all_prices( # noqa: PLR0913 - Comprehensive filter relaxation require
) )
phase_label_full = f"flex={current_flex * 100:.1f}% +level_any" phase_label_full = f"flex={current_flex * 100:.1f}% +level_any"
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Trying %s: config has %d intervals (all days together), level_filter=%s", "%s Trying %s: config has %d intervals (all days together), level_filter=%s",
INDENT_L2, INDENT_L2,
phase_label_full, phase_label_full,
@ -462,7 +463,7 @@ def relax_all_prices( # noqa: PLR0913 - Comprehensive filter relaxation require
result = calculate_periods(all_prices, config=relaxed_config, time=time) result = calculate_periods(all_prices, config=relaxed_config, time=time)
new_periods = result["periods"] new_periods = result["periods"]
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s %s: calculate_periods returned %d periods", "%s %s: calculate_periods returned %d periods",
INDENT_L2, INDENT_L2,
phase_label_full, phase_label_full,
@ -494,7 +495,7 @@ def relax_all_prices( # noqa: PLR0913 - Comprehensive filter relaxation require
if period_count >= min_periods: if period_count >= min_periods:
days_meeting_requirement += 1 days_meeting_requirement += 1
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s Day %s: %d periods%s", "%s Day %s: %d periods%s",
INDENT_L2, INDENT_L2,
day, day,
@ -503,7 +504,7 @@ def relax_all_prices( # noqa: PLR0913 - Comprehensive filter relaxation require
) )
total_periods = len(combined) total_periods = len(combined)
_LOGGER.debug( _LOGGER_DETAILS.debug(
"%s %s: found %d periods total, %d/%d days meet requirement", "%s %s: found %d periods total, %d/%d days meet requirement",
INDENT_L2, INDENT_L2,
phase_label_full, phase_label_full,