feat: add device diagnostics for missing voice replies

Track microphone levels, short reads and PCM buffer drops. Report audio
queue admission separately from TLS writes, expose server replies and
ACKs before filtering, and capture per-round counters before timeouts.

Add diagnostic regression coverage and support POSIX hosts in WSS tests.

docs/voice_diagnostics.md

@@ -0,0 +1,29 @@
+# 对话无回复诊断日志
+
+设备端新增四类日志，按 `round`、`session`、单调运行时间关联。诊断不调整对话协议、VAD 阈值或回复等待时限。
+
+| 标记 | 内容 | 可以缩小的范围 |
+| --- | --- | --- |
+| `MIC-DIAG` | 录音打开结果及句柄、读取返回值/字节数、全零帧、峰值/平均绝对幅值、录音事件、PCM 缓冲写入丢失 | 区分未取得 PCM、全零输入、已有音频但没有通过 VAD、音频交给编码器前丢失 |
+| `VOICE-TX` | 认证消息入队结果；START/END 的序号、类型、字节数、返回值和入队耗时；音频入队失败 | 区分请求未入队、内存分配失败、正常提交发送队列 |
+| `WSS-IO` | 实际 TLS 写入结果、累计写入次数和字节；TLS 错误码、部分写入进度和重试；实际接收字节；关闭时的累计收发及未消费接收字节 | 区分入队后未完成写入、对端关闭、收到字节但应用层未获得完整消息 |
+| `VOICE-RX` | 接收文本长度、前 192 字节、当前会话、是否通过会话准入检查；二进制消息计数 | 显示 START_ACK/END_ACK、未知回复、被准入检查丢弃的消息。二进制消息仍沿用原有忽略行为 |
+| `VOICE-DIAG` | START/END 入队后的摘要、超时断开前和断开回调时的摘要 | 汇总入队成功/失败数、音频载荷字节、文本/二进制消息数、ACK 次数、末次收包距今时长和回复等待时长 |
+
+拾音统计按一次录音累计，每秒及停止时输出。`peak`/`mean_abs` 是 16 位有符号 PCM 的绝对幅值，不是分贝；`zero` 统计有效读取长度内全部为零的帧。`short` 包括零长度以及所有非 640 字节的读取。PCM 写入不足或失败计入 `ring_drops`，同时记录丢失字节数。录音 tick 回调不打印，其他重复事件限频。
+
+`VOICE-TX ret=0` 只代表入队成功。`queue_bytes` 只计成功入队的音频载荷，不含自定义包头、WebSocket 帧头、认证和控制消息。`WSS-IO tx_bytes` 是传给传输层并成功返回的明文字节数，含握手/帧头，不能与 `queue_bytes` 直接比较；TLS 失败时已写出的部分字节由 `tls_write_failed`/`tls_write_timeout` 的 `sent` 单独报告。正常写入首条和每 50 次打印一次，实际接收前 20 次及每 50 次打印，断开时输出累计值。`tick`/`elapsed_ticks` 使用 RTOS tick，其他带 `ms` 的字段使用单调毫秒。
+
+`start_ack`/`end_ack` 按收到的文本子串统计，包含被准入检查拒绝的消息；它们不是对当前 session 的服务端确认保证。应结合 `VOICE-RX` 原文中的会话标识判断归属。若服务端协议不发送 ACK，ACK 为零本身不代表失败。`accepted=1` 表示通过外层会话准入检查，后续仍可能因 OTA、打断状态、URL 或 session 校验而未播放。文本仅保留前 192 字节，原有错误消息完整分块日志继续保留。
+
+复现时保留开机到失败后第二次对话结束的完整串口日志。推荐按以下顺序判断：
+
+1. `MIC-DIAG` 检查读取长度、返回值和电平，结合既有 FVAD 语音确认日志判断拾音与 VAD。
+2. `VOICE-TX` 检查 START、音频、END 入队；`queue_fail` 和 `ring_drops` 应为零。
+3. `WSS-IO` 检查实际写入是否失败，关闭时是否有接收字节和残留未消费数据。
+4. `VOICE-RX` 检查 ACK、未知错误文本、被拒绝的回复或二进制数据。
+5. `timeout-before-disconnect` 检查 `wait_ms`。`wait=2` 是等待回复，`wait=1` 是无语音，`wait=3` 是 END 入队失败。`response` 表示现有业务逻辑已接收可用音频 URL，不等同于收到任意文本或 TTS_START。
+
+即使 TLS 写入成功，也不能证明服务器应用收到完整录音。若已经看到归属正确的 END_ACK，却没有后续 TTS，优先按 session 查服务端识别和生成链路；若没有 ACK，也需要结合服务端接收记录判断。设备单侧日志不能完全区分服务端未处理、网络中断和回复延迟。
+
+本机验证：`python3 tools/test_voice_diag.py`、`python3 tools/test_conversation_timeout.py`、`python3 tools/test_wss_io.py`、`python3 tools/test_wss_receive.py`。诊断测试直接编译实际函数并注入录音、缓冲区、队列及收包结果；不替代目标固件构建及设备实测。

ql-application/threadx/interface/custom_app/lib/librws/inc/rws_socket.h

@@ -96,6 +96,9 @@ typedef struct _rws_socket_struct
     int command;
 
     unsigned int next_message_id;
+    /* Worker-owned transport counters; socket creation zero-initializes these. */
+    unsigned int diag_tx_calls, diag_tx_bytes, diag_tx_failed;
+    unsigned int diag_rx_calls, diag_rx_bytes;
 
     rws_bool is_connected; // sock connected + handshake done
 

ql-application/threadx/interface/custom_app/lib/librws/src/rws_socketpriv.c

@@ -193,17 +193,30 @@ static int rws_tls_send_all(_rws_socket *s, const unsigned char *data, size_t si
 {
     size_t sent = 0;
     unsigned int started = ql_rtos_get_systicks();
-    if (!s->ssl) return -1;
+    unsigned int retries = 0;
+    if (!s->ssl) {
+        printf("[WSS-IO] tls_write_no_context requested=%u\n", (unsigned int)size);
+        return -1;
+    }
     while (sent < size) {
         int ret = mbedtls_ssl_write(&s->ssl->ssl_ctx, data + sent, size - sent);
         if (ret > 0) {
             sent += (size_t)ret;
         } else if (ret != MBEDTLS_ERR_SSL_WANT_READ && ret != MBEDTLS_ERR_SSL_WANT_WRITE) {
+            printf("[WSS-IO] tls_write_failed ret=%d sent=%u requested=%u retries=%u elapsed_ticks=%u\n",
+                   ret, (unsigned int)sent, (unsigned int)size, retries,
+                   (unsigned int)(ql_rtos_get_systicks() - started));
             return -1;
         } else {
+            retries++;
             rws_thread_sleep(5);
         }
-        if (sent < size && (unsigned int)(ql_rtos_get_systicks() - started) >= 1000) return -1;
+        if (sent < size && (unsigned int)(ql_rtos_get_systicks() - started) >= 1000) {
+            printf("[WSS-IO] tls_write_timeout last_ret=%d sent=%u requested=%u retries=%u elapsed_ticks=%u\n",
+                   ret, (unsigned int)sent, (unsigned int)size, retries,
+                   (unsigned int)(ql_rtos_get_systicks() - started));
+            return -1;
+        }
     }
     return (int)sent;
 }
@@ -218,7 +231,6 @@ rws_bool rws_socket_send(_rws_socket *s, const void *data, const size_t data_siz
 #ifdef LIBRWS_USING_MBED_TLS
     if (s->scheme && strcmp(s->scheme, "wss") == 0)
     {
-        LOG_D("[T:%.8d, L:%.5d, %*.*s] try send data with tls", ql_rtos_get_systicks(), __LINE__, DBG_FUNCTION_NUM, DBG_FUNCTION_NUM, __FUNCTION__);
         sended = rws_tls_send_all(s, (const unsigned char *)data, data_size);
     }
     else
@@ -243,6 +255,14 @@ rws_bool rws_socket_send(_rws_socket *s, const void *data, const size_t data_siz
     }
 #endif
 
+    s->diag_tx_calls++;
+    if (sended > 0) s->diag_tx_bytes += (unsigned int)sended;
+    if (sended != (int)data_size) s->diag_tx_failed++;
+    if (s->diag_tx_calls == 1 || s->diag_tx_calls % 50 == 0 || sended != (int)data_size) {
+        printf("[WSS-IO] write tick=%u requested=%u ret=%d calls=%u bytes=%u failed=%u\n",
+               ql_rtos_get_systicks(), (unsigned int)data_size, sended,
+               s->diag_tx_calls, s->diag_tx_bytes, s->diag_tx_failed);
+    }
     if (sended == (int)data_size)
     {
     	rws_socket_error_cnt = 0;
@@ -283,7 +303,6 @@ rws_bool rws_socket_recv(_rws_socket *s)
     rws_bool result = rws_true;
     int is_reading = 1, error_number = -1, len = -1;
     char *received = NULL;
-    size_t total_len = 0;
     // char *buff = 0;
 
    // LOG_D("[T:%.8d, L:%.5d, %*.*s] receive data", ql_rtos_get_systicks(), __LINE__, DBG_FUNCTION_NUM, DBG_FUNCTION_NUM, __FUNCTION__);
@@ -365,7 +384,12 @@ rws_bool rws_socket_recv(_rws_socket *s)
 
         if (len > 0)
         {
-            total_len += len;
+            s->diag_rx_calls++;
+            s->diag_rx_bytes += (unsigned int)len;
+            if (s->diag_rx_calls <= 20 || s->diag_rx_calls % 50 == 0)
+                printf("[WSS-IO] read tick=%u bytes=%d calls=%u total=%u buffered=%u command=%d\n",
+                       ql_rtos_get_systicks(), len, s->diag_rx_calls, s->diag_rx_bytes,
+                       (unsigned int)s->received_len, s->command);
             if (s->command == COMMAND_WAIT_HANDSHAKE_RESPONCE &&
                 s->received_len + (size_t)len > RWS_HANDSHAKE_MAX + RWS_RECEIVE_BUFF_SIZE) {
                 s->error = rws_error_new_code_descr(rws_error_code_parse_handshake, "WebSocket headers too large");
@@ -1650,9 +1674,12 @@ void rws_socket_resize_received(_rws_socket *s, const size_t size)
 
 void rws_socket_close(_rws_socket *s)
 {
-    s->received_len = 0;
     if (s->socket != RWS_INVALID_SOCKET)
     {
+        printf("[WSS-IO] close tick=%u tx_calls=%u tx_bytes=%u tx_failed=%u rx_calls=%u rx_bytes=%u buffered=%u command=%d\n",
+               ql_rtos_get_systicks(), s->diag_tx_calls, s->diag_tx_bytes,
+               s->diag_tx_failed, s->diag_rx_calls, s->diag_rx_bytes,
+               (unsigned int)s->received_len, s->command);
 #ifdef LIBRWS_USING_MBED_TLS
         if (s->scheme && strcmp(s->scheme, "wss") == 0)
         {
@@ -1669,6 +1696,7 @@ void rws_socket_close(_rws_socket *s)
         WSACleanup();
 #endif
     }
+    s->received_len = 0;
     s->is_connected = rws_false;
 }
 

ql-application/threadx/interface/custom_app/vad_det.c

@@ -71,6 +71,55 @@ static int vad_tts_playback_finished_status = 0;
 // 统计
 static uint32 frame_count = 0;
 static uint32 speech_frame_count = 0;
+static struct {
+    unsigned int reads, short_reads, read_errors, zero_frames, samples, peak;
+    unsigned int ring_drops, ring_drop_bytes;
+    uint64_t abs_sum, last_log_ms, started_ms;
+} mic_diag;
+
+static void mic_diag_log(const char *stage)
+{
+    printf("[MIC-DIAG] %s uptime_ms=%u age_ms=%u reads=%u short=%u read_errors=%u zero=%u peak=%u mean_abs=%u ring_drops=%u ring_drop_bytes=%u\n",
+           stage, (unsigned int)hal_os_up_time_ms(),
+           (unsigned int)(hal_os_up_time_ms() - mic_diag.started_ms),
+           mic_diag.reads, mic_diag.short_reads, mic_diag.read_errors, mic_diag.zero_frames,
+           mic_diag.peak, mic_diag.samples ? (unsigned int)(mic_diag.abs_sum / mic_diag.samples) : 0,
+           mic_diag.ring_drops, mic_diag.ring_drop_bytes);
+}
+
+/* Observe both preroll and live PCM writes; retain the caller's wakeup policy. */
+static int mic_diag_write(const void *data, int len)
+{
+    int written = hal_os_rb_write(ring_sender, data, len, 25);
+    if (written < len) {
+        mic_diag.ring_drops++;
+        mic_diag.ring_drop_bytes += (unsigned int)(len - (written > 0 ? written : 0));
+    }
+    return written;
+}
+
+static void mic_diag_read(const uint8_t *data, int len, int ret)
+{
+    int i, bounded = len > VAD_FRAME_BYTES ? VAD_FRAME_BYTES : len;
+    unsigned int peak = 0;
+    mic_diag.reads++;
+    if (ret < 0) mic_diag.read_errors++;
+    if (len != VAD_FRAME_BYTES) mic_diag.short_reads++;
+    for (i = 0; i + 1 < bounded; i += 2) {
+        int sample = (int16_t)((unsigned int)data[i] | ((unsigned int)data[i + 1] << 8));
+        unsigned int magnitude = (unsigned int)(sample < 0 ? -sample : sample);
+        if (magnitude > peak) peak = magnitude;
+        mic_diag.abs_sum += magnitude;
+        mic_diag.samples++;
+    }
+    if (bounded > 0 && peak == 0) mic_diag.zero_frames++;
+    if (peak > mic_diag.peak) mic_diag.peak = peak;
+    if (mic_diag.reads == 1 || hal_os_up_time_ms() - mic_diag.last_log_ms >= 1000) {
+        printf("[MIC-DIAG] read ret=%d bytes=%d frame_peak=%u state=%d\n", ret, len, peak, g_state);
+        mic_diag_log("sampling");
+        mic_diag.last_log_ms = hal_os_up_time_ms();
+    }
+}
 extern int audio_packet_type;
 
 
@@ -84,7 +133,17 @@ static	audio_record_handle record_hd;
 
 static void ql_audio_record_callback(acm_audio_track_handle handle, acm_audio_record_event_t event)
 {
-	//printf("audio_record_callback event:%d\r\n", event);
+    static int last_event = -1;
+    static uint64_t last_log_ms;
+    uint64_t now;
+    (void)handle;
+    if (event == AUDIO_RECORD_EVENT_TICK || event == AUDIO_RECORD_EVENT_NONE) return;
+    now = hal_os_up_time_ms();
+    if ((int)event != last_event || now - last_log_ms >= 1000) {
+        printf("[MIC-DIAG] callback event=%d uptime_ms=%u\n", event, (unsigned int)now);
+        last_event = (int)event;
+        last_log_ms = now;
+    }
 }
 
 void vad_tts_playback_finished()
@@ -206,7 +265,13 @@ int vad_audio_init(void) {
 
 // 启动录音
 int vad_audio_start(void) {
-	vad_audio_init();
+    memset(&mic_diag, 0, sizeof(mic_diag));
+    mic_diag.started_ms = hal_os_up_time_ms();
+    {
+        int init_ret = vad_audio_init();
+        printf("[MIC-DIAG] open ret=%d handle=%u uptime_ms=%u\n",
+               init_ret, (unsigned int)record_hd, (unsigned int)hal_os_up_time_ms());
+    }
     
     frame_count = 0;
     speech_frame_count = 0;
@@ -217,6 +282,7 @@ int vad_audio_start(void) {
 
 // 停止录音
 int vad_audio_stop(void) {
+    mic_diag_log("stop");
 
     printf("Audio recording stopped, frames: %d, speech: %d", 
              frame_count, speech_frame_count);
@@ -235,6 +301,7 @@ int vad_audio_stop(void) {
 
 // 停止录音
 int vad_audio_stop_no_wait_resp(void) {
+    mic_diag_log("cancel");
     conversation_cancel_wait();
 
     printf("Audio recording stopped no_wait_resp, frames: %d, speech: %d", 
@@ -381,7 +448,10 @@ void vad_audio_process(void) {
         case STATE_RECORDING_ACTIVE:
 			memset(mic_buf, 0, sizeof(mic_buf));
 			//每次读取640字节音频数据
-			ql_audio_record_read(record_hd, mic_buf, &record_len); 
+            {
+                int read_ret = ql_audio_record_read(record_hd, mic_buf, &record_len);
+                mic_diag_read(mic_buf, record_len, read_ret);
+            }
 
 			if (g_state == STATE_RECORDING_WAIT_SOUND) {
 				/* 首次开口确认前不向服务端发送静音。只在本地保留最近500ms，
@@ -392,7 +462,7 @@ void vad_audio_process(void) {
 					vad_preroll_count++;
 				}
 			} else {
-				if(hal_os_rb_write(ring_sender, (uint8*)mic_buf, record_len, 25)>0){
+				if(mic_diag_write(mic_buf, record_len)>0){
 					ql_rtos_semaphore_release(sender_sem);
 				}
 			}
@@ -437,7 +507,7 @@ void vad_audio_process(void) {
 							int preroll_queued = 0;
 							for (n = 0; n < vad_preroll_count; n++) {
 								size_t frame_index = (first + n) % VAD_PREROLL_FRAMES;
-								if (hal_os_rb_write(ring_sender, vad_preroll[frame_index], VAD_FRAME_BYTES, 25) > 0) {
+								if (mic_diag_write(vad_preroll[frame_index], VAD_FRAME_BYTES) > 0) {
 									preroll_queued = 1;
 								}
 							}

ql-application/threadx/interface/custom_app/ws_talkingq.c

@@ -62,6 +62,12 @@ enum { WAIT_NONE, WAIT_NO_SPEECH, WAIT_REPLY, WAIT_SEND_FAILURE };
 static int conversation_wait = WAIT_NONE;
 static int timeout_action_busy = 0;
 static int round_response_received = 0;
+/* Queue admission is distinct from a completed TLS write and from server ACK. */
+static struct {
+    unsigned int tx_packets, tx_bytes, tx_failed, rx_text, rx_bin;
+    unsigned int start_ack, end_ack;
+    uint64_t started_ms, last_rx_ms;
+} voice_diag;
 static unsigned int active_session_round = 0;
 static int active_session_valid = 0;
 static uint64_t startup_start_ms = 0;
@@ -87,6 +93,10 @@ static void conversation_unlock(void)
 static void conversation_begin_round(void)
 {
     conversation_round++;
+    memset(&voice_diag, 0, sizeof(voice_diag));
+    voice_diag.started_ms = hal_os_up_time_ms();
+    printf("[VOICE-DIAG] begin round=%u uptime_ms=%u\n",
+           conversation_round, (unsigned int)voice_diag.started_ms);
     conversation_wait = WAIT_NONE;
     round_response_received = 0;
     active_session_valid = 0;
@@ -217,6 +227,20 @@ unsigned char get_xiaoice_connected_status(void)
 	return xiaoice_wss_connect_status;
 }
 
+/* Called with conversation_mutex held. Ages use monotonic milliseconds. */
+static void voice_diag_snapshot(const char *stage)
+{
+    uint64_t now = hal_os_up_time_ms();
+    printf("[VOICE-DIAG] %s round=%u session=%s age_ms=%u queue_pkts=%u queue_bytes=%u queue_fail=%u rx_text=%u rx_bin=%u start_ack=%u end_ack=%u last_rx_age_ms=%d wait=%d wait_ms=%u response=%d\n",
+           stage, conversation_round, active_session_valid ? sessionId : "none",
+           (unsigned int)(now - voice_diag.started_ms), voice_diag.tx_packets,
+           voice_diag.tx_bytes, voice_diag.tx_failed, voice_diag.rx_text,
+           voice_diag.rx_bin, voice_diag.start_ack, voice_diag.end_ack,
+           voice_diag.rx_text || voice_diag.rx_bin ? (int)(now - voice_diag.last_rx_ms) : -1,
+           conversation_wait, conversation_wait == WAIT_REPLY ?
+           (unsigned int)(now - reply_wait_start_ms) : 0, round_response_received);
+}
+
 static void onopen(rws_socket socket) 
 {
     if (socket != app->socket || !app->init) return;
@@ -245,6 +269,9 @@ static void onclose(rws_socket socket)
     }
 
     if (socket != app->socket) return;
+    conversation_lock();
+    voice_diag_snapshot("disconnected");
+    conversation_unlock();
     xiaoice_wss_connect_status = 0;
     app->socket = NULL;
     /* The worker owns and releases this socket after the callback. */
@@ -649,6 +676,16 @@ static void conversation_log_error_message(const char *text, unsigned int len)
 static void onmessage_text(rws_socket socket, const char *text, const unsigned int len)
 {
     conversation_lock();
+    voice_diag.rx_text++;
+    voice_diag.last_rx_ms = hal_os_up_time_ms();
+    if (strstr(text, "START_ACK")) voice_diag.start_ack++;
+    if (strstr(text, "END_ACK")) voice_diag.end_ack++;
+    /* Bounded preview includes unrecognized replies and ACKs before filtering. */
+    printf("[VOICE-RX] round=%u session=%s uptime_ms=%u len=%u accepted=%d preview=%.*s%s\n",
+           conversation_round, active_session_valid ? sessionId : "none",
+           (unsigned int)voice_diag.last_rx_ms, len,
+           conversation_accept_voice_message(text), (int)(len > 192 ? 192 : len), text,
+           len > 192 ? " [truncated]" : "");
     if (strstr(text, "tts_error") != NULL || strstr(text, "tts_err") != NULL ||
         strstr(text, "PROMPT_SOUND_URL") != NULL) {
         conversation_log_error_message(text, len);
@@ -663,8 +700,16 @@ static void onmessage_text(rws_socket socket, const char *text, const unsigned i
 }
 
 static void onmessage_bin(rws_socket socket, const void * data, const unsigned int len)
-{	
-	LOG_D("message(bin): %d ", len);
+{
+    (void)socket;
+    (void)data;
+    conversation_lock();
+    voice_diag.rx_bin++;
+    voice_diag.last_rx_ms = hal_os_up_time_ms();
+    if (voice_diag.rx_bin == 1 || voice_diag.rx_bin % 50 == 0)
+        printf("[VOICE-RX] binary round=%u len=%u count=%u ignored=1\n",
+               conversation_round, len, voice_diag.rx_bin);
+    conversation_unlock();
 		
 	return;
 }
@@ -811,7 +856,11 @@ int  talkingq_ws_send_text(char *senddata)
     
     LOG_D("talkingq_wss_send_text string = %s, len = %d", senddata, strlen(senddata)); 
 
-    rws_socket_send_text(app->socket, senddata); 
+    {
+        int queued = rws_socket_send_text(app->socket, senddata);
+        printf("[VOICE-TX] auth/text queue uptime_ms=%u bytes=%u accepted=%d\n",
+               (unsigned int)hal_os_up_time_ms(), (unsigned int)strlen(senddata), queued != 0);
+    }
     
     return 0; 
 }
@@ -1041,6 +1090,7 @@ void sendStartPacket(void) {
     startPacket.dataSize = 0;
     
     active_session_valid = sendRecordingAudioPacket(&startPacket) == 0;
+    voice_diag_snapshot("start-queued");
     conversation_unlock();
  //   rt_kprintf("sendStartPacket, seq=%u\r\n", startPacket.sequenceNumber);
 }
@@ -1059,6 +1109,7 @@ void sendEndPacket(void) {
             reply_wait_start_ms = hal_os_up_time_ms();
             conversation_wait = end_ret == 0 ? WAIT_REPLY : WAIT_SEND_FAILURE;
         }
+        voice_diag_snapshot("end-queued");
     }
     conversation_unlock();
   //  rt_kprintf("sendEndPacket, seq=%u\r\n", endPacket.sequenceNumber);
@@ -1074,12 +1125,19 @@ void sendAudioPacket(const uint8_t* data, size_t dataSize) {
         audioPacket.data = malloc(audioPacket.dataSize);
         if(audioPacket.data==NULL){
             RLOGE("audioPacket.data NULL");
+            conversation_lock();
+            voice_diag.tx_failed++;
+            printf("[VOICE-TX] alloc_failed round=%u seq=%u bytes=%u\n",
+                   conversation_round, audioPacket.sequenceNumber, (unsigned int)dataSize);
+            conversation_unlock();
             return;
         }
         memcpy(audioPacket.data, data, dataSize);
     }
 
+    conversation_lock();
     sendRecordingAudioPacket(&audioPacket);
+    conversation_unlock();
    // rt_kprintf("sendAudioPacket, seq=%u\r\n", audioPacket.sequenceNumber);
    if(audioPacket.data){
         free(audioPacket.data);
@@ -1092,7 +1150,9 @@ void sendInterruptPacket(void) {
     interruptPacket.packetType = 3;
     interruptPacket.dataSize = 0;
 
+    conversation_lock();
     sendRecordingAudioPacket(&interruptPacket);
+    conversation_unlock();
 }
 
 void sendAuthentication() 
@@ -1122,6 +1182,9 @@ int sendRecordingAudioPacket(AudioPacket *packet) {
     sendBuffer = malloc(DEVICE_ID_SIZE + SESSION_ID_SIZE + sizeof(uint32_t) * 2 + sizeof(uint32_t) + packet->dataSize);
     if(sendBuffer==NULL){
         RLOGE("sendBuffer NULL");
+        voice_diag.tx_failed++;
+        printf("[VOICE-TX] alloc_failed seq=%u type=%u bytes=%u\n",
+               packet->sequenceNumber, packet->packetType, (unsigned int)packet->dataSize);
         return -1;
     }
 
@@ -1151,7 +1214,21 @@ int sendRecordingAudioPacket(AudioPacket *packet) {
    // memcpy(recorder->save_buf, (void *)sendBuffer, recorder->save_len);
     //record_msg_send(recorder, RECORD_MSG_DATA, recorder->save_len);
 
+    uint64_t queue_started = hal_os_up_time_ms();
 	int send_ret = talkingq_ws_send_bin((uint8_t*)sendBuffer, totalSize);
+    if (send_ret == 0) {
+        voice_diag.tx_packets++;
+        voice_diag.tx_bytes += (unsigned int)packet->dataSize;
+    } else {
+        voice_diag.tx_failed++;
+    }
+    if (packet->packetType == 1 || packet->packetType == 2 || send_ret != 0 ||
+        voice_diag.tx_packets % 50 == 0) {
+        printf("[VOICE-TX] queue round=%u session=%s seq=%u type=%u bytes=%u ret=%d elapsed_ms=%u\n",
+               conversation_round, sessionId, packet->sequenceNumber, packet->packetType,
+               (unsigned int)packet->dataSize, send_ret,
+               (unsigned int)(hal_os_up_time_ms() - queue_started));
+    }
     free(sendBuffer);
     return send_ret;
  //   rt_kprintf("sendRecordingAudioPacket - Device ID: %s, Session ID: %s\n", deviceId, sessionId);
@@ -1493,6 +1570,7 @@ static void conversation_check_timeout(void)
         (conversation_wait == WAIT_NO_SPEECH ||
          conversation_wait == WAIT_SEND_FAILURE ||
          hal_os_up_time_ms() - reply_wait_start_ms > 5000)) {
+        voice_diag_snapshot("timeout-before-disconnect");
         expired = conversation_wait;
         expired_round = wait_round;
         conversation_wait = WAIT_NONE;

tools/test_conversation_timeout.py

@@ -38,6 +38,7 @@ static int queued, disconnected, flags_reset, mutex_locked, player_mq_couter, va
 static uint64_t now;
 static unsigned int gSequenceNumber;
 static int end_result;
+static char sessionId[33] = "test-session";
 typedef struct { unsigned int sequenceNumber; int packetType, dataSize; } AudioPacket;
 static int ql_rtos_mutex_lock(ql_mutex_t m, unsigned int t) {
     (void)m; (void)t; assert(!mutex_locked); mutex_locked = 1; return 0;
@@ -66,7 +67,7 @@ static void talkingq_ws_disconnect(void) {
 static int sendRecordingAudioPacket(AudioPacket *p) { assert(p->packetType == 2); return end_result; }
 '''
 harness += source[state_start:state_end]
-for name in ['conversation_try_begin', 'sendEndPacket', 'conversation_check_timeout', 'conversation_accept_voice_message', 'conversation_finish_startup_prompt', 'conversation_find_session_id', 'role_notice_is_url', 'role_notice_start_locked', 'role_notice_poll_locked', 'app_role_notice_handle_url', 'app_role_notice_before_finish', 'role_notice_finished']:
+for name in ['voice_diag_snapshot', 'conversation_try_begin', 'sendEndPacket', 'conversation_check_timeout', 'conversation_accept_voice_message', 'conversation_finish_startup_prompt', 'conversation_find_session_id', 'role_notice_is_url', 'role_notice_start_locked', 'role_notice_poll_locked', 'app_role_notice_handle_url', 'app_role_notice_before_finish', 'role_notice_finished']:
     harness += function(name)
 harness += r'''
 static void reset(void) {

tools/test_voice_diag.py

@@ -0,0 +1,112 @@
+"""Compile actual microphone, queue and receive diagnostics with scripted inputs."""
+from pathlib import Path
+import subprocess
+import tempfile
+
+root = Path(__file__).resolve().parents[1]
+app = root / 'ql-application/threadx/interface/custom_app'
+voice = (app / 'ws_talkingq.c').read_text()
+mic = (app / 'vad_det.c').read_text()
+
+def function(source, signature):
+    start = source.index(signature)
+    opening = source.index('{', start)
+    depth, end = 1, opening + 1
+    while depth:
+        depth += (source[end] == '{') - (source[end] == '}')
+        end += 1
+    return source[start:end] + '\n'
+
+harness = r'''
+#include <assert.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#define VAD_FRAME_BYTES 640
+#define DEVICE_ID_SIZE 32
+#define SESSION_ID_SIZE 33
+#define RLOGE(...) ((void)0)
+typedef int rws_socket;
+static int g_mic_working;
+static int g_state, ring_result = 640, fail_alloc, queue_result, dispatched;
+static unsigned int conversation_round = 7;
+static int active_session_valid = 1;
+static char sessionId[33] = "session", deviceId[32] = "device";
+static void *ring_sender;
+static uint64_t now = 1000;
+static int mutex_locked;
+static uint64_t hal_os_up_time_ms(void) { return now; }
+static void conversation_lock(void) { assert(!mutex_locked); mutex_locked = 1; }
+static void conversation_unlock(void) { assert(mutex_locked); mutex_locked = 0; }
+static int hal_os_rb_write(void *ring, const void *data, int len, unsigned int timeout) {
+    (void)ring; (void)data; (void)len; assert(timeout == 25); return ring_result;
+}
+static void *test_malloc(size_t size) { return fail_alloc ? NULL : malloc(size); }
+static int talkingq_ws_send_bin(uint8_t *data, int len) {
+    uint32_t seq;
+    assert(len >= DEVICE_ID_SIZE + SESSION_ID_SIZE + 12);
+    memcpy(&seq, data + DEVICE_ID_SIZE + SESSION_ID_SIZE, 4);
+    assert(seq == 9);
+    return queue_result;
+}
+typedef struct { uint32_t sequenceNumber, packetType, dataSize; uint8_t *data; } AudioPacket;
+static int conversation_accept_voice_message(const char *text) { return strstr(text, "old") == NULL; }
+static void conversation_log_error_message(const char *text, unsigned int len) { (void)text; (void)len; }
+static void onmessage_text_locked(rws_socket socket, const char *text, unsigned int len) {
+    (void)socket; (void)text; (void)len; assert(mutex_locked); dispatched++;
+}
+'''
+start = voice.index('static struct {')
+end = voice.index('} voice_diag;', start) + len('} voice_diag;')
+harness += voice[start:end] + '\n'
+start = mic.index('static struct {')
+end = mic.index('extern int audio_packet_type;', start)
+harness += mic[start:end]
+harness += '#define malloc test_malloc\n'
+harness += function(voice, 'int sendRecordingAudioPacket(AudioPacket *packet) {')
+harness += '#undef malloc\n'
+harness += function(voice, 'static void onmessage_text(rws_socket socket,')
+harness += function(voice, 'static void onmessage_bin(rws_socket socket,')
+harness += r'''
+int main(void) {
+    uint8_t pcm[640] = {0};
+    AudioPacket packet = {9, 0, 4, pcm};
+    mic_diag.started_ms = now;
+    mic_diag_read(pcm, 640, 0);
+    assert(mic_diag.reads == 1 && mic_diag.zero_frames == 1 && mic_diag.peak == 0);
+    /* Full-scale negative input must avoid int16 absolute-value overflow. */
+    pcm[0] = 0; pcm[1] = 128;
+    mic_diag_read(pcm, 640, 0);
+    assert(mic_diag.peak == 32768 && mic_diag.abs_sum == 32768 && mic_diag.samples == 640);
+    mic_diag_read(pcm, 0, -1);
+    assert(mic_diag.short_reads == 1 && mic_diag.read_errors == 1 && mic_diag.zero_frames == 1);
+    mic_diag_read(pcm, 10000, 0); /* Diagnostic sampling stays inside the buffer. */
+    assert(mic_diag.samples == 960 && mic_diag.short_reads == 2);
+    ring_result = 640; assert(mic_diag_write(pcm, 640) == 640 && !mic_diag.ring_drops);
+    ring_result = -1; assert(mic_diag_write(pcm, 640) == -1);
+    ring_result = 320; assert(mic_diag_write(pcm, 640) == 320);
+    assert(mic_diag.ring_drops == 2 && mic_diag.ring_drop_bytes == 960);
+    mic_diag_log("test");
+    queue_result = 0; assert(sendRecordingAudioPacket(&packet) == 0);
+    assert(voice_diag.tx_packets == 1 && voice_diag.tx_bytes == 4 && !voice_diag.tx_failed);
+    queue_result = -1; assert(sendRecordingAudioPacket(&packet) == -1);
+    fail_alloc = 1; assert(sendRecordingAudioPacket(&packet) == -1);
+    assert(voice_diag.tx_packets == 1 && voice_diag.tx_bytes == 4 && voice_diag.tx_failed == 2);
+    onmessage_text(0, "START_ACK", 9);
+    onmessage_text(0, "END_ACK", 7);
+    onmessage_text(0, "unknown backend response", 24);
+    onmessage_text(0, "old TTS_START", 13);
+    assert(voice_diag.start_ack == 1 && voice_diag.end_ack == 1 && voice_diag.rx_text == 4);
+    assert(dispatched == 3 && !mutex_locked);
+    now = 2000; onmessage_bin(0, pcm, 640);
+    assert(voice_diag.rx_bin == 1 && voice_diag.last_rx_ms == now && !mutex_locked);
+    puts("PASS: microphone silence/level/short reads/errors, PCM drops, queue failure/allocation failure, ACK visibility, unknown/rejected replies, ignored binary replies");
+}
+'''
+with tempfile.TemporaryDirectory(prefix='banban-voice-diag-') as directory:
+    cfile = Path(directory) / 'diag.c'
+    exe = Path(directory) / 'diag-test'
+    cfile.write_text(harness)
+    subprocess.run(['cc', '-std=c99', '-Wall', '-Wextra', '-Werror', '-fsanitize=address,undefined', str(cfile), '-o', str(exe)], check=True)
+    subprocess.run([str(exe)], check=True)

tools/test_wss_io.py

@@ -1,6 +1,7 @@
 """Compile actual SDK-independent function bodies with scripted TLS/RTOS stubs."""
 from pathlib import Path
 import subprocess
+import os
 
 root = Path(__file__).resolve().parents[1]
 lib = root / 'ql-application/threadx/interface/custom_app/lib/librws/src'
@@ -75,6 +76,9 @@ output.mkdir(parents=True, exist_ok=True)
 cfile = output / 'test_wss_io.c'
 cfile.write_text(harness, encoding='utf-8')
 exe = output / 'test_wss_io.exe'
-subprocess.run(['cl', '/nologo', '/W4', '/WX', '/TC', str(cfile),
-                '/Fo' + str(output / 'test_wss_io.obj'), '/Fe' + str(exe)], check=True)
+if os.name == "nt":
+    subprocess.run(['cl', '/nologo', '/W4', '/WX', '/TC', str(cfile),
+                    '/Fo' + str(output / 'test_wss_io.obj'), '/Fe' + str(exe)], check=True)
+else:
+    subprocess.run(['cc', '-std=c99', '-Wall', '-Wextra', '-Werror', str(cfile), '-o', str(exe)], check=True)
 subprocess.run([str(exe)], check=True)

tools/test_wss_receive.py

@@ -1,6 +1,7 @@
 """Exercise the real receive/upgrade loop with delayed TLS records."""
 from pathlib import Path
 import subprocess
+import os
 
 root = Path(__file__).resolve().parents[1]
 lib = root / 'ql-application/threadx/interface/custom_app/lib/librws'
@@ -37,6 +38,7 @@ typedef struct {
     char *payload_buff, *received;
     size_t received_size, received_len;
     int socket, command, is_connected;
+    unsigned int diag_rx_calls, diag_rx_bytes;
     const char *error;
 } _rws_socket;
 static int replies[16], reply_count, calls, closes;
@@ -120,7 +122,10 @@ output.mkdir(parents=True, exist_ok=True)
 cfile = output / 'test_wss_receive.c'
 cfile.write_text(harness, encoding='utf-8')
 exe = output / 'test_wss_receive.exe'
-subprocess.run(['cl', '/nologo', '/W4', '/WX', '/wd4018', '/TC',
-                '/I' + str(lib / 'inc'), str(cfile), str(lib / 'src/rws_handshake.c'),
-                '/Fo' + str(output) + '/', '/Fe' + str(exe)], check=True)
+if os.name == "nt":
+    subprocess.run(['cl', '/nologo', '/W4', '/WX', '/wd4018', '/TC',
+                    '/I' + str(lib / 'inc'), str(cfile), str(lib / 'src/rws_handshake.c'),
+                    '/Fo' + str(output) + '/', '/Fe' + str(exe)], check=True)
+else:
+    subprocess.run(['cc', '-std=c99', '-Wall', '-Wextra', '-Werror', '-Wno-sign-compare', '-I' + str(lib / 'inc'), str(cfile), str(lib / 'src/rws_handshake.c'), '-o', str(exe)], check=True)
 subprocess.run([str(exe)], check=True)