diff --git a/apps/predbat/const.py b/apps/predbat/const.py index cffb378f6..694fa7425 100644 --- a/apps/predbat/const.py +++ b/apps/predbat/const.py @@ -168,3 +168,7 @@ # need the same answer to "which of these two states is the more significant one to show". CHARGE_STATE_PRECEDENCE = ["Charging", "Freeze charging", "Hold charging"] EXPORT_STATE_PRECEDENCE = ["Exporting", "Freeze exporting", "Hold exporting"] + +# A log text that repeats (an API response, an Intelligent slot list) is logged in full again after this long, so +# the full text is never only in a rotated-out log file; in between it is logged as one short line +REPEAT_FULL_LOG_SECONDS = 3600 diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py index bbb79a5a6..2938ff5dc 100644 --- a/apps/predbat/octopus.py +++ b/apps/predbat/octopus.py @@ -18,8 +18,8 @@ import re from datetime import datetime, timedelta, timezone from predbat_metrics import record_api_call -from const import TIME_FORMAT, TIME_FORMAT_OCTOPUS, DISPATCH_SOURCE_CHARGER_SCHEDULE -from utils import str2time, minutes_to_time, dp1, dp2, dp4, minute_data, round_out_to_period, filter_payment_method, is_edge_block_body, token_mint_backoff_seconds, TOKEN_MINT_BACKOFF_LOG_INTERVAL_SECONDS +from const import TIME_FORMAT, TIME_FORMAT_OCTOPUS, DISPATCH_SOURCE_CHARGER_SCHEDULE, REPEAT_FULL_LOG_SECONDS +from utils import RepeatLogGate, str2time, minutes_to_time, dp1, dp2, dp4, minute_data, round_out_to_period, filter_payment_method, is_edge_block_body, token_mint_backoff_seconds, TOKEN_MINT_BACKOFF_LOG_INTERVAL_SECONDS from component_base import ComponentBase from mock_base import MockBase as SharedMockBase import aiohttp @@ -652,6 +652,8 @@ def initialize(self, key, account_id, automatic): # API request metrics for monitoring self.requests_total = 0 self.failures_total = 0 + # Repeated GraphQL requests and responses, and skipped Happy Hours, are logged briefly between full logs + self.log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS) # In-memory cache for product info (keyed by product_code) to avoid repeated API calls self._product_info_cache = {} @@ -1361,7 +1363,8 @@ def get_saving_session_data(self): # v19.0.1 for the same reason; match that. The reward/code/type maps are populated above # first, because a joined Happy Hour takes its event type from this list. if event.get("eventType", None) == "WEEKEND_HAPPY_HOUR": - self.log("OctopusAPI: Not offering Weekend Happy Hour event code {} as available - it cannot be joined through the API".format(code)) + # Logged once an hour per event (by id, so events with no code are told apart): the event list is re-read every poll + self.log_gate.log(self.log, "happy-hour", (event_id, code), ["OctopusAPI: Not offering Weekend Happy Hour event code {} as available - it cannot be joined through the API".format(code)], None) continue target_regions = [region.get("regionId") for region in (event.get("targetRegion", None) or []) if region] if target_regions and account_region_id not in target_regions: @@ -1646,7 +1649,6 @@ async def async_get_saving_sessions(self, account_id): if response_data is None: return self.saving_sessions else: - self.log("OctopusAPI: Fetched saving sessions data from GraphQL API: {}".format(response_data)) savingSessions = response_data.get("savingSessions", {}) if savingSessions is None: savingSessions = {} @@ -2328,6 +2330,29 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i if returns_data: self.log(f"Warn: OctopusAPI: Failed to retrieve data from graphql query {request_context} - token refresh failed") return None + # Whether the request was logged in full, and its full line, so a failure can show the request beside it + request_logged = [True, None] + + def log_request_beside_failure(): + """Log the full request beside a failure when it was only logged briefly ("as logged in full at ..."). + + Not on a retry: only a failure causes one, and that failure has just logged the request in full.""" + if not request_logged[0] and request_logged[1] and _retry_count == 0: + # Through the gate, so it records this full log: later brief lines name this time, and the hourly re-log counts from it + self.log_gate.log(self.log, ("request", request_context), query, [request_logged[1]], None, always_full=True) + request_logged[0] = True + + def log_response(status, text, always_full): + """Log a response in full when new, due again or always_full, else as one line naming when it was last logged in full.""" + self.log_gate.log( + self.log, + ("response", request_context), + "{} {}".format(status, text), + ["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, status, text)], + lambda when: "OctopusAPI: GraphQL response for {} (status {}) same as logged in full at {}, {} characters".format(request_context, status, when, len(text)), + always_full=always_full, + ) + try: self.requests_total += 1 client = await self.api.async_create_client_session() @@ -2338,13 +2363,17 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i headers = {"Authorization": f"{auth_prefix}{self.graphql_token}", integration_context_header: request_context} # Redact the Authorization header so the JWT token is never written to the log log_headers = {**headers, "Authorization": f"{auth_prefix}"} - self.log("OctopusAPI: Making GraphQL request to {} payload {} headers {}".format(url, payload, log_headers)) + request_line = "OctopusAPI: Making GraphQL request to {} payload {} headers {}".format(url, payload, log_headers) + request_logged[0] = self.log_gate.log(self.log, ("request", request_context), query, [request_line], lambda when: "OctopusAPI: Making GraphQL request {} to {} (query as logged in full at {})".format(request_context, url, when)) + request_logged[1] = request_line async with client.post(url, json=payload, headers=headers) as response: # Check for HTTP-level 401/403 (transport-level auth failure) and retry once. # This handles cases where the JWT has been revoked server-side and the server # returns a bare 401/403 status rather than a GraphQL error body — which would # otherwise loop forever without ever refreshing the token. The one exception is # a 403 carrying a CDN/WAF block page, handled immediately below. + if response.status in [401, 403]: + log_request_beside_failure() if response.status in [401, 403] and _retry_count == 0: # A CDN/WAF block is rate limiting, not an auth failure. Re-minting a token # here would be rejected by the same block, leaving the component permanently @@ -2352,7 +2381,12 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i # Only 403 is treated this way: Kraken reports genuine auth problems as HTTP # 200 with a GraphQL errorCode, or as a 401, so a 403 carrying a non-JSON # body comes from the edge rather than the API. - if response.status == 403 and is_edge_block_body(await response.text()): + # Log the response in full first: the WAF return and the retry below both leave before the + # response logger further down. A second-attempt 401/403 is not logged here: its body is logged + # by async_read_response_retry below + error_text = await response.text() + log_response(response.status, error_text, always_full=True) + if response.status == 403 and is_edge_block_body(error_text): self.consecutive_edge_blocks += 1 if self.consecutive_edge_blocks <= EDGE_BLOCK_REFRESH_AFTER: record_api_call("octopus", False, "rate_limit") @@ -2378,7 +2412,13 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i # Process response (which reads the text) response_body = await self.async_read_response_retry(response, url, ignore_errors=ignore_errors) - self.log("OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, response_body)) + body_text = str(response_body) + # Logged in full with its request: a bad status, a body that is missing (unreadable JSON, a rate limit) + # or has no data, or any errors key - even a partial error returned with data when ignore_errors is set + failed = response.status != 200 or not isinstance(response_body, dict) or "errors" in response_body or response_body.get("data") is None + if failed: + log_request_beside_failure() + log_response(response.status, body_text, always_full=failed) # Check for auth errors and retry once if response_body and "errors" in response_body and _retry_count == 0: @@ -2419,6 +2459,7 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i return None except TimeoutError: self.failures_total += 1 + log_request_beside_failure() self.log(f"Warn: OctopusAPI: Failed to connect, timeout exceeded.") record_api_call("octopus", False, "connection_error") @@ -3819,6 +3860,7 @@ def rate_add_io_slots(self, car_n, rates, octopus_slots): slots_added_set = set() plan_interval_minutes = self.plan_interval_minutes saved_slots = set() # For logging purposes, track which slots we actually applied as low rate + slot_lines = [] # One log line per half hour of each slot, logged after the loop only when the list changes # Dynamic load has seen this car in its slot but not charging: none of its dispatches from now # on get the cheap rate (see dynamic_load_car_check()). Elapsed minutes keep theirs - they record # what the tariff charged, and today's cost is built from them. None when the car is not cancelled. @@ -3913,12 +3955,16 @@ def rate_add_io_slots(self, car_n, rates, octopus_slots): rates[minute] = assumed_price if minute % 30 == 0 and start_minutes > -24 * 60: - self.log( + slot_lines.append( "Octopus: Intelligent slot at {}-{}, assumed price {}, amount {}, kWh location {}, source {}, octopus_slot_low_rate {}".format( self.time_abs_str(start_minutes), self.time_abs_str(end_minutes), dp2(assumed_price), dp2(kwh), location, source, octopus_slot_low_rate ) ) + # The slot list is re-derived every plan but rarely changes, so log it only when it does, and at least hourly + if slot_lines: + self.io_slot_log_gate.log(self.log, ("slots", car_n), "\n".join(slot_lines), slot_lines, lambda when: "Octopus: Intelligent slots for car {} same as logged in full at {}, {} half-hour slot lines".format(car_n, when, len(slot_lines))) + # Log daily slot counts for debugging for day_offset in sorted(slots_per_day.keys()): if slots_per_day[day_offset] > 0: diff --git a/apps/predbat/predbat.py b/apps/predbat/predbat.py index 8af085388..df6e6f366 100644 --- a/apps/predbat/predbat.py +++ b/apps/predbat/predbat.py @@ -65,6 +65,7 @@ print("Running in compiled mode; skipping local file checks and auto-update.") from const import ( + REPEAT_FULL_LOG_SECONDS, TIME_FORMAT, PREDICT_STEP, RUN_EVERY, @@ -77,6 +78,7 @@ from config import APPS_SCHEMA, CONFIG_ITEMS import debug_history from utils import ( + RepeatLogGate, minutes_since_yesterday, minutes_since_midnight, dp1, @@ -491,6 +493,8 @@ def reset(self): self.car_charging_power = 0 self.car_charging_power_configured = False self.io_adjusted = {} + # Repeated Intelligent slot lists are logged briefly between full logs (rate_add_io_slots) + self.io_slot_log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS) self.current_charge_limit = 0.0 self.current_charge_limit_kwh = 0.0 self.inverter_limit = 0.0 diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py index 3910ab73c..71a4df264 100644 --- a/apps/predbat/tests/test_octopus_logging.py +++ b/apps/predbat/tests/test_octopus_logging.py @@ -7,7 +7,9 @@ import asyncio from unittest.mock import AsyncMock, MagicMock +from const import REPEAT_FULL_LOG_SECONDS from octopus import OctopusAPI +from utils import RepeatLogGate def test_octopus_logging_wrapper(my_predbat): @@ -82,4 +84,134 @@ async def test_octopus_logging(my_predbat): else: print("PASS: GraphQL response body logged") + # A repeat of the same query and response is logged briefly, without the query or body + log_lines.clear() + await api.async_graphql_query("query { account }", "test-logging", returns_data=True) + repeat = "\n".join(log_lines) + brief_request = "Making GraphQL request test-logging to " in repeat and "(query as logged in full at" in repeat + brief_response = "GraphQL response for test-logging (status 200) same as logged in full" in repeat + if "A-LOG-12345" in repeat or "query { account }" in repeat or not brief_request or not brief_response: + print("ERROR: a repeated query and response should be logged briefly, got {}".format(log_lines)) + failed = True + else: + print("PASS: repeated query and response logged briefly") + + # A changed response is logged in full again + log_lines.clear() + api.async_read_response_retry = AsyncMock(return_value={"data": {"account": {"accountNumber": "A-LOG-67890"}}}) + await api.async_graphql_query("query { account }", "test-logging", returns_data=True) + if "A-LOG-67890" not in "\n".join(log_lines): + print("ERROR: a changed response should be logged in full, got {}".format(log_lines)) + failed = True + + # An unchanged response is logged in full again once REPEAT_FULL_LOG_SECONDS have passed + for entry, (logged_at, wall) in list(api.log_gate.logged.items()): + api.log_gate.logged[entry] = (logged_at - REPEAT_FULL_LOG_SECONDS - 1, wall) + log_lines.clear() + await api.async_graphql_query("query { account }", "test-logging", returns_data=True) + logged_again = "\n".join(log_lines) + if "A-LOG-67890" not in logged_again or "query { account }" not in logged_again: + print("ERROR: an unchanged response should be logged in full again after an hour, got {}".format(log_lines)) + failed = True + + # Two queries sharing one request context (one per device) are each logged briefly when they repeat + api.log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS) + api.async_read_response_retry = AsyncMock(return_value=response_body) + await api.async_graphql_query("query { device(id: 1) }", "test-device", returns_data=True) + await api.async_graphql_query("query { device(id: 2) }", "test-device", returns_data=True) + log_lines.clear() + await api.async_graphql_query("query { device(id: 1) }", "test-device", returns_data=True) + if not any("(query as logged in full at" in line for line in log_lines) or not any("same as logged in full" in line for line in log_lines): + print("ERROR: a repeated query should be logged briefly even when another query shares its context, got {}".format(log_lines)) + failed = True + + # An error response is always logged in full, even when it repeats + api.async_read_response_retry = AsyncMock(return_value={"errors": [{"message": "Something failed", "extensions": {"errorCode": "KT-CT-9999"}}]}) + await api.async_graphql_query("query { broken }", "test-error", returns_data=True, ignore_errors=True) + log_lines.clear() + await api.async_graphql_query("query { broken }", "test-error", returns_data=True, ignore_errors=True) + if not any("Something failed" in line for line in log_lines): + print("ERROR: a repeated error response should still be logged in full, got {}".format(log_lines)) + failed = True + if not any("query { broken }" in line for line in log_lines): + print("ERROR: the request behind a repeated error should be logged in full beside it, got {}".format(log_lines)) + failed = True + + # A request re-logged in full beside a failure is recorded by the gate, so the hourly full re-log counts from + # that time rather than the earlier one: a success just after the old hour runs out logs the request briefly + api.log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS) + api.async_read_response_retry = AsyncMock(return_value=response_body) + await api.async_graphql_query("query { refetch }", "test-refetch", returns_data=True) + for entry, (logged_at, wall) in list(api.log_gate.logged.items()): + api.log_gate.logged[entry] = (logged_at - REPEAT_FULL_LOG_SECONDS + 5, wall) + api.async_read_response_retry = AsyncMock(return_value={"errors": [{"message": "Refetch failed", "extensions": {"errorCode": "KT-CT-9999"}}]}) + log_lines.clear() + await api.async_graphql_query("query { refetch }", "test-refetch", returns_data=True, ignore_errors=True) + if not any("query { refetch }" in line for line in log_lines): + print("ERROR: the request behind a failure should be logged in full, got {}".format(log_lines)) + failed = True + for entry, (logged_at, wall) in list(api.log_gate.logged.items()): + api.log_gate.logged[entry] = (logged_at - 10, wall) + api.async_read_response_retry = AsyncMock(return_value=response_body) + log_lines.clear() + await api.async_graphql_query("query { refetch }", "test-refetch", returns_data=True) + if any("query { refetch }" in line for line in log_lines) or not any("(query as logged in full at" in line for line in log_lines): + print("ERROR: a request re-logged in full beside a failure should restart its hourly interval, got {}".format(log_lines)) + failed = True + + # A status 200 with no usable body (unreadable JSON, a rate limit) or no data is a failure too: the request and + # the response are logged in full beside it, even when they repeat + for bad_body, context in [(None, "test-no-body"), ({"other": 1}, "test-no-data"), ({"data": None}, "test-null-data")]: + api.async_read_response_retry = AsyncMock(return_value=bad_body) + await api.async_graphql_query("query { empty }", context, returns_data=True) + log_lines.clear() + await api.async_graphql_query("query { empty }", context, returns_data=True) + if not any("query { empty }" in line for line in log_lines) or not any("GraphQL response for {} (status 200): {}".format(context, bad_body) in line for line in log_lines): + print("ERROR: a repeated response with no data should be logged in full with its request, got {}".format(log_lines)) + failed = True + + # The token must not leak through any of the later lines either + if secret_token in logged_again or secret_token in repeat: + print("ERROR: JWT token leaked on a repeat or re-log") + failed = True + + failed |= test_repeat_log_gate() + return failed + + +def test_repeat_log_gate(): + """RepeatLogGate logs a text in full when new, briefly while it repeats, alternating texts each keep their own + entry, always_full forces a full log, and entries older than the interval are dropped.""" + failed = False + gate = RepeatLogGate(3600) + if gate.last_full("key", "a") is not None: + print("ERROR: a new text should be logged in full") + failed = True + if gate.last_full("key", "a") is None: + print("ERROR: a repeated text should be logged briefly") + failed = True + if gate.last_full("key", "b") is not None or gate.last_full("key", "a") is None: + print("ERROR: a second text under the same key should not make the first one log in full again") + failed = True + if gate.last_full("other", "a") is not None: + print("ERROR: the same text under another key is new") + failed = True + if gate.last_full("key", "a", always_full=True) is not None: + print("ERROR: always_full should log in full") + failed = True + for entry, (logged_at, wall) in list(gate.logged.items()): + gate.logged[entry] = (logged_at - 3601, wall) + if gate.last_full("key", "a") is not None or len(gate.logged) != 1: + print("ERROR: entries older than the interval should be dropped, leaving {}".format(gate.logged)) + failed = True + if gate.last_full("key", None) is not None or gate.last_full("key", None) is None: + print("ERROR: a None text should be gated like any other") + failed = True + lines = [] + if not gate.log(lines.append, "lines", "x", ["one", "two"], lambda when: "brief " + when) or gate.log(lines.append, "lines", "x", ["one"], lambda when: "brief " + when): + print("ERROR: log() should report a full log, then a brief one") + failed = True + if lines[:2] != ["one", "two"] or not lines[2].startswith("brief "): + print("ERROR: log() should write every full line, then the brief line, got {}".format(lines)) + failed = True return failed diff --git a/apps/predbat/tests/test_octopus_saving_event_type.py b/apps/predbat/tests/test_octopus_saving_event_type.py index ef2a85460..3787f0ded 100644 --- a/apps/predbat/tests/test_octopus_saving_event_type.py +++ b/apps/predbat/tests/test_octopus_saving_event_type.py @@ -56,6 +56,41 @@ def make_api(events, joined): else: print("PASS: Happy Hours are withheld from available_events but keep their type when joined") + # Each Happy Hour is logged as not offered once, not on every poll of the event list + api = make_api([happy_joined, happy_offered, power_down], []) + log_lines = [] + api.log = lambda message: log_lines.append(str(message)) + api.get_saving_session_data() + api.get_saving_session_data() + happy_logs = [line for line in log_lines if "Not offering Weekend Happy Hour" in line] + if len(happy_logs) != 2 or not any("EVENT_56" in line for line in happy_logs) or not any("EVENT_57" in line for line in happy_logs): + print("ERROR: Expected each Happy Hour logged once across two polls, got {}".format(happy_logs)) + failed = True + else: + print("PASS: Each Happy Hour is logged once") + + # A Happy Hour with no code is still skipped, and does not stop the rest of the events being read + uncoded = dict(happy_offered, id=5801, code=None) + api = make_api([uncoded, power_down], []) + available, _ = api.get_saving_session_data() + if [event.get("code") for event in available] != ["EVENT_58"]: + print("ERROR: a Happy Hour with no code should be skipped without breaking the event list, got {}".format(available)) + failed = True + else: + print("PASS: A Happy Hour with no code is skipped") + + # Two Happy Hours with no code are each logged, told apart by their id + api = make_api([uncoded, dict(uncoded, id=5802)], []) + log_lines = [] + api.log = lambda message: log_lines.append(str(message)) + api.get_saving_session_data() + happy_logs = [line for line in log_lines if "Not offering Weekend Happy Hour" in line] + if len(happy_logs) != 2: + print("ERROR: Expected two uncoded Happy Hours each logged once, got {}".format(happy_logs)) + failed = True + else: + print("PASS: Uncoded Happy Hours are each logged") + # An event with no eventType is unchanged - older API responses must keep working untyped = {"id": 5900, "code": "EVENT_59", "rewardPerKwhInOctoPoints": 200, "startAt": "2030-01-07T17:00:00+00:00", "endAt": "2030-01-07T18:00:00+00:00", "targetRegion": []} api = make_api([untyped], []) diff --git a/apps/predbat/tests/test_octopus_waf_block.py b/apps/predbat/tests/test_octopus_waf_block.py index ac9961592..4196b3ffd 100644 --- a/apps/predbat/tests/test_octopus_waf_block.py +++ b/apps/predbat/tests/test_octopus_waf_block.py @@ -171,6 +171,43 @@ async def counting_read(resp, url, ignore_errors=False): else: print("PASS: edge block honoured ignore_errors") + # Test 6: a first-attempt 401/403 response is logged in full, even though the WAF branch returns and the + # auth branch retries before the response logger. The retry's own 401 body is logged by the response reader, + # so the first-attempt line appears once. + print("\n*** Test 6: first-attempt 401/403 response body is logged ***") + api6 = _make_api(my_predbat, _make_response(403, CLOUDFRONT_403_BODY)) + api6.graphql_token = "token" + api6.async_refresh_token = AsyncMock(return_value="token") + lines6 = [] + api6.log = lambda message: lines6.append(str(message)) + await api6.async_graphql_query("query { test }", "test-query") + if not any("GraphQL response for test-query (status 403):" in line and "Request blocked." in line for line in lines6): + print("ERROR: the edge block response body was not logged, got {}".format(lines6)) + failed = True + else: + print("PASS: edge block response body logged") + + body_401 = '{"errors":[{"message":"Unauthorized first attempt"}]}' + api6b = _make_api(my_predbat, _make_response(401, body_401)) + api6b.graphql_token = "token" + api6b.async_refresh_token = AsyncMock(return_value="token") + lines6b = [] + api6b.log = lambda message: lines6b.append(str(message)) + await api6b.async_graphql_query("query { test }", "test-query") + first_attempt = [line for line in lines6b if line == "OctopusAPI: GraphQL response for test-query (status 401): {}".format(body_401)] + if len(first_attempt) != 1: + print("ERROR: the first-attempt 401 response should be logged in full once, got {}".format(lines6b)) + failed = True + else: + print("PASS: first-attempt 401 response body logged once") + # The retry's own 401 must not log the full request again: the first attempt has just logged it in full + full_requests = [line for line in lines6b if line.startswith("OctopusAPI: Making GraphQL request to ")] + if len(full_requests) != 1: + print("ERROR: a 401 then a failed retry should log the full request once, got {}".format(full_requests)) + failed = True + else: + print("PASS: full request logged once across a failed retry") + if failed: print("**** Octopus WAF/CloudFront 403 tests FAILED ****") else: diff --git a/apps/predbat/tests/test_rate_add_io_slots.py b/apps/predbat/tests/test_rate_add_io_slots.py index 5e5576362..7284e8c3c 100644 --- a/apps/predbat/tests/test_rate_add_io_slots.py +++ b/apps/predbat/tests/test_rate_add_io_slots.py @@ -10,6 +10,8 @@ from datetime import timedelta from tests.test_infra import reset_rates +from const import REPEAT_FULL_LOG_SECONDS +from utils import RepeatLogGate def run_rate_add_io_slots_test(testname, my_predbat, slots, octopus_slot_low_rate, octopus_slot_max, expected_rates, expected_slots_per_day=None): @@ -145,6 +147,7 @@ def run_rate_add_io_slots_tests(my_predbat): saved_args = {key: my_predbat.args[key] for key in ("octopus_slot_low_rate", "octopus_slot_max") if key in my_predbat.args} saved_io_adjusted = my_predbat.io_adjusted saved_effective = my_predbat.dynamic_load_car_effective + saved_slot_log = my_predbat.io_slot_log_gate original_forecast_minutes = my_predbat.forecast_minutes my_predbat.io_adjusted = {} try: @@ -157,6 +160,7 @@ def run_rate_add_io_slots_tests(my_predbat): my_predbat.args.pop(key, None) my_predbat.io_adjusted = saved_io_adjusted my_predbat.dynamic_load_car_effective = saved_effective + my_predbat.io_slot_log_gate = saved_slot_log my_predbat.forecast_minutes = original_forecast_minutes if failed: @@ -622,4 +626,53 @@ def run_rate_add_io_slots_cases(my_predbat): failed |= run_rate_add_io_slots_test("test25_completed_away_consumes_cap", my_predbat, slots, True, 2, expected_rates) failed |= run_rate_add_io_slots_flag_tests(my_predbat, midnight_utc, TIME_FORMAT) + failed |= run_rate_add_io_slots_log_test(my_predbat, midnight_utc, TIME_FORMAT) + return failed + + +def run_rate_add_io_slots_log_test(my_predbat, midnight_utc, time_format): + """The slot list is logged in full when it changes and at least hourly, and as one line when it repeats.""" + print("\n**** Test: Intelligent slot list logged only when it changes ****") + failed = False + slot_start = midnight_utc + timedelta(hours=2) + slots = [{"start": slot_start.strftime(time_format), "end": (slot_start + timedelta(minutes=30)).strftime(time_format), "charge_in_kwh": 2.5, "source": "smart-charge", "location": "AT_HOME"}] + lines = [] + # Put back whatever was there: another test may have left its own log on the shared fixture + missing = object() + previous_log = my_predbat.__dict__.get("log", missing) + my_predbat.log = lambda message, *args, **kwargs: lines.append(str(message)) + try: + my_predbat.io_slot_log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS) + + def run(slot_list): + """Run rate_add_io_slots and return the slot lines it logged.""" + lines.clear() + my_predbat.rate_add_io_slots(0, {minute: 10.0 for minute in range(-24 * 60, 3 * 24 * 60)}, slot_list) + return [line for line in lines if line.startswith("Octopus: Intelligent slot") and "for day" not in line] + + first = run(slots) + if len(first) != 1 or "Intelligent slot at" not in first[0]: + print("ERROR: the first slot list should be logged in full, got {}".format(first)) + failed = True + repeat = run(slots) + if len(repeat) != 1 or "same as logged in full at" not in repeat[0] or "1 half-hour slot lines" not in repeat[0]: + print("ERROR: an unchanged slot list should be one line, got {}".format(repeat)) + failed = True + changed = [dict(slots[0], charge_in_kwh=3.0)] + if not any("amount 3.0" in line for line in run(changed)): + print("ERROR: a changed slot list should be logged in full") + failed = True + for entry, (logged_at, wall) in list(my_predbat.io_slot_log_gate.logged.items()): + my_predbat.io_slot_log_gate.logged[entry] = (logged_at - REPEAT_FULL_LOG_SECONDS, wall) + if not any("Intelligent slot at" in line for line in run(changed)): + print("ERROR: an unchanged slot list should be logged in full again after an hour") + failed = True + if run([]): + print("ERROR: no slots should log no slot lines, as before") + failed = True + finally: + if previous_log is missing: + del my_predbat.log + else: + my_predbat.log = previous_log return failed diff --git a/apps/predbat/tests/test_web_mcp.py b/apps/predbat/tests/test_web_mcp.py index d16e08b26..01eebfd4a 100644 --- a/apps/predbat/tests/test_web_mcp.py +++ b/apps/predbat/tests/test_web_mcp.py @@ -1219,7 +1219,7 @@ def _fat_log(now): stamp = now.replace(microsecond=0) lines = [ "{}: Info: short line before".format(stamp - timedelta(minutes=3)), - "{}: OctopusAPI: Fetched saving sessions data from GraphQL API: {}".format(stamp - timedelta(minutes=2), "x" * 20000), + "{}: OctopusAPI: GraphQL response for get-saving-sessions (status 200): {}".format(stamp - timedelta(minutes=2), "x" * 20000), "{}: Info: short line after".format(stamp - timedelta(minutes=1)), ] return "\n".join(lines) + "\n" diff --git a/apps/predbat/utils.py b/apps/predbat/utils.py index 135b5d254..9f310ae31 100644 --- a/apps/predbat/utils.py +++ b/apps/predbat/utils.py @@ -39,7 +39,9 @@ FULL_EXPORT_POWER, ) import copy +import hashlib import json +import time as time_module DAY_OF_WEEK_MAP = {"mon": 0, "tue": 1, "wed": 2, "thu": 3, "fri": 4, "sat": 5, "sun": 6} @@ -175,6 +177,50 @@ def predbat_log_count(args): STR2TIME_USE_FROMISOFORMAT = True +class RepeatLogGate: + """Decide whether a text that tends to repeat (an API response, a slot list) should be logged in full again. + + A text is logged in full the first time it is seen for a key, and again once interval_seconds have passed, so + the full text is never only in a rotated-out log file; in between, the caller logs one short line instead. + Only a hash of each text is kept, per key, so several texts can alternate under one key (one request context + serving several devices, or tariff comparison runs) without each one forcing the others out, and entries older + than the interval are dropped so the memory used stays bounded. Expiry runs on a monotonic clock, so a clock + change cannot stretch or shorten it; the time reported is local wall-clock time, matching the log's own stamps. + """ + + def __init__(self, interval_seconds): + """Create an empty gate that logs each text in full again at most every interval_seconds.""" + self.interval_seconds = interval_seconds + self.logged = {} + + def last_full(self, key, text, always_full=False): + """Return when text was last logged in full for key, or None when it should be logged in full now (recorded as such). + + always_full forces a full log, e.g. for an error response. text may be any value; it is compared as str(). + """ + now = time_module.monotonic() + for entry in [entry for entry, (logged_at, _wall) in self.logged.items() if now - logged_at >= self.interval_seconds]: + del self.logged[entry] + entry = (key, hashlib.sha1(str(text).encode("utf-8", "replace")).hexdigest()) + previous = self.logged.get(entry) + if previous is not None and not always_full: + return previous[1] + self.logged[entry] = (now, datetime.now()) + return None + + def log(self, log, key, text, full_lines, brief_line, always_full=False): + """Log full_lines through log when text is new for key or due again, else the one line brief_line(time of the + last full log) returns, or nothing when brief_line is None. Returns True when logged in full.""" + last = self.last_full(key, text, always_full=always_full) + if last is None: + for line in full_lines: + log(line) + return True + if brief_line is not None: + log(brief_line(last.strftime("%H:%M:%S"))) + return False + + class MinuteArray: """Dense array-backed replacement for dict[int, float] keyed by contiguous minute indices. diff --git a/docs/components.md b/docs/components.md index 09acdecb5..1dfec5e79 100644 --- a/docs/components.md +++ b/docs/components.md @@ -250,7 +250,7 @@ total size budget - `truncated_reason` says which of the two ended it. A cut lin its number, and passing that back as `line_number` returns it in full: ```text -2026-08-30 09:58:11: OctopusAPI: Fetched saving sessions... [+19069 chars, get_log line_number=26793] +2026-08-30 09:58:11: OctopusAPI: GraphQL response for get-saving-sessions (status 200): {'data': {'savingSessions': {'events': ... [+19069 chars, get_log line_number=26793] ``` Line numbers count from the start of the previous (rotated) log through the current one, so they