Compare commits

...
Author SHA1 Message Date
chenjintao 407051d420 chore: silence GNSS application logs by default 2026-10-27 17:53:35 +08:00
chenjintao e57ddbe89c Merge remote-tracking branch 'origin/fix/time-calibrate' into test/server-err 2026-10-27 17:50:00 +08:00
chenjintao db6109172c 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.
2026-10-26 18:35:24 +08:00
13 changed files with 503 additions and 50 deletions
+35
View File
@@ -0,0 +1,35 @@
# 对话无回复诊断日志
设备端新增四类日志,按 `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`。诊断测试直接编译实际函数并注入录音、缓冲区、队列及收包结果;不替代目标固件构建及设备实测。
## GNSS 日志开关
`inc/app_gnss_log.h` 中的 `APP_GNSS_LOG_ENABLED` 默认是 `0`,关闭应用侧全部 GNSS/NMEA 原始输出、解析失败、模式切换、卫星搜索、坐标打印和 GPS 查询提示。需要恢复时可在编译参数中设置 `-DAPP_GNSS_LOG_ENABLED=1`。语音与 NITZ 时间校准诊断继续输出。
GNSS 数据解析、定位上报和硬件开关流程继续运行。原先放在打印参数内的四处 `ql_gnss_close()` 已分离为独立操作,避免禁用日志时跳过关闭定位。`python3 tools/test_gnss_logging.py` 在日志开启和关闭两种配置下验证真实解析代码、无卫星退出、卫星不足退出、搜索超时退出及 FAST 切换 SLOW 的关闭路径。
@@ -15,6 +15,7 @@
#include "sockets.h" #include "sockets.h"
#include "netdb.h" #include "netdb.h"
#include "app_inc.h" #include "app_inc.h"
#include "app_gnss_log.h"
// 新增宏定义(原代码中未定义) // 新增宏定义(原代码中未定义)
#define GNSS_FAST_MODE_HOLD_TIME (5 * 60 * 1000) // FAST模式持续5分钟后切SLOW #define GNSS_FAST_MODE_HOLD_TIME (5 * 60 * 1000) // FAST模式持续5分钟后切SLOW
@@ -211,10 +212,7 @@ void quec_gnss_callback(char *data, int len)
char nmea_buffer[512]; char nmea_buffer[512];
int fix_status = 0; int fix_status = 0;
// 打印原始 NMEA 数据 APP_GNSS_LOG("%.*s", len, data);
for (i = 0; i < len; i++) {
printf("%c", data[i]);
}
// 在 data 中定位 GGA 句子的起止位置 // 在 data 中定位 GGA 句子的起止位置
// GGA 格式: $xxGGA,...,*CS\r\n // GGA 格式: $xxGGA,...,*CS\r\n
@@ -267,7 +265,7 @@ void quec_gnss_callback(char *data, int len)
g_gps_location.is_valid = (fix_status >= 1) ? 1 : 0; g_gps_location.is_valid = (fix_status >= 1) ? 1 : 0;
} else { } else {
g_gps_location.is_valid = 0; g_gps_location.is_valid = 0;
printf("\n[GNSS Parse failed] FS=%d, %s\n", APP_GNSS_LOG("\n[GNSS Parse failed] FS=%d, %s\n",
fix_status, fix_status,
(fix_status == 0) ? "No Fix (Invalid)" : "Format error"); (fix_status == 0) ? "No Fix (Invalid)" : "Format error");
} }
@@ -321,7 +319,7 @@ void quec_gnss_callback(char *data, int len)
void set_gnss_mode(gnss_mode_t mode) void set_gnss_mode(gnss_mode_t mode)
{ {
g_gnss_mode = mode; g_gnss_mode = mode;
printf("[GNSSMode] Set to %s Mode\n", APP_GNSS_LOG("[GNSSMode] Set to %s Mode\n",
(mode == GNSS_MODE_FAST) ? "Fast (30s)" : "Slow (5min)"); (mode == GNSS_MODE_FAST) ? "Fast (30s)" : "Slow (5min)");
} }
@@ -353,11 +351,11 @@ gps_location_info_t* get_gps_location_info(void)
void print_gps_location_info(void) void print_gps_location_info(void)
{ {
if (g_gps_location.is_valid) { if (g_gps_location.is_valid) {
printf("[GPSinfo] Latitude: %.8f, Longitude: %.8f\n", APP_GNSS_LOG("[GPSinfo] Latitude: %.8f, Longitude: %.8f\n",
g_gps_location.latitude, g_gps_location.longitude); g_gps_location.latitude, g_gps_location.longitude);
printf("[GPSinfo] rawNMEA: %s\n", g_gps_location.raw_nmea); APP_GNSS_LOG("[GPSinfo] rawNMEA: %s\n", g_gps_location.raw_nmea);
} else { } else {
printf("[GPSinfo] No valid position data\n"); APP_GNSS_LOG("[GPSinfo] No valid position data\n");
} }
} }
@@ -395,26 +393,29 @@ static void quec_gnss_test(void * argv)
/* ========== FAST MODE ========== */ /* ========== FAST MODE ========== */
if (fast_mode_start_time == 0) { if (fast_mode_start_time == 0) {
fast_mode_start_time = hal_os_up_time_ms(); fast_mode_start_time = hal_os_up_time_ms();
printf("[GNSS] Enter FAST mode\n"); APP_GNSS_LOG("[GNSS] Enter FAST mode\n");
} }
if (!gnss_is_open) { if (!gnss_is_open) {
gnss_is_open = 1; gnss_is_open = 1;
app_set_app_operation(1); app_set_app_operation(1);
ql_gnss_open(quec_gnss_callback); ql_gnss_open(quec_gnss_callback);
printf("[GNSS] FAST: GPS OPEN\n"); APP_GNSS_LOG("[GNSS] FAST: GPS OPEN\n");
} }
// 5分钟超时切SLOW // 5分钟超时切SLOW
if (hal_os_up_time_ms() - fast_mode_start_time >= GNSS_FAST_MODE_HOLD_TIME) { if (hal_os_up_time_ms() - fast_mode_start_time >= GNSS_FAST_MODE_HOLD_TIME) {
printf("[GNSS] FAST 5min timeout -> SLOW\n"); APP_GNSS_LOG("[GNSS] FAST 5min timeout -> SLOW\n");
g_gnss_mode = GNSS_MODE_SLOW; g_gnss_mode = GNSS_MODE_SLOW;
fast_mode_start_time = 0; fast_mode_start_time = 0;
slow_mode_start_time = 0; slow_mode_start_time = 0;
slow_next_wake_time = 0; slow_next_wake_time = 0;
gnss_is_open = 0; gnss_is_open = 0;
printf("[GNSS] SLOW: GPS CLOSED ret:%d\n", ql_gnss_close());
int close_ret = ql_gnss_close();
(void)close_ret;
APP_GNSS_LOG("[GNSS] SLOW: GPS CLOSED ret:%d\n", close_ret);
} }
} }
else else
@@ -426,12 +427,12 @@ static void quec_gnss_test(void * argv)
if (slow_mode_start_time == 0) { if (slow_mode_start_time == 0) {
slow_mode_start_time = now; slow_mode_start_time = now;
slow_next_wake_time = now; // 立即尝试第一次定位 slow_next_wake_time = now; // 立即尝试第一次定位
printf("[GNSS] Enter SLOW mode (fixed 15min interval)\n"); APP_GNSS_LOG("[GNSS] Enter SLOW mode (fixed 15min interval)\n");
} }
// 检查是否到达唤醒时间 // 检查是否到达唤醒时间
if (now < slow_next_wake_time) { if (now < slow_next_wake_time) {
printf("[GNSS] SLOW: next wake in %d s\n", APP_GNSS_LOG("[GNSS] SLOW: next wake in %d s\n",
(slow_next_wake_time - now) / 1000); (slow_next_wake_time - now) / 1000);
} }
else if (!gnss_is_open) { else if (!gnss_is_open) {
@@ -444,7 +445,7 @@ static void quec_gnss_test(void * argv)
app_set_app_operation(1); app_set_app_operation(1);
ql_gnss_open(quec_gnss_callback); ql_gnss_open(quec_gnss_callback);
printf("[GNSS] SLOW: GPS OPEN, search start\n"); APP_GNSS_LOG("[GNSS] SLOW: GPS OPEN, search start\n");
/* ---- 第一阶段:60秒卫星检测 ---- */ /* ---- 第一阶段:60秒卫星检测 ---- */
int sat_found = 0; int sat_found = 0;
@@ -454,7 +455,7 @@ static void quec_gnss_test(void * argv)
elapsed++; elapsed++;
if (g_gnss_sat_count > 1) { if (g_gnss_sat_count > 1) {
sat_found = 1; sat_found = 1;
printf("[GNSS] SLOW: Sat found! count=%d, after %ds\n", APP_GNSS_LOG("[GNSS] SLOW: Sat found! count=%d, after %ds\n",
g_gnss_sat_count, elapsed); g_gnss_sat_count, elapsed);
break; break;
} }
@@ -462,10 +463,13 @@ static void quec_gnss_test(void * argv)
if (!sat_found) { if (!sat_found) {
// 60秒无卫星 → 立即关闭,等待15分钟 // 60秒无卫星 → 立即关闭,等待15分钟
printf("[GNSS] SLOW: No satellite in 30s, stop ret:%d.\n", ql_gnss_close());
int close_ret = ql_gnss_close();
(void)close_ret;
APP_GNSS_LOG("[GNSS] SLOW: No satellite in 30s, stop ret:%d.\n", close_ret);
gnss_is_open = 0; gnss_is_open = 0;
slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000); slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000);
printf("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); APP_GNSS_LOG("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL);
continue; continue;
} }
@@ -478,17 +482,20 @@ static void quec_gnss_test(void * argv)
// 1.5分钟时刻检查卫星数 // 1.5分钟时刻检查卫星数
int sat_count_now = g_gnss_sat_count; int sat_count_now = g_gnss_sat_count;
printf("[GNSS] SLOW: 1min check, satellite count = %d\n", sat_count_now); APP_GNSS_LOG("[GNSS] SLOW: 1min check, satellite count = %d\n", sat_count_now);
if (sat_count_now < GNSS_SAT_MIN_COUNT) { if (sat_count_now < GNSS_SAT_MIN_COUNT) {
printf("[GNSS] SLOW: Sat count < %d, stop search ret:%d.\n", GNSS_SAT_MIN_COUNT,ql_gnss_close());
int close_ret = ql_gnss_close();
(void)close_ret;
APP_GNSS_LOG("[GNSS] SLOW: Sat count < %d, stop search ret:%d.\n", GNSS_SAT_MIN_COUNT, close_ret);
gnss_is_open = 0; gnss_is_open = 0;
slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000); slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000);
printf("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); APP_GNSS_LOG("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL);
continue; continue;
} }
/* ---- 第三阶段:卫星足够,继续定位,但总时间不超过3分钟 ---- */ /* ---- 第三阶段:卫星足够,继续定位,但总时间不超过3分钟 ---- */
printf("[GNSS] SLOW: Sat count OK, continue for fix (max %ds total)\n", APP_GNSS_LOG("[GNSS] SLOW: Sat count OK, continue for fix (max %ds total)\n",
GNSS_MAX_SEARCH_TIME); GNSS_MAX_SEARCH_TIME);
// 继续等待直到总时间达到 GNSS_MAX_SEARCH_TIME (180秒) // 继续等待直到总时间达到 GNSS_MAX_SEARCH_TIME (180秒)
@@ -498,28 +505,30 @@ static void quec_gnss_test(void * argv)
// 如果获得有效定位,打印提示(但继续等待至3分钟) // 如果获得有效定位,打印提示(但继续等待至3分钟)
if (g_gps_location.is_valid) { if (g_gps_location.is_valid) {
printf("[GNSS] SLOW: Fix obtained at %ds!\n", elapsed); APP_GNSS_LOG("[GNSS] SLOW: Fix obtained at %ds!\n", elapsed);
print_gps_location_info(); print_gps_location_info();
// 若希望在定位成功后立即关闭,可在此 break,但此处按“最长3分钟”处理 // 若希望在定位成功后立即关闭,可在此 break,但此处按“最长3分钟”处理
} }
} }
// 3分钟时间到,关闭GPS // 3分钟时间到,关闭GPS
printf("[GNSS] SLOW: Max search time reached, stop.\n"); APP_GNSS_LOG("[GNSS] SLOW: Max search time reached, stop.\n");
if (g_gps_location.is_valid) { if (g_gps_location.is_valid) {
printf("[GNSS] SLOW: Final valid position:\n"); APP_GNSS_LOG("[GNSS] SLOW: Final valid position:\n");
print_gps_location_info(); print_gps_location_info();
} else { } else {
printf("[GNSS] SLOW: No valid fix within 3min.\n"); APP_GNSS_LOG("[GNSS] SLOW: No valid fix within 3min.\n");
} }
printf("[GNSS] SLOW: GPS CLOSED ret:%d",ql_gnss_close()); int close_ret = ql_gnss_close();
(void)close_ret;
APP_GNSS_LOG("[GNSS] SLOW: GPS CLOSED ret:%d", close_ret);
gnss_is_open = 0; gnss_is_open = 0;
g_gps_location.is_valid = 0; // 重置状态 g_gps_location.is_valid = 0; // 重置状态
// 设置下次唤醒时间为 15分钟 后 // 设置下次唤醒时间为 15分钟 后
slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000); slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000);
printf("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); APP_GNSS_LOG("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL);
} }
// else: GPS正在运行中(理论上不会到这里) // else: GPS正在运行中(理论上不会到这里)
} }
@@ -0,0 +1,18 @@
#ifndef APP_GNSS_LOG_H
#define APP_GNSS_LOG_H
/* GNSS diagnostics are quiet by default while investigating voice replies.
* Define APP_GNSS_LOG_ENABLED=1 at build time to restore application logs.
* Keep state changes and hardware operations outside log arguments. */
#ifndef APP_GNSS_LOG_ENABLED
#define APP_GNSS_LOG_ENABLED 0
#endif
#if APP_GNSS_LOG_ENABLED
#include <stdio.h>
#define APP_GNSS_LOG(...) printf(__VA_ARGS__)
#else
#define APP_GNSS_LOG(...) ((void)0)
#endif
#endif
@@ -96,6 +96,9 @@ typedef struct _rws_socket_struct
int command; int command;
unsigned int next_message_id; 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 rws_bool is_connected; // sock connected + handshake done
@@ -193,17 +193,30 @@ static int rws_tls_send_all(_rws_socket *s, const unsigned char *data, size_t si
{ {
size_t sent = 0; size_t sent = 0;
unsigned int started = ql_rtos_get_systicks(); 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) { while (sent < size) {
int ret = mbedtls_ssl_write(&s->ssl->ssl_ctx, data + sent, size - sent); int ret = mbedtls_ssl_write(&s->ssl->ssl_ctx, data + sent, size - sent);
if (ret > 0) { if (ret > 0) {
sent += (size_t)ret; sent += (size_t)ret;
} else if (ret != MBEDTLS_ERR_SSL_WANT_READ && ret != MBEDTLS_ERR_SSL_WANT_WRITE) { } 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; return -1;
} else { } else {
retries++;
rws_thread_sleep(5); 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; 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 #ifdef LIBRWS_USING_MBED_TLS
if (s->scheme && strcmp(s->scheme, "wss") == 0) 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); sended = rws_tls_send_all(s, (const unsigned char *)data, data_size);
} }
else else
@@ -243,6 +255,14 @@ rws_bool rws_socket_send(_rws_socket *s, const void *data, const size_t data_siz
} }
#endif #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) if (sended == (int)data_size)
{ {
rws_socket_error_cnt = 0; rws_socket_error_cnt = 0;
@@ -283,7 +303,6 @@ rws_bool rws_socket_recv(_rws_socket *s)
rws_bool result = rws_true; rws_bool result = rws_true;
int is_reading = 1, error_number = -1, len = -1; int is_reading = 1, error_number = -1, len = -1;
char *received = NULL; char *received = NULL;
size_t total_len = 0;
// char *buff = 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__); // 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) 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 && if (s->command == COMMAND_WAIT_HANDSHAKE_RESPONCE &&
s->received_len + (size_t)len > RWS_HANDSHAKE_MAX + RWS_RECEIVE_BUFF_SIZE) { 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"); 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) void rws_socket_close(_rws_socket *s)
{ {
s->received_len = 0;
if (s->socket != RWS_INVALID_SOCKET) 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 #ifdef LIBRWS_USING_MBED_TLS
if (s->scheme && strcmp(s->scheme, "wss") == 0) if (s->scheme && strcmp(s->scheme, "wss") == 0)
{ {
@@ -1669,6 +1696,7 @@ void rws_socket_close(_rws_socket *s)
WSACleanup(); WSACleanup();
#endif #endif
} }
s->received_len = 0;
s->is_connected = rws_false; s->is_connected = rws_false;
} }
@@ -9,6 +9,7 @@
#include "ql_application.h" #include "ql_application.h"
#include "sockets.h" #include "sockets.h"
#include "app_inc.h" #include "app_inc.h"
#include "app_gnss_log.h"
#include "cjson.h" #include "cjson.h"
#include "ql_fs.h" #include "ql_fs.h"
#include "ql_fota.h" #include "ql_fota.h"
@@ -442,7 +443,7 @@ int parse_command(const char *json_str, command_t *cmd)
if (params != NULL) { if (params != NULL) {
switch (cmd->type) { switch (cmd->type) {
case MSG_GPS_QUERY: case MSG_GPS_QUERY:
printf("MSG_GPS_QUERY\r\n"); APP_GNSS_LOG("MSG_GPS_QUERY\r\n");
/*返回当前的GPS坐标信息*/ /*返回当前的GPS坐标信息*/
break; break;
@@ -71,6 +71,55 @@ static int vad_tts_playback_finished_status = 0;
// 统计 // 统计
static uint32 frame_count = 0; static uint32 frame_count = 0;
static uint32 speech_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; 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) 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() void vad_tts_playback_finished()
@@ -206,7 +265,13 @@ int vad_audio_init(void) {
// 启动录音 // 启动录音
int vad_audio_start(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; frame_count = 0;
speech_frame_count = 0; speech_frame_count = 0;
@@ -217,6 +282,7 @@ int vad_audio_start(void) {
// 停止录音 // 停止录音
int vad_audio_stop(void) { int vad_audio_stop(void) {
mic_diag_log("stop");
printf("Audio recording stopped, frames: %d, speech: %d", printf("Audio recording stopped, frames: %d, speech: %d",
frame_count, speech_frame_count); frame_count, speech_frame_count);
@@ -235,6 +301,7 @@ int vad_audio_stop(void) {
// 停止录音 // 停止录音
int vad_audio_stop_no_wait_resp(void) { int vad_audio_stop_no_wait_resp(void) {
mic_diag_log("cancel");
conversation_cancel_wait(); conversation_cancel_wait();
printf("Audio recording stopped no_wait_resp, frames: %d, speech: %d", printf("Audio recording stopped no_wait_resp, frames: %d, speech: %d",
@@ -381,7 +448,10 @@ void vad_audio_process(void) {
case STATE_RECORDING_ACTIVE: case STATE_RECORDING_ACTIVE:
memset(mic_buf, 0, sizeof(mic_buf)); memset(mic_buf, 0, sizeof(mic_buf));
//每次读取640字节音频数据 //每次读取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) { if (g_state == STATE_RECORDING_WAIT_SOUND) {
/* 首次开口确认前不向服务端发送静音。只在本地保留最近500ms, /* 首次开口确认前不向服务端发送静音。只在本地保留最近500ms,
@@ -392,7 +462,7 @@ void vad_audio_process(void) {
vad_preroll_count++; vad_preroll_count++;
} }
} else { } 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); ql_rtos_semaphore_release(sender_sem);
} }
} }
@@ -437,7 +507,7 @@ void vad_audio_process(void) {
int preroll_queued = 0; int preroll_queued = 0;
for (n = 0; n < vad_preroll_count; n++) { for (n = 0; n < vad_preroll_count; n++) {
size_t frame_index = (first + n) % VAD_PREROLL_FRAMES; 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; preroll_queued = 1;
} }
} }
@@ -62,6 +62,12 @@ enum { WAIT_NONE, WAIT_NO_SPEECH, WAIT_REPLY, WAIT_SEND_FAILURE };
static int conversation_wait = WAIT_NONE; static int conversation_wait = WAIT_NONE;
static int timeout_action_busy = 0; static int timeout_action_busy = 0;
static int round_response_received = 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 unsigned int active_session_round = 0;
static int active_session_valid = 0; static int active_session_valid = 0;
static uint64_t startup_start_ms = 0; static uint64_t startup_start_ms = 0;
@@ -87,6 +93,10 @@ static void conversation_unlock(void)
static void conversation_begin_round(void) static void conversation_begin_round(void)
{ {
conversation_round++; 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; conversation_wait = WAIT_NONE;
round_response_received = 0; round_response_received = 0;
active_session_valid = 0; active_session_valid = 0;
@@ -217,6 +227,20 @@ unsigned char get_xiaoice_connected_status(void)
return xiaoice_wss_connect_status; 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) static void onopen(rws_socket socket)
{ {
if (socket != app->socket || !app->init) return; if (socket != app->socket || !app->init) return;
@@ -245,6 +269,9 @@ static void onclose(rws_socket socket)
} }
if (socket != app->socket) return; if (socket != app->socket) return;
conversation_lock();
voice_diag_snapshot("disconnected");
conversation_unlock();
xiaoice_wss_connect_status = 0; xiaoice_wss_connect_status = 0;
app->socket = NULL; app->socket = NULL;
/* The worker owns and releases this socket after the callback. */ /* 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) static void onmessage_text(rws_socket socket, const char *text, const unsigned int len)
{ {
conversation_lock(); 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 || if (strstr(text, "tts_error") != NULL || strstr(text, "tts_err") != NULL ||
strstr(text, "PROMPT_SOUND_URL") != NULL) { strstr(text, "PROMPT_SOUND_URL") != NULL) {
conversation_log_error_message(text, len); 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) 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; 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)); 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; return 0;
} }
@@ -1041,6 +1090,7 @@ void sendStartPacket(void) {
startPacket.dataSize = 0; startPacket.dataSize = 0;
active_session_valid = sendRecordingAudioPacket(&startPacket) == 0; active_session_valid = sendRecordingAudioPacket(&startPacket) == 0;
voice_diag_snapshot("start-queued");
conversation_unlock(); conversation_unlock();
// rt_kprintf("sendStartPacket, seq=%u\r\n", startPacket.sequenceNumber); // 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(); reply_wait_start_ms = hal_os_up_time_ms();
conversation_wait = end_ret == 0 ? WAIT_REPLY : WAIT_SEND_FAILURE; conversation_wait = end_ret == 0 ? WAIT_REPLY : WAIT_SEND_FAILURE;
} }
voice_diag_snapshot("end-queued");
} }
conversation_unlock(); conversation_unlock();
// rt_kprintf("sendEndPacket, seq=%u\r\n", endPacket.sequenceNumber); // 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); audioPacket.data = malloc(audioPacket.dataSize);
if(audioPacket.data==NULL){ if(audioPacket.data==NULL){
RLOGE("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; return;
} }
memcpy(audioPacket.data, data, dataSize); memcpy(audioPacket.data, data, dataSize);
} }
conversation_lock();
sendRecordingAudioPacket(&audioPacket); sendRecordingAudioPacket(&audioPacket);
conversation_unlock();
// rt_kprintf("sendAudioPacket, seq=%u\r\n", audioPacket.sequenceNumber); // rt_kprintf("sendAudioPacket, seq=%u\r\n", audioPacket.sequenceNumber);
if(audioPacket.data){ if(audioPacket.data){
free(audioPacket.data); free(audioPacket.data);
@@ -1092,7 +1150,9 @@ void sendInterruptPacket(void) {
interruptPacket.packetType = 3; interruptPacket.packetType = 3;
interruptPacket.dataSize = 0; interruptPacket.dataSize = 0;
conversation_lock();
sendRecordingAudioPacket(&interruptPacket); sendRecordingAudioPacket(&interruptPacket);
conversation_unlock();
} }
void sendAuthentication() 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); sendBuffer = malloc(DEVICE_ID_SIZE + SESSION_ID_SIZE + sizeof(uint32_t) * 2 + sizeof(uint32_t) + packet->dataSize);
if(sendBuffer==NULL){ if(sendBuffer==NULL){
RLOGE("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; return -1;
} }
@@ -1151,7 +1214,21 @@ int sendRecordingAudioPacket(AudioPacket *packet) {
// memcpy(recorder->save_buf, (void *)sendBuffer, recorder->save_len); // memcpy(recorder->save_buf, (void *)sendBuffer, recorder->save_len);
//record_msg_send(recorder, RECORD_MSG_DATA, 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); 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); free(sendBuffer);
return send_ret; return send_ret;
// rt_kprintf("sendRecordingAudioPacket - Device ID: %s, Session ID: %s\n", deviceId, sessionId); // 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_NO_SPEECH ||
conversation_wait == WAIT_SEND_FAILURE || conversation_wait == WAIT_SEND_FAILURE ||
hal_os_up_time_ms() - reply_wait_start_ms > 5000)) { hal_os_up_time_ms() - reply_wait_start_ms > 5000)) {
voice_diag_snapshot("timeout-before-disconnect");
expired = conversation_wait; expired = conversation_wait;
expired_round = wait_round; expired_round = wait_round;
conversation_wait = WAIT_NONE; conversation_wait = WAIT_NONE;
+2 -1
View File
@@ -38,6 +38,7 @@ static int queued, disconnected, flags_reset, mutex_locked, player_mq_couter, va
static uint64_t now; static uint64_t now;
static unsigned int gSequenceNumber; static unsigned int gSequenceNumber;
static int end_result; static int end_result;
static char sessionId[33] = "test-session";
typedef struct { unsigned int sequenceNumber; int packetType, dataSize; } AudioPacket; typedef struct { unsigned int sequenceNumber; int packetType, dataSize; } AudioPacket;
static int ql_rtos_mutex_lock(ql_mutex_t m, unsigned int t) { 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; (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; } static int sendRecordingAudioPacket(AudioPacket *p) { assert(p->packetType == 2); return end_result; }
''' '''
harness += source[state_start:state_end] 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 += function(name)
harness += r''' harness += r'''
static void reset(void) { static void reset(void) {
+89
View File
@@ -0,0 +1,89 @@
"""Run the actual GNSS parser and power-state paths with logging off and on."""
from pathlib import Path
import re
import subprocess
import tempfile
root = Path(__file__).resolve().parents[1]
app = root / 'ql-application/threadx/interface/custom_app'
source = (app / 'gnss.c').read_text()
source = re.sub(r'^#include "(?!app_gnss_log.h")[^"]+"\n', '', source, flags=re.M)
harness = r'''
#include <assert.h>
#include <math.h>
#include <setjmp.h>
#include <stdarg.h>
#include <stdint.h>
#include <stdio.h>
#include <string.h>
typedef unsigned int u32;
typedef unsigned char u8;
typedef void *ql_task_t;
typedef enum { GNSS_MODE_FAST, GNSS_MODE_SLOW } gnss_mode_t;
typedef struct { double latitude, longitude; int is_valid; char raw_nmea[512]; } gps_location_info_t;
enum { AGPS_GNSS_ENABLE, APFLASH_GNSS_ENABLE, PACKET_MODE };
static unsigned int now;
static int scenario, opened, closed, printed;
static jmp_buf stop;
static unsigned int hal_os_up_time_ms(void) { return now; }
static int test_printf(const char *format, ...) { (void)format; printed++; return 0; }
#define printf test_printf
static int ql_gnss_close(void) { closed++; return 0; }
static int ql_gnss_open(void (*cb)(char *, int)) { (void)cb; opened++; return 0; }
static void app_set_app_operation(int value) { assert(value == 1); }
static void ql_gnss_cfgsys_set(int value) { (void)value; }
static void ql_gnss_cfgmsg_set(int value) { (void)value; }
static void ql_gnss_agps_cfg(int value, int extra) { (void)value; (void)extra; }
static void ql_gnss_apflash_cfg(int value) { (void)value; }
static void ql_set_gnss_nmea_mode(int value) { (void)value; }
static void ql_rtos_task_sleep_s(int seconds);
static void ql_rtos_task_create(ql_task_t *task, int stack, int priority, char *name, void (*entry)(void *), void *arg) {
(void)task; (void)stack; (void)priority; (void)name; (void)entry; (void)arg;
}
'''
harness += source
harness += r'''
#undef printf
static void ql_rtos_task_sleep_s(int seconds) {
if (closed) longjmp(stop, 1);
now += (unsigned int)seconds * 1000;
if (scenario == 1) g_gnss_sat_count = 2;
if (scenario == 2) { g_gnss_sat_count = 4; g_gps_location.is_valid = 1; }
assert(now < 1000000);
}
int main(void) {
(void)test_printf;
char data[] = "$GPGGA,120000,2311.71298,N,11328.63118,E,1,08,0.9,10,M,0,M,0,0*00\r\n"
"$GPGSV,1,1,08,01,10,10,30*00\r\n";
quec_gnss_callback(data, (int)strlen(data));
assert(g_gps_location.is_valid && g_gnss_sat_count == 8);
assert(fabs(g_gps_location.latitude - 23.1952163333) < 0.000001);
assert(fabs(g_gps_location.longitude - 113.4771863333) < 0.000001);
assert(strncmp(g_gps_location.raw_nmea, "$GPGGA,", 7) == 0);
print_gps_location_info();
set_gnss_mode(GNSS_MODE_FAST);
assert(get_gnss_mode() == GNSS_MODE_FAST && get_gnss_interval() == 180);
for (scenario = 0; scenario < 4; scenario++) {
now = 1; opened = closed = 0; gnss_is_open = 0;
g_gnss_mode = scenario == 3 ? GNSS_MODE_FAST : GNSS_MODE_SLOW;
if (!setjmp(stop)) quec_gnss_test(NULL);
assert(opened == 1 && closed == 1 && get_gnss_open_status() == 0);
}
#if APP_GNSS_LOG_ENABLED
assert(printed > 0);
#else
assert(printed == 0);
#endif
puts("PASS: GNSS parsing and all four hardware-close paths preserved; expected log visibility");
}
'''
with tempfile.TemporaryDirectory(prefix='banban-gnss-log-') as directory:
cfile = Path(directory) / 'gnss-test.c'
cfile.write_text(harness)
for enabled in (0, 1):
exe = Path(directory) / f'gnss-test-{enabled}'
subprocess.run(['cc', '-std=c99', '-Wall', '-Wextra', '-Werror',
'-Wno-unused-parameter', '-Wno-unused-variable', '-Wno-sign-compare',
'-fsanitize=address,undefined', f'-DAPP_GNSS_LOG_ENABLED={enabled}',
'-I' + str(app / 'inc'), str(cfile), '-o', str(exe)], check=True)
subprocess.run([str(exe)], check=True)
+112
View File
@@ -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)
+6 -2
View File
@@ -1,6 +1,7 @@
"""Compile actual SDK-independent function bodies with scripted TLS/RTOS stubs.""" """Compile actual SDK-independent function bodies with scripted TLS/RTOS stubs."""
from pathlib import Path from pathlib import Path
import subprocess import subprocess
import os
root = Path(__file__).resolve().parents[1] root = Path(__file__).resolve().parents[1]
lib = root / 'ql-application/threadx/interface/custom_app/lib/librws/src' 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 = output / 'test_wss_io.c'
cfile.write_text(harness, encoding='utf-8') cfile.write_text(harness, encoding='utf-8')
exe = output / 'test_wss_io.exe' exe = output / 'test_wss_io.exe'
subprocess.run(['cl', '/nologo', '/W4', '/WX', '/TC', str(cfile), if os.name == "nt":
'/Fo' + str(output / 'test_wss_io.obj'), '/Fe' + str(exe)], check=True) 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) subprocess.run([str(exe)], check=True)
+8 -3
View File
@@ -1,6 +1,7 @@
"""Exercise the real receive/upgrade loop with delayed TLS records.""" """Exercise the real receive/upgrade loop with delayed TLS records."""
from pathlib import Path from pathlib import Path
import subprocess import subprocess
import os
root = Path(__file__).resolve().parents[1] root = Path(__file__).resolve().parents[1]
lib = root / 'ql-application/threadx/interface/custom_app/lib/librws' lib = root / 'ql-application/threadx/interface/custom_app/lib/librws'
@@ -37,6 +38,7 @@ typedef struct {
char *payload_buff, *received; char *payload_buff, *received;
size_t received_size, received_len; size_t received_size, received_len;
int socket, command, is_connected; int socket, command, is_connected;
unsigned int diag_rx_calls, diag_rx_bytes;
const char *error; const char *error;
} _rws_socket; } _rws_socket;
static int replies[16], reply_count, calls, closes; 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 = output / 'test_wss_receive.c'
cfile.write_text(harness, encoding='utf-8') cfile.write_text(harness, encoding='utf-8')
exe = output / 'test_wss_receive.exe' exe = output / 'test_wss_receive.exe'
subprocess.run(['cl', '/nologo', '/W4', '/WX', '/wd4018', '/TC', if os.name == "nt":
'/I' + str(lib / 'inc'), str(cfile), str(lib / 'src/rws_handshake.c'), subprocess.run(['cl', '/nologo', '/W4', '/WX', '/wd4018', '/TC',
'/Fo' + str(output) + '/', '/Fe' + str(exe)], check=True) '/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) subprocess.run([str(exe)], check=True)