Skip to content

Commit 0dbcce3

Browse files
chore(octopus): log repeated GraphQL responses and slot lists briefly instead of in full (#5428)
* 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> * 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> * 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> * 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> * 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> * 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> * 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> * 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> * 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> * 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> * 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> --------- Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
1 parent dcc6017 commit 0dbcce3

10 files changed

Lines changed: 367 additions & 10 deletions

‎apps/predbat/const.py‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -171,3 +171,7 @@
171171
# need the same answer to "which of these two states is the more significant one to show".
172172
CHARGE_STATE_PRECEDENCE = ["Charging", "Freeze charging", "Hold charging"]
173173
EXPORT_STATE_PRECEDENCE = ["Exporting", "Freeze exporting", "Hold exporting"]
174+
175+
# A log text that repeats (an API response, an Intelligent slot list) is logged in full again after this long, so
176+
# the full text is never only in a rotated-out log file; in between it is logged as one short line
177+
REPEAT_FULL_LOG_SECONDS = 3600

‎apps/predbat/octopus.py‎

Lines changed: 54 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -19,8 +19,8 @@
1919
import re
2020
from datetime import datetime, timedelta, timezone
2121
from predbat_metrics import record_api_call
22-
from const import TIME_FORMAT, TIME_FORMAT_OCTOPUS, DISPATCH_SOURCE_CHARGER_SCHEDULE
23-
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
22+
from const import TIME_FORMAT, TIME_FORMAT_OCTOPUS, DISPATCH_SOURCE_CHARGER_SCHEDULE, REPEAT_FULL_LOG_SECONDS
23+
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
2424
from component_base import ComponentBase
2525
from mock_base import MockBase as SharedMockBase
2626
import aiohttp
@@ -711,6 +711,8 @@ def initialize(self, key, account_id, automatic):
711711
# API request metrics for monitoring
712712
self.requests_total = 0
713713
self.failures_total = 0
714+
# Repeated GraphQL requests and responses, and skipped Happy Hours, are logged briefly between full logs
715+
self.log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS)
714716

715717
# In-memory cache for product info (keyed by product_code) to avoid repeated API calls
716718
self._product_info_cache = {}
@@ -1420,7 +1422,8 @@ def get_saving_session_data(self):
14201422
# v19.0.1 for the same reason; match that. The reward/code/type maps are populated above
14211423
# first, because a joined Happy Hour takes its event type from this list.
14221424
if event.get("eventType", None) == "WEEKEND_HAPPY_HOUR":
1423-
self.log("OctopusAPI: Not offering Weekend Happy Hour event code {} as available - it cannot be joined through the API".format(code))
1425+
# Logged once an hour per event (by id, so events with no code are told apart): the event list is re-read every poll
1426+
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)
14241427
continue
14251428
target_regions = [region.get("regionId") for region in (event.get("targetRegion", None) or []) if region]
14261429
if target_regions and account_region_id not in target_regions:
@@ -1710,7 +1713,6 @@ async def async_get_saving_sessions(self, account_id):
17101713
if response_data is None:
17111714
return self.saving_sessions
17121715
else:
1713-
self.log("OctopusAPI: Fetched saving sessions data from GraphQL API: {}".format(response_data))
17141716
savingSessions = response_data.get("savingSessions", {})
17151717
if savingSessions is None:
17161718
savingSessions = {}
@@ -2392,6 +2394,29 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i
23922394
if returns_data:
23932395
self.log(f"Warn: OctopusAPI: Failed to retrieve data from graphql query {request_context} - token refresh failed")
23942396
return None
2397+
# Whether the request was logged in full, and its full line, so a failure can show the request beside it
2398+
request_logged = [True, None]
2399+
2400+
def log_request_beside_failure():
2401+
"""Log the full request beside a failure when it was only logged briefly ("as logged in full at ...").
2402+
2403+
Not on a retry: only a failure causes one, and that failure has just logged the request in full."""
2404+
if not request_logged[0] and request_logged[1] and _retry_count == 0:
2405+
# Through the gate, so it records this full log: later brief lines name this time, and the hourly re-log counts from it
2406+
self.log_gate.log(self.log, ("request", request_context), query, [request_logged[1]], None, always_full=True)
2407+
request_logged[0] = True
2408+
2409+
def log_response(status, text, always_full):
2410+
"""Log a response in full when new, due again or always_full, else as one line naming when it was last logged in full."""
2411+
self.log_gate.log(
2412+
self.log,
2413+
("response", request_context),
2414+
"{} {}".format(status, text),
2415+
["OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, status, text)],
2416+
lambda when: "OctopusAPI: GraphQL response for {} (status {}) same as logged in full at {}, {} characters".format(request_context, status, when, len(text)),
2417+
always_full=always_full,
2418+
)
2419+
23952420
try:
23962421
self.requests_total += 1
23972422
client = await self.api.async_create_client_session()
@@ -2402,21 +2427,30 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i
24022427
headers = {"Authorization": f"{auth_prefix}{self.graphql_token}", integration_context_header: request_context}
24032428
# Redact the Authorization header so the JWT token is never written to the log
24042429
log_headers = {**headers, "Authorization": f"{auth_prefix}<redacted>"}
2405-
self.log("OctopusAPI: Making GraphQL request to {} payload {} headers {}".format(url, payload, log_headers))
2430+
request_line = "OctopusAPI: Making GraphQL request to {} payload {} headers {}".format(url, payload, log_headers)
2431+
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))
2432+
request_logged[1] = request_line
24062433
async with client.post(url, json=payload, headers=headers) as response:
24072434
# Check for HTTP-level 401/403 (transport-level auth failure) and retry once.
24082435
# This handles cases where the JWT has been revoked server-side and the server
24092436
# returns a bare 401/403 status rather than a GraphQL error body — which would
24102437
# otherwise loop forever without ever refreshing the token. The one exception is
24112438
# a 403 carrying a CDN/WAF block page, handled immediately below.
2439+
if response.status in [401, 403]:
2440+
log_request_beside_failure()
24122441
if response.status in [401, 403] and _retry_count == 0:
24132442
# A CDN/WAF block is rate limiting, not an auth failure. Re-minting a token
24142443
# here would be rejected by the same block, leaving the component permanently
24152444
# locked out, so keep the cached token and let the caller back off instead.
24162445
# Only 403 is treated this way: Kraken reports genuine auth problems as HTTP
24172446
# 200 with a GraphQL errorCode, or as a 401, so a 403 carrying a non-JSON
24182447
# body comes from the edge rather than the API.
2419-
if response.status == 403 and is_edge_block_body(await response.text()):
2448+
# Log the response in full first: the WAF return and the retry below both leave before the
2449+
# response logger further down. A second-attempt 401/403 is not logged here: its body is logged
2450+
# by async_read_response_retry below
2451+
error_text = await response.text()
2452+
log_response(response.status, error_text, always_full=True)
2453+
if response.status == 403 and is_edge_block_body(error_text):
24202454
self.consecutive_edge_blocks += 1
24212455
if self.consecutive_edge_blocks <= EDGE_BLOCK_REFRESH_AFTER:
24222456
record_api_call("octopus", False, "rate_limit")
@@ -2442,7 +2476,13 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i
24422476

24432477
# Process response (which reads the text)
24442478
response_body = await self.async_read_response_retry(response, url, ignore_errors=ignore_errors)
2445-
self.log("OctopusAPI: GraphQL response for {} (status {}): {}".format(request_context, response.status, response_body))
2479+
body_text = str(response_body)
2480+
# Logged in full with its request: a bad status, a body that is missing (unreadable JSON, a rate limit)
2481+
# or has no data, or any errors key - even a partial error returned with data when ignore_errors is set
2482+
failed = response.status != 200 or not isinstance(response_body, dict) or "errors" in response_body or response_body.get("data") is None
2483+
if failed:
2484+
log_request_beside_failure()
2485+
log_response(response.status, body_text, always_full=failed)
24462486

24472487
# Check for auth errors and retry once
24482488
if response_body and "errors" in response_body and _retry_count == 0:
@@ -2483,6 +2523,7 @@ async def async_graphql_query(self, query, request_context, returns_data=True, i
24832523
return None
24842524
except TimeoutError:
24852525
self.failures_total += 1
2526+
log_request_beside_failure()
24862527
self.log(f"Warn: OctopusAPI: Failed to connect, timeout exceeded.")
24872528
record_api_call("octopus", False, "connection_error")
24882529

@@ -3903,6 +3944,7 @@ def rate_add_io_slots(self, car_n, rates, octopus_slots):
39033944
slots_added_set = set()
39043945
plan_interval_minutes = self.plan_interval_minutes
39053946
saved_slots = set() # For logging purposes, track which slots we actually applied as low rate
3947+
slot_lines = [] # One log line per half hour of each slot, logged after the loop only when the list changes
39063948
# Dynamic load has seen this car in its slot but not charging: none of its dispatches from now
39073949
# on get the cheap rate (see dynamic_load_car_check()). Elapsed minutes keep theirs - they record
39083950
# what the tariff charged, and today's cost is built from them. None when the car is not cancelled.
@@ -3997,12 +4039,16 @@ def rate_add_io_slots(self, car_n, rates, octopus_slots):
39974039
rates[minute] = assumed_price
39984040

39994041
if minute % 30 == 0 and start_minutes > -24 * 60:
4000-
self.log(
4042+
slot_lines.append(
40014043
"Octopus: Intelligent slot at {}-{}, assumed price {}, amount {}, kWh location {}, source {}, octopus_slot_low_rate {}".format(
40024044
self.time_abs_str(start_minutes), self.time_abs_str(end_minutes), dp2(assumed_price), dp2(kwh), location, source, octopus_slot_low_rate
40034045
)
40044046
)
40054047

4048+
# The slot list is re-derived every plan but rarely changes, so log it only when it does, and at least hourly
4049+
if slot_lines:
4050+
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)))
4051+
40064052
# Log daily slot counts for debugging
40074053
for day_offset in sorted(slots_per_day.keys()):
40084054
if slots_per_day[day_offset] > 0:

‎apps/predbat/predbat.py‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,7 @@
6565
print("Running in compiled mode; skipping local file checks and auto-update.")
6666

6767
from const import (
68+
REPEAT_FULL_LOG_SECONDS,
6869
TIME_FORMAT,
6970
PREDICT_STEP,
7071
RUN_EVERY,
@@ -77,6 +78,7 @@
7778
from config import APPS_SCHEMA, CONFIG_ITEMS
7879
import debug_history
7980
from utils import (
81+
RepeatLogGate,
8082
minutes_since_yesterday,
8183
minutes_since_midnight,
8284
dp1,
@@ -495,6 +497,8 @@ def reset(self):
495497
self.car_charging_power = 0
496498
self.car_charging_power_configured = False
497499
self.io_adjusted = {}
500+
# Repeated Intelligent slot lists are logged briefly between full logs (rate_add_io_slots)
501+
self.io_slot_log_gate = RepeatLogGate(REPEAT_FULL_LOG_SECONDS)
498502
self.current_charge_limit = 0.0
499503
self.current_charge_limit_kwh = 0.0
500504
self.inverter_limit = 0.0

0 commit comments

Comments
 (0)