diff --git a/docs/voice_diagnostics.md b/docs/voice_diagnostics.md new file mode 100644 index 0000000..d7ebf8a --- /dev/null +++ b/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`。诊断测试直接编译实际函数并注入录音、缓冲区、队列及收包结果；不替代目标固件构建及设备实测。 diff --git a/ql-application/threadx/interface/custom_app/lib/librws/inc/rws_socket.h b/ql-application/threadx/interface/custom_app/lib/librws/inc/rws_socket.h index ca51d6e..a5448b0 100644 --- a/ql-application/threadx/interface/custom_app/lib/librws/inc/rws_socket.h +++ b/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 diff --git a/ql-application/threadx/interface/custom_app/lib/librws/src/rws_socketpriv.c b/ql-application/threadx/interface/custom_app/lib/librws/src/rws_socketpriv.c index d8bb566..9010aa0 100644 --- a/ql-application/threadx/interface/custom_app/lib/librws/src/rws_socketpriv.c +++ b/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; } diff --git a/ql-application/threadx/interface/custom_app/vad_det.c b/ql-application/threadx/interface/custom_app/vad_det.c index 973df56..764d61c 100644 --- a/ql-application/threadx/interface/custom_app/vad_det.c +++ b/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; } } diff --git a/ql-application/threadx/interface/custom_app/ws_talkingq.c b/ql-application/threadx/interface/custom_app/ws_talkingq.c index 7b13919..a318308 100644 --- a/ql-application/threadx/interface/custom_app/ws_talkingq.c +++ b/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; diff --git a/tools/test_conversation_timeout.py b/tools/test_conversation_timeout.py index 7aeb794..b1e75f2 100644 --- a/tools/test_conversation_timeout.py +++ b/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) { diff --git a/tools/test_voice_diag.py b/tools/test_voice_diag.py new file mode 100644 index 0000000..2eeb594 --- /dev/null +++ b/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 +#include +#include +#include +#include +#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) diff --git a/tools/test_wss_io.py b/tools/test_wss_io.py index 1d2f3a1..785bb4c 100644 --- a/tools/test_wss_io.py +++ b/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) diff --git a/tools/test_wss_receive.py b/tools/test_wss_receive.py index 190cbe2..cf0aa9f 100644 --- a/tools/test_wss_receive.py +++ b/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)