chore(octopus): log repeated GraphQL responses and slot lists briefly instead of in full by chalfontchubby · Pull Request #5428 · springfall2008/batpred

chalfontchubby · 2026-10-07T12:44:50Z

Opened by Claude on Rik's behalf.

Summary

On a live system with an Octopus account, about 40% of predbat.log was the same text logged again and again. The biggest single item was the saving sessions GraphQL response, about 22 KB, logged in full on every poll and then a second time as "Fetched saving sessions data". This logs a repeat as one short line instead, without losing anything.

GraphQL requests and responses: a request or response already logged in full within the last hour is logged as one line, "same as logged in full at HH:MM:SS" (and, for a response, its size). It is logged in full again at least hourly, so the full text is never only in a rotated-out log. An error response, or one with no data (unreadable JSON, a rate limit, data null), is always logged in full, with the request that caused it, including on the 401/403, WAF-block and timeout paths (a first-attempt 401/403 body is logged before the retry or the WAF return; a failed retry does not log the request in full a second time). The duplicate "Fetched saving sessions data" line is dropped.
Intelligent slot list: about 16 lines every plan, now logged in full only when it changes (or hourly), otherwise as one line ("same as logged in full at HH:MM:SS"). An empty list is not logged, as before.
Weekend Happy Hour: "Not offering ... it cannot be joined" is logged hourly per event (by event id, so events with no code are each logged), not on every poll.

The decision is one small class, RepeatLogGate (utils.py). For each key it keeps a hash of each text logged in full, not the text itself, so:

several texts can alternate under one key without forcing each other out: one request context serving several Intelligent devices, or tariff comparison runs whose slot prices differ;
entries older than the interval are dropped, so memory stays bounded;
expiry runs on a monotonic clock, so a clock change cannot stretch it, and the time shown is local wall-clock time, matching the log's own timestamps.

The JWT stays redacted on every line.

Not changed

write_and_poll ... No write needed, which shows the control is being checked.
The per-run "Inverter does not support reserve" note, about 0.5% of the log.
The short repeat lines name the request context, not the device. With two Intelligent devices, the brief lines for each look alike. The full lines still differ.
An edge/WAF 403 page is logged in full on each blocked call (about 400 characters for CloudFront), because error responses are not shortened.
A response with an errors key is always logged in full, including a partial error returned with data on an ignore_errors query, so a query that fails the same way every poll is not shortened.

Changes

apps/predbat/utils.py: RepeatLogGate.
apps/predbat/const.py: REPEAT_FULL_LOG_SECONDS (3600).
apps/predbat/octopus.py: the GraphQL logging, the slot list and the Happy Hour line go through the gate.
apps/predbat/predbat.py: the slot-list gate in reset().
docs/components.md: the get_log example line no longer quotes the dropped line.
Tests: test_octopus_logging (repeat, change, hourly re-log, the hourly interval restarting after a full log beside a failure, two queries per context, errors, responses with no body or no data, the gate itself, token redaction), test_rate_add_io_slots (slot list), test_octopus_saving_event_type (Happy Hour, including events with no code), test_octopus_waf_block (first-attempt 401/403 body logged once, request logged once across a failed retry), and test_web_mcp (fixture line).

Test plan

Full suite and pre-commit pass on each commit.
Measure the log size on a live system after deploying.

🤖 Generated with Claude Code

…ead 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>

…nd 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>

… 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>

…ot 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>

… 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>

…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>

Copilot

🟡 Changes recommended

Early 401/403 responses are not logged as promised, and failure-side request logging leaves stale gate timestamps.

2 open findings

What changed in this PR

Reduces repeated Octopus API and Intelligent-slot logging while retaining periodic diagnostic detail.

Changes:

Adds reusable repeat-log gating.
Applies gating to GraphQL, slot, and Happy Hour logs.
Adds tests and updates documentation fixtures.

File	Description
`apps/predbat/utils.py`	Adds `RepeatLogGate`.
`apps/predbat/const.py`	Defines the hourly interval.
`apps/predbat/octopus.py`	Gates repeated Octopus logs.
`apps/predbat/predbat.py`	Initializes the slot-log gate.
`apps/predbat/tests/test_octopus_logging.py`	Tests GraphQL log gating.
`apps/predbat/tests/test_rate_add_io_slots.py`	Tests slot-log gating.
`apps/predbat/tests/test_octopus_saving_event_type.py`	Tests Happy Hour logging.
`apps/predbat/tests/test_web_mcp.py`	Updates the large-log fixture.
`docs/components.md`	Updates the logging example.

🧠 Review effort: Balanced

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

…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>

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>

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>

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>

…spell 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>

…rning-status Conflicts resolved: - apps/predbat/const.py: kept both new constants - this branch's COMPONENT_ERROR_STATUS_PREFIX/SUFFIX and main's REPEAT_FULL_LOG_SECONDS (#5428). - apps/predbat/predbat.py: const import takes both sides' additions. - apps/predbat/output.py: const import keeps this branch's multi-line form plus main's new RUN_EVERY (used by history_slot/history_refresh_minutes). The calculate_yesterday() publish_html_plan call auto-merged with both status_warnings and main's refresh_minutes. - docs/inverter-setup.md: took main's reformatted LuxPower freeze automations and re-applied this branch's four 'Hold charging' exact matches as startswith('Hold charging'). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

chalfontchubby and others added 2 commits October 7, 2026 13:36

chalfontchubby added the enhancement New feature or request label Oct 7, 2026

chalfontchubby and others added 4 commits October 11, 2026 11:08

chalfontchubby requested a balanced review from Copilot October 11, 2026 10:48

Copilot started reviewing on behalf of chalfontchubby October 11, 2026 10:49 View session

Copilot AI reviewed Oct 11, 2026

View reviewed changes

Comment thread apps/predbat/octopus.py Outdated

Comment thread apps/predbat/octopus.py

chalfontchubby and others added 5 commits October 11, 2026 12:32

test(octopus): use 'refetch' in the re-log test's query name, which c…

ecd2a89

…spell 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>

springfall2008 merged commit 0dbcce3 into main Oct 12, 2026
2 checks passed

springfall2008 deleted the chore/log-reduction branch October 12, 2026 07:23

Navigation Menu

Repository navigation

chore(octopus): log repeated GraphQL responses and slot lists briefly instead of in full - #5428

chore(octopus): log repeated GraphQL responses and slot lists briefly instead of in full#5428
springfall2008 merged 11 commits into
mainfrom
chore/log-reduction

chalfontchubby commented Oct 7, 2026 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

chalfontchubby commented Oct 7, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

Not changed

Changes

Test plan

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

🟡 Changes recommended

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

chalfontchubby commented Oct 7, 2026 •

edited

Loading