diff --git a/lib/lxst_audio/i2s_capture.cpp b/lib/lxst_audio/i2s_capture.cpp index 633cee32..d2dc425b 100644 --- a/lib/lxst_audio/i2s_capture.cpp +++ b/lib/lxst_audio/i2s_capture.cpp @@ -238,13 +238,17 @@ void I2SCapture::captureLoop() { if (v > runningPeak) runningPeak = v; } - // Measure actual sample rate + // Measure actual sample rate. Only print when something + // notable happened — peak above noise floor or any ring + // drops — otherwise this fires every 2s and during an active + // LXST call the serial buffer can't keep up alongside the + // per-batch TX/RX logs. Pyxis still keeps the count internally. totalSamples += ch0Count; uint32_t now = millis(); uint32_t elapsed = now - rateCheckMs; if (elapsed >= 2000) { uint32_t rate = (totalSamples * 1000) / elapsed; - { + if (ringDrops > 0 || runningPeak > 1000) { char logbuf[128]; snprintf(logbuf, sizeof(logbuf), "[CAP] rate=%luHz frames=%lu peak=%d ringDrops=%lu", (unsigned long)rate, (unsigned long)framesEncoded, diff --git a/patch_filestore.py b/patch_filestore.py index 6c8652e7..6f501e15 100644 --- a/patch_filestore.py +++ b/patch_filestore.py @@ -1,11 +1,20 @@ """ -PlatformIO pre-build script: TEMPORARY diagnostic patch for -microStore's FileStore::exists(). +PlatformIO pre-build script: patches the libdeps copy of microStore +FileStore.h before each build. -Adds a printf at the top of `bool exists(const uint8_t*, uint8_t)` so -we can see why the path-table store's exists returns false even when -the most recent put for the same key succeeded. Remove once the -investigation is done. +Two purposes: + +1. Adds diagnostic printfs to `exists()` and `put()` for tracking down + the path-table-store bug where exists() returns false right after a + successful put for the same key. Temporary; remove once that + investigation is closed. + +2. Silences the spammy "[ustore] get: key not found in index" print + that fires on every path-table miss. RNS hits path-store lookups + constantly on every incoming packet — during an active LXST call + that print floods USB CDC at hundreds of lines/sec, saturating the + serial buffer and starving T:CALL_QOS responses (#75). The print + is unconditional in upstream microStore, so we patch it out here. """ Import("env") import os @@ -45,8 +54,22 @@ PUT_NEW = """\t\tindex_insert(key, key_len, current_segment, offset, ts, ttl); \t\t// Enforce max_recs:""" +SPAMMY_OLD = '\t\t\tprintf("[ustore] get: key not found in index\\n");' +SPAMMY_NEW = '\t\t\t/* silenced — fires on every path-store miss, floods USB CDC */' + +DIAG_ENABLED = os.environ.get("PYXIS_FILESTORE_DIAG", "0") == "1" + def patch(content): out = content + # Silence patch always runs. + if SPAMMY_OLD in out: + out = out.replace(SPAMMY_OLD, SPAMMY_NEW) + print("PATCH: FileStore.h: silenced 'key not found in index' spam") + elif "silenced — fires on every path-store miss" in content: + print("PATCH: FileStore.h: 'key not found' spam already silenced") + # Diagnostic patches only when explicitly requested. + if not DIAG_ENABLED: + return out if OLD in out: out = out.replace(OLD, NEW) print("PATCH: FileStore.h: exists() diagnostics added") diff --git a/platformio.ini b/platformio.ini index d6b23279..7bac3f34 100644 --- a/platformio.ini +++ b/platformio.ini @@ -137,8 +137,12 @@ extra_scripts = pre:generate_splash.py pre:patch_nimble.py pre:patch_msgpack.py - ; pre:patch_filestore.py — diagnostic patch (very chatty); re-add - ; only when investigating put/exists drift in the path-table store + ; patch_filestore.py silences upstream microStore's spammy + ; "[ustore] get: key not found in index" print (fires on every + ; path-store miss; saturated USB CDC during LXST calls). Set + ; PYXIS_FILESTORE_DIAG=1 to also enable exists()/put() diagnostic + ; prints when investigating path-store drift. + pre:patch_filestore.py platform = espressif32 board = esp32-s3-devkitc-1 framework = arduino diff --git a/src/TCPClientInterface.cpp b/src/TCPClientInterface.cpp index 0db102ba..90440d01 100644 --- a/src/TCPClientInterface.cpp +++ b/src/TCPClientInterface.cpp @@ -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); }