fix(serial): silence audio/wire/path-store noise during active calls

Real-LXST 14s call at ULBW (Codec2-700C) was timing out T:CALL_QOS /
T:CALL_STATS responses ~10-15s in. Pyxis itself was still processing
audio fine; the host's serial reader was just overrun by debug-level
prints from three sources, all firing per-packet during voice traffic:

1. TCPClientInterface: per-frame "[TCP] Reading X bytes" / "[TCP]
   First bytes: ..." / "[HDLC] Frame #N: ..." / "[TCP] Processing
   frame" / 5s "[TCP] connected= ..." were unconditional Serial.printf.
   Now gated behind `RNS::loglevel() >= LOG_DEBUG` and the snprintf
   work skipped when it'd be discarded.

2. i2s_capture.cpp: "[CAP] rate=" fired every 2s regardless of
   activity. Now only emits when ringDrops > 0 OR runningPeak > 1000
   (something happened worth noting). Counters still update — only
   the print is gated.

3. microStore upstream: "[ustore] get: key not found in index" fires
   on every path-store miss, which RNS hits constantly during a call.
   patch_filestore.py was already a registered pre-build script for
   diagnostic patches; reactivate it (was commented out in
   platformio.ini) and add a silence patch as the always-on default.
   Diagnostic exists()/put() patches gated behind PYXIS_FILESTORE_DIAG=1
   so they're easy to bring back when investigating path-store drift
   without touching the script each time.

After this, the ULBW real-LXST call validator returns PASS with full
final stats (pyxis_tx=34 rx=119 decode_ok=151 decode_fail=0
pyxis_rms=4410). 1600bps/3200bps profiles still hit serial-timeout
patterns under sustained TX — likely CPU saturation in the main
loop, separate from this fix; tracked in #75 followup.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
torlando-tech
2026-05-09 01:52:34 -04:00
co-authored by Claude Opus 4.7
parent f5d9e6a480
commit f6b90a330b
4 changed files with 69 additions and 26 deletions
+28 -16
View File
@@ -252,11 +252,17 @@ void TCPClientInterface::handle_disconnect() {
static uint32_t total_rx = 0;
loop_count++;
uint32_t now = millis();
if (now - last_status_log >= 5000) { // Every 5 seconds
// [TCP] connection-status heartbeat — protocol-debug only. Was at
// INFO level firing every 5s; combined with the per-frame [TCP] /
// [HDLC] / [ustore] prints below, this saturated USB CDC during
// active LXST calls and starved T:CALL_QOS responses (#75).
if (now - last_status_log >= 5000) {
last_status_log = now;
int avail = _client.available();
Serial.printf("[TCP] connected=%d online=%d avail=%d loops=%u rx=%u buf=%d\n",
_client.connected(), _online, avail, loop_count, total_rx, (int)_frame_buffer.size());
if (RNS::loglevel() >= RNS::LOG_DEBUG) {
int avail = _client.available();
Serial.printf("[TCP] connected=%d online=%d avail=%d loops=%u rx=%u buf=%d\n",
_client.connected(), _online, avail, loop_count, total_rx, (int)_frame_buffer.size());
}
loop_count = 0;
}
@@ -305,7 +311,8 @@ void TCPClientInterface::handle_disconnect() {
// Read available data
int avail = _client.available();
if (avail > 0) {
Serial.printf("[TCP] Reading %d bytes\n", avail);
bool dbg = RNS::loglevel() >= RNS::LOG_DEBUG;
if (dbg) Serial.printf("[TCP] Reading %d bytes\n", avail);
total_rx += avail;
_last_data_received = now; // Update stale timer on any data receipt
size_t start_pos = _frame_buffer.size();
@@ -313,14 +320,15 @@ void TCPClientInterface::handle_disconnect() {
uint8_t byte = _client.read();
_frame_buffer.append(byte);
}
// Dump first 20 bytes of new data
Serial.printf("[TCP] First bytes: ");
size_t dump_len = (_frame_buffer.size() - start_pos);
if (dump_len > 20) dump_len = 20;
for (size_t i = 0; i < dump_len; ++i) {
Serial.printf("%02x ", _frame_buffer.data()[start_pos + i]);
if (dbg) {
Serial.printf("[TCP] First bytes: ");
size_t dump_len = (_frame_buffer.size() - start_pos);
if (dump_len > 20) dump_len = 20;
for (size_t i = 0; i < dump_len; ++i) {
Serial.printf("%02x ", _frame_buffer.data()[start_pos + i]);
}
Serial.printf("\n");
}
Serial.printf("\n");
}
#else
// Non-blocking read
@@ -396,21 +404,23 @@ void TCPClientInterface::extract_and_process_frames() {
// Extract frame content between FLAGS (excluding the FLAGS)
Bytes frame_content = _frame_buffer.mid(1, end - 1);
frame_count++;
Serial.printf("[HDLC] Frame #%u: %d escaped bytes\n", frame_count, (int)frame_content.size());
if (RNS::loglevel() >= RNS::LOG_DEBUG) {
Serial.printf("[HDLC] Frame #%u: %d escaped bytes\n", frame_count, (int)frame_content.size());
}
// Remove processed frame from buffer (keep data after end FLAG)
_frame_buffer = _frame_buffer.mid(end);
// Skip empty frames (consecutive FLAGs)
if (frame_content.size() == 0) {
Serial.printf("[HDLC] Empty frame, skipping\n");
if (RNS::loglevel() >= RNS::LOG_DEBUG) Serial.printf("[HDLC] Empty frame, skipping\n");
continue;
}
// Unescape frame
Bytes unescaped = HDLC::unescape(frame_content);
if (unescaped.size() == 0) {
Serial.printf("[HDLC] Unescape failed!\n");
if (RNS::loglevel() >= RNS::LOG_DEBUG) Serial.printf("[HDLC] Unescape failed!\n");
DEBUG("TCPClientInterface: HDLC unescape error, discarding frame");
continue;
}
@@ -422,7 +432,9 @@ void TCPClientInterface::extract_and_process_frames() {
}
// Pass to transport layer
Serial.printf("[TCP] Processing frame: %d bytes\n", (int)unescaped.size());
if (RNS::loglevel() >= RNS::LOG_DEBUG) {
Serial.printf("[TCP] Processing frame: %d bytes\n", (int)unescaped.size());
}
DEBUG(toString() + ": Received frame, " + std::to_string(unescaped.size()) + " bytes");
InterfaceImpl::handle_incoming(unescaped);
}