Skip to content

Log Signal K deltas at verbose level#1046

Merged
mairas merged 1 commit into
mainfrom
fix/delta-log-level-verbose
Jun 25, 2026
Merged

Log Signal K deltas at verbose level#1046
mairas merged 1 commit into
mainfrom
fix/delta-log-level-verbose

Conversation

@mairas

@mairas mairas commented Jun 25, 2026

Copy link
Copy Markdown
Collaborator

Why

Outbound Signal K deltas are logged at DEBUG and written synchronously to UART0. Under the default DEBUG runtime level they print on every delta, and on a high-rate device the blocking UART write stalls the event loop when the TX FIFO fills. That loop stall starves the SK WebSocket client itself, turning heavy logging into dropped deltas and disconnects.

What

Move the three delta log calls in signalk_delta_queue.cpp from ESP_LOGD to ESP_LOGV. Deltas are then suppressed at the default DEBUG level but still available when the runtime level is raised to VERBOSE for debugging — they remain the primary "is my data going out?" diagnostic, just off by default.

Evidence

Validated on a live AIS device (ESP32-C3) carrying real bus traffic. Together with quieting the application's own per-message logs, the device went from loop-starved — HTTP API answering 0/8, SK WebSocket chronically "not connected", every delta dropped — to healthy: HTTP 8/8, WebSocket connected, deltas and N2K both flowing steadily, no reboot.

This is the cheap mitigation. The synchronous, blocking UART log transport is the underlying cause; anyone who raises the runtime level to DEBUG/VERBOSE re-triggers the stall. #1045 tracks the real fix (a non-blocking log transport).

Refs #1045.

Outbound SK deltas were logged at DEBUG and written synchronously to UART0. Under the default DEBUG runtime level they print on every delta, stalling the event loop when the TX FIFO fills on high-rate devices. Move them to VERBOSE so they are suppressed by default but available when the runtime level is raised. Refs #1045.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
@mairas

mairas commented Jun 25, 2026

Copy link
Copy Markdown
Collaborator Author

Review — independent persona fan-out (4 reviewers, fresh context)

Verdict: ready to merge. CI all-green. No P0/P1.

Confirmed

  • Completeness. The three delta: %s lines are the only per-delta-batch logs in SKDeltaQueue::get_deltas. send_delta() (signalk_ws_client.cpp) has no per-delta log; signalk_put_request.cpp:48 is user-action-triggered (low frequency, correctly DEBUG); the inbound Websocket payload received log is behind #ifdef SIGNALK_PRINT_RCV_DELTA (compiled out by default). No sibling high-frequency site was missed.
  • Right level. Matches the documented convention (migration guide: VERBOSE = "Bigger chunks of debugging information, or frequent messages which can potentially flood the output"). A serialized per-delta JSON payload is exactly that. VERBOSE is the lowest level that actually suppresses, since the runtime default is ESP_LOG_DEBUG (sensesp_base_app.h:22).
  • No dependence. No native test, tooling, doc, or example asserts on or greps the "delta: " string or its level.

P3 — advisory (no merge block)

With CORE_DEBUG_LEVEL=VERBOSE the three strings stay compiled in, so raising the runtime level to VERBOSE reintroduces the loop-blocking flood this PR fixes. That's inherent to the stopgap — #1045 tracks the real non-blocking-transport cure. Optional: a one-line comment at the first delta: line noting these fire per delta batch and block on UART0, so a future maintainer raising the level understands the cause.

Advisory

CHANGELOG.md nominally "lists each PR as merged," but the file is de-facto abandoned (newest entries ~2020). Not applied.

@mairas mairas merged commit d3e8a6f into main Jun 25, 2026
8 checks passed
@mairas mairas deleted the fix/delta-log-level-verbose branch June 25, 2026 17:28
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant