diff --git a/VERSION b/VERSION index fe50cf9..a1c59a3 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -0.6.3-dev +0.6.3-speechdiag diff --git a/boards/m5stack_stopwatch/audio_backend.cpp b/boards/m5stack_stopwatch/audio_backend.cpp index 6240f0d..59a3ce4 100644 --- a/boards/m5stack_stopwatch/audio_backend.cpp +++ b/boards/m5stack_stopwatch/audio_backend.cpp @@ -12,6 +12,7 @@ #include "esp_log.h" #include "esp_timer.h" #include "esp_heap_caps.h" +#include "mbedtls/sha256.h" #include "freertos/FreeRTOS.h" #include "freertos/queue.h" #include "freertos/idf_additions.h" @@ -53,6 +54,13 @@ std::atomic s_speech_id{0}; std::atomic s_approval_tone{false}; std::mutex s_speech_lock; TickType_t s_speech_progress_at; +mbedtls_sha256_context s_diag_accepted; +size_t s_diag_accepted_bytes=0;unsigned s_diag_frames=0; +void diag_digest(mbedtls_sha256_context *ctx, char *hex) { + unsigned char digest[32];mbedtls_sha256_finish(ctx,digest); + static const char digits[]="0123456789abcdef"; + for(unsigned i=0;i<32;++i){hex[2*i]=digits[digest[i]>>4];hex[2*i+1]=digits[digest[i]&15];}hex[64]=0; +} @@ -196,6 +204,8 @@ void audio_task(void *) void speech_task(void *) { auto *frame = new SpeechFrame{}; + mbedtls_sha256_context written_ctx;mbedtls_sha256_init(&written_ctx); + uint32_t written_id=0;size_t written_bytes=0;unsigned written_frames=0;int64_t first_us=0; const TickType_t idle_timeout = pdMS_TO_TICKS(3000); while (true) { TickType_t wait = idle_timeout; @@ -213,6 +223,9 @@ void speech_task(void *) std::lock_guard guard(s_speech_lock); const TickType_t age = xTaskGetTickCount() - s_speech_progress_at; if (s_speech_id && age >= idle_timeout && uxQueueMessagesWaiting(s_speech_queue)==0) { + char diag_accepted_hex[65],diag_written_hex[65]; + diag_digest(&s_diag_accepted,diag_accepted_hex);diag_digest(&written_ctx,diag_written_hex); + ESP_LOGI(TAG,"[DIAG_SPEECH] timeout_totals accepted_bytes=%u accepted_frames=%u accepted_sha=%s written_bytes=%u written_frames=%u written_sha=%s",unsigned(s_diag_accepted_bytes),s_diag_frames,diag_accepted_hex,unsigned(written_bytes),written_frames,diag_written_hex); ESP_LOGW(TAG,"[SPEECH] receive idle timeout generation=%u elapsed_ms=%u", static_cast(s_speech_id.load()),static_cast(age*portTICK_PERIOD_MS)); s_speech_id=0; @@ -220,12 +233,22 @@ void speech_task(void *) continue; } std::lock_guard lock(s_audio_mode_lock); - if (s_speech_id != frame->id || s_recording || s_approval_tone) continue; + if (s_speech_id != frame->id || s_recording || s_approval_tone) { + ESP_LOGW(TAG,"[DIAG_SPEECH] drop generation=%u active=%u recording=%d approval=%d bytes=%u",frame->id,s_speech_id.load(),s_recording.load(),s_approval_tone.load(),unsigned(frame->size));continue; + } + if(written_id!=frame->id){written_id=frame->id;written_bytes=0;written_frames=0;first_us=esp_timer_get_time();mbedtls_sha256_starts(&written_ctx,0);ESP_LOGI(TAG,"[DIAG_SPEECH] first_write generation=%u device_us=%lld",written_id,(long long)first_us);} bool ok = true; for (size_t offset=0; offsetsize && s_speech_id==frame->id && !s_recording && !s_approval_tone; offset+=512) { - if (esp_codec_dev_write(s_codec_dev, frame->pcm+offset, std::min(512,frame->size-offset))!=ESP_OK) { ok=false; break; } + const size_t bytes=std::min(512,frame->size-offset); + const int rc=esp_codec_dev_write(s_codec_dev,frame->pcm+offset,bytes); + if(rc!=ESP_OK){ESP_LOGW(TAG,"[DIAG_SPEECH] codec_write_fail rc=%d total=%u",rc,unsigned(written_bytes));ok=false;break;} + mbedtls_sha256_update(&written_ctx,frame->pcm+offset,bytes);written_bytes+=bytes; } + if(frame->size)++written_frames; + if(written_frames==1 || written_frames%10==0 || frame->end)ESP_LOGI(TAG,"[DIAG_SPEECH] written generation=%u frames=%u bytes=%u queue=%u",written_id,written_frames,unsigned(written_bytes),unsigned(uxQueueMessagesWaiting(s_speech_queue))); if (!ok || frame->end) { + char hex[65];diag_digest(&written_ctx,hex); + ESP_LOGI(TAG,"[DIAG_SPEECH] playback_end generation=%u reason=%s written_bytes=%u elapsed_ms=%lld sha256=%s",written_id,ok?"end":"codec-error",unsigned(written_bytes),(long long)((esp_timer_get_time()-first_us)/1000),hex); uint32_t expected=frame->id; s_speech_id.compare_exchange_strong(expected,0); } @@ -420,7 +443,9 @@ bool audio_backend_take_capture(AudioCaptureFrame *frame) bool audio_backend_speech_start(uint32_t id) { std::lock_guard guard(s_speech_lock); - if (!s_ready || !id || s_recording || s_approval_tone) return false; + if (!s_ready || !id || s_recording || s_approval_tone) {ESP_LOGW(TAG,"[DIAG_SPEECH] start_reject ready=%d recording=%d approval=%d",s_ready,s_recording.load(),s_approval_tone.load());return false;} + mbedtls_sha256_init(&s_diag_accepted);mbedtls_sha256_starts(&s_diag_accepted,0);s_diag_accepted_bytes=0;s_diag_frames=0; + ESP_LOGI(TAG,"[DIAG_SPEECH] backend_start generation=%u device_us=%lld recording=0 approval=0",id,(long long)esp_timer_get_time()); s_speech_id=0; xQueueReset(s_speech_queue); xQueueReset(s_notification_queue); s_speech_progress_at=xTaskGetTickCount(); @@ -437,8 +462,12 @@ bool audio_backend_speech_push(uint32_t id, const uint8_t *pcm, size_t size, boo frame.id=id; frame.size=size; frame.end=end; if (size) std::copy(pcm,pcm+size,frame.pcm); if (xQueueSend(s_speech_queue,&frame,0)!=pdTRUE) { + ESP_LOGW(TAG,"[DIAG_SPEECH] queue_full generation=%u accepted=%u queue=%u",id,unsigned(s_diag_accepted_bytes),unsigned(uxQueueMessagesWaiting(s_speech_queue))); s_speech_id=0; xQueueReset(s_speech_queue); return false; } + if(size){mbedtls_sha256_update(&s_diag_accepted,pcm,size);s_diag_accepted_bytes+=size;++s_diag_frames;} + if(s_diag_frames==1 || s_diag_frames%10==0 || end)ESP_LOGI(TAG,"[DIAG_SPEECH] accepted generation=%u frames=%u bytes=%u queue=%u",id,s_diag_frames,unsigned(s_diag_accepted_bytes),unsigned(uxQueueMessagesWaiting(s_speech_queue))); + if(end){char hex[65];diag_digest(&s_diag_accepted,hex);ESP_LOGI(TAG,"[DIAG_SPEECH] accepted_end generation=%u bytes=%u sha256=%s",id,unsigned(s_diag_accepted_bytes),hex);} s_speech_progress_at=xTaskGetTickCount(); return true; } diff --git a/boards/m5stack_stopwatch/board.cpp b/boards/m5stack_stopwatch/board.cpp index 24cebbe..c443f2e 100644 --- a/boards/m5stack_stopwatch/board.cpp +++ b/boards/m5stack_stopwatch/board.cpp @@ -2898,7 +2898,7 @@ bool speech_settings_message(cJSON *root, const std::string &type) { const auto id=js(root,"speech_id"); auto number=[&](const char *key) {const auto *v=cJSON_GetObjectItemCaseSensitive(root,key);return cJSON_IsNumber(v)?v->valuedouble:-1;}; if (type=="speech_start") { - if (s_approval.modal() || (s_input_modal!=InputModal::NONE && !(s_input_modal==InputModal::VOICE && s_voice_phase=="SENT")) || js(root,"target")!=selected_target()) {stop_speech();return true;} + if (s_approval.modal() || (s_input_modal!=InputModal::NONE && !(s_input_modal==InputModal::VOICE && s_voice_phase=="SENT")) || js(root,"target")!=selected_target()) {ESP_LOGW(TAG,"[DIAG_SPEECH] rejected_start approval=%d modal=%s target_match=%d",s_approval.modal(),modal_name(s_input_modal),js(root,"target")==selected_target());stop_speech();return true;} if (s_input_modal==InputModal::VOICE) cancel_input(false,"speech-preemption"); if (s_speech.start(id,number("sample_rate"),number("bits"),number("channels"))) { if (++s_speech_generation==0) ++s_speech_generation; @@ -2951,7 +2951,8 @@ void board_control_message(const char *json) { if(history_message(root,type)) {cJSON_Delete(root);draw_status();return;} if (speech_settings_message(root,type)) {cJSON_Delete(root);draw_status();return;} if (type.rfind("speech_",0)==0) { - cJSON_Delete(root);return; + const bool redraw=speech_message(root,type); + cJSON_Delete(root);if(redraw) draw_status();return; } if (type.rfind("voice_",0)==0 && s_input_modal==InputModal::VOICE && js(root,"voice_id")==s_voice_id) { if (type=="voice_error") {audio_backend_record_stop(true);s_voice_phase="VOICE ERROR\n"+js(root,"message");s_transcript.clear();} diff --git a/firmware/main/CMakeLists.txt b/firmware/main/CMakeLists.txt index b737a70..2295962 100644 --- a/firmware/main/CMakeLists.txt +++ b/firmware/main/CMakeLists.txt @@ -1,7 +1,13 @@ idf_component_register( - SRCS "app_main.cpp" "cloud_client.cpp" "wifi_manager.cpp" + SRCS "app_main.cpp" "cloud_client.cpp" "wifi_manager.cpp" "net_trace.cpp" INCLUDE_DIRS "." REQUIRES m5stack_stopwatch esp_event esp_netif esp_wifi esp_timer esp_websocket_client json nvs_flash mbedtls ) target_compile_definitions(${COMPONENT_LIB} PRIVATE DEVICE_LAB_FIRMWARE_VERSION="0.6.3-dev") + +target_link_options(${COMPONENT_LIB} INTERFACE "-Wl,--wrap=mbedtls_net_recv") + +target_link_options(${COMPONENT_LIB} INTERFACE "-Wl,--wrap=lwip_getaddrinfo") + +target_link_options(${COMPONENT_LIB} INTERFACE "-Wl,--wrap=tcp_segs_free" "-Wl,--wrap=esp_netif_receive" "-Wl,--wrap=esp_netif_free_rx_buffer") diff --git a/firmware/main/cloud_client.cpp b/firmware/main/cloud_client.cpp index e9cec79..c545fa2 100644 --- a/firmware/main/cloud_client.cpp +++ b/firmware/main/cloud_client.cpp @@ -1,3 +1,4 @@ +extern "C" void speech_diag_net_init(); #include "cloud_client.h" #include @@ -24,6 +25,8 @@ #include "freertos/event_groups.h" #include "freertos/task.h" #include "wifi_manager.h" +#include "../../.cache/speech-diagnostics/lan_ca.h" +#include "../../.cache/lan_config.h" // Isolated diagnostic LAN configuration. static const char *TAG = "CLOUD"; static constexpr int CLOUD_RECONNECT_TIMEOUT_MS = 1500; @@ -37,6 +40,8 @@ static char s_device_id[24]; static WebSocketTextReceiver s_text_receiver; static int64_t s_rx_started_us, s_last_rx_trace_us; static unsigned s_rx_parts; +struct RxTrace { int64_t us; int offset, bytes, total; unsigned opcode, fin; }; +static RxTrace s_rx_trace[16]; static const char *link_error_type(esp_websocket_error_type_t type) { @@ -141,8 +146,8 @@ static void send_hello(void) // playback. Playback stays FROZEN: no speech_playback capability is // advertised, so the Gateway never sends speech_start/chunk/end to this // firmware and a saved mode cannot re-enable playback. - const char *capabilities[]={"agent_target","approval","voice_input","settings","catalog","target-select","permissions","native-interaction","session-create","speech-settings"}; - cJSON_AddItemToObject(root,"capabilities",cJSON_CreateStringArray(capabilities,10)); + const char *capabilities[]={"agent_target","approval","voice_input","settings","catalog","target-select","permissions","native-interaction","session-create","speech-settings","speech_playback"}; + cJSON_AddItemToObject(root,"capabilities",cJSON_CreateStringArray(capabilities,11)); if (send_json(root)) { ESP_LOGI(TAG, "[CLOUD] sent hello device_id=%s", s_device_id); } @@ -313,7 +318,11 @@ static void websocket_event(void *, esp_event_base_t, int32_t event_id, void *ev s_rx_started_us = esp_timer_get_time(); s_rx_parts = 0; } - if (event->op_code == 0x1 || event->op_code == 0x0) ++s_rx_parts; + if (event->op_code == 0x1 || event->op_code == 0x0) { + if (s_rx_parts < 16) s_rx_trace[s_rx_parts] = {esp_timer_get_time(), event->payload_offset, + event->data_len, event->payload_len, event->op_code, event->fin}; + ++s_rx_parts; + } const auto result = s_text_receiver.receive(event->op_code, event->fin, event->data_ptr, event->data_len, event->payload_len, event->payload_offset); if (result == WebSocketTextReceiver::Result::COMPLETE) { @@ -324,6 +333,18 @@ static void websocket_event(void *, esp_event_base_t, int32_t event_id, void *ev s_last_rx_trace_us = now; log_link_health("slow-text", s_text_receiver.size(), s_rx_parts, elapsed_ms); } + if (s_text_receiver.size() > 9000) { + const char *seq = strstr(s_text_receiver.data(), "\"sequence\""); + const int sequence = seq ? atoi(strchr(seq, ':') + 1) : -1; + // Retain timestamps during receive, print only after frame completion. + for (unsigned i=0; i #include @@ -62,6 +63,7 @@ esp_err_t wifi_manager_start(void) // Credentials are already supplied by Kconfig on every boot. Keep Wi-Fi // independent of preference-store failure and never write its namespace. init.nvs_enable = false; + ESP_LOGI(TAG, "[WIFI_RX_DIAG] dynamic_limit=%d",init.dynamic_rx_buf_num); ESP_ERROR_CHECK(esp_wifi_init(&init)); ESP_ERROR_CHECK(esp_wifi_set_storage(WIFI_STORAGE_RAM)); ESP_ERROR_CHECK(esp_event_handler_instance_register(