From 2a8eb2e19f691b0a75c1b9ac4cb461c68d5031f3 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Wed, 7 Oct 2026 11:35:49 +0100
Subject: [PATCH 01/11] chore(octopus): log a repeated GraphQL query or
 response briefly instead of in full

The Octopus GraphQL logging was about 30% of a typical log: every request logged its fixed query text and every
response its full body, poll after poll, and the saving sessions response (about 22 KB) was then logged a
second time as "Fetched saving sessions data". Now a request or response already logged in full within the hour
is logged as one line saying when it was last logged in full, and is logged in full again at least hourly so the
full text is never only in a rotated-out log file. The duplicate saving sessions line is dropped.

The decision is a new RepeatLogGate (utils.py): it keeps only a hash of each text per key, so several queries
sharing one request context (one per Intelligent device) each keep their own entry, and drops entries older than
the interval so its memory stays bounded. An error response is always logged in full, with the request that
caused it. The JWT stays redacted on every line.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/const.py                      |  4 +
 apps/predbat/octopus.py                    | 36 ++++++--
 apps/predbat/tests/test_octopus_logging.py | 99 ++++++++++++++++++++++
 apps/predbat/tests/test_web_mcp.py         |  2 +-
 apps/predbat/utils.py                      | 46 ++++++++++
 docs/components.md                         |  2 +-
 6 files changed, 182 insertions(+), 7 deletions(-)

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..168d594ff 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 = {}
@@ -1646,7 +1648,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 +2329,15 @@ 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 ...")."""
+            if not request_logged[0] and request_logged[1]:
+                self.log(request_logged[1])
+                request_logged[0] = True
+
         try:
             self.requests_total += 1
             client = await self.api.async_create_client_session()
@@ -2338,13 +2348,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}<redacted>"}
-            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
@@ -2378,7 +2392,18 @@ 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)
+                failed = response.status != 200 or (isinstance(response_body, dict) and "errors" in response_body)
+                if failed:
+                    log_request_beside_failure()
+                self.log_gate.log(
+                    self.log,
+                    ("response", request_context),
+                    "{} {}".format(response.status, body_text),
+                    ["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, body_text)],
+                    lambda when: "OctopusAPI: GraphQL response for {} (status {}) unchanged since logged in full at {}, {} characters".format(request_context, response.status, when, len(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 +2444,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")
 
diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py
index 3910ab73c..6663c6f25 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,101 @@ 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) unchanged since 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("unchanged since 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
+
+    # 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_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

From a6d1074a1abc4b06f15334d27f0b8539f19761ab Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Wed, 7 Oct 2026 11:35:49 +0100
Subject: [PATCH 02/11] chore(octopus): log the Intelligent slot list only when
 it changes, and each Happy Hour skip hourly

The slot list (about 16 lines) was logged on every plan though it rarely changes; it now goes through the same
RepeatLogGate, logged in full when it changes and at least hourly, and as one line saying when it was last
logged in full otherwise. Tariff comparison runs, whose slot prices differ, keep their own entries rather than
forcing the live list to be logged again. An empty list is not logged, as before. The "Not offering Weekend Happy
Hour" line is logged once an hour per event code rather than on every poll of the event list.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                       | 10 +++-
 apps/predbat/predbat.py                       |  4 ++
 .../tests/test_octopus_saving_event_type.py   | 23 ++++++++
 apps/predbat/tests/test_rate_add_io_slots.py  | 53 +++++++++++++++++++
 4 files changed, 88 insertions(+), 2 deletions(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 168d594ff..6f047c2a0 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -1363,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: the event list is re-read every poll
+                self.log_gate.log(self.log, "happy-hour", 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:
@@ -3845,6 +3846,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.
@@ -3939,12 +3941,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 {} unchanged since 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_saving_event_type.py b/apps/predbat/tests/test_octopus_saving_event_type.py
index ef2a85460..39113d7db 100644
--- a/apps/predbat/tests/test_octopus_saving_event_type.py
+++ b/apps/predbat/tests/test_octopus_saving_event_type.py
@@ -56,6 +56,29 @@ 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")
+
     # 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_rate_add_io_slots.py b/apps/predbat/tests/test_rate_add_io_slots.py
index 5e5576362..a9d490378 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 "unchanged since 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

From be89726eee25345b99e7498ab33f723cf09f425c Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 11:08:41 +0100
Subject: [PATCH 03/11] fix(octopus): treat a status 200 with no body or no
 data as a failure when gating GraphQL logs

A 200 whose body could not be read (unreadable JSON, a KT-CT-1199 rate limit, read retries used up)
or carried no data key still ends in "Failed to retrieve data from graphql query", but the gate treated
it as a success: a repeat logged the request and response as brief lines, so the full request was not
beside the failure. Now any response the function will not return data for is logged in full with its
request, as an errors response already was.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                    |  4 +++-
 apps/predbat/tests/test_octopus_logging.py | 11 +++++++++++
 2 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 6f047c2a0..a22683899 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2394,7 +2394,9 @@ def log_request_beside_failure():
                 # Process response (which reads the text)
                 response_body = await self.async_read_response_retry(response, url, ignore_errors=ignore_errors)
                 body_text = str(response_body)
-                failed = response.status != 200 or (isinstance(response_body, dict) and "errors" in response_body)
+                # A failure is anything the code below will not return data for: a bad status, an errors key, or a
+                # body that is missing (unreadable JSON, a rate limit) or has no data
+                failed = response.status != 200 or not isinstance(response_body, dict) or "errors" in response_body or "data" not in response_body
                 if failed:
                     log_request_beside_failure()
                 self.log_gate.log(
diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py
index 6663c6f25..ad631cd94 100644
--- a/apps/predbat/tests/test_octopus_logging.py
+++ b/apps/predbat/tests/test_octopus_logging.py
@@ -137,6 +137,17 @@ async def test_octopus_logging(my_predbat):
         print("ERROR: the request behind a repeated error should be logged in full beside it, 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")]:
+        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")

From b2b2818333f1d1a66c502de28a5b3f9e7a426225 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 11:09:55 +0100
Subject: [PATCH 04/11] fix(octopus): gate each skipped Weekend Happy Hour by
 its event id, not only its code

The hourly gate on "Not offering Weekend Happy Hour" used the event code as its text, so every
Happy Hour with no code hashed the same and only the first was logged each hour. Gate on the
event id with the code, so each event is logged hourly as described.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                              |  4 ++--
 apps/predbat/tests/test_octopus_saving_event_type.py | 12 ++++++++++++
 2 files changed, 14 insertions(+), 2 deletions(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index a22683899..edf41e551 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -1363,8 +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":
-                # Logged once an hour per event: the event list is re-read every poll
-                self.log_gate.log(self.log, "happy-hour", code, ["OctopusAPI: Not offering Weekend Happy Hour event code {} as available - it cannot be joined through the API".format(code)], None)
+                # 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:
diff --git a/apps/predbat/tests/test_octopus_saving_event_type.py b/apps/predbat/tests/test_octopus_saving_event_type.py
index 39113d7db..3787f0ded 100644
--- a/apps/predbat/tests/test_octopus_saving_event_type.py
+++ b/apps/predbat/tests/test_octopus_saving_event_type.py
@@ -79,6 +79,18 @@ def make_api(events, joined):
     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], [])

From ffd84e4f272ed8f12fba6de72288be235f54eed5 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 11:11:03 +0100
Subject: [PATCH 05/11] fix(octopus): say "same as logged in full at", not
 "unchanged since", on a brief repeat line

The gate keeps several texts per key, so a response or slot list can change and change back
within the hour (A, B, then A again). The brief line for the third was worded "unchanged since
logged in full at" the time A was logged, which is false: it changed in between. "Same as" is true
in every case.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                      | 4 ++--
 apps/predbat/tests/test_octopus_logging.py   | 4 ++--
 apps/predbat/tests/test_rate_add_io_slots.py | 2 +-
 3 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index edf41e551..1500a46f1 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2404,7 +2404,7 @@ def log_request_beside_failure():
                     ("response", request_context),
                     "{} {}".format(response.status, body_text),
                     ["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, body_text)],
-                    lambda when: "OctopusAPI: GraphQL response for {} (status {}) unchanged since logged in full at {}, {} characters".format(request_context, response.status, when, len(body_text)),
+                    lambda when: "OctopusAPI: GraphQL response for {} (status {}) same as logged in full at {}, {} characters".format(request_context, response.status, when, len(body_text)),
                     always_full=failed,
                 )
 
@@ -3951,7 +3951,7 @@ def rate_add_io_slots(self, car_n, rates, octopus_slots):
 
         # 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 {} unchanged since logged in full at {}, {} half-hour slot lines".format(car_n, when, len(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()):
diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py
index ad631cd94..f7ab10dc2 100644
--- a/apps/predbat/tests/test_octopus_logging.py
+++ b/apps/predbat/tests/test_octopus_logging.py
@@ -89,7 +89,7 @@ async def test_octopus_logging(my_predbat):
     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) unchanged since logged in full" 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
@@ -121,7 +121,7 @@ async def test_octopus_logging(my_predbat):
     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("unchanged since logged in full" in line for line in log_lines):
+    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
 
diff --git a/apps/predbat/tests/test_rate_add_io_slots.py b/apps/predbat/tests/test_rate_add_io_slots.py
index a9d490378..7284e8c3c 100644
--- a/apps/predbat/tests/test_rate_add_io_slots.py
+++ b/apps/predbat/tests/test_rate_add_io_slots.py
@@ -655,7 +655,7 @@ def run(slot_list):
             print("ERROR: the first slot list should be logged in full, got {}".format(first))
             failed = True
         repeat = run(slots)
-        if len(repeat) != 1 or "unchanged since logged in full at" not in repeat[0] or "1 half-hour slot lines" not in repeat[0]:
+        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)]

From 62ad4c5f9a66c5971f17357387efece3874d1834 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 11:17:59 +0100
Subject: [PATCH 06/11] fix(octopus): count a GraphQL body of data null as a
 failure for the log gate, and correct its comment

A body of data null with no errors key returns None to the caller, which then reports the query
as failed, but the gate treated it as a success and logged a repeat briefly without the request.
Count a missing or null data value as a failure. The comment also claimed every gated failure
returns no data; a partial error returned with data under ignore_errors is logged in full too,
so say so.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                    | 6 +++---
 apps/predbat/tests/test_octopus_logging.py | 2 +-
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 1500a46f1..875270af2 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2394,9 +2394,9 @@ def log_request_beside_failure():
                 # Process response (which reads the text)
                 response_body = await self.async_read_response_retry(response, url, ignore_errors=ignore_errors)
                 body_text = str(response_body)
-                # A failure is anything the code below will not return data for: a bad status, an errors key, or a
-                # body that is missing (unreadable JSON, a rate limit) or has no data
-                failed = response.status != 200 or not isinstance(response_body, dict) or "errors" in response_body or "data" not in 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()
                 self.log_gate.log(
diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py
index f7ab10dc2..cb0f22dee 100644
--- a/apps/predbat/tests/test_octopus_logging.py
+++ b/apps/predbat/tests/test_octopus_logging.py
@@ -139,7 +139,7 @@ async def test_octopus_logging(my_predbat):
 
     # 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")]:
+    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()

From 00af0c4119a27f8d643c3349008aac72282bb145 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 12:32:47 +0100
Subject: [PATCH 07/11] fix(octopus): record the full request logged beside a
 failure in the log gate

The request re-logged in full beside a failure went straight to the log, so the
gate kept the older full-log time. The next brief line named that older time,
and once the hour ran out from it the request was logged in full again, though
it had been logged in full more recently. Route it through the gate with
always_full so the gate's record matches the log.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                    |  3 ++-
 apps/predbat/tests/test_octopus_logging.py | 22 ++++++++++++++++++++++
 2 files changed, 24 insertions(+), 1 deletion(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 875270af2..4b429fb7b 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2336,7 +2336,8 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i
         def log_request_beside_failure():
             """Log the full request beside a failure when it was only logged briefly ("as logged in full at ...")."""
             if not request_logged[0] and request_logged[1]:
-                self.log(request_logged[1])
+                # 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
 
         try:
diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py
index cb0f22dee..06dd5bca0 100644
--- a/apps/predbat/tests/test_octopus_logging.py
+++ b/apps/predbat/tests/test_octopus_logging.py
@@ -137,6 +137,28 @@ async def test_octopus_logging(my_predbat):
         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 { relog }", "test-relog", 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": "Relog failed", "extensions": {"errorCode": "KT-CT-9999"}}]})
+    log_lines.clear()
+    await api.async_graphql_query("query { relog }", "test-relog", returns_data=True, ignore_errors=True)
+    if not any("query { relog }" 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 { relog }", "test-relog", returns_data=True)
+    if any("query { relog }" 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")]:

From 9abef94304c9740b115c6651a237ce9422ed8339 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 12:33:46 +0100
Subject: [PATCH 08/11] fix(octopus): log a first-attempt 401/403 GraphQL
 response in full

The first-attempt 401/403 branch either returns (an edge/WAF block) or
retries with a fresh token before reaching the response logger, so the
response body was never logged. Read it once there and log it through the
gate with always_full. A second-attempt 401/403 is not logged here: it reaches
async_read_response_retry, which logs its body.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                      | 14 ++++++++-
 apps/predbat/tests/test_octopus_waf_block.py | 30 ++++++++++++++++++++
 2 files changed, 43 insertions(+), 1 deletion(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 4b429fb7b..3db785794 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2368,7 +2368,19 @@ def log_request_beside_failure():
                     # 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()
+                    self.log_gate.log(
+                        self.log,
+                        ("response", request_context),
+                        "{} {}".format(response.status, error_text),
+                        ["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, error_text)],
+                        None,
+                        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")
diff --git a/apps/predbat/tests/test_octopus_waf_block.py b/apps/predbat/tests/test_octopus_waf_block.py
index ac9961592..516b9c7fc 100644
--- a/apps/predbat/tests/test_octopus_waf_block.py
+++ b/apps/predbat/tests/test_octopus_waf_block.py
@@ -171,6 +171,36 @@ 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")
+
     if failed:
         print("**** Octopus WAF/CloudFront 403 tests FAILED ****")
     else:

From 8bbdaba896b1e1a472e66749ae9c860af05831b2 Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 12:38:01 +0100
Subject: [PATCH 09/11] refactor(octopus): share one helper for the GraphQL
 response log line

The first-attempt 401/403 path and the normal path each built the same gated
response log call. Move it into one local helper so the format and gate key
cannot drift apart.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py | 29 +++++++++++++----------------
 1 file changed, 13 insertions(+), 16 deletions(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 3db785794..01b473495 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2340,6 +2340,17 @@ def log_request_beside_failure():
                 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()
@@ -2372,14 +2383,7 @@ def log_request_beside_failure():
                     # 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()
-                    self.log_gate.log(
-                        self.log,
-                        ("response", request_context),
-                        "{} {}".format(response.status, error_text),
-                        ["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, error_text)],
-                        None,
-                        always_full=True,
-                    )
+                    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:
@@ -2412,14 +2416,7 @@ def log_request_beside_failure():
                 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()
-                self.log_gate.log(
-                    self.log,
-                    ("response", request_context),
-                    "{} {}".format(response.status, body_text),
-                    ["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, body_text)],
-                    lambda when: "OctopusAPI: GraphQL response for {} (status {}) same as logged in full at {}, {} characters".format(request_context, response.status, when, len(body_text)),
-                    always_full=failed,
-                )
+                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:

From 4bf2e0026976fd7164db91f5c4c308d60d04df2e Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 12:43:25 +0100
Subject: [PATCH 10/11] fix(octopus): log the full request once when a token
 retry also fails

A retry only follows a failure, and that failure has just logged the request
in full. The retry's gate rightly logs the request briefly, pointing at that
line, but its own 401/403 then logged the full request a second time. Skip the
beside-failure re-log on a retry.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/octopus.py                      | 6 ++++--
 apps/predbat/tests/test_octopus_waf_block.py | 7 +++++++
 2 files changed, 11 insertions(+), 2 deletions(-)

diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py
index 01b473495..2938ff5dc 100644
--- a/apps/predbat/octopus.py
+++ b/apps/predbat/octopus.py
@@ -2334,8 +2334,10 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i
         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 ...")."""
-            if not request_logged[0] and request_logged[1]:
+            """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
diff --git a/apps/predbat/tests/test_octopus_waf_block.py b/apps/predbat/tests/test_octopus_waf_block.py
index 516b9c7fc..4196b3ffd 100644
--- a/apps/predbat/tests/test_octopus_waf_block.py
+++ b/apps/predbat/tests/test_octopus_waf_block.py
@@ -200,6 +200,13 @@ async def counting_read(resp, url, ignore_errors=False):
         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 ****")

From ecd2a893d81ecf7f06c6b312b485d2296c48937f Mon Sep 17 00:00:00 2001
From: Rik Allen <rikallen@yahoo.com>
Date: Sun, 11 Oct 2026 13:30:31 +0100
Subject: [PATCH 11/11] test(octopus): use 'refetch' in the re-log test's query
 name, which cspell knows

CI's cspell rejected 'relog' in test_octopus_logging.py. Renaming the
test query avoids adding a made-up word to the dictionary.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 apps/predbat/tests/test_octopus_logging.py | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/apps/predbat/tests/test_octopus_logging.py b/apps/predbat/tests/test_octopus_logging.py
index 06dd5bca0..71a4df264 100644
--- a/apps/predbat/tests/test_octopus_logging.py
+++ b/apps/predbat/tests/test_octopus_logging.py
@@ -141,21 +141,21 @@ async def test_octopus_logging(my_predbat):
     # 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 { relog }", "test-relog", returns_data=True)
+    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": "Relog failed", "extensions": {"errorCode": "KT-CT-9999"}}]})
+    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 { relog }", "test-relog", returns_data=True, ignore_errors=True)
-    if not any("query { relog }" in line for line in log_lines):
+    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 { relog }", "test-relog", returns_data=True)
-    if any("query { relog }" in line for line in log_lines) or not any("(query as logged in full at" in line for line in log_lines):
+    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