fix(log): redact serials, add connection context, demote non-fault errors - #616
Conversation
…rors Three problems made production logs hard to use for triage: - The IP module and panel serial numbers were printed verbatim, and logs are routinely pasted into GitHub issues. - The connection method appeared once at startup, often thousands of lines before the failure being reported. - Benign, recoverable and bad-input conditions were logged at ERROR, making an ERROR-only log unusable and training users to ignore it. Redaction: add mask_secret() and mask_email() and apply them to the IP module serial and the STUN site listing's panel serial. Context: add describe_connection(), which renders the configured connection as a short redacted descriptor from config alone, so it is safe to call before connecting and after a drop. Log a startup banner (version, Python, platform, connection, interfaces) and include the descriptor in the connect-failure and connection-lost messages. Levels: demote 31 sites to WARNING (unhandled broadcasts, unsupported commands, bad MQTT input, PRT3 config errors, recoverable framing noise, MQTT broker drops) and 7 `control_* canceled` sites to DEBUG, since those fire on CancelledError during shutdown and are never actionable. Message text is unchanged; only the level moves. Genuine faults (timeouts, login failures, connection loss, every logger.exception) stay at ERROR. Uptime: track connect/disconnect timestamps in the retry loop with time.monotonic() and log "Panel connection ended after X up" and "Connection recovered after X down", so stability is greppable from an ERROR/WARNING-level log. Also drops an unused paho import and a redundant getattr in mqtt/core.py, which the flake8 hook flags on any commit touching that file.
- Cold start no longer claims a false recovery. mark_disconnected() now returns early when no healthy session was ever established, so a run that fails its first N connect attempts does not log "Connection recovered after X down" on the first success. Covered by a test that fails against the previous logic. - "Send panic: user or partition is not found" goes back to ERROR. A panic command silently failing is operationally serious and should reach anyone alerting on ERROR. Also adds the missing `return False` on that branch: control flow previously fell through to `partition["id"]` and raised TypeError on None. - Redacts the SWAN site listing. The full site_info blob was dumped to DEBUG as raw JSON, leaking every module's panelSerial and the account email four lines before the point where panelSerial was masked. - Records session uptime when the loop exits via PAICriticalException, KeyboardInterrupt or SystemExit, which previously lost the uptime of a session ending in a critical fault. - Raises the two uptime messages and the LOGGING_LEVEL_FILE default to WARNING. The default was ERROR, so the uptime signal this feature adds would have been invisible in exactly the file logs users paste into issue reports. The demotions in the previous commit lower the noise floor enough that WARNING is now a quiet level. Adds tests for the cold-start case, the connect/drop/recover cycle, the site-info redaction, and the SITEID-without-EMAIL fallback.
Review round 1 — findings addressedReviewed by three perspectives (Advocate / Critic / Architect). Pushed FixedMajor — false recovery on cold start. Major — panic failure demoted. Minor — SWAN site listing leaked wholesale. Minor — uptime lost on critical exit. Minor — test gaps. Added coverage for the SITEID-without-EMAIL fallback and the full connect → drop → fail → recover cycle. Design change from the Architect review
This is the one behaviour change beyond logging levels, and it is deliberate. The startup banner stays INFO; connection context still reaches shared logs because the failure messages carry Deferred to follow-upBoth from the Architect, both agreed but out of scope:
1700 tests pass. |
|
1 participant
Why
Reviewing a real 0.5 MB production log surfaced three problems that make PAI logs hard to triage:
serial: 7106152c). Logs get pasted into issues routinely.Using IP Connectionis logged once at startup — often thousands of lines before the error being reported, so issue reports rarely show which transport was involved.LOGGING_LEVEL_FILE = ERRORlog (the default), the noise floor made real faults invisible, and "has the connection been stable?" could only be answered by inferring it from the absence of messages.What changed
Redaction
mask_secret()/mask_email()inparadox/lib/utils.py.connections/ip/commands.py) and the STUN site listing's panel serial (connections/ip/stun_session.py).Authentication Success. IP(IP150) Module version 20, firmware: 1.32, serial: ****152cConnection context
New
describe_connection()renders the configured connection as a short, redacted descriptor. It reads config only — never a live connection object — so it is safe to call before connecting and after a drop.CONNECTION_TYPESerialSerial(/dev/ttyS1@9600)IPlocalIP(192.168.1.10:10000)IPsite/SWANSITE(MySite / j****@e****.com, serial ****152c)PRT3PRT3(/dev/ttyUSB0@57600)Used in a startup banner and injected into the connect-failure and connection-lost messages:
Local IP host/port are shown unmasked — they are almost always RFC1918 and are essential for diagnosing wrong-host problems. The site name is shown (user-chosen, not a credential); the account email and panel serial are masked.
Log level audit
ERROR → WARNING (31 sites): unhandled panel broadcasts (
No handler for message), unsupported/not-implemented commands,No <zones/partitions/outputs/doors> selected, invalid MQTT topics and utility keys, PRT3PRT3_USER_CODEconfig errors, recoverable IP framing noise, MQTT broker drops (the client auto-reconnects), and unimplemented RAM status parsers.ERROR → DEBUG (7 sites): every
control_* canceled/send_panic canceled. These fire onCancelledErrorduring shutdown or supersession and are never actionable.Deliberately unchanged:
control_* timeout,Installer login failed,Authentication Failed,Could not read <mem_type>,Could not fully load labels,Unable to parse RAM Status Block,Connection to panel was lost,Serial Port Timeout, port-not-readable, everything inlib/help.py, and everylogger.exception(...).Message text is byte-identical for all demoted sites — only the level moves — so anyone grepping for the exact strings still matches.
Connection uptime
The retry loop in
main.pynow tracks connect/disconnect timestamps usingtime.monotonic()(not wall clock, so NTP steps and DST cannot produce negative durations):First connect after process start logs no recovery line.
Testing
mask_secret,mask_email,format_durationanddescribe_connection, including an assertion that the email and panel serial never appear verbatim in the descriptor.tests/lib/test_handlers_level.pyassertsNo handler for messageis emitted at WARNING.Notes for the reviewer
interfaces/mqtt/core.py(unusedMQTT_ERR_SUCCESSimport, redundantgetattr) are included because the flake8 pre-commit hook blocks any commit touching that file until they are fixed. They pre-date this branch.pyupgrade/blackreformatted some pre-existing long lines ininterfaces/mqtt/core.pyandhardware/evo/panel.pyas a side effect of the hooks running on touched files..gitignoregains/docs/superpowers/for local design notes.