chenjintao/banban
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

feat: add device diagnostics for missing voice replies

Browse Source 
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.
This commit is contained in:
chenjintao
2026-10-26 18:35:24 +08:00
parent 280b7a4149
commit db6109172c
9 changed files with 350 additions and 20 deletions
Download Patch File Download Diff File Expand all files Collapse all files
ql-application/threadx/interface/custom_app/lib/librws/inc/rws_socket.h
+3
View File
@@ -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
+34 -6
View File
@@ -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
+75 -5
View File
@@ -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
+81 -3
View File
@@ -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;