diff --git a/docs/现场网络诊断.md b/docs/现场网络诊断.md index bcc0a2e..d984911 100644 --- a/docs/现场网络诊断.md +++ b/docs/现场网络诊断.md @@ -2,41 +2,88 @@ GPIO84 原报警/留言按键改为诊断键。释放时按住超过 50 ms、少于 3 秒，开启主动模式。超过或等于 3 秒不执行动作。重复短按只打印已开启，不创建重复任务；重启恢复关闭。该按键不再报警、留言、播放提示音或停止音频。 -设备处于定时休眠、OTA 或关机流程时不响应开启。开启之后遇到这些状态，暂停采样和新探测，已有探测可能继续到返回。没有新增常亮、常唤醒或自动重启操作；主动网络流量本身仍可能影响空闲态和耗电。 +设备处于定时休眠、OTA 或关机流程时不响应开启。开启之后遇到这些状态，暂停采样和新探测。TCP 等待期间每不超过 200 ms 检查一次取消；SDK 的域名解析是同步调用，必须等待返回才能取消，未修改全局 DNS 超时设置。原有休眠和定位流程保留。 -## 查看日志 +## Mac 直接读取 USB 日志 -使用原有固件日志串口，终端设置 UTF-8，保存完整串口输出。搜索 `[现场诊断]` 可筛出诊断行。时间为开机毫秒（目标平台计数会回绕），不是北京时间。日志不写 Flash、不上传服务器；断网时电脑仍可留存串口日志。 +刷入这版固件后，用支持数据传输的 USB 线连接设备与 Mac。固件通过 `QL_USB_CDC_PORT` 输出 UTF-8 纯文本，并保留 UART 输出。没有使用基带 DIAG 二进制日志端口。 -- 每约 2 秒：注册状态、PDP 数据连接、MQTT、WSS，及 LTE 信号原始字段。 -- 每约 10 秒：SINR 原始值、LTE 驻留小区 CID/PCI/EARFCN 和 MCC/MNC。标记小区变化。 -- 主动探测：依次 Ping `223.5.5.5` 和当前业务域名 `banban.api.talkingq.com`，每目标 1 个 32 字节载荷，ICMP 超时 2000 ms；整轮完成后等待 10 秒。域名解析和 SDK 调度可能增加耗时，非严格周期。 -- 即时事件：数据连接回调、当前 WSS 的建立/断开；注册/PDP 的采样变化、不可用和恢复。 -- 每次探测后：本次开机的已发送、收到、未回应、未回应率和执行异常数量。超时连续次数遇到收到回应时清零。未获得有效发包统计的 SDK 错误单独计数。 +在仓库根目录运行下面命令。读取工具只用 Python 3 标准库，不需要安装 pyserial。 -示例（演示数据，并非现场测量）： +```sh +python3 tools/read_usb_log.py --list +python3 tools/read_usb_log.py --port /dev/cu.usbmodemXXXX --reconnect +``` + +将 `cu.usbmodemXXXX` 换成拔插设备后新增的实际端口。多个串口时，工具要求明确选择，不会自行选择第一个。确认选对端口的方法是看到 `[USB日志]` 在线提示；普通 USB 转串口适配器也可能出现在列表中。 + +默认保存到当前目录的 `usb-logs/banban-年月日-时分秒.log`，同时在终端显示。短按原报警键开始网络诊断，随后进行对话，按 Ctrl+C 停止保存。`--reconnect` 等待同名端口重新出现，端口改名后需重新指定。可添加 `--output 路径` 更改文件位置，或 `--diag-only` 只保存 `[现场诊断]` 和 `[USB日志]` 行。 + +也可以使用现有串口终端打开这个 USB CDC 口：115200、8N1、无流控、UTF-8。同一端口同时只用一个读取程序。没有新增端口时，先检查数据线和 Mac 的 USB 设备枚举；实际板上的 USB 数据连接、CDC 描述符和 Mac 驱动识别仍需上板确认。 + +日志通过约 8 KB 的有界队列交给独立低优先级 USB 转发任务。业务日志入队使用零等待；USB 写失败时关闭并重新打开 CDC。队列拥塞或写失败会丢弃 USB 副本并累计计数，在线提示每约 5 秒报告一次。电脑接收时间不等于设备事件时间；断线前 SDK 已接受但未送到电脑的数据也无法保证补回，不支持历史日志回放。 + +转发范围是 `custom_app` 目标内编译的 `printf`，包括这次新增的诊断、VAD、WSS 和播放器日志。预编译库、内核、基带和启动前日志不经过本转发。单次格式化最多 511 字节，超长记录会明确加 `[TRUNCATED]`，并在 UTF-8 字符边界截断。日志不写设备 Flash、不上传服务器。 + +## 日志内容 + +设备时间为开机毫秒；目标平台计数会回绕。搜索 `[现场诊断]` 筛选诊断行，按 `[对话#编号]` 关联一轮对话。 + +- 每约 2 秒：注册状态、PDP 数据连接、MQTT、WSS，及 LTE 信号原始字段。SDK 查询可能增加采样间隔。 +- 每约 10 秒：可用的 SINR、LTE 驻留小区 CID/PCI/EARFCN、MCC/MNC 原始编码。标记小区变化。 +- 主动探测：依次测量参照 DNS 服务 `223.5.5.5:53` 和业务 WSS 入口 `banban.api.talkingq.com:443` 的 DNS 解析与 TCP 建连耗时。整轮完成后等待 10 秒；使用 PDP 1 的实际数据连接地址绑定。TCP 等待上限 3000 ms，不发送业务内容，也不进行 TLS/WSS 握手。 +- 即时事件：数据连接回调、当前 WSS 的建立/断开；注册/PDP 的采样变化、不可用和恢复。底层套接字写入失败或耗时达到 200 ms 时单独记录。 +- 每次探测后：本次开机的 TCP 有效尝试、成功、失败、失败率和执行异常数量。连续 TCP 失败遇到成功时清零。DNS、套接字初始化、绑定和本地等待错误单独计数，不混作 TCP 失败。 + +原现场日志中两个目标均在 `ql_ping_init()` 阶段返回空指针，没有形成有效探测。当前默认直接使用业务已有的 DNS/TCP 路径，移除对可选 Ping API 的依赖；没有把空指针的根因武断归为网络错误或已确认的内核缺失。 + +SINR 接口未导出或返回 255 时只记录一次不可用提示，本次开机跳过该项。CQI 不在 0～15 范围内时标为不可用并保留原始值。MCC/MNC 用十六进制明确表示原始编码，避免将编码值误当作普通十进制运营商号码。 + +示例为演示数据，并非上板测量： ```text [现场诊断][12000 ms][连接] 注册=已注册本地网络(1) 数据连接=已连接 MQTT=已连接 WSS=已连接 -[现场诊断][12000 ms][信号原始值] RSSI=-71 RSRP=-97 RSRQ=-12 CQI=8；单位/无效值以模组为准 -[现场诊断][12500 ms][探测成功] 参照节点 223.5.5.5；往返=123 ms -[现场诊断][12500 ms][累计统计] 参照节点；已发送=20 收到=19 未回应=1 未回应率=5% 执行异常=0（本次开机累计） +[现场诊断][12000 ms][信号原始值] RSSI=-55 RSRP=-80 RSRQ=-3 CQI=不可用(raw=255)；单位/无效值以模组为准 +[现场诊断][12500 ms][探测成功] 业务WSS入口；IP=192.0.2.1 解析=35 ms TCP建连=123 ms（非AI响应时间） +[现场诊断][12500 ms][累计统计] 业务WSS入口；TCP有效尝试=20 成功=19 失败=1 失败率=5% 执行异常=0；非业务丢包率 ``` -## 判断边界 +## 一轮对话的分段计时 -信号值以 SDK 返回的原始字段记录。必须结合模组实际单位、无效值和无线制式确认后解释，暂不直接分档。注册成功不代表有互联网；MQTT/WSS 状态是业务维护的状态，断网瞬间可能滞后。当前按 LTE 项目设计，其他制式不能直接使用 LTE 字段判读。 +诊断模式开启后的下一轮录音开始计时，依次记录：开始录音、确认用户语音、录音结束、结束包入发送队列、收到 END_ACK（服务器实际返回时）、收到 TTS_START、收到首段音频 URL、首段开始下载/下载完成、首 PCM 交给播放接口。 -参照节点属于外部公共服务，可能限速或禁 ICMP；业务域名对应入口也可能不回答 Ping。两者均不是 AI 服务健康检查。ICMP 未回应率不等于语音业务丢包率；域名探测结果中的 RTT 是 ICMP 往返时间，不包括 DNS 或 AI 处理时间。 +首段根据通过当前 session 校验的完整 URL 匹配，只跟踪第一段正常回复，排除不匹配的本地提示、留言确认和错误提示；后续录音轮次开始后不接受上一轮的延迟阶段事件。VAD 统计显示总帧、活跃录音帧，以及首次确认前连续语音峰值，例如 `13/20`，帮助判断为什么一直没有确认开口。没有根据一份日志直接降低 VAD 阈值。 -网络不可用计时依据注册状态和实际 PDP 查询；查询失败不虚构掉线/恢复。时间包含采样误差和暂停期间，不能当作精确无线断线时间。小区变化表示驻留记录改变，不等同于已确认发生连接态切换。 +阶段齐全且顺序合理时，在首 PCM 提交后输出汇总： -本次实现侧重网络现场日志，尚未新增每轮对话的 VAD/上传/服务端/首音分段计时，也未新增 DNS/TCP/TLS 独立探测。若网络记录正常但回复仍慢，需结合已有 WSS/TLS/音频日志和服务端记录继续定位。 +```text +[现场诊断][3350 ms][对话#3][耗时汇总] 录音结束到首PCM=2350 ms；收尾入队=100 等TTS通知=400 等首URL=1500 播放队列=100 下载=200 解码提交=50（均ms；含网络与服务端处理，尚未分离） +``` + +`录音结束` 是 VAD 停止录音的时间，不是人实际停止说话的时间。`结束包入队` 不表示底层发送完成或服务端收到；底层慢写事件可作辅助，END_ACK 也仅在后端返回该事件时存在。`首PCM提交` 不是扬声器的精确出声时刻。只有后端配合同一轮请求的收包/ASR/模型/TTS 时间，才能进一步分离服务端处理与网络等待。 + +## 如何判断 + +先看对话编号对应的慢阶段，再看同一时段的信号、DNS、TCP 和掉线事件。连续语音峰值未达到确认条件、最后以 no_speech 结束，应优先核对当时是否说话及采音/VAD。首 URL 出现得晚应结合服务器日志；URL 已到但下载/播放排队慢，则优先看对应下载和播放阶段。 + +TCP 建连成功只说明该次能连接目标端口，不代表 TLS、WSS 或 AI 业务正常；失败也可能是目标端口策略、服务状态等原因。参照端口和业务端口不相同，不能仅凭一次结果直接归责运营商。解析可能命中缓存，未清空业务 DNS 缓存，解析耗时不是强制冷查询耗时。TCP 失败率不等于业务丢包率。 + +信号按 SDK 原始字段记录，单位和无效值仍应以模组确认结果解释。注册成功不代表有互联网；MQTT/WSS 状态是业务维护的状态，可能滞后。网络不可用计时包含采样误差和暂停时间，查询失败不会虚构掉线/恢复。小区变化表示驻留记录改变，不等同于已确认发生连接态切换。 + +## GNSS 日志开关 + +`gnss.c` 中 `BANBAN_GNSS_LOG_ENABLED` 默认 0，临时屏蔽模式提示、倒计时、坐标、解析提示和原始 NMEA 输出。定位、卫星搜索、开关 GNSS 与位置上报流程保留。静默函数仍求值原日志参数，保留历史上写在参数中的 `ql_gnss_close()` 调用。需要恢复时设为 1 或为该目标添加同名编译宏。 ## 验证与上板 -运行 `python3 tools/test_net_diag.py`，以 SDK 头文件和模拟模组接口编译运行真实诊断源码，验证任务创建失败重试、重复开启、成功/无回应/执行异常统计、网络恢复计时和休眠暂停；并检查按键分支没有原报警/留言/音频操作。 +```sh +python3 tools/test_net_diag.py +python3 tools/test_conversation_timeout.py +python3 tools/test_read_usb_log.py +``` -macOS 测试仅在临时副本中移除 SDK 与宿主不兼容的 32 位 size_t 定义，不改 SDK 文件。该测试不代表 ARM 完整固件编译或硬件验收。正式构建沿用项目 Windows ARM Compiler 5 构建流程。 +诊断测试编译执行真实诊断源码，模拟 SDK 的成功、DNS 失败、连接拒绝、超时、初始化失败、取消和资源释放；验证统计、SINR/CQI 不可用处理、USB 零等待队列/部分写/断线重开、对话分段与旧轮次隔离、GNSS 静默仍保留副作用。已有对话回归测试验证超时、打断和角色提示流程。Mac 读取工具使用临时伪终端验证 UTF-8 分包、过滤、Ctrl+C 与末行保存，不打开物理串口。 -上板后核对：UTF-8 中文是否正确；50 ms 以下抖动、正常短按、重复短按、3 秒以上长按；断网仍可开启诊断；两目标成功和不回应；恢复网络；对话时不因按键中断声音；OTA/定时休眠暂停；重启关闭。核实实际模组信号单位、Ping 回调和内存余量。 +宿主测试只在临时头文件副本/编译选项中处理 SDK 的 32 位 size_t 和 timeval 与 Mac 的差异，不修改 SDK。测试不能代替完整 ARM 固件构建与硬件验收。正式构建沿用项目 Windows 工具链；当前应用 Makefile 使用 arm-none-eabi-gcc。 + +上板后确认：直接 USB 枚举与端口识别；UTF-8 日志；晚插线、拔插、拥塞和 USB 丢弃计数；离线仍可开启诊断；两个目标的 DNS/TCP 结果；对话时音频正常且汇总匹配；OTA/定时休眠暂停；重启关闭。核实模组信号单位、实际内存余量和 USB SDK 的返回语义。 diff --git a/ql-application/threadx/interface/custom_app/Makefile b/ql-application/threadx/interface/custom_app/Makefile index c287ff1..8271355 100644 --- a/ql-application/threadx/interface/custom_app/Makefile +++ b/ql-application/threadx/interface/custom_app/Makefile @@ -68,6 +68,9 @@ SRC_FILES+= \ http_aofei.c \ net_mgt.c \ net_diag.c \ + net_diag_probe.c \ + net_diag_voice.c \ + field_log.c \ ws_talkingq.c \ talkingq_wss.c \ talkingq_root_ca.c \ @@ -114,7 +117,7 @@ INC_DIRS+= \ #------------------------------------------------------------------------------- # Configure compile flag for C #------------------------------------------------------------------------------- -U_FLAGS:= +U_FLAGS:= -Dprintf=field_log_printf #------------------------------------------------------------------------------- # Configure compile flag for C++ diff --git a/ql-application/threadx/interface/custom_app/custom_app.c b/ql-application/threadx/interface/custom_app/custom_app.c index e045ffd..8da556b 100644 --- a/ql-application/threadx/interface/custom_app/custom_app.c +++ b/ql-application/threadx/interface/custom_app/custom_app.c @@ -26,7 +26,8 @@ #include "ql_uart.h" #include "ql_application.h" -#include "ql_log.h" +#include "ql_log.h" +#include "field_log.h" #include "hal_api.h" #include "nfc.h" #include "ota_baseline.h" @@ -78,35 +79,8 @@ int app_get_app_sleep_flag(void) } -void quec_usbcdc_callback(QL_UART_PORT_NUMBER_E port, void *para) -{ - int read_len = 0; - char r_data[1024] = {0}; - read_len = ql_uart_read(port, r_data, sizeof(r_data)); - printf("uart[%d] callback read data, data:%s, read_len:%d \n", port, r_data, read_len); -} - -void quec_usbcdc_write(unsigned char *data, int len) -{ - ql_uart_write(QL_USB_CDC_PORT, data, len); -} - -static void quec_usbcdc_init(void) -{ - - ql_uart_config_t dcb; - ql_uart_open(QL_USB_CDC_PORT, QL_UART_BAUD_115200, QL_FC_NONE); - - dcb.baudrate = QL_UART_BAUD_115200; - dcb.data_bit = 8; - dcb.stop_bit = 1; - dcb.parity_bit = 0; - dcb.flow_ctrl = 0; - ql_uart_set_dcbconfig(QL_USB_CDC_PORT, &dcb); - - ql_uart_register_cb(QL_USB_CDC_PORT, quec_usbcdc_callback); //use callback to read uart data -} - +/* USB CDC is owned by field_log.c; no receive/echo callback is installed. */ + #define AT_CMD_SLEPP_SUFFIX "\r\n" void ql_atcmd_sleep(void) { @@ -135,6 +109,8 @@ static void custom_app_task(void * argv) uint8_t flag = 0; u32 app_start_time_record = 0; + field_log_init(); + // 安全修复：初始化互斥锁 ql_rtos_mutex_create(&g_app_op_mutex); @@ -162,7 +138,6 @@ static void custom_app_task(void * argv) //app_uartsh_init(); -// quec_usbcdc_init(); //ql_rtos_task_sleep_s(15); diff --git a/ql-application/threadx/interface/custom_app/field_log.c b/ql-application/threadx/interface/custom_app/field_log.c new file mode 100644 index 0000000..4ff0e1f --- /dev/null +++ b/ql-application/threadx/interface/custom_app/field_log.c @@ -0,0 +1,120 @@ +/* Mirror application printf calls to plain-text USB CDC without waiting + * for the USB host in producers. UART still uses the SDK's original printf. */ +#include +#include +#include +#include "ql_rtos.h" +#include "ql_uart.h" +#include "field_log.h" +/* This module is also compiled with -Dprintf=field_log_printf. */ +#undef printf +extern int printf(const char *format, ...); + +#define LOG_RECORD_BYTES 512 +#define LOG_QUEUE_DEPTH 16 +struct log_record { unsigned int length; char text[LOG_RECORD_BYTES]; }; +static ql_queue_t usb_queue; +static ql_task_t usb_task; +static volatile int ready; +static unsigned long dropped; + +static void note_drop(void) +{ + ql_rtos_task_sched_lock(); + ++dropped; + ql_rtos_task_sched_unlock(); +} + +int field_log_printf(const char *format, ...) +{ + struct log_record record; + va_list args; + int n, ret; + va_start(args, format); + n = vsnprintf(record.text, sizeof(record.text), format, args); + va_end(args); + if (n < 0) return n; + if (n >= (int)sizeof(record.text)) { + const char suffix[] = " [TRUNCATED]\r\n"; + size_t cut = sizeof(record.text) - sizeof(suffix); + /* Keep the UTF-8 prefix valid if a multi-byte character crosses cut. */ + while (cut && ((unsigned char)record.text[cut] & 0xc0) == 0x80) --cut; + memcpy(record.text + cut, suffix, sizeof(suffix)); + } + record.length = (unsigned int)strlen(record.text); + ret = printf("%s", record.text); + if (ready && record.length && + ql_rtos_queue_release(usb_queue, sizeof(record), (u8 *)&record, QL_NO_WAIT) != 0) + note_drop(); + return ret; +} + +/* SDK variants return zero on success or a positive byte count. */ +static int usb_write_all(const char *text, int length) +{ + int offset = 0; + while (offset < length) { + int n = ql_uart_write(QL_USB_CDC_PORT, (unsigned char *)text + offset, length - offset); + if (n == 0) return 0; + if (n < 0 || n > length - offset) return -1; + offset += n; + } + return 0; +} + +static void usb_worker(void *arg) +{ + struct log_record record; + int opened = 0; + unsigned long last_notice = 0, reported = 0; + (void)arg; + for (;;) { + if (!opened) { + int open_result = ql_uart_open(QL_USB_CDC_PORT, QL_UART_BAUD_115200, QL_FC_NONE); + if (open_result == QL_UART_SUCCESS || open_result == QL_UART_ALREAD_OPEN) { + const char banner[] = "\r\n[USB日志] 板板现场日志 CDC 已开启；UTF-8 / 115200 8N1；短按原报警键开始网络诊断\r\n"; + opened = usb_write_all(banner, sizeof(banner) - 1) == 0; + if (!opened) ql_uart_close(QL_USB_CDC_PORT); + } + if (!opened) { ql_rtos_task_sleep_ms(1000); continue; } + } + if (ql_rtos_queue_wait(usb_queue, (u8 *)&record, sizeof(record), 1000) == 0) { + if (usb_write_all(record.text, record.length) != 0) { + note_drop(); + ql_uart_close(QL_USB_CDC_PORT); + opened = 0; + ql_rtos_task_sleep_ms(1000); + } + } + /* Beacons identify the correct serial interface even when app is idle. + * Drop totals are never reset: concurrent producers cannot lose them. */ + if (opened && (u32)(ql_rtos_get_systicks() - last_notice) >= 1000) { + char status[160]; + unsigned long total; + ql_rtos_task_sched_lock(); total = dropped; ql_rtos_task_sched_unlock(); + snprintf(status, sizeof(status), "\r\n[USB日志] 在线；累计丢弃=%lu 条%s\r\n", total, + total != reported ? "；USB拥塞或未连接，记录可能不完整" : ""); + if (usb_write_all(status, (int)strlen(status)) != 0) { + ql_uart_close(QL_USB_CDC_PORT); opened = 0; + } else reported = total; + last_notice = ql_rtos_get_systicks(); + } + } +} + +int field_log_init(void) +{ + int ret; + if (ready) return 0; + ret = ql_rtos_queue_create(&usb_queue, sizeof(struct log_record), LOG_QUEUE_DEPTH); + if (ret != 0) { printf("[USB日志] 队列创建失败=%d；仅保留UART日志\r\n", ret); return ret; } + ret = ql_rtos_task_create(&usb_task, 4096, 130, "usb_log", usb_worker, NULL); + if (ret != 0) { + ql_rtos_queue_delete(usb_queue); usb_queue = NULL; + printf("[USB日志] 转发任务创建失败=%d；仅保留UART日志\r\n", ret); + return ret; + } + ready = 1; + field_log_printf("[USB日志] 应用日志已同步到USB CDC；内核/基带日志不在此转发范围\r\n"); + return 0; +} diff --git a/ql-application/threadx/interface/custom_app/gnss.c b/ql-application/threadx/interface/custom_app/gnss.c index a2e0682..00a0539 100644 --- a/ql-application/threadx/interface/custom_app/gnss.c +++ b/ql-application/threadx/interface/custom_app/gnss.c @@ -16,6 +16,18 @@ #include "netdb.h" #include "app_inc.h" +/* Temporary field-debug switch: set to 1 to restore GNSS text/NMEA logs. + * The quiet function deliberately evaluates arguments (some close the GNSS). */ +#ifndef BANBAN_GNSS_LOG_ENABLED +#define BANBAN_GNSS_LOG_ENABLED 0 +#endif +#if BANBAN_GNSS_LOG_ENABLED +#define GNSS_LOG printf +#else +static int gnss_log_quiet(const char *format, ...) { (void)format; return 0; } +#define GNSS_LOG gnss_log_quiet +#endif + // 新增宏定义（原代码中未定义） #define GNSS_FAST_MODE_HOLD_TIME (5 * 60 * 1000) // FAST模式持续5分钟后切SLOW @@ -213,7 +225,7 @@ void quec_gnss_callback(char *data, int len) // 打印原始 NMEA 数据 for (i = 0; i < len; i++) { - printf("%c", data[i]); + GNSS_LOG("%c", data[i]); } // 在 data 中定位 GGA 句子的起止位置 @@ -267,7 +279,7 @@ void quec_gnss_callback(char *data, int len) g_gps_location.is_valid = (fix_status >= 1) ? 1 : 0; } else { g_gps_location.is_valid = 0; - printf("\n[GNSS Parse failed] FS=%d, %s\n", + GNSS_LOG("\n[GNSS Parse failed] FS=%d, %s\n", fix_status, (fix_status == 0) ? "No Fix (Invalid)" : "Format error"); } @@ -321,7 +333,7 @@ void quec_gnss_callback(char *data, int len) void set_gnss_mode(gnss_mode_t mode) { g_gnss_mode = mode; - printf("[GNSSMode] Set to %s Mode\n", + GNSS_LOG("[GNSSMode] Set to %s Mode\n", (mode == GNSS_MODE_FAST) ? "Fast (30s)" : "Slow (5min)"); } @@ -353,11 +365,11 @@ gps_location_info_t* get_gps_location_info(void) void print_gps_location_info(void) { if (g_gps_location.is_valid) { - printf("[GPSinfo] Latitude: %.8f, Longitude: %.8f\n", + GNSS_LOG("[GPSinfo] Latitude: %.8f, Longitude: %.8f\n", g_gps_location.latitude, g_gps_location.longitude); - printf("[GPSinfo] rawNMEA: %s\n", g_gps_location.raw_nmea); + GNSS_LOG("[GPSinfo] rawNMEA: %s\n", g_gps_location.raw_nmea); } else { - printf("[GPSinfo] No valid position data\n"); + GNSS_LOG("[GPSinfo] No valid position data\n"); } } @@ -395,26 +407,26 @@ static void quec_gnss_test(void * argv) /* ========== FAST MODE ========== */ if (fast_mode_start_time == 0) { fast_mode_start_time = hal_os_up_time_ms(); - printf("[GNSS] Enter FAST mode\n"); + GNSS_LOG("[GNSS] Enter FAST mode\n"); } if (!gnss_is_open) { gnss_is_open = 1; app_set_app_operation(1); ql_gnss_open(quec_gnss_callback); - printf("[GNSS] FAST: GPS OPEN\n"); + GNSS_LOG("[GNSS] FAST: GPS OPEN\n"); } // 5分钟超时切SLOW if (hal_os_up_time_ms() - fast_mode_start_time >= GNSS_FAST_MODE_HOLD_TIME) { - printf("[GNSS] FAST 5min timeout -> SLOW\n"); + GNSS_LOG("[GNSS] FAST 5min timeout -> SLOW\n"); g_gnss_mode = GNSS_MODE_SLOW; fast_mode_start_time = 0; slow_mode_start_time = 0; slow_next_wake_time = 0; gnss_is_open = 0; - printf("[GNSS] SLOW: GPS CLOSED ret:%d\n", ql_gnss_close()); + GNSS_LOG("[GNSS] SLOW: GPS CLOSED ret:%d\n", ql_gnss_close()); } } else @@ -426,12 +438,12 @@ static void quec_gnss_test(void * argv) if (slow_mode_start_time == 0) { slow_mode_start_time = now; slow_next_wake_time = now; // 立即尝试第一次定位 - printf("[GNSS] Enter SLOW mode (fixed 15min interval)\n"); + GNSS_LOG("[GNSS] Enter SLOW mode (fixed 15min interval)\n"); } // 检查是否到达唤醒时间 if (now < slow_next_wake_time) { - printf("[GNSS] SLOW: next wake in %d s\n", + GNSS_LOG("[GNSS] SLOW: next wake in %d s\n", (slow_next_wake_time - now) / 1000); } else if (!gnss_is_open) { @@ -444,7 +456,7 @@ static void quec_gnss_test(void * argv) app_set_app_operation(1); ql_gnss_open(quec_gnss_callback); - printf("[GNSS] SLOW: GPS OPEN, search start\n"); + GNSS_LOG("[GNSS] SLOW: GPS OPEN, search start\n"); /* ---- 第一阶段：60秒卫星检测 ---- */ int sat_found = 0; @@ -454,7 +466,7 @@ static void quec_gnss_test(void * argv) elapsed++; if (g_gnss_sat_count > 1) { sat_found = 1; - printf("[GNSS] SLOW: Sat found! count=%d, after %ds\n", + GNSS_LOG("[GNSS] SLOW: Sat found! count=%d, after %ds\n", g_gnss_sat_count, elapsed); break; } @@ -462,10 +474,10 @@ static void quec_gnss_test(void * argv) if (!sat_found) { // 60秒无卫星 → 立即关闭，等待15分钟 - printf("[GNSS] SLOW: No satellite in 30s, stop ret:%d.\n", ql_gnss_close()); + GNSS_LOG("[GNSS] SLOW: No satellite in 30s, stop ret:%d.\n", ql_gnss_close()); gnss_is_open = 0; slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000); - printf("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); + GNSS_LOG("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); continue; } @@ -478,17 +490,17 @@ static void quec_gnss_test(void * argv) // 1.5分钟时刻检查卫星数 int sat_count_now = g_gnss_sat_count; - printf("[GNSS] SLOW: 1min check, satellite count = %d\n", sat_count_now); + GNSS_LOG("[GNSS] SLOW: 1min check, satellite count = %d\n", sat_count_now); 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()); + GNSS_LOG("[GNSS] SLOW: Sat count < %d, stop search ret:%d.\n", GNSS_SAT_MIN_COUNT,ql_gnss_close()); gnss_is_open = 0; slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000); - printf("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); + GNSS_LOG("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); continue; } /* ---- 第三阶段：卫星足够，继续定位，但总时间不超过3分钟 ---- */ - printf("[GNSS] SLOW: Sat count OK, continue for fix (max %ds total)\n", + GNSS_LOG("[GNSS] SLOW: Sat count OK, continue for fix (max %ds total)\n", GNSS_MAX_SEARCH_TIME); // 继续等待直到总时间达到 GNSS_MAX_SEARCH_TIME (180秒) @@ -498,28 +510,28 @@ static void quec_gnss_test(void * argv) // 如果获得有效定位，打印提示（但继续等待至3分钟） if (g_gps_location.is_valid) { - printf("[GNSS] SLOW: Fix obtained at %ds!\n", elapsed); + GNSS_LOG("[GNSS] SLOW: Fix obtained at %ds!\n", elapsed); print_gps_location_info(); // 若希望在定位成功后立即关闭，可在此 break，但此处按“最长3分钟”处理 } } // 3分钟时间到，关闭GPS - printf("[GNSS] SLOW: Max search time reached, stop.\n"); + GNSS_LOG("[GNSS] SLOW: Max search time reached, stop.\n"); if (g_gps_location.is_valid) { - printf("[GNSS] SLOW: Final valid position:\n"); + GNSS_LOG("[GNSS] SLOW: Final valid position:\n"); print_gps_location_info(); } else { - printf("[GNSS] SLOW: No valid fix within 3min.\n"); + GNSS_LOG("[GNSS] SLOW: No valid fix within 3min.\n"); } - printf("[GNSS] SLOW: GPS CLOSED ret:%d",ql_gnss_close()); + GNSS_LOG("[GNSS] SLOW: GPS CLOSED ret:%d",ql_gnss_close()); gnss_is_open = 0; g_gps_location.is_valid = 0; // 重置状态 // 设置下次唤醒时间为 15分钟 后 slow_next_wake_time = search_start_time + (GNSS_SEARCH_INTERVAL * 1000); - printf("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); + GNSS_LOG("[GNSS] SLOW: GPS CLOSED, next search at +%ds\n", GNSS_SEARCH_INTERVAL); } // else: GPS正在运行中（理论上不会到这里） } diff --git a/ql-application/threadx/interface/custom_app/inc/field_log.h b/ql-application/threadx/interface/custom_app/inc/field_log.h new file mode 100644 index 0000000..d724c3a --- /dev/null +++ b/ql-application/threadx/interface/custom_app/inc/field_log.h @@ -0,0 +1,6 @@ +#ifndef BANBAN_FIELD_LOG_H +#define BANBAN_FIELD_LOG_H +/* Init once from the application startup task, before other app workers. */ +int field_log_init(void); +int field_log_printf(const char *format, ...); +#endif diff --git a/ql-application/threadx/interface/custom_app/inc/net_diag.h b/ql-application/threadx/interface/custom_app/inc/net_diag.h index 0f7eeb1..6750b56 100644 --- a/ql-application/threadx/interface/custom_app/inc/net_diag.h +++ b/ql-application/threadx/interface/custom_app/inc/net_diag.h @@ -1,5 +1,7 @@ #ifndef BANBAN_NET_DIAG_H #define BANBAN_NET_DIAG_H +int net_diag_is_enabled(void); +int net_diag_can_probe(void); void net_diag_start(void); void net_diag_event(const char *event, int code); #endif diff --git a/ql-application/threadx/interface/custom_app/inc/net_diag_probe.h b/ql-application/threadx/interface/custom_app/inc/net_diag_probe.h new file mode 100644 index 0000000..ada6f59 --- /dev/null +++ b/ql-application/threadx/interface/custom_app/inc/net_diag_probe.h @@ -0,0 +1,11 @@ +#ifndef BANBAN_NET_DIAG_PROBE_H +#define BANBAN_NET_DIAG_PROBE_H +/* Transport failures are distinct from local setup/resource failures. */ +enum { PROBE_OK, PROBE_DNS, PROBE_LOCAL, PROBE_CONNECT, PROBE_TIMEOUT, PROBE_CANCELLED }; +typedef struct { + int outcome, error, dns_result, tcp_started; + unsigned long dns_ms, tcp_ms; + char address[48]; +} net_probe_result; +void net_diag_probe(const char *host, unsigned short port, net_probe_result *result); +#endif diff --git a/ql-application/threadx/interface/custom_app/inc/net_diag_voice.h b/ql-application/threadx/interface/custom_app/inc/net_diag_voice.h new file mode 100644 index 0000000..e95b7d7 --- /dev/null +++ b/ql-application/threadx/interface/custom_app/inc/net_diag_voice.h @@ -0,0 +1,15 @@ +#ifndef BANBAN_NET_DIAG_VOICE_H +#define BANBAN_NET_DIAG_VOICE_H +enum { + VOICE_SPEECH, VOICE_RECORD_STOP, VOICE_END_QUEUED, VOICE_END_ACK, + VOICE_TTS_START, VOICE_FIRST_URL, VOICE_DOWNLOAD_BEGIN, + VOICE_DOWNLOAD_DONE, VOICE_FIRST_PCM, VOICE_STAGE_COUNT +}; +void net_diag_voice_begin(unsigned int round); +/* round=0 means the currently recording round (for the VAD task). */ +void net_diag_voice_mark(unsigned int round, int stage); +void net_diag_voice_url(unsigned int round, const char *url); +unsigned int net_diag_audio_begin(const char *url); +void net_diag_audio_done(unsigned int round, int bytes, int result); +void net_diag_vad_stats(unsigned int frames, unsigned int speech, unsigned int peak); +#endif 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..348a56a 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 @@ -26,7 +26,8 @@ #include "rws_string.h" #include #include "sockets.h" -#include "ql_rtos.h" +#include "ql_rtos.h" +#include "net_diag.h" #include #include "rws_handshake.h" #ifdef LIBRWS_USING_MBED_TLS @@ -212,13 +213,14 @@ static int rws_tls_send_all(_rws_socket *s, const unsigned char *data, size_t si // need close socket on error rws_bool rws_socket_send(_rws_socket *s, const void *data, const size_t data_size) { - int sended = -1; + int sended = -1; + unsigned int diag_write_start = ql_rtos_get_systicks(); // rws_error_delete_clean(&s->error); #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__); + /* Individual frame tracing overwhelms field logs; report slow writes below. */ sended = rws_tls_send_all(s, (const unsigned char *)data, data_size); } else @@ -243,7 +245,13 @@ rws_bool rws_socket_send(_rws_socket *s, const void *data, const size_t data_siz } #endif - if (sended == (int)data_size) + if (net_diag_is_enabled()) { + unsigned long elapsed = (unsigned int)(ql_rtos_get_systicks() - diag_write_start) * 5UL; + if (elapsed >= 200UL || sended != (int)data_size) + printf("[现场诊断][%lu ms][底层发送] 请求=%lu 字节 已写=%d 耗时=%lu ms；未代表服务端已收到\r\n", + (unsigned long)ql_rtos_get_systicks() * 5UL, (unsigned long)data_size, sended, elapsed); + } + if (sended == (int)data_size) { rws_socket_error_cnt = 0; rws_socket_error_staus = 0; diff --git a/ql-application/threadx/interface/custom_app/mp3_player.c b/ql-application/threadx/interface/custom_app/mp3_player.c index 42826be..a964d31 100644 --- a/ql-application/threadx/interface/custom_app/mp3_player.c +++ b/ql-application/threadx/interface/custom_app/mp3_player.c @@ -13,7 +13,8 @@ #include #include "sockets.h" #include "mp3dec.h" -#include "test_mp3.h" +#include "test_mp3.h" +#include "net_diag_voice.h" #define RLOGD printf struct webclient_session *session = NULL; @@ -24,6 +25,7 @@ static Mp3PlayConfigInfo mp3_configInfo; static unsigned char mp3_player_status = 0; QFILE *local_mp3_file_fd=NULL; +static unsigned int diag_player_round; static int mp3_player_end_frame = 0; static int mp3_player_last_result = 0; @@ -252,7 +254,13 @@ int mp3_decoder_run(struct mp3_decoder* decoder) current_sample_rate = decoder->frame_info.samprate; } - ql_audio_track_write(track_hd, (char*)pcm_buff, 1152); + { + int pcm_ret = ql_audio_track_write(track_hd, (char*)pcm_buff, 1152); + if (diag_player_round && pcm_ret >= 0) { + net_diag_voice_mark(diag_player_round, VOICE_FIRST_PCM); + diag_player_round = 0; + } + } } return 0; @@ -396,6 +404,7 @@ void aofei_mp3_player(char *file_name) { int ret = 0; uint8_t *mp3_buff = NULL; + diag_player_round = 0; mp3_player_last_result = -1; if(file_name == NULL){ @@ -413,7 +422,9 @@ void aofei_mp3_player(char *file_name) //直接下载到一个100k的buffer if(strncmp(file_name, "http://", strlen("http://")) == 0 || strncmp(file_name, "https://", strlen("https://")) == 0){//播放url + diag_player_round = net_diag_audio_begin(file_name); ret = url_mp3_data_fetch(file_name, mp3_buff, 100*1024); + net_diag_audio_done(diag_player_round, total_length, ret); }else if(strstr(file_name, "test.mp3")){//播放本地音频 total_length = test_data_size; memcpy(mp3_buff, test_data, total_length); diff --git a/ql-application/threadx/interface/custom_app/net_diag.c b/ql-application/threadx/interface/custom_app/net_diag.c index c0ce220..2a6eb0c 100644 --- a/ql-application/threadx/interface/custom_app/net_diag.c +++ b/ql-application/threadx/interface/custom_app/net_diag.c @@ -5,7 +5,8 @@ #include "hal_api.h" #include "ql_nw.h" #include "ql_data_call.h" -#include "ql_ping.h" +#include "ql_func.h" +#include "net_diag_probe.h" #include "net_diag.h" extern uint8_t get_sleep_mode(void); @@ -16,10 +17,10 @@ extern u8 power_down_status; static volatile int enabled; static ql_task_t sample_task, probe_task; -static ql_ping_stat_t ping_result; -static int ping_seen, ping_error; +static int sinr_unavailable; static const char *targets[] = {"223.5.5.5", "banban.api.talkingq.com"}; -static const char *labels[] = {"参照节点", "业务域名"}; +static const char *labels[] = {"参照DNS服务", "业务WSS入口"}; +static const unsigned short ports[] = {53, 443}; static unsigned long attempts[2], received[2], streak[2], errors[2]; static const char *registration_name(int state) @@ -51,6 +52,9 @@ static int paused(void) return fota_start == 1 || power_down_status != 0 || get_sleep_mode(); } +int net_diag_is_enabled(void) { return enabled; } +int net_diag_can_probe(void) { return enabled && !paused(); } + static void sample_worker(void *arg) { int previous_reg = -1, previous_pdp = -1, previous_pause = -1; @@ -84,10 +88,16 @@ static void sample_worker(void *arg) pdp == 1 ? "已连接" : (pdp == -1 ? "读取失败" : "未连接"), get_mqtt_connect_status() == 1 ? "已连接" : "未连接", get_xiaoice_connected_status() ? "已连接" : "未连接"); - if (sr == QL_NW_SUCCESS && (registered == 1 || registered == 5)) { - printf("[现场诊断][%lu ms][信号原始值] RSSI=%d RSRP=%d RSRQ=%d CQI=%d；单位/无效值以模组为准\r\n", + if (sr == QL_NW_SUCCESS && rr == QL_NW_SUCCESS && + (reg.data_reg.rat == QL_NW_ACCESS_TECH_E_UTRAN || + reg.data_reg.rat == QL_NW_ACCESS_TECH_E_UTRAN_CA)) { + char cqi[32]; + if (signal.LTE_SignalStrength.cqi >= 0 && signal.LTE_SignalStrength.cqi <= 15) + snprintf(cqi, sizeof(cqi), "%d", signal.LTE_SignalStrength.cqi); + else snprintf(cqi, sizeof(cqi), "不可用(raw=%d)", signal.LTE_SignalStrength.cqi); + printf("[现场诊断][%lu ms][信号原始值] RSSI=%d RSRP=%d RSRQ=%d CQI=%s；单位/无效值以模组为准\r\n", now_ms(), signal.LTE_SignalStrength.rssi, signal.LTE_SignalStrength.rsrp, - signal.LTE_SignalStrength.rsrq, signal.LTE_SignalStrength.cqi); + signal.LTE_SignalStrength.rsrq, cqi); } else { printf("[现场诊断][%lu ms][信号] 暂不可判读；接口返回=%d 注册=%d\r\n", now_ms(), sr, registered); } @@ -107,10 +117,20 @@ static void sample_worker(void *arg) if ((unsigned long)(now_ms() - next_cell) >= 10000UL || next_cell == 0) { int sinr, result; next_cell = now_ms(); - result = ql_nw_get_sinr(&sinr); - if (result == QL_NW_SUCCESS) - printf("[现场诊断][%lu ms][信噪比原始值] SINR=%d；编码以模组为准\r\n", now_ms(), sinr); - else net_diag_event("SINR读取失败", result); + if (!sinr_unavailable) { + if (!m_get_api_ptr || !m_get_api_ptr("ql_nw_get_sinr")) { + sinr_unavailable = 1; + net_diag_event("当前内核未导出SINR接口；本次开机跳过该项", 0); + } else { + result = ql_nw_get_sinr(&sinr); + if (result == QL_NW_SUCCESS && sinr != 255) + printf("[现场诊断][%lu ms][信噪比原始值] SINR=%d；编码以模组为准\r\n", now_ms(), sinr); + else if (result == 255 || (result == QL_NW_SUCCESS && sinr == 255)) { + sinr_unavailable = 1; + net_diag_event("SINR接口/数值不可用；本次开机跳过该项", result); + } else net_diag_event("SINR暂时读取失败", result); + } + } memset(&cells, 0, sizeof(cells)); result = ql_nw_get_cell_info(&cells); if (result == QL_NW_SUCCESS && cells.lte_info_valid) { @@ -118,7 +138,7 @@ static void sample_worker(void *arg) for (i = 0; i < cells.lte_info_num && i < QL_NW_CELL_MAX_NUM; ++i) { QL_MCM_NW_LTE_CELL_INFO_T *c = &cells.lte_info[i]; if (c->flag != 0 || c->cid == 0) continue; - printf("[现场诊断][%lu ms][驻留小区] CID=%lu PCI=%lu EARFCN=%lu MCC=%lu MNC=%lu%s\r\n", + printf("[现场诊断][%lu ms][驻留小区] CID=%lu PCI=%lu EARFCN=%lu MCC原始编码=0x%lX MNC原始编码=0x%lX%s\r\n", now_ms(), (unsigned long)c->cid, (unsigned long)c->pci, (unsigned long)c->earfcn, (unsigned long)c->mcc, (unsigned long)c->mnc, had_cell && (cell_id != c->cid || pci != c->pci) ? "；驻留小区发生变化" : ""); @@ -135,46 +155,34 @@ static void sample_worker(void *arg) } } -static void ping_callback(ql_ping_state_e state, int err, ql_ping_stat_t *stat) -{ - (void)state; - if (err) ping_error = err; - if (stat) { ping_result = *stat; ping_seen = 1; } -} - static void probe_once(int index) { - ql_ping_cfg_t cfg; - ql_ping_ctx_t *ctx; - int ret; - memset(&cfg, 0, sizeof(cfg)); - cfg.pdpCid = 1; cfg.host = (char *)targets[index]; - cfg.timeout = 2000; cfg.dataSize = 32; cfg.pingNum = 1; - ctx = ql_ping_init(cfg, ping_callback); - if (!ctx) { ++errors[index]; net_diag_event("探测初始化失败，下轮重试", index); return; } - memset(&ping_result, 0, sizeof(ping_result)); - ping_seen = 0; ping_error = 0; - /* SDK declares ql_ping synchronous: callbacks complete before return. */ - ret = ql_ping(ctx); - ql_ping_deinit(ctx); - if (ping_seen && ping_result.sentNum) { - attempts[index] += ping_result.sentNum; - received[index] += ping_result.rcvdNum; - if (ping_result.rcvdNum) { - streak[index] = 0; - printf("[现场诊断][%lu ms][探测成功] %s %s；往返=%lu ms\r\n", - now_ms(), labels[index], targets[index], (unsigned long)ping_result.rtt); + net_probe_result result; + printf("[现场诊断][%lu ms][探测开始] %s %s:%u；解析后TCP连接，连接超时3000ms\r\n", + now_ms(), labels[index], targets[index], (unsigned int)ports[index]); + net_diag_probe(targets[index], ports[index], &result); + if (result.outcome == PROBE_CANCELLED) { + net_diag_event("状态变化，已取消本轮新连接探测", 0); return; + } + if (result.outcome == PROBE_OK || result.outcome == PROBE_CONNECT || result.outcome == PROBE_TIMEOUT) { + ++attempts[index]; + if (result.outcome == PROBE_OK) { + ++received[index]; streak[index] = 0; + printf("[现场诊断][%lu ms][探测成功] %s；IP=%s 解析=%lu ms TCP建连=%lu ms（非AI响应时间）\r\n", + now_ms(), labels[index], result.address, result.dns_ms, result.tcp_ms); } else { ++streak[index]; - printf("[现场诊断][%lu ms][探测未回应] %s；连续=%lu 次；可能超时或节点禁Ping，不能单独判定断网\r\n", - now_ms(), labels[index], streak[index]); + printf("[现场诊断][%lu ms][探测失败] %s；阶段=%s IP=%s 解析=%lu ms TCP等待=%lu ms 错误=%d 连续失败=%lu\r\n", + now_ms(), labels[index], result.outcome == PROBE_TIMEOUT ? "TCP超时" : "TCP拒绝/连接错误", + result.address, result.dns_ms, result.tcp_ms, result.error, streak[index]); } } else { ++errors[index]; - printf("[现场诊断][%lu ms][探测执行异常] %s；返回=%d 回调错误=%d；无有效发包统计，不计入未回应率\r\n", - now_ms(), labels[index], ret, ping_error); + printf("[现场诊断][%lu ms][探测执行异常] 目标=%s 阶段=%s 错误=%d 解析返回=%d 解析=%lu ms；不计入TCP失败率\r\n", + now_ms(), labels[index], result.outcome == PROBE_DNS ? "域名解析" : "本地套接字/数据连接", + result.error, result.dns_result, result.dns_ms); } - printf("[现场诊断][%lu ms][累计统计] %s；已发送=%lu 收到=%lu 未回应=%lu 未回应率=%lu%% 执行异常=%lu（本次开机累计）\r\n", + printf("[现场诊断][%lu ms][累计统计] %s；TCP有效尝试=%lu 成功=%lu 失败=%lu 失败率=%lu%% 执行异常=%lu；非业务丢包率\r\n", now_ms(), labels[index], attempts[index], received[index], attempts[index] - received[index], attempts[index] ? (attempts[index] - received[index]) * 100UL / attempts[index] : 0, errors[index]); } @@ -212,10 +220,10 @@ void net_diag_start(void) ret = ql_rtos_task_create(&probe_task, 4096, 120, "net_probe", probe_worker, NULL); if (ret != 0) { probe_task = NULL; printf("[现场诊断][错误] 探测任务创建失败=%d，请短按重试\r\n", ret); return; } } - printf("\r\n[现场诊断] ===== 主动模式开启：重启退出 =====\r\n" - "[现场诊断] 时间=开机毫秒；串口请选择UTF-8并保存完整日志\r\n" - "[现场诊断] 信号/连接约2秒一条；小区约10秒一次；两节点依次探测后间隔10秒\r\n" - "[现场诊断] 每节点32字节，ICMP超时2000ms；业务域名探测可能另有解析耗时，不等于WSS/AI处理耗时\r\n" - "[现场诊断] 主动流量可能改变空闲态、耗电及故障表现；休眠/升级/关机时暂停新探测\r\n"); + printf("\r\n[现场诊断] ===== 主动模式开启：重启退出 =====\r\n"); + printf("[现场诊断] 时间=开机毫秒；UART与USB CDC同步，UTF-8；下一轮录音开始记录分段耗时\r\n"); + printf("[现场诊断] 信号/连接约2秒一条；小区约10秒一次；两节点依次探测后间隔10秒\r\n"); + printf("[现场诊断] 主动探测改用DNS/TCP，不依赖可选Ping接口；3000ms连接超时不含DNS解析耗时\r\n"); + printf("[现场诊断] 主动流量可能改变空闲态、耗电及故障表现；休眠/升级/关机时暂停新探测\r\n"); enabled = 1; } diff --git a/ql-application/threadx/interface/custom_app/net_diag_probe.c b/ql-application/threadx/interface/custom_app/net_diag_probe.c new file mode 100644 index 0000000..de338ff --- /dev/null +++ b/ql-application/threadx/interface/custom_app/net_diag_probe.c @@ -0,0 +1,91 @@ +/* Use the same PDP 1 socket path as the working WSS client. No raw ICMP + * or optional Ping API; select + SO_ERROR distinguish timeout/refusal/success. */ +#include +#include +#include "ql_rtos.h" +#include "ql_data_call.h" +#include "sockets.h" +#include "netdb.h" +#include "hal_api.h" +#include "net_diag_probe.h" +#include "net_diag.h" + +static unsigned long probe_ms(void) { return (unsigned long)hal_os_up_time_ms(); } + +void net_diag_probe(const char *host, unsigned short port, net_probe_result *r) +{ + struct addrinfo hints, *addresses = NULL, *address; + struct sockaddr_in local; + struct ql_data_call_info data; + char service[8]; + unsigned long started; + int fd = -1, nonblocking = 1, ret, connect_error; + socklen_t error_size; + memset(r, 0, sizeof(*r)); r->outcome = PROBE_LOCAL; + memset(&hints, 0, sizeof(hints)); + hints.ai_family = AF_INET; hints.ai_socktype = SOCK_STREAM; + snprintf(service, sizeof(service), "%u", (unsigned int)port); + if (!net_diag_can_probe()) { r->outcome = PROBE_CANCELLED; return; } + started = probe_ms(); + ret = getaddrinfo_with_pcid(host, service, &hints, &addresses, 1); + r->dns_ms = probe_ms() - started; r->dns_result = ret; + if (ret != 0 || !addresses) { + r->outcome = PROBE_DNS; r->error = ret ? ret : -1; + if (addresses) freeaddrinfo(addresses); + return; + } + /* One address per round: avoid multiplying timeout/load by DNS answer count. */ + for (address = addresses; address; address = address->ai_next) + if (address->ai_family == AF_INET && address->ai_addr && + address->ai_addrlen >= sizeof(struct sockaddr_in)) break; + if (!address) { r->outcome = PROBE_DNS; r->error = -1; goto done; } + inet_ntop(AF_INET, &((struct sockaddr_in *)address->ai_addr)->sin_addr, r->address, sizeof(r->address)); + if (!net_diag_can_probe()) { r->outcome = PROBE_CANCELLED; goto done; } + memset(&data, 0, sizeof(data)); + ret = ql_get_data_call_info(1, 0, &data); + if (ret != 0 || data.v4.state != 1) { r->error = ret ? ret : -1; goto done; } + fd = socket(AF_INET, SOCK_STREAM, 0); + if (fd < 0) { r->error = ql_get_soc_errno(); goto done; } + if (ioctl(fd, FIONBIO, &nonblocking) != 0) { r->error = ql_get_soc_errno(); goto done; } + memset(&local, 0, sizeof(local)); + local.sin_family = AF_INET; local.sin_port = htons(ql_soc_generate_port()); + local.sin_addr = data.v4.addr.ip; + if (bind(fd, (struct sockaddr *)&local, sizeof(local)) != 0) { r->error = ql_get_soc_errno(); goto done; } + started = probe_ms(); + ret = connect(fd, address->ai_addr, address->ai_addrlen); + r->tcp_started = 1; + if (ret == 0) { r->outcome = PROBE_OK; goto connected; } + connect_error = ql_get_soc_errno(); + if (connect_error != EINPROGRESS && connect_error != EWOULDBLOCK && connect_error != EALREADY) { + r->outcome = PROBE_CONNECT; r->error = connect_error; goto connected; + } + /* Short slices allow OTA/sleep/shutdown to cancel within one select slice. */ + r->outcome = PROBE_TIMEOUT; + while ((unsigned long)(probe_ms() - started) < 3000UL) { + fd_set writable, exceptional; + struct timeval wait; + int error = 0; + if (!net_diag_can_probe()) { r->outcome = PROBE_CANCELLED; break; } + FD_ZERO(&writable); FD_ZERO(&exceptional); + FD_SET(fd, &writable); FD_SET(fd, &exceptional); + { + unsigned long remaining = 3000UL - (unsigned long)(probe_ms() - started); + if (remaining > 3000UL) break; + wait.tv_sec = 0; wait.tv_usec = (remaining < 200UL ? remaining : 200UL) * 1000UL; + } + ret = select(fd + 1, NULL, &writable, &exceptional, &wait); + if (ret < 0) { r->outcome = PROBE_LOCAL; r->error = ql_get_soc_errno(); break; } + if (ret == 0) continue; + if (!FD_ISSET(fd, &writable) && !FD_ISSET(fd, &exceptional)) continue; + error_size = sizeof(error); + ret = getsockopt(fd, SOL_SOCKET, SO_ERROR, &error, &error_size); + if (ret != 0) { r->outcome = PROBE_LOCAL; r->error = ql_get_soc_errno(); } + else { r->error = error; r->outcome = error == 0 ? PROBE_OK : PROBE_CONNECT; } + break; + } +connected: + r->tcp_ms = probe_ms() - started; +done: + if (fd >= 0) close(fd); + freeaddrinfo(addresses); +} diff --git a/ql-application/threadx/interface/custom_app/net_diag_voice.c b/ql-application/threadx/interface/custom_app/net_diag_voice.c new file mode 100644 index 0000000..bde9a5e --- /dev/null +++ b/ql-application/threadx/interface/custom_app/net_diag_voice.c @@ -0,0 +1,99 @@ +#include +#include +#include "ql_rtos.h" +#include "hal_api.h" +#include "net_diag.h" +#include "net_diag_voice.h" + +static struct { + unsigned int round, seen; + unsigned long started, stamp[VOICE_STAGE_COUNT]; + char first_url[128]; +} voice; +static const char *stages[] = { + "确认用户语音", "录音结束", "结束包已入发送队列（不代表服务端收到）", + "收到END_ACK", "收到TTS_START", "收到首段音频URL", "首段开始下载", + "首段下载完成", "首PCM提交播放接口（不等于实际出声）" +}; + +void net_diag_voice_begin(unsigned int round) +{ + if (!net_diag_is_enabled()) return; + ql_rtos_task_sched_lock(); + memset(&voice, 0, sizeof(voice)); + voice.round = round; voice.started = (unsigned long)hal_os_up_time_ms(); + ql_rtos_task_sched_unlock(); + printf("[现场诊断][%lu ms][对话#%u] 开始录音；分段计时起点\r\n", voice.started, round); +} + +void net_diag_voice_mark(unsigned int round, int stage) +{ + unsigned long now, since_start, total = 0, tail = 0, server = 0, wait_url = 0, queue = 0, download = 0, pcm = 0; + unsigned int bit, seen; + if (!net_diag_is_enabled() || stage < 0 || stage >= VOICE_STAGE_COUNT) return; + now = (unsigned long)hal_os_up_time_ms(); bit = 1U << stage; + ql_rtos_task_sched_lock(); + if (!voice.round || (round && round != voice.round) || (voice.seen & bit)) { + ql_rtos_task_sched_unlock(); return; + } + round = voice.round; voice.seen |= bit; voice.stamp[stage] = now; + since_start = now - voice.started; seen = voice.seen; +#define HAVE(s) ((seen & (1U << (s))) != 0) + if (stage == VOICE_FIRST_PCM && HAVE(VOICE_RECORD_STOP) && HAVE(VOICE_END_QUEUED) && + HAVE(VOICE_TTS_START) && HAVE(VOICE_FIRST_URL) && HAVE(VOICE_DOWNLOAD_BEGIN) && HAVE(VOICE_DOWNLOAD_DONE)) { + total = now - voice.stamp[VOICE_RECORD_STOP]; + tail = voice.stamp[VOICE_END_QUEUED] - voice.stamp[VOICE_RECORD_STOP]; + server = voice.stamp[VOICE_TTS_START] - voice.stamp[VOICE_END_QUEUED]; + wait_url = voice.stamp[VOICE_FIRST_URL] - voice.stamp[VOICE_TTS_START]; + queue = voice.stamp[VOICE_DOWNLOAD_BEGIN] - voice.stamp[VOICE_FIRST_URL]; + download = voice.stamp[VOICE_DOWNLOAD_DONE] - voice.stamp[VOICE_DOWNLOAD_BEGIN]; + pcm = now - voice.stamp[VOICE_DOWNLOAD_DONE]; + } + ql_rtos_task_sched_unlock(); + printf("[现场诊断][%lu ms][对话#%u] %s；距录音开始=%lu ms\r\n", now, round, stages[stage], since_start); + /* Nonstandard server ordering is printed as events, never unsigned deltas. */ + if (total && tail <= total && server <= total && wait_url <= total && queue <= total && download <= total && pcm <= total) + printf("[现场诊断][%lu ms][对话#%u][耗时汇总] 录音结束到首PCM=%lu ms；收尾入队=%lu 等TTS通知=%lu 等首URL=%lu 播放队列=%lu 下载=%lu 解码提交=%lu（均ms；含网络与服务端处理，尚未分离）\r\n", + now, round, total, tail, server, wait_url, queue, download, pcm); +#undef HAVE +} + +void net_diag_voice_url(unsigned int round, const char *url) +{ + int accepted = 0; + if (!net_diag_is_enabled() || !url) return; + ql_rtos_task_sched_lock(); + if (round == voice.round && !voice.first_url[0] && strlen(url) < sizeof(voice.first_url)) { + strcpy(voice.first_url, url); accepted = 1; + } + ql_rtos_task_sched_unlock(); + if (accepted) net_diag_voice_mark(round, VOICE_FIRST_URL); +} + +unsigned int net_diag_audio_begin(const char *url) +{ + unsigned int round = 0; + if (!net_diag_is_enabled() || !url) return 0; + ql_rtos_task_sched_lock(); + if (voice.first_url[0] && strcmp(url, voice.first_url) == 0) round = voice.round; + ql_rtos_task_sched_unlock(); + if (round) net_diag_voice_mark(round, VOICE_DOWNLOAD_BEGIN); + return round; +} + +void net_diag_audio_done(unsigned int round, int bytes, int result) +{ + if (!round || !net_diag_is_enabled()) return; + printf("[现场诊断][%lu ms][对话#%u][首段下载] 字节=%d 返回=%d\r\n", + (unsigned long)hal_os_up_time_ms(), round, bytes, result); + if (result >= 0 && bytes > 0) net_diag_voice_mark(round, VOICE_DOWNLOAD_DONE); +} + +void net_diag_vad_stats(unsigned int frames, unsigned int speech, unsigned int peak) +{ + unsigned int round; + if (!net_diag_is_enabled()) return; + ql_rtos_task_sched_lock(); round = voice.round; ql_rtos_task_sched_unlock(); + printf("[现场诊断][%lu ms][对话#%u][语音检测] 总帧=%u 活跃录音帧=%u 首次确认前连续语音峰值=%u/20；帧长20ms\r\n", + (unsigned long)hal_os_up_time_ms(), round, frames, speech, peak); +} diff --git a/ql-application/threadx/interface/custom_app/vad_det.c b/ql-application/threadx/interface/custom_app/vad_det.c index 973df56..106060b 100644 --- a/ql-application/threadx/interface/custom_app/vad_det.c +++ b/ql-application/threadx/interface/custom_app/vad_det.c @@ -2,7 +2,9 @@ #include #include #include "cJSON.h" -#include "app_inc.h" +#include "app_inc.h" +#include "net_diag.h" +#include "net_diag_voice.h" #include "ql_rtos.h" #include "ql_application.h" #include "ql_audio.h" @@ -27,6 +29,7 @@ // 在文件顶部添加状态变量 +static uint8_t speech_detect_peak = 0; static uint8_t speech_detect_count = 0; // 连续语音帧计数器 #define SPEECH_DETECT_THRESHOLD 20 // 连续检测到语音的阈值 #define PLAYBACK_VAD_GUARD_MS 800 // 屏蔽播放结束后的尾音和音频通路切换噪声 @@ -209,16 +212,19 @@ int vad_audio_start(void) { vad_audio_init(); frame_count = 0; - speech_frame_count = 0; + speech_frame_count = 0; + speech_detect_peak = 0; - printf("Audio recording started with FVAD"); + printf("Audio recording started with FVAD\r\n"); return 0; } // 停止录音 int vad_audio_stop(void) { - printf("Audio recording stopped, frames: %d, speech: %d", + net_diag_voice_mark(0, VOICE_RECORD_STOP); + net_diag_vad_stats(frame_count, speech_frame_count, speech_detect_peak); + printf("Audio recording stopped, frames: %d, speech: %d\r\n", frame_count, speech_frame_count); vad_audio_deinit(); @@ -416,7 +422,7 @@ void vad_audio_process(void) { } if (current_vad == VAD_STATE_ACTIVE) { speech_detect_count++; - printf("Speech frame count: %d\r\n", speech_detect_count); + if (speech_detect_count > speech_detect_peak) speech_detect_peak = speech_detect_count; // 连续达到阈值才确认检测到声音 if (speech_detect_count >= SPEECH_DETECT_THRESHOLD) { @@ -447,12 +453,13 @@ void vad_audio_process(void) { vad_preroll_count = 0; } set_state(STATE_RECORDING_ACTIVE); - printf("First speech confirmed by FVAD (continuous %d frames)", SPEECH_DETECT_THRESHOLD); + net_diag_voice_mark(0, VOICE_SPEECH); + printf("First speech confirmed by FVAD (continuous %d frames)\r\n", SPEECH_DETECT_THRESHOLD); } } else { // 出现静音帧，计数器清零 if (speech_detect_count > 0) { - printf("Speech interrupted, reset count\r\n"); + /* Per-frame chatter replaced by the final peak statistic. */ speech_detect_count = 0; } diff --git a/ql-application/threadx/interface/custom_app/ws_talkingq.c b/ql-application/threadx/interface/custom_app/ws_talkingq.c index 2711e33..7c7a8d2 100644 --- a/ql-application/threadx/interface/custom_app/ws_talkingq.c +++ b/ql-application/threadx/interface/custom_app/ws_talkingq.c @@ -5,6 +5,7 @@ #include "app_inc.h" #include "talkingq_wss.h" #include "net_diag.h" +#include "net_diag_voice.h" #include "ql_rtos.h" #include "ql_application.h" #include "ql_audio.h" @@ -102,6 +103,7 @@ void conversation_record_begin(void) conversation_lock(); if (!g_mic_working) conversation_begin_round(); g_mic_working = 1; + net_diag_voice_begin(conversation_round); conversation_unlock(); } @@ -118,7 +120,8 @@ void conversation_no_speech(void) { conversation_lock(); wait_round = conversation_round; - conversation_wait = WAIT_NO_SPEECH; + conversation_wait = WAIT_NO_SPEECH; + net_diag_event("VAD未确认用户语音，本轮等待超时提示；不是AI回复耗时", 0); conversation_unlock(); } static volatile int player_mq_couter = 0; @@ -504,7 +507,8 @@ static void onmessage_text_locked(rws_socket socket, const char *text, const uns char url_buff_bak[128]={0x00}; if(strstr(text, "_START")){ - printf("TTS_START\r\n"); + printf("TTS_START\r\n"); + if (active_session_valid) net_diag_voice_mark(active_session_round, VOICE_TTS_START); //语音交互音频开始 tts_playing = 1; tts_play_status = 1; @@ -514,7 +518,9 @@ static void onmessage_text_locked(rws_socket socket, const char *text, const uns //语音交互音频结束 // tts_playing = 0; tts_play_status = 2; - }else if(strstr(text, "END_ACK")||strstr(text, "START_ACK")){ + }else if(strstr(text, "END_ACK")||strstr(text, "START_ACK")){ + if (active_session_valid && strstr(text, "END_ACK")) + net_diag_voice_mark(active_session_round, VOICE_END_ACK); }else{//TTS_URL:audio_url char *ret_str1 = strstr(text, "https://"); @@ -584,6 +590,9 @@ static void onmessage_text_locked(rws_socket socket, const char *text, const uns /* 对话超时提示使用 type=3，云端播放失败时由播放线程切换到本地兜底。 */ + if (active_session_valid && !is_tts_error_url && !is_message_ok_url && + strstr(url_buff_bak, sessionId) != NULL) + net_diag_voice_url(active_session_round, url_buff); add_file_to_play_player_queue(url_buff, is_tts_error_url == 1 ? 3 : 0); } } @@ -1056,7 +1065,9 @@ void sendEndPacket(void) { conversation_lock(); if (sender_round == conversation_round) { - int end_ret = sendRecordingAudioPacket(&endPacket); + int end_ret = sendRecordingAudioPacket(&endPacket); + if (end_ret == 0) net_diag_voice_mark(sender_round, VOICE_END_QUEUED); + else net_diag_event("结束包入队失败；不能按等待AI回复解释", end_ret); if (!round_response_received) { wait_round = sender_round; reply_wait_start_ms = hal_os_up_time_ms(); diff --git a/tools/read_usb_log.py b/tools/read_usb_log.py new file mode 100644 index 0000000..bb077bd --- /dev/null +++ b/tools/read_usb_log.py @@ -0,0 +1,127 @@ +#!/usr/bin/env python3 +"""Read a USB CDC tty on macOS using only Python's standard library.""" +import argparse +import codecs +from datetime import datetime +import glob +import os +from pathlib import Path +import select +import sys +import termios +import time +import tty + + +def available_ports(): + return sorted(set(glob.glob('/dev/cu.usbmodem*') + glob.glob('/dev/cu.usbserial*'))) + + +def open_port(path): + fd = os.open(path, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK) + try: + saved = termios.tcgetattr(fd) + tty.setraw(fd, termios.TCSANOW) + config = termios.tcgetattr(fd) + config[2] |= termios.CLOCAL | termios.CREAD + config[2] &= ~(termios.PARENB | termios.CSTOPB | termios.CSIZE) + config[2] |= termios.CS8 + if hasattr(termios, 'CRTSCTS'): + config[2] &= ~termios.CRTSCTS + config[4] = config[5] = termios.B115200 + termios.tcsetattr(fd, termios.TCSANOW, config) + return fd, saved + except BaseException: + os.close(fd) + raise + + +def read_session(path, output, diag_only=False): + fd, saved = open_port(path) + decoder = codecs.getincrementaldecoder('utf-8')(errors='replace') + pending = '' + + def emit(line): + line = line.rstrip('\r') + if not line or (diag_only and '[现场诊断]' not in line and '[USB日志]' not in line): + return + stamped = f'{datetime.now().astimezone().isoformat(timespec="milliseconds")} {line}\n' + output.write(stamped) + output.flush() + sys.stdout.write(stamped) + sys.stdout.flush() + + print(f'已连接 {path}，UTF-8 / 115200 8N1；Ctrl+C 结束。', file=sys.stderr) + try: + while True: + readable, _, _ = select.select([fd], [], [], 1) + if not readable: + continue + try: + block = os.read(fd, 4096) + except BlockingIOError: + continue + if not block: + raise OSError('USB端口已关闭') + pending += decoder.decode(block) + while '\n' in pending: + line, pending = pending.split('\n', 1) + emit(line) + if len(pending) > 8192: + emit(pending + ' [未换行，分段保存]') + pending = '' + finally: + pending += decoder.decode(b'', final=True) + if pending: + emit(pending) + try: + termios.tcsetattr(fd, termios.TCSANOW, saved) + except termios.error: + pass + os.close(fd) + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument('--list', action='store_true', help='列出 USB 串口，不打开设备') + parser.add_argument('--port', help='例如 /dev/cu.usbmodemXXXX；仅一个USB串口时可省略') + parser.add_argument('--output', type=Path, help='日志路径；默认 usb-logs/banban-时间.log') + parser.add_argument('--diag-only', action='store_true', help='只保存现场诊断与USB状态行') + parser.add_argument('--reconnect', action='store_true', help='拔插后等待同名端口重连；端口改名需重新指定') + args = parser.parse_args() + ports = available_ports() + if args.list: + print('\n'.join(ports) if ports else '未发现 USB 串口；检查数据线和设备枚举。') + return 0 + path = args.port + if not path: + if len(ports) != 1: + print('请用 --port 指定设备 CDC 口；先运行 --list 并对比拔插前后的列表。', file=sys.stderr) + for port in ports: + print(port, file=sys.stderr) + return 2 + path = ports[0] + destination = args.output or Path('usb-logs') / f'banban-{datetime.now():%Y%m%d-%H%M%S}.log' + destination.parent.mkdir(parents=True, exist_ok=True) + print(f'日志保存到 {destination.resolve()}；时间戳是电脑接收时间。', file=sys.stderr) + try: + with destination.open('a', encoding='utf-8') as output: + while True: + try: + read_session(path, output, args.diag_only) + except (OSError, termios.error) as error: + notice = f'[电脑读取] {datetime.now().astimezone().isoformat(timespec="milliseconds")} 连接中断：{error}' + print(notice, file=sys.stderr) + output.write(notice + '\n') + output.flush() + if not args.reconnect: + return 1 + print('等待同名USB端口重连……', file=sys.stderr) + time.sleep(1) + except KeyboardInterrupt: + print('\n已停止，日志已保存。', file=sys.stderr) + return 0 + + +if __name__ == '__main__': + raise SystemExit(main()) diff --git a/tools/test_conversation_timeout.py b/tools/test_conversation_timeout.py index 7aeb794..00a27f9 100644 --- a/tools/test_conversation_timeout.py +++ b/tools/test_conversation_timeout.py @@ -25,6 +25,11 @@ harness = r''' #include #include #include +#include "net_diag.h" +#include "net_diag_voice.h" +void net_diag_voice_begin(unsigned int round) { (void)round; } +void net_diag_voice_mark(unsigned int round, int stage) { (void)round; (void)stage; } +void net_diag_event(const char *event, int code) { (void)event; (void)code; } typedef void *ql_mutex_t; static int g_mic_working, recording, shine_init, fota_start; enum { STATE_IDLE, STATE_RECORDING_WAIT_SOUND, STATE_RECORDING_ACTIVE, STATE_WAITING_COMMAND }; @@ -214,5 +219,5 @@ with tempfile.TemporaryDirectory(prefix='banban-timeout-') as directory: cfile = Path(directory) / 'timeout.c' exe = Path(directory) / 'timeout-test' cfile.write_text(harness) - subprocess.run(['cc', '-std=c99', '-Wall', '-Wextra', '-Werror', str(cfile), '-o', str(exe)], check=True) + subprocess.run(['cc', '-std=c99', '-Wall', '-Wextra', '-Werror', '-I' + str(root / 'ql-application/threadx/interface/custom_app/inc'), str(cfile), '-o', str(exe)], check=True) subprocess.run([str(exe)], check=True) diff --git a/tools/test_net_diag.py b/tools/test_net_diag.py index 9d0f6cb..7ddb5e0 100644 --- a/tools/test_net_diag.py +++ b/tools/test_net_diag.py @@ -1,34 +1,38 @@ -"""Run the real diagnostic code with mocked modem APIs (no network traffic).""" +"""Exercise real diagnostic modules with SDK headers and fake modem/USB APIs. + +No live network or physical serial port is used. Host size_t adaptation is +restricted to temporary SDK header copies; firmware headers remain untouched. +""" from pathlib import Path import re import shutil import subprocess import tempfile -root = Path(__file__).resolve().parents[1] -base = root / 'ql-application/threadx/interface/custom_app' -sdk = root / 'ql-application/threadx/common/include' -harness = r''' +ROOT = Path(__file__).resolve().parents[1] +BASE = ROOT / 'ql-application/threadx/interface/custom_app' +SDK = ROOT / 'ql-application/threadx/common/include' + +SAMPLE = r''' #include #include #include "net_diag.c" -static int creates, fail_create, mode, hold, pdp = 1; +static int creates, fail_create, mode, hold, pdp = 1, sinr_calls; static unsigned long clock_ms; static int sample_steps, step_limit = 1; static jmp_buf loop_exit; -static ql_ping_ctx_t mock_ctx; -static ql_ping_cb_t callback; uint64_t hal_os_up_time_ms(void) { return clock_ms; } uint8_t get_sleep_mode(void) { return hold; } int get_mqtt_connect_status(void) { return 1; } unsigned char get_xiaoice_connected_status(void) { return 1; } int fota_start; u8 power_down_status; +static s32 api_lookup(char *name) { (void)name; return 1; } +_get_api_ptr_t m_get_api_ptr = api_lookup; QlOSStatus ql_rtos_task_create(ql_task_t *task, u32 stack, u8 priority, char *name, void (*entry)(void *), void *arg, ...) { (void)name; (void)entry; (void)arg; - assert(stack == 4096 && priority == 120); - ++creates; + assert(stack == 4096 && priority == 120); ++creates; if (fail_create == creates) return -9; *task = (void *)1; return 0; } @@ -43,75 +47,287 @@ void ql_rtos_task_sleep_ms(u32 ms) { longjmp(loop_exit, 1); } QL_NW_ERROR_CODE ql_nw_get_signal_strength(QL_NW_SIGNAL_STRENGTH_INFO_T *s) { - s->LTE_SignalStrength.rsrp = -97; return QL_NW_SUCCESS; + s->LTE_SignalStrength.rsrp = -97; s->LTE_SignalStrength.cqi = 255; return QL_NW_SUCCESS; } QL_NW_ERROR_CODE ql_nw_get_reg_status(QL_NW_REG_STATUS_INFO_T *r) { - r->data_reg.state = 1; return QL_NW_SUCCESS; + r->data_reg.state = 1; r->data_reg.rat = QL_NW_ACCESS_TECH_E_UTRAN; return QL_NW_SUCCESS; } int ql_get_data_call_info(int profile, int version, struct ql_data_call_info *d) { assert(profile == 1 && version == 0); d->v4.state = pdp; return 0; } -QL_NW_ERROR_CODE ql_nw_get_sinr(int *s) { *s = 13; return QL_NW_SUCCESS; } +QL_NW_ERROR_CODE ql_nw_get_sinr(int *s) { (void)s; ++sinr_calls; return (QL_NW_ERROR_CODE)255; } QL_NW_ERROR_CODE ql_nw_get_cell_info(QL_NW_CELL_INFO_T *c) { c->lte_info_valid = 1; c->lte_info_num = 1; c->lte_info[0].cid = 123; c->lte_info[0].pci = 42; return QL_NW_SUCCESS; } -ql_ping_ctx_t *ql_ping_init(ql_ping_cfg_t cfg, ql_ping_cb_t cb) { - assert(cfg.timeout == 2000 && cfg.pingNum == 1 && cfg.dataSize == 32 && cfg.pdpCid == 1); - callback = cb; return mode == 3 ? NULL : &mock_ctx; +void net_diag_probe(const char *host, unsigned short port, net_probe_result *r) { + assert(host && (port == 53 || port == 443)); + memset(r, 0, sizeof(*r)); + r->outcome = mode; r->tcp_started = mode == PROBE_OK || mode == PROBE_TIMEOUT; + strcpy(r->address, "192.0.2.1"); r->tcp_ms = 123; } -int ql_ping(ql_ping_ctx_t *ctx) { - ql_ping_stat_t s; - assert(ctx == &mock_ctx); memset(&s, 0, sizeof(s)); - if (mode == 2) return -2; - s.sentNum = 1; s.rcvdNum = mode == 0; s.rtt = 123; - callback(QL_PING_FINISHED, mode == 1 ? -1 : 0, &s); return 0; -} -void ql_ping_deinit(ql_ping_ctx_t *ctx) { assert(ctx == &mock_ctx); } int main(void) { fail_create = 2; net_diag_start(); assert(!enabled && sample_task && !probe_task); fail_create = 0; net_diag_start(); assert(enabled && creates == 3); net_diag_start(); assert(creates == 3); - mode = 0; probe_once(0); assert(attempts[0] == 1 && received[0] == 1 && !streak[0]); - mode = 1; probe_once(0); assert(attempts[0] == 2 && received[0] == 1 && streak[0] == 1); - mode = 2; probe_once(0); assert(attempts[0] == 2 && errors[0] == 1); - mode = 3; probe_once(0); assert(attempts[0] == 2 && errors[0] == 2); - mode = 0; probe_once(0); assert(!streak[0]); + mode = PROBE_OK; probe_once(0); assert(attempts[0] == 1 && received[0] == 1 && !streak[0]); + mode = PROBE_TIMEOUT; probe_once(0); assert(attempts[0] == 2 && received[0] == 1 && streak[0] == 1); + mode = PROBE_DNS; probe_once(0); assert(attempts[0] == 2 && errors[0] == 1); + mode = PROBE_LOCAL; probe_once(0); assert(attempts[0] == 2 && errors[0] == 2); + mode = PROBE_CANCELLED; probe_once(0); assert(attempts[0] == 2 && errors[0] == 2); + mode = PROBE_OK; probe_once(0); assert(!streak[0]); step_limit = 3; if (!setjmp(loop_exit)) sample_worker(NULL); step_limit = 1; + if (!setjmp(loop_exit)) sample_worker(NULL); + assert(sinr_calls == 1 && sinr_unavailable); hold = 1; if (!setjmp(loop_exit)) probe_worker(NULL); assert(attempts[1] == 0); - puts("PASS: creation failure/retry, idempotent activation, probe counters, sampling, sleep pause"); + puts("PASS: diagnostic activation, statistics, invalid metrics, recovery and pause"); return 0; } ''' -with tempfile.TemporaryDirectory(prefix='banban-netdiag-') as directory: - tmp = Path(directory) - for name in ['ql_type.h', 'ql_rtos.h', 'ql_nw.h', 'ql_data_call.h', 'ql_ping.h']: - content = (sdk / name).read_bytes() - if name == 'ql_type.h': - # The ARM SDK defines 32-bit size_t unconditionally. Host tests use libc's. - content, count = re.subn(rb'typedef unsigned int\s+size_t;', b'/* host size_t */', content) - assert count == 1 - (tmp / name).write_bytes(content) - (tmp / 'test.c').write_text(harness) - command = [shutil.which('clang') or 'cc', '-std=c99', '-Werror=implicit-function-declaration', - '-Wno-typedef-redefinition'] - for include in [tmp, base, base / 'inc', base / 'lib/hal', sdk, sdk / 'lwipv4v6']: - command.extend(['-I', str(include)]) - subprocess.run(command + [str(tmp / 'test.c'), '-o', str(tmp / 'test')], check=True) - result = subprocess.run([str(tmp / 'test')], check=True, capture_output=True, text=True) - print(result.stdout, end='') - assert '本次网络不可用观测时长=2000 ms' in result.stdout - assert '未回应率=50%' in result.stdout -key = (base / 'hal_key.c').read_text() -alarm = key[key.index('if(key_press_alarm_counter!=0'):key.index('ql_rtos_task_sleep_ms(10);')] -assert 'net_diag_start();' in alarm -for forbidden in ['build_alarm(', 'build_leave_to_parent(', 'stop_player_func(', 'app_play_tips_file(']: - assert forbidden not in alarm, forbidden -print('PASS: diagnostic key has no former alarm/message/audio actions') +PROBE = r''' +#include +#include "net_diag_probe.c" +static int mode, closes, frees, sys_error, permitted = 1, selects, socket_calls; +static unsigned long clock_ms; +static struct sockaddr_in remote; +static struct addrinfo address; +uint64_t hal_os_up_time_ms(void) { return clock_ms; } +int net_diag_can_probe(void) { return permitted; } +int getaddrinfo_with_pcid(const char *host, const char *service, const struct addrinfo *hints, + struct addrinfo **result, u8_t cid) { + assert(host && service && hints->ai_family == AF_INET && cid == 1); + clock_ms += 35; + if (mode == 1) return 202; + if (mode == 2) { *result = NULL; return 0; } + memset(&address, 0, sizeof(address)); memset(&remote, 0, sizeof(remote)); + remote.sin_family = AF_INET; + address.ai_family = AF_INET; address.ai_addr = (struct sockaddr *)&remote; address.ai_addrlen = sizeof(remote); + *result = &address; + if (mode == 12) permitted = 0; + return 0; +} +void freeaddrinfo(struct addrinfo *p) { assert(p == &address); ++frees; } +int ql_get_data_call_info(int cid, int version, struct ql_data_call_info *d) { + assert(cid == 1 && version == 0); d->v4.state = mode == 14 ? 0 : 1; return 0; +} +int socket(int family, int type, int protocol) { + assert(family == AF_INET && type == SOCK_STREAM && protocol == 0); ++socket_calls; + return mode == 3 ? -1 : 2; +} +int ioctl(int fd, long cmd, void *value) { + assert(fd == 2 && cmd == FIONBIO && *(int *)value == 1); return mode == 4 ? -1 : 0; +} +u16 ql_soc_generate_port(void) { return 12345; } +u16 ql_get_soc_errno(void) { return sys_error; } +int bind(int fd, const struct sockaddr *addr, socklen_t len) { + assert(fd == 2 && addr && len == sizeof(struct sockaddr_in)); return mode == 5 ? -1 : 0; +} +int connect(int fd, const struct sockaddr *addr, socklen_t len) { + assert(fd == 2 && addr && len == sizeof(struct sockaddr_in)); + if (mode == 7) return 0; + sys_error = mode == 6 ? 111 : EINPROGRESS; + if (mode == 13) permitted = 0; + return -1; +} +int select(int nfds, fd_set *readable, fd_set *writable, fd_set *exceptional, struct timeval *wait) { + assert(nfds == 3 && !readable && writable && exceptional && wait->tv_usec <= 200000); + ++selects; + if (mode == 9) { clock_ms += wait->tv_usec / 1000; return 0; } + clock_ms += 120; + if (mode == 10) { sys_error = 5; return -1; } + FD_ZERO(exceptional); FD_SET(2, writable); return 1; +} +int getsockopt(int fd, int level, int option, void *value, socklen_t *len) { + assert(fd == 2 && level == SOL_SOCKET && option == SO_ERROR && *len == sizeof(int)); + if (mode == 11) { sys_error = 5; return -1; } + *(int *)value = mode == 8 ? 111 : 0; return 0; +} +int close(int fd) { assert(fd == 2); ++closes; return 0; } +int main(void) { + net_probe_result r; + int expected[] = {PROBE_OK, PROBE_DNS, PROBE_DNS, PROBE_LOCAL, PROBE_LOCAL, PROBE_LOCAL, + PROBE_CONNECT, PROBE_OK, PROBE_CONNECT, PROBE_TIMEOUT, PROBE_LOCAL, PROBE_LOCAL, + PROBE_CANCELLED, PROBE_CANCELLED, PROBE_LOCAL}; + for (mode = 0; mode < 15; ++mode) { + closes = frees = selects = socket_calls = sys_error = 0; clock_ms = 0; permitted = 1; + net_diag_probe("test.example", 443, &r); + assert(r.outcome == expected[mode]); assert(r.dns_ms == 35); + assert(frees == (mode != 1 && mode != 2)); + assert(closes == (mode != 1 && mode != 2 && mode != 3 && mode != 12 && mode != 14)); + if (mode == 0) assert(r.tcp_ms == 120 && r.error == 0); + if (mode == 8) assert(r.error == 111); + if (mode == 9) assert(r.tcp_ms == 3000 && selects == 15); + } + permitted = 0; socket_calls = 0; + net_diag_probe("test.example", 443, &r); + assert(r.outcome == PROBE_CANCELLED && !socket_calls && r.dns_ms == 0); + puts("PASS: real probe DNS/connect success, refusal, timeout, local errors, cancellation and cleanup"); + return 0; +} +''' + +USB = r''' +#include +#include +#include "field_log.c" +static int queue_mode, queue_deletes, task_error, writes, write_mode, close_count; +static int worker_run, worker_reads, open_count; +static jmp_buf usb_exit; +static struct log_record last_record; +static char sent_text[4096]; +QlOSStatus ql_rtos_task_sched_lock(void) { return 0; } +QlOSStatus ql_rtos_task_sched_unlock(void) { return 0; } +QlOSStatus ql_rtos_queue_create(ql_queue_t *q, u32 size, u32 count) { + assert(size == sizeof(struct log_record) && size % 4 == 0 && count == 16); + *q = (void *)1; return queue_mode == 1 ? -1 : 0; +} +QlOSStatus ql_rtos_queue_delete(ql_queue_t q) { assert(q); ++queue_deletes; return 0; } +QlOSStatus ql_rtos_queue_release(ql_queue_t q, u32 size, u8 *record, u32 timeout) { + assert(q && size == sizeof(struct log_record) && timeout == 0); + last_record = *(struct log_record *)record; return queue_mode == 2 ? -1 : 0; +} +QlOSStatus ql_rtos_queue_wait(ql_queue_t q, u8 *record, u32 size, u32 timeout) { + (void)q; (void)size; (void)timeout; + if (worker_run) { + if (++worker_reads > 1) longjmp(usb_exit, 1); + strcpy(((struct log_record *)record)->text, "test"); + ((struct log_record *)record)->length = 4; return 0; + } + return -1; +} +QlOSStatus ql_rtos_task_create(ql_task_t *t, u32 size, u8 priority, char *name, void (*fn)(void *), void *arg, ...) { + assert(size == 4096 && priority == 130); (void)name; (void)fn; (void)arg; + *t = (void *)1; return task_error; +} +void ql_rtos_task_sleep_ms(u32 ms) { (void)ms; } +u32 ql_rtos_get_systicks(void) { return 0; } +int ql_uart_open(QL_UART_PORT_NUMBER_E port, QL_UART_BAUD_E baud, QL_UART_FLOWCTRL_E flow) { + assert(port == QL_USB_CDC_PORT && baud == QL_UART_BAUD_115200 && flow == QL_FC_NONE); ++open_count; return QL_UART_ALREAD_OPEN; +} +int ql_uart_close(QL_UART_PORT_NUMBER_E port) { assert(port == QL_USB_CDC_PORT); ++close_count; return 0; } +int ql_uart_write(QL_UART_PORT_NUMBER_E port, unsigned char *data, int len) { + int n = write_mode == 1 && len > 3 ? 3 : len; + assert(port == QL_USB_CDC_PORT); ++writes; + if (write_mode == 2 || (write_mode == 3 && len == 4)) return -1; + strncat(sent_text, (char *)data, write_mode == 0 ? len : n); + return write_mode == 0 ? 0 : n; +} +int main(void) { + char large[1001]; + queue_mode = 1; assert(field_log_init() == -1 && !ready); + queue_mode = 0; task_error = -2; assert(field_log_init() == -2 && !ready && queue_deletes == 1); + task_error = 0; assert(field_log_init() == 0 && ready); + assert(field_log_init() == 0); + field_log_printf("[现场诊断] 中文 value=%d\r\n", 42); + assert(strcmp(last_record.text, "[现场诊断] 中文 value=42\r\n") == 0); + assert(last_record.length == strlen(last_record.text)); + queue_mode = 2; field_log_printf("queue full\n"); assert(dropped == 1); + queue_mode = 0; memset(large, 'A', 1000); large[1000] = 0; + field_log_printf("%s", large); assert(strstr(last_record.text, "[TRUNCATED]") && last_record.length < 512); + write_mode = 0; assert(usb_write_all("abcdef", 6) == 0 && writes == 1 && strcmp(sent_text, "abcdef") == 0); + sent_text[0] = 0; writes = 0; write_mode = 1; + assert(usb_write_all("abcdef", 6) == 0 && writes == 2 && strcmp(sent_text, "abcdef") == 0); + write_mode = 2; assert(usb_write_all("abcdef", 6) == -1); + worker_run = 1; write_mode = 3; writes = 0; sent_text[0] = 0; + if (!setjmp(usb_exit)) usb_worker(NULL); + assert(open_count == 2 && close_count == 1 && dropped == 2); + puts("PASS: USB init rollback, no-wait queue, mirror, truncation, writes, disconnect/reopen"); + return 0; +} +''' + +VOICE = r''' +#include +#include "net_diag_voice.c" +static unsigned long clock_ms; +static int active = 1; +uint64_t hal_os_up_time_ms(void) { return clock_ms; } +int net_diag_is_enabled(void) { return active; } +QlOSStatus ql_rtos_task_sched_lock(void) { return 0; } +QlOSStatus ql_rtos_task_sched_unlock(void) { return 0; } +int main(void) { + unsigned int token; + clock_ms = 100; net_diag_voice_begin(3); + clock_ms = 500; net_diag_voice_mark(3, VOICE_SPEECH); + clock_ms = 1000; net_diag_voice_mark(3, VOICE_RECORD_STOP); + clock_ms = 1100; net_diag_voice_mark(3, VOICE_END_QUEUED); + clock_ms = 1200; net_diag_voice_mark(3, VOICE_END_ACK); + clock_ms = 1500; net_diag_voice_mark(3, VOICE_TTS_START); + clock_ms = 3000; net_diag_voice_url(3, "http://test/first.mp3"); + net_diag_voice_url(3, "http://test/second.mp3"); + assert(net_diag_audio_begin("http://test/unrelated.mp3") == 0); + clock_ms = 3100; token = net_diag_audio_begin("http://test/first.mp3"); assert(token == 3); + clock_ms = 3300; net_diag_audio_done(token, 8001, 0); + clock_ms = 3350; net_diag_voice_mark(token, VOICE_FIRST_PCM); + clock_ms = 3500; net_diag_voice_mark(token, VOICE_FIRST_PCM); + assert(voice.stamp[VOICE_FIRST_PCM] == 3350); + net_diag_voice_begin(4); + net_diag_voice_mark(3, VOICE_FIRST_PCM); assert(!voice.seen); + net_diag_voice_url(3, "http://old.mp3"); assert(!voice.first_url[0]); + active = 0; net_diag_voice_begin(5); assert(voice.round == 4); + puts("PASS: voice stage timing, first URL matching, duplicate/stale events, disabled mode"); + return 0; +} +''' + + +def run_c(tmp, name, source, flags=()): + path = tmp / f'{name}.c' + path.write_text(source) + command = [shutil.which('clang') or 'cc', '-std=c99', '-Werror=implicit-function-declaration', + '-Wno-typedef-redefinition', *flags] + for include in [tmp, BASE, BASE / 'inc', BASE / 'lib/hal', SDK, SDK / 'lwipv4v6']: + command.extend(['-I', str(include)]) + subprocess.run(command + [str(path), '-o', str(tmp / name)], check=True) + result = subprocess.run([str(tmp / name)], capture_output=True, text=True) + if result.returncode: + print(result.stdout, result.stderr) + result.check_returncode() + for line in result.stdout.splitlines(): + if line.startswith('PASS:'): + print(line) + return result.stdout + + +def main(): + with tempfile.TemporaryDirectory(prefix='banban-netdiag-') as directory: + tmp = Path(directory) + for name in ['ql_type.h', 'ql_rtos.h', 'ql_nw.h', 'ql_data_call.h']: + content = (SDK / name).read_bytes() + if name == 'ql_type.h': + content, count = re.subn(rb'typedef unsigned int\s+size_t;', b'/* host size_t */', content) + assert count == 1 + (tmp / name).write_bytes(content) + sample = run_c(tmp, 'sample', SAMPLE) + assert '本次网络不可用观测时长=2000 ms' in sample + assert '失败率=50%' in sample and 'CQI=不可用(raw=255)' in sample + run_c(tmp, 'probe', PROBE, flags=['-include', 'sys/time.h', '-DTIME_VAL_DEF', '-Wno-macro-redefined']) + run_c(tmp, 'usb', USB, flags=['-Dprintf=field_log_printf']) + voice = run_c(tmp, 'voice', VOICE) + assert '录音结束到首PCM=2350 ms' in voice + assert '收尾入队=100 等TTS通知=400 等首URL=1500 播放队列=100 下载=200 解码提交=50' in voice + assert voice.count('[耗时汇总]') == 1 + # Exercise the actual quiet macro: muting must still execute side effects. + gnss = (BASE / 'gnss.c').read_text() + config = gnss[gnss.index('#ifndef BANBAN_GNSS_LOG_ENABLED'):gnss.index('// 新增宏定义')] + run_c(tmp, 'gnss', '#include \n#include \n' + config + r''' +int main(void) { int closed = 0; GNSS_LOG("close=%d", ++closed); assert(closed == 1); +puts("PASS: GNSS mute preserves side effects"); return 0; } +''') + key = (BASE / 'hal_key.c').read_text() + alarm = key[key.index('if(key_press_alarm_counter!=0'):key.index('ql_rtos_task_sleep_ms(10);')] + assert 'net_diag_start();' in alarm + for forbidden in ['build_alarm(', 'build_leave_to_parent(', 'stop_player_func(', 'app_play_tips_file(']: + assert forbidden not in alarm, forbidden + print('PASS: diagnostic key retains no former alarm/message/audio actions') + + +if __name__ == '__main__': + main() diff --git a/tools/test_read_usb_log.py b/tools/test_read_usb_log.py new file mode 100644 index 0000000..8833482 --- /dev/null +++ b/tools/test_read_usb_log.py @@ -0,0 +1,62 @@ +"""Test the Mac USB reader against a temporary pseudo-terminal, not hardware.""" +from pathlib import Path +import os +import pty +import select +import signal +import subprocess +import sys +import tempfile +import time + +ROOT = Path(__file__).resolve().parents[1] + + +def exercise(diag_only): + master, slave = pty.openpty() + port = os.ttyname(slave) + process = None + try: + with tempfile.TemporaryDirectory(prefix='banban-usb-reader-') as directory: + output = Path(directory) / 'capture.log' + command = [sys.executable, str(ROOT / 'tools/read_usb_log.py'), '--port', port, '--output', str(output)] + if diag_only: + command.append('--diag-only') + process = subprocess.Popen(command, stdout=subprocess.PIPE, stderr=subprocess.PIPE) + notice = b'' + deadline = time.monotonic() + 5 + while '已连接'.encode() not in notice: + assert time.monotonic() < deadline, notice.decode(errors='replace') + if select.select([process.stderr], [], [], 0.1)[0]: + notice += os.read(process.stderr.fileno(), 4096) + assert process.poll() is None, notice.decode(errors='replace') + payload = '[现场诊断] 中文连续测试\r\nordinary application log\r\n[USB日志] 在线\n[现场诊断] 最后一行'.encode() + os.write(master, payload[:3]) # Deliberately split a UTF-8 character. + time.sleep(0.02) + os.write(master, payload[3:]) + deadline = time.monotonic() + 5 + while not output.exists() or '[USB日志] 在线' not in output.read_text(): + assert time.monotonic() < deadline + time.sleep(0.02) + process.send_signal(signal.SIGINT) + stdout, stderr = process.communicate(timeout=5) + assert process.returncode == 0, stderr.decode() + saved = output.read_text() + assert '\ufffd' not in saved + assert '[现场诊断] 中文连续测试' in saved + assert '[USB日志] 在线' in saved + assert '[现场诊断] 最后一行' in saved + assert ('ordinary application log' in saved) != diag_only + assert '[现场诊断] 中文连续测试' in stdout.decode() + finally: + if process and process.poll() is None: + process.kill() + process.communicate() + os.close(master) + os.close(slave) + + +if __name__ == '__main__': + exercise(False) + exercise(True) + print('PASS: pseudo-terminal USB capture, split UTF-8, diagnostic filter, Ctrl+C and final-line flush')