chore(logging): trim firmware logs and remove runtime diagnostics scaffolding

This commit is contained in:
admin
2026-03-02 03:26:03 +08:00
parent d83111191d
commit 6d82ccae3e
20 changed files with 81 additions and 630 deletions

View File

@@ -45,7 +45,6 @@ static void lifecycle_set_state_locked(control_plane_lifecycle_state_t state,
s_status.last_error = last_error; s_status.last_error = last_error;
s_status.last_transition_ms = esp_timer_get_time() / 1000; s_status.last_transition_ms = esp_timer_get_time() / 1000;
strlcpy(s_status.last_stage, stage != NULL ? stage : "unknown", sizeof(s_status.last_stage)); strlcpy(s_status.last_stage, stage != NULL ? stage : "unknown", sizeof(s_status.last_stage));
domain_diag_set_gauge(DOMAIN_DIAG_GAUGE_LIFECYCLE_STATE, (int32_t)state);
} }
const char *control_plane_lifecycle_state_str(control_plane_lifecycle_state_t state) { const char *control_plane_lifecycle_state_str(control_plane_lifecycle_state_t state) {
@@ -125,7 +124,6 @@ static esp_err_t lifecycle_run_step_with_retry(const char *stage, lifecycle_step
return rc; return rc;
} }
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_START_RETRY, 1);
vTaskDelay(pdMS_TO_TICKS(domain_policy_lifecycle_retry_backoff_ms(attempt))); vTaskDelay(pdMS_TO_TICKS(domain_policy_lifecycle_retry_backoff_ms(attempt)));
} }
@@ -133,11 +131,8 @@ static esp_err_t lifecycle_run_step_with_retry(const char *stage, lifecycle_step
} }
esp_err_t control_plane_lifecycle_start(void) { esp_err_t control_plane_lifecycle_start(void) {
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_START_ATTEMPT, 1);
if (!lifecycle_lock_take(1000)) { if (!lifecycle_lock_take(1000)) {
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_START_FAILED, 1);
domain_diag_record_error("lifecycle_start", ESP_ERR_TIMEOUT, "lifecycle lock timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
@@ -188,7 +183,6 @@ esp_err_t control_plane_lifecycle_start(void) {
xSemaphoreGive(s_lock); xSemaphoreGive(s_lock);
} }
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_START_SUCCESS, 1);
ESP_LOGI(TAG, "control-plane lifecycle started"); ESP_LOGI(TAG, "control-plane lifecycle started");
return ESP_OK; return ESP_OK;
@@ -208,8 +202,6 @@ start_failed:
xSemaphoreGive(s_lock); xSemaphoreGive(s_lock);
} }
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_START_FAILED, 1);
domain_diag_record_error("lifecycle_start", rc, failed_stage);
ESP_LOGE(TAG, ESP_LOGE(TAG,
"control-plane lifecycle start failed at stage=%s, rc=0x%x", "control-plane lifecycle start failed at stage=%s, rc=0x%x",
failed_stage, failed_stage,
@@ -218,11 +210,8 @@ start_failed:
} }
esp_err_t control_plane_lifecycle_stop(void) { esp_err_t control_plane_lifecycle_stop(void) {
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_ATTEMPT, 1);
if (!lifecycle_lock_take(1000)) { if (!lifecycle_lock_take(1000)) {
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_FAILED, 1);
domain_diag_record_error("lifecycle_stop", ESP_ERR_TIMEOUT, "lifecycle lock timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
@@ -266,11 +255,8 @@ esp_err_t control_plane_lifecycle_stop(void) {
} }
if (first_err == ESP_OK) { if (first_err == ESP_OK) {
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_SUCCESS, 1);
ESP_LOGI(TAG, "control-plane lifecycle stopped"); ESP_LOGI(TAG, "control-plane lifecycle stopped");
} else { } else {
domain_diag_counter_add(DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_FAILED, 1);
domain_diag_record_error("lifecycle_stop", first_err, "control-plane stop failed");
ESP_LOGE(TAG, "control-plane lifecycle stop failed, rc=0x%x", (unsigned)first_err); ESP_LOGE(TAG, "control-plane lifecycle stop failed, rc=0x%x", (unsigned)first_err);
} }

View File

@@ -33,40 +33,6 @@ uint32_t domain_policy_image_download_timeout_default_ms(void);
uint32_t domain_policy_image_download_timeout_min_ms(void); uint32_t domain_policy_image_download_timeout_min_ms(void);
uint32_t domain_policy_image_download_timeout_max_ms(void); uint32_t domain_policy_image_download_timeout_max_ms(void);
// ---------- domain_diagnostics ----------
typedef enum {
DOMAIN_DIAG_COUNTER_LIFECYCLE_START_ATTEMPT = 0,
DOMAIN_DIAG_COUNTER_LIFECYCLE_START_SUCCESS,
DOMAIN_DIAG_COUNTER_LIFECYCLE_START_FAILED,
DOMAIN_DIAG_COUNTER_LIFECYCLE_START_RETRY,
DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_ATTEMPT,
DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_SUCCESS,
DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_FAILED,
DOMAIN_DIAG_COUNTER_WIFI_CONNECT_SUCCESS,
DOMAIN_DIAG_COUNTER_WIFI_CONNECT_FAILED,
DOMAIN_DIAG_COUNTER_WIFI_CONNECT_TIMEOUT,
DOMAIN_DIAG_COUNTER_PRINTER_JOB_SUBMITTED,
DOMAIN_DIAG_COUNTER_PRINTER_JOB_SUCCESS,
DOMAIN_DIAG_COUNTER_PRINTER_JOB_FAILED,
DOMAIN_DIAG_COUNTER_PRINTER_JOB_CANCELED,
DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_ATTEMPT,
DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_SUCCESS,
DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_FAILED,
DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_TIMEOUT,
DOMAIN_DIAG_COUNTER_MAX,
} domain_diag_counter_t;
typedef enum {
DOMAIN_DIAG_GAUGE_LIFECYCLE_STATE = 0,
DOMAIN_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH,
DOMAIN_DIAG_GAUGE_PRINTER_QUEUE_DEPTH,
DOMAIN_DIAG_GAUGE_MAX,
} domain_diag_gauge_t;
void domain_diag_counter_add(domain_diag_counter_t counter, uint32_t delta);
void domain_diag_set_gauge(domain_diag_gauge_t gauge, int32_t value);
void domain_diag_record_error(const char *source, esp_err_t code, const char *message);
// ---------- raster_tools ---------- // ---------- raster_tools ----------
esp_err_t raster_tools_render_text_384(const char *text, esp_err_t raster_tools_render_text_384(const char *text,
uint8_t scale, uint8_t scale,

View File

@@ -78,7 +78,6 @@ typedef struct {
bool stop_requested; bool stop_requested;
bool ws_text_shutdown; bool ws_text_shutdown;
bool ws_text_busy; bool ws_text_busy;
bool ws_low_stack_warned;
bool response_first_sentence_checked; bool response_first_sentence_checked;
voice_dialog_state_t dialog_state; voice_dialog_state_t dialog_state;
@@ -102,8 +101,6 @@ void voice_fill_err(char *err, size_t err_len, const char *msg);
void voice_set_last_error_locked(const char *msg); void voice_set_last_error_locked(const char *msg);
bool voice_lock(uint32_t timeout_ms); bool voice_lock(uint32_t timeout_ms);
void voice_unlock(void); void voice_unlock(void);
void voice_log_status_snapshot(const char *stage);
void voice_log_heap_snapshot(const char *stage);
void voice_wait_audio_playback_done(uint32_t timeout_ms, const char *stage); void voice_wait_audio_playback_done(uint32_t timeout_ms, const char *stage);
void voice_close_audio_with_drain(uint32_t timeout_ms, const char *stage); void voice_close_audio_with_drain(uint32_t timeout_ms, const char *stage);

View File

@@ -2,62 +2,6 @@
#include "platform.h" #include "platform.h"
static runtime_diag_counter_t to_platform_counter(domain_diag_counter_t counter) {
switch (counter) {
case DOMAIN_DIAG_COUNTER_LIFECYCLE_START_ATTEMPT:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_START_ATTEMPT;
case DOMAIN_DIAG_COUNTER_LIFECYCLE_START_SUCCESS:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_START_SUCCESS;
case DOMAIN_DIAG_COUNTER_LIFECYCLE_START_FAILED:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_START_FAILED;
case DOMAIN_DIAG_COUNTER_LIFECYCLE_START_RETRY:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_START_RETRY;
case DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_ATTEMPT:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_STOP_ATTEMPT;
case DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_SUCCESS:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_STOP_SUCCESS;
case DOMAIN_DIAG_COUNTER_LIFECYCLE_STOP_FAILED:
return RUNTIME_DIAG_COUNTER_LIFECYCLE_STOP_FAILED;
case DOMAIN_DIAG_COUNTER_WIFI_CONNECT_SUCCESS:
return RUNTIME_DIAG_COUNTER_WIFI_CONNECT_SUCCESS;
case DOMAIN_DIAG_COUNTER_WIFI_CONNECT_FAILED:
return RUNTIME_DIAG_COUNTER_WIFI_CONNECT_FAILED;
case DOMAIN_DIAG_COUNTER_WIFI_CONNECT_TIMEOUT:
return RUNTIME_DIAG_COUNTER_WIFI_CONNECT_TIMEOUT;
case DOMAIN_DIAG_COUNTER_PRINTER_JOB_SUBMITTED:
return RUNTIME_DIAG_COUNTER_PRINTER_JOB_SUBMITTED;
case DOMAIN_DIAG_COUNTER_PRINTER_JOB_SUCCESS:
return RUNTIME_DIAG_COUNTER_PRINTER_JOB_SUCCESS;
case DOMAIN_DIAG_COUNTER_PRINTER_JOB_FAILED:
return RUNTIME_DIAG_COUNTER_PRINTER_JOB_FAILED;
case DOMAIN_DIAG_COUNTER_PRINTER_JOB_CANCELED:
return RUNTIME_DIAG_COUNTER_PRINTER_JOB_CANCELED;
case DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_ATTEMPT:
return RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_ATTEMPT;
case DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_SUCCESS:
return RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_SUCCESS;
case DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_FAILED:
return RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_FAILED;
case DOMAIN_DIAG_COUNTER_IMAGE_GENERATE_TIMEOUT:
return RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_TIMEOUT;
default:
return RUNTIME_DIAG_COUNTER_MAX;
}
}
static runtime_diag_gauge_t to_platform_gauge(domain_diag_gauge_t gauge) {
switch (gauge) {
case DOMAIN_DIAG_GAUGE_LIFECYCLE_STATE:
return RUNTIME_DIAG_GAUGE_LIFECYCLE_STATE;
case DOMAIN_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH:
return RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH;
case DOMAIN_DIAG_GAUGE_PRINTER_QUEUE_DEPTH:
return RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH;
default:
return RUNTIME_DIAG_GAUGE_MAX;
}
}
uint32_t domain_policy_lifecycle_start_retry_count(void) { uint32_t domain_policy_lifecycle_start_retry_count(void) {
return runtime_policy_lifecycle_start_retry_count(); return runtime_policy_lifecycle_start_retry_count();
} }
@@ -97,23 +41,3 @@ uint32_t domain_policy_image_download_timeout_min_ms(void) {
uint32_t domain_policy_image_download_timeout_max_ms(void) { uint32_t domain_policy_image_download_timeout_max_ms(void) {
return runtime_policy_image_download_timeout_max_ms(); return runtime_policy_image_download_timeout_max_ms();
} }
void domain_diag_counter_add(domain_diag_counter_t counter, uint32_t delta) {
runtime_diag_counter_t mapped = to_platform_counter(counter);
if (mapped >= RUNTIME_DIAG_COUNTER_MAX) {
return;
}
runtime_diag_counter_add(mapped, delta);
}
void domain_diag_set_gauge(domain_diag_gauge_t gauge, int32_t value) {
runtime_diag_gauge_t mapped = to_platform_gauge(gauge);
if (mapped >= RUNTIME_DIAG_GAUGE_MAX) {
return;
}
runtime_diag_set_gauge(mapped, value);
}
void domain_diag_record_error(const char *source, esp_err_t code, const char *message) {
runtime_diag_record_error(source, code, message);
}

View File

@@ -845,11 +845,9 @@ esp_err_t image_generation_generate_png(const image_generation_request_t *req,
image_generation_result_t *out_result, image_generation_result_t *out_result,
char *err, char *err,
size_t err_len) { size_t err_len) {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_ATTEMPT, 1);
if (req == NULL || out_result == NULL || req->prompt == NULL || req->prompt[0] == '\0') { if (req == NULL || out_result == NULL || req->prompt == NULL || req->prompt[0] == '\0') {
image_generation_fill_err(err, err_len, "prompt is required"); image_generation_fill_err(err, err_len, "prompt is required");
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_FAILED, 1);
return ESP_ERR_INVALID_ARG; return ESP_ERR_INVALID_ARG;
} }
@@ -879,12 +877,6 @@ esp_err_t image_generation_generate_png(const image_generation_request_t *req,
"image generate stage failed, rc=0x%x, msg=%s", "image generate stage failed, rc=0x%x, msg=%s",
(unsigned)gen_rc, (unsigned)gen_rc,
(err != NULL && err[0] != '\0') ? err : "model invoke failed"); (err != NULL && err[0] != '\0') ? err : "model invoke failed");
if (gen_rc == ESP_ERR_TIMEOUT) {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_TIMEOUT, 1);
} else {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_FAILED, 1);
}
runtime_diag_record_error("image_generate", gen_rc, err != NULL ? err : "model invoke failed");
image_generation_result_free(out_result); image_generation_result_free(out_result);
return gen_rc; return gen_rc;
} }
@@ -900,12 +892,6 @@ esp_err_t image_generation_generate_png(const image_generation_request_t *req,
"image download stage failed, rc=0x%x, msg=%s", "image download stage failed, rc=0x%x, msg=%s",
(unsigned)dl_rc, (unsigned)dl_rc,
(err != NULL && err[0] != '\0') ? err : "download failed"); (err != NULL && err[0] != '\0') ? err : "download failed");
if (dl_rc == ESP_ERR_TIMEOUT) {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_TIMEOUT, 1);
} else {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_FAILED, 1);
}
runtime_diag_record_error("image_download", dl_rc, err != NULL ? err : "download failed");
image_generation_result_free(out_result); image_generation_result_free(out_result);
return dl_rc; return dl_rc;
} }
@@ -919,7 +905,6 @@ esp_err_t image_generation_generate_png(const image_generation_request_t *req,
(long long)(t_gen_done_ms - t0_ms), (long long)(t_gen_done_ms - t0_ms),
(long long)(t_dl_done_ms - t_gen_done_ms), (long long)(t_dl_done_ms - t_gen_done_ms),
(long long)(t_dl_done_ms - t0_ms)); (long long)(t_dl_done_ms - t0_ms));
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_SUCCESS, 1);
return ESP_OK; return ESP_OK;
} }

View File

@@ -172,8 +172,6 @@ printer_status_poll_pause_token_t printer_protocol_status_poll_pause_acquire(voi
} }
s_status_poll_pause_tokens[slot] = token; s_status_poll_pause_tokens[slot] = token;
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH,
(int32_t)status_poll_pause_depth_locked());
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
return token; return token;
} }
@@ -199,8 +197,6 @@ void printer_protocol_status_poll_pause_release(printer_status_poll_pause_token_
} }
} }
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH,
(int32_t)status_poll_pause_depth_locked());
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
*token = 0; *token = 0;
} }
@@ -281,8 +277,6 @@ esp_err_t printer_protocol_init(void) {
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
} }
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH, 0);
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH, 0);
s_protocol_initialized = true; s_protocol_initialized = true;
s_protocol_stopping = false; s_protocol_stopping = false;
@@ -345,8 +339,6 @@ esp_err_t printer_protocol_stop(uint32_t timeout_ms) {
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
} }
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH, 0);
if (s_evt != NULL) { if (s_evt != NULL) {
xEventGroupSetBits(s_evt, EVT_SHUTDOWN); xEventGroupSetBits(s_evt, EVT_SHUTDOWN);
} }
@@ -396,9 +388,6 @@ esp_err_t printer_protocol_stop(uint32_t timeout_ms) {
s_protocol_initialized = false; s_protocol_initialized = false;
s_protocol_stopping = false; s_protocol_stopping = false;
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH, 0);
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH, 0);
platform_printer_deinit(); platform_printer_deinit();
ESP_LOGI(TAG, "printer protocol stopped"); ESP_LOGI(TAG, "printer protocol stopped");
@@ -439,6 +428,4 @@ void printer_protocol_get_runtime_status(printer_runtime_status_t *out_status) {
: 0; : 0;
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
} }
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH, (int32_t)out_status->queue_depth);
} }

View File

@@ -177,8 +177,6 @@ esp_err_t printer_protocol_submit_raster_job_ex(const uint8_t *raster,
density != NULL ? density : "中等", density != NULL ? density : "中等",
ignore_precheck, ignore_precheck,
(unsigned)queue_depth); (unsigned)queue_depth);
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_PRINTER_JOB_SUBMITTED, 1);
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH, (int32_t)queue_depth);
return ESP_OK; return ESP_OK;
} }
@@ -320,7 +318,6 @@ esp_err_t printer_protocol_cancel_job(uint32_t job_id, char *err, size_t err_len
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
if (canceled_finalized) { if (canceled_finalized) {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_PRINTER_JOB_CANCELED, 1);
} }
return ESP_OK; return ESP_OK;
} }
@@ -357,7 +354,5 @@ size_t printer_protocol_cleanup_jobs(bool include_success, bool include_failed,
} }
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH,
s_job_queue != NULL ? (int32_t)uxQueueMessagesWaiting(s_job_queue) : 0);
return removed; return removed;
} }

View File

@@ -211,16 +211,13 @@ void printer_protocol_worker_task(void *arg) {
if (ok) { if (ok) {
s_jobs[idx].state = PRINT_JOB_STATE_SUCCESS; s_jobs[idx].state = PRINT_JOB_STATE_SUCCESS;
s_jobs[idx].error[0] = 0; s_jobs[idx].error[0] = 0;
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_PRINTER_JOB_SUCCESS, 1);
} else if (s_jobs[idx].cancel_requested || printer_protocol_is_stopping()) { } else if (s_jobs[idx].cancel_requested || printer_protocol_is_stopping()) {
s_jobs[idx].state = PRINT_JOB_STATE_CANCELED; s_jobs[idx].state = PRINT_JOB_STATE_CANCELED;
if (s_jobs[idx].error[0] == 0) { if (s_jobs[idx].error[0] == 0) {
strlcpy(s_jobs[idx].error, "job canceled", sizeof(s_jobs[idx].error)); strlcpy(s_jobs[idx].error, "job canceled", sizeof(s_jobs[idx].error));
} }
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_PRINTER_JOB_CANCELED, 1);
} else { } else {
s_jobs[idx].state = PRINT_JOB_STATE_FAILED; s_jobs[idx].state = PRINT_JOB_STATE_FAILED;
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_PRINTER_JOB_FAILED, 1);
} }
int64_t duration_ms = 0; int64_t duration_ms = 0;
@@ -244,8 +241,6 @@ void printer_protocol_worker_task(void *arg) {
free(s_jobs[idx].data); free(s_jobs[idx].data);
s_jobs[idx].data = NULL; s_jobs[idx].data = NULL;
runtime_diag_set_gauge(RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH,
(int32_t)uxQueueMessagesWaiting(s_job_queue));
xSemaphoreGive(s_mutex); xSemaphoreGive(s_mutex);
} }

View File

@@ -65,7 +65,7 @@ static bool voice_wait_worker_tasks_exit(uint32_t timeout_ms) {
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] worker_task_exit_timeout: uplink_alive=%d heartbeat_alive=%d ws_text_alive=%d", "worker_task_exit_timeout: uplink_alive=%d heartbeat_alive=%d ws_text_alive=%d",
s_voice.uplink_task != NULL, s_voice.uplink_task != NULL,
s_voice.heartbeat_task != NULL, s_voice.heartbeat_task != NULL,
s_voice.ws_text_task != NULL); s_voice.ws_text_task != NULL);
@@ -118,10 +118,9 @@ esp_err_t voice_interaction_init(void) {
esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, size_t err_len) { esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, size_t err_len) {
uint32_t connect_timeout_ms = uint32_t connect_timeout_ms =
clamp_timeout_ms(timeout_ms, VOICE_START_CONNECT_TIMEOUT_MS, 1000, 30000); clamp_timeout_ms(timeout_ms, VOICE_START_CONNECT_TIMEOUT_MS, 1000, 30000);
ESP_LOGI(TAG, "[stage] session_start_enter");
if (!s_voice.ready) { if (!s_voice.ready) {
voice_fill_err(err, err_len, "voice interaction not initialized"); voice_fill_err(err, err_len, "voice interaction not initialized");
ESP_LOGW(TAG, "[stage] session_start_abort: not initialized"); ESP_LOGW(TAG, "session_start_abort: not initialized");
return ESP_ERR_INVALID_STATE; return ESP_ERR_INVALID_STATE;
} }
@@ -129,20 +128,13 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
strlen(CONFIG_TQ_VOICE_WORKSPACE_ID) == 0 || strlen(CONFIG_TQ_VOICE_WORKSPACE_ID) == 0 ||
strlen(CONFIG_TQ_VOICE_APP_ID) == 0) { strlen(CONFIG_TQ_VOICE_APP_ID) == 0) {
voice_fill_err(err, err_len, "voice API key/workspace/app_id is missing"); voice_fill_err(err, err_len, "voice API key/workspace/app_id is missing");
ESP_LOGW(TAG, "[stage] session_start_abort: config missing"); ESP_LOGW(TAG, "session_start_abort: config missing");
return ESP_ERR_INVALID_STATE; return ESP_ERR_INVALID_STATE;
} }
ESP_LOGI(TAG,
"[stage] session_config_ok: ws_uri=%s sample_rate=%d frame_ms=%d bitrate_kbps=%d ws_stack=%d",
CONFIG_TQ_VOICE_WS_URI,
CONFIG_TQ_VOICE_SAMPLE_RATE,
CONFIG_TQ_VOICE_OPUS_FRAME_MS,
CONFIG_TQ_VOICE_OPUS_BITRATE_KBPS,
VOICE_WS_TASK_STACK);
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGW(TAG, "[stage] session_start_abort: lock timeout"); ESP_LOGW(TAG, "session_start_abort: lock timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
bool already_active = s_voice.session_active; bool already_active = s_voice.session_active;
@@ -152,13 +144,11 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
if (already_active) { if (already_active) {
if (ws_connected && started) { if (ws_connected && started) {
ESP_LOGI(TAG, "[stage] session_start_skip: already active");
voice_log_status_snapshot("already_active");
return ESP_OK; return ESP_OK;
} }
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] session_start_recover: active=%d ws_connected=%d started=%d", "session_start_recover: active=%d ws_connected=%d started=%d",
already_active, already_active,
ws_connected, ws_connected,
started); started);
@@ -167,13 +157,11 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
voice_interaction_ws_init_cjson_hooks(); voice_interaction_ws_init_cjson_hooks();
ESP_LOGI(TAG, "[stage] opus_setup_begin");
esp_err_t opus_setup_err = voice_setup_opus(err, err_len); esp_err_t opus_setup_err = voice_setup_opus(err, err_len);
if (opus_setup_err != ESP_OK) { if (opus_setup_err != ESP_OK) {
ESP_LOGE(TAG, "voice opus setup failed: %s", esp_err_to_name(opus_setup_err)); ESP_LOGE(TAG, "voice opus setup failed: %s", esp_err_to_name(opus_setup_err));
goto exit_err; goto exit_err;
} }
ESP_LOGI(TAG, "[stage] opus_setup_ok");
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_make_uuid(s_voice.task_id); voice_make_uuid(s_voice.task_id);
@@ -188,7 +176,6 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
s_voice.stop_requested = false; s_voice.stop_requested = false;
s_voice.tap_active = false; s_voice.tap_active = false;
s_voice.speech_active = false; s_voice.speech_active = false;
s_voice.ws_low_stack_warned = false;
s_voice.response_first_sentence_checked = false; s_voice.response_first_sentence_checked = false;
s_voice.uplink_task_with_caps = false; s_voice.uplink_task_with_caps = false;
s_voice.heartbeat_task_with_caps = false; s_voice.heartbeat_task_with_caps = false;
@@ -196,10 +183,6 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
s_voice.ws_text_shutdown = false; s_voice.ws_text_shutdown = false;
s_voice.ws_text_busy = false; s_voice.ws_text_busy = false;
s_voice.last_event_ms = voice_now_ms(); s_voice.last_event_ms = voice_now_ms();
ESP_LOGI(TAG,
"[stage] session_context_prepared: task_id=%s device_uuid=%s",
s_voice.task_id,
s_voice.device_uuid);
voice_unlock(); voice_unlock();
} }
@@ -222,54 +205,47 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
#endif #endif
}; };
ESP_LOGI(TAG, "[stage] ws_init_begin");
esp_websocket_client_handle_t ws = esp_websocket_client_init(&ws_cfg); esp_websocket_client_handle_t ws = esp_websocket_client_init(&ws_cfg);
if (ws == NULL) { if (ws == NULL) {
voice_fill_err(err, err_len, "websocket init failed"); voice_fill_err(err, err_len, "websocket init failed");
ESP_LOGE(TAG, "[stage] ws_init_failed"); ESP_LOGE(TAG, "ws_init_failed");
goto exit_err; goto exit_err;
} }
ESP_LOGI(TAG, "[stage] ws_init_ok");
size_t auth_len = strlen(CONFIG_TQ_VOICE_API_KEY) + 8; size_t auth_len = strlen(CONFIG_TQ_VOICE_API_KEY) + 8;
char *auth_value = (char *)voice_malloc_prefer_psram(auth_len); char *auth_value = (char *)voice_malloc_prefer_psram(auth_len);
if (auth_value == NULL) { if (auth_value == NULL) {
voice_fill_err(err, err_len, "no memory for auth header"); voice_fill_err(err, err_len, "no memory for auth header");
ESP_LOGE(TAG, "[stage] ws_auth_header_alloc_failed"); ESP_LOGE(TAG, "ws_auth_header_alloc_failed");
esp_websocket_client_destroy(ws); esp_websocket_client_destroy(ws);
goto exit_err; goto exit_err;
} }
snprintf(auth_value, auth_len, "Bearer %s", CONFIG_TQ_VOICE_API_KEY); snprintf(auth_value, auth_len, "Bearer %s", CONFIG_TQ_VOICE_API_KEY);
esp_websocket_client_append_header(ws, "Authorization", auth_value); esp_websocket_client_append_header(ws, "Authorization", auth_value);
free(auth_value); free(auth_value);
ESP_LOGI(TAG, "[stage] ws_auth_header_set");
ESP_LOGI(TAG, "[stage] ws_register_events_begin");
esp_err_t reg_err = esp_websocket_register_events(ws, esp_err_t reg_err = esp_websocket_register_events(ws,
WEBSOCKET_EVENT_ANY, WEBSOCKET_EVENT_ANY,
voice_websocket_event_handler, voice_websocket_event_handler,
NULL); NULL);
if (reg_err != ESP_OK) { if (reg_err != ESP_OK) {
voice_fill_err(err, err_len, "websocket register events failed"); voice_fill_err(err, err_len, "websocket register events failed");
ESP_LOGE(TAG, "[stage] ws_register_events_failed: %s", esp_err_to_name(reg_err)); ESP_LOGE(TAG, "ws_register_events_failed: %s", esp_err_to_name(reg_err));
esp_websocket_client_destroy(ws); esp_websocket_client_destroy(ws);
goto exit_err; goto exit_err;
} }
ESP_LOGI(TAG, "[stage] ws_register_events_ok");
ESP_LOGI(TAG, "[stage] ws_start_begin");
esp_err_t ws_start_err = esp_websocket_client_start(ws); esp_err_t ws_start_err = esp_websocket_client_start(ws);
if (ws_start_err != ESP_OK) { if (ws_start_err != ESP_OK) {
voice_fill_err(err, err_len, "websocket start failed"); voice_fill_err(err, err_len, "websocket start failed");
ESP_LOGE(TAG, "[stage] ws_start_failed: %s", esp_err_to_name(ws_start_err)); ESP_LOGE(TAG, "ws_start_failed: %s", esp_err_to_name(ws_start_err));
esp_websocket_client_destroy(ws); esp_websocket_client_destroy(ws);
goto exit_err; goto exit_err;
} }
ESP_LOGI(TAG, "[stage] ws_start_ok");
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGE(TAG, "[stage] session_start_abort: lock timeout after ws_start"); ESP_LOGE(TAG, "session_start_abort: lock timeout after ws_start");
esp_websocket_client_stop(ws); esp_websocket_client_stop(ws);
esp_websocket_client_destroy(ws); esp_websocket_client_destroy(ws);
goto exit_err; goto exit_err;
@@ -282,12 +258,10 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
s_voice.ws_text_shutdown = false; s_voice.ws_text_shutdown = false;
s_voice.ws_text_busy = false; s_voice.ws_text_busy = false;
voice_unlock(); voice_unlock();
voice_log_status_snapshot("session_marked_active");
voice_log_heap_snapshot("before_create_uplink");
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGE(TAG, "[stage] session_start_abort: lock timeout before ws_text_task create"); ESP_LOGE(TAG, "session_start_abort: lock timeout before ws_text_task create");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
@@ -298,12 +272,11 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
voice_unlock(); voice_unlock();
if (ws_text_queue == NULL) { if (ws_text_queue == NULL) {
voice_fill_err(err, err_len, "create ws text queue failed"); voice_fill_err(err, err_len, "create ws text queue failed");
ESP_LOGE(TAG, "[stage] ws_text_queue_create_failed"); ESP_LOGE(TAG, "ws_text_queue_create_failed");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_NO_MEM; return ESP_ERR_NO_MEM;
} }
ESP_LOGI(TAG, "[stage] ws_text_task_create_begin");
BaseType_t ok = voice_create_task_prefer_psram(voice_ws_text_task, BaseType_t ok = voice_create_task_prefer_psram(voice_ws_text_task,
"voice_ws_text", "voice_ws_text",
VOICE_HEARTBEAT_TASK_STACK, VOICE_HEARTBEAT_TASK_STACK,
@@ -312,13 +285,11 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
&s_voice.ws_text_task_with_caps); &s_voice.ws_text_task_with_caps);
if (ok != pdPASS) { if (ok != pdPASS) {
voice_fill_err(err, err_len, "create ws text task failed"); voice_fill_err(err, err_len, "create ws text task failed");
ESP_LOGE(TAG, "[stage] ws_text_task_create_failed"); ESP_LOGE(TAG, "ws_text_task_create_failed");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_NO_MEM; return ESP_ERR_NO_MEM;
} }
ESP_LOGI(TAG, "[stage] ws_text_task_create_ok");
ESP_LOGI(TAG, "[stage] uplink_task_create_begin");
ok = voice_create_task_prefer_psram(voice_uplink_task, ok = voice_create_task_prefer_psram(voice_uplink_task,
"voice_uplink", "voice_uplink",
VOICE_UPLINK_TASK_STACK, VOICE_UPLINK_TASK_STACK,
@@ -327,15 +298,11 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
&s_voice.uplink_task_with_caps); &s_voice.uplink_task_with_caps);
if (ok != pdPASS) { if (ok != pdPASS) {
voice_fill_err(err, err_len, "create uplink task failed"); voice_fill_err(err, err_len, "create uplink task failed");
ESP_LOGE(TAG, "[stage] uplink_task_create_failed"); ESP_LOGE(TAG, "uplink_task_create_failed");
voice_log_heap_snapshot("uplink_create_failed");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_NO_MEM; return ESP_ERR_NO_MEM;
} }
ESP_LOGI(TAG, "[stage] uplink_task_create_ok");
voice_log_heap_snapshot("after_create_uplink");
ESP_LOGI(TAG, "[stage] heartbeat_task_create_begin");
ok = voice_create_task_prefer_psram(voice_heartbeat_task, ok = voice_create_task_prefer_psram(voice_heartbeat_task,
"voice_hb", "voice_hb",
VOICE_HEARTBEAT_TASK_STACK, VOICE_HEARTBEAT_TASK_STACK,
@@ -344,15 +311,11 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
&s_voice.heartbeat_task_with_caps); &s_voice.heartbeat_task_with_caps);
if (ok != pdPASS) { if (ok != pdPASS) {
voice_fill_err(err, err_len, "create heartbeat task failed"); voice_fill_err(err, err_len, "create heartbeat task failed");
ESP_LOGE(TAG, "[stage] heartbeat_task_create_failed"); ESP_LOGE(TAG, "heartbeat_task_create_failed");
voice_log_heap_snapshot("heartbeat_create_failed");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_NO_MEM; return ESP_ERR_NO_MEM;
} }
ESP_LOGI(TAG, "[stage] heartbeat_task_create_ok");
voice_log_heap_snapshot("after_create_heartbeat");
ESP_LOGI(TAG, "[stage] wait_ws_connected_begin: timeout_ms=%u", (unsigned)connect_timeout_ms);
int64_t deadline = voice_now_ms() + connect_timeout_ms; int64_t deadline = voice_now_ms() + connect_timeout_ms;
while (voice_now_ms() < deadline) { while (voice_now_ms() < deadline) {
bool connected = false; bool connected = false;
@@ -368,7 +331,7 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGE(TAG, "[stage] wait_ws_connected_abort: lock timeout"); ESP_LOGE(TAG, "wait_ws_connected_abort: lock timeout");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
@@ -376,18 +339,15 @@ esp_err_t voice_interaction_start_with_timeout(uint32_t timeout_ms, char *err, s
voice_unlock(); voice_unlock();
if (!connected) { if (!connected) {
voice_fill_err(err, err_len, "websocket connect timeout"); voice_fill_err(err, err_len, "websocket connect timeout");
ESP_LOGE(TAG, "[stage] wait_ws_connected_timeout"); ESP_LOGE(TAG, "wait_ws_connected_timeout");
voice_log_status_snapshot("wait_ws_connected_timeout");
(void)voice_interaction_stop(NULL, 0); (void)voice_interaction_stop(NULL, 0);
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
ESP_LOGI(TAG, "[stage] wait_ws_connected_ok");
voice_log_status_snapshot("session_start_exit_ok");
return ESP_OK; return ESP_OK;
exit_err: exit_err:
ESP_LOGE(TAG, "[stage] session_start_exit_err: %s", (err != NULL && err[0] != '\0') ? err : "unknown"); ESP_LOGE(TAG, "session_start_exit_err: %s", (err != NULL && err[0] != '\0') ? err : "unknown");
voice_release_runtime_resources(); voice_release_runtime_resources();
voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_MS, "session_start_exit_err_close"); voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_MS, "session_start_exit_err_close");
return ESP_FAIL; return ESP_FAIL;
@@ -399,24 +359,22 @@ esp_err_t voice_interaction_start(char *err, size_t err_len) {
esp_err_t voice_interaction_stop_with_timeout(uint32_t timeout_ms, char *err, size_t err_len) { esp_err_t voice_interaction_stop_with_timeout(uint32_t timeout_ms, char *err, size_t err_len) {
uint32_t worker_exit_timeout_ms = clamp_timeout_ms(timeout_ms, 1500, 500, 10000); uint32_t worker_exit_timeout_ms = clamp_timeout_ms(timeout_ms, 1500, 500, 10000);
ESP_LOGI(TAG, "[stage] session_stop_enter");
if (!s_voice.ready) { if (!s_voice.ready) {
voice_fill_err(err, err_len, "voice interaction not initialized"); voice_fill_err(err, err_len, "voice interaction not initialized");
ESP_LOGW(TAG, "[stage] session_stop_abort: not initialized"); ESP_LOGW(TAG, "session_stop_abort: not initialized");
return ESP_ERR_INVALID_STATE; return ESP_ERR_INVALID_STATE;
} }
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGW(TAG, "[stage] session_stop_abort: lock timeout"); ESP_LOGW(TAG, "session_stop_abort: lock timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
if (!s_voice.session_active) { if (!s_voice.session_active) {
voice_unlock(); voice_unlock();
voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_MS, "session_stop_skip_close"); voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_MS, "session_stop_skip_close");
ESP_LOGI(TAG, "[stage] session_stop_skip: not active");
return ESP_OK; return ESP_OK;
} }
@@ -431,12 +389,11 @@ esp_err_t voice_interaction_stop_with_timeout(uint32_t timeout_ms, char *err, si
s_voice.tap_active = false; s_voice.tap_active = false;
s_voice.speech_active = false; s_voice.speech_active = false;
voice_unlock(); voice_unlock();
voice_log_status_snapshot("session_stop_requested");
if (ws_connected) { if (ws_connected) {
(void)voice_send_directive("finish-task", "Stop", true); (void)voice_send_directive("finish-task", "Stop", true);
if (!voice_wait_ws_text_idle(VOICE_WS_SEND_TIMEOUT_MS + 1200)) { if (!voice_wait_ws_text_idle(VOICE_WS_SEND_TIMEOUT_MS + 1200)) {
ESP_LOGW(TAG, "[stage] ws_text_idle_timeout_before_shutdown"); ESP_LOGW(TAG, "ws_text_idle_timeout_before_shutdown");
} }
} }
voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_ON_STOP_MS, "session_stop_close"); voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_ON_STOP_MS, "session_stop_close");
@@ -460,7 +417,7 @@ esp_err_t voice_interaction_stop_with_timeout(uint32_t timeout_ms, char *err, si
voice_set_last_error_locked("worker exit timeout"); voice_set_last_error_locked("worker exit timeout");
voice_unlock(); voice_unlock();
} }
ESP_LOGW(TAG, "[stage] session_stop_abort: workers still alive"); ESP_LOGW(TAG, "session_stop_abort: workers still alive");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
@@ -470,13 +427,11 @@ esp_err_t voice_interaction_stop_with_timeout(uint32_t timeout_ms, char *err, si
} }
if (ws != NULL) { if (ws != NULL) {
ESP_LOGI(TAG, "[stage] ws_stop_destroy_begin");
esp_websocket_unregister_events(ws, esp_websocket_unregister_events(ws,
WEBSOCKET_EVENT_ANY, WEBSOCKET_EVENT_ANY,
voice_websocket_event_handler); voice_websocket_event_handler);
esp_websocket_client_stop(ws); esp_websocket_client_stop(ws);
esp_websocket_client_destroy(ws); esp_websocket_client_destroy(ws);
ESP_LOGI(TAG, "[stage] ws_stop_destroy_ok");
} }
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
@@ -502,11 +457,9 @@ esp_err_t voice_interaction_stop_with_timeout(uint32_t timeout_ms, char *err, si
s_voice.playback_deadline_ms = 0; s_voice.playback_deadline_ms = 0;
voice_unlock(); voice_unlock();
} }
voice_log_status_snapshot("session_stop_cleared");
voice_release_runtime_resources(); voice_release_runtime_resources();
voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_MS, "session_stop_exit_close"); voice_close_audio_with_drain(VOICE_AUDIO_DRAIN_WAIT_MS, "session_stop_exit_close");
ESP_LOGI(TAG, "[stage] session_stop_exit_ok");
return ESP_OK; return ESP_OK;
} }
@@ -539,7 +492,7 @@ esp_err_t voice_interaction_try_send_speech(char *err, size_t err_len) {
esp_err_t send_err = voice_send_directive("continue-task", "SendSpeech", true); esp_err_t send_err = voice_send_directive("continue-task", "SendSpeech", true);
if (send_err != ESP_OK) { if (send_err != ESP_OK) {
voice_fill_err(err, err_len, "send speech failed"); voice_fill_err(err, err_len, "send speech failed");
ESP_LOGW(TAG, "[stage] send_speech_failed: rc=0x%x", (unsigned)send_err); ESP_LOGW(TAG, "send_speech_failed: rc=0x%x", (unsigned)send_err);
return send_err; return send_err;
} }
@@ -569,16 +522,15 @@ esp_err_t voice_interaction_try_send_speech(char *err, size_t err_len) {
} }
esp_err_t voice_interaction_tap_start(char *err, size_t err_len) { esp_err_t voice_interaction_tap_start(char *err, size_t err_len) {
ESP_LOGI(TAG, "[stage] tap_start_enter");
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGW(TAG, "[stage] tap_start_abort: lock timeout"); ESP_LOGW(TAG, "tap_start_abort: lock timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
if (!s_voice.session_active || !s_voice.ws_connected || !s_voice.started) { if (!s_voice.session_active || !s_voice.ws_connected || !s_voice.started) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] tap_start_abort: session_active=%d ws_connected=%d started=%d", "tap_start_abort: session_active=%d ws_connected=%d started=%d",
s_voice.session_active, s_voice.session_active,
s_voice.ws_connected, s_voice.ws_connected,
s_voice.started); s_voice.started);
@@ -588,24 +540,22 @@ esp_err_t voice_interaction_tap_start(char *err, size_t err_len) {
} }
voice_unlock(); voice_unlock();
voice_log_heap_snapshot("tap_start_before_audio_open");
esp_err_t audio_err = voice_open_audio_for_dialog(err, err_len); esp_err_t audio_err = voice_open_audio_for_dialog(err, err_len);
if (audio_err != ESP_OK) { if (audio_err != ESP_OK) {
voice_log_heap_snapshot("tap_start_audio_open_failed");
return audio_err; return audio_err;
} }
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
voice_audio_close(); voice_audio_close();
ESP_LOGW(TAG, "[stage] tap_start_abort: lock timeout after audio open"); ESP_LOGW(TAG, "tap_start_abort: lock timeout after audio open");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
if (!s_voice.session_active || !s_voice.ws_connected || !s_voice.started) { if (!s_voice.session_active || !s_voice.ws_connected || !s_voice.started) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] tap_start_abort_after_audio_open: session_active=%d ws_connected=%d started=%d", "tap_start_abort_after_audio_open: session_active=%d ws_connected=%d started=%d",
s_voice.session_active, s_voice.session_active,
s_voice.ws_connected, s_voice.ws_connected,
s_voice.started); s_voice.started);
@@ -619,7 +569,6 @@ esp_err_t voice_interaction_tap_start(char *err, size_t err_len) {
s_voice.tap_active = true; s_voice.tap_active = true;
s_voice.speech_active = false; s_voice.speech_active = false;
voice_unlock(); voice_unlock();
ESP_LOGI(TAG, "[stage] tap_start_marked_active: listening=%d", listening);
if (!listening) { if (!listening) {
esp_err_t req_rc = voice_send_directive("continue-task", "RequestToSpeak", true); esp_err_t req_rc = voice_send_directive("continue-task", "RequestToSpeak", true);
@@ -630,7 +579,7 @@ esp_err_t voice_interaction_tap_start(char *err, size_t err_len) {
voice_unlock(); voice_unlock();
} }
voice_fill_err(err, err_len, "request to speak failed"); voice_fill_err(err, err_len, "request to speak failed");
ESP_LOGW(TAG, "[stage] tap_start_abort: request_to_speak failed rc=0x%x", (unsigned)req_rc); ESP_LOGW(TAG, "tap_start_abort: request_to_speak failed rc=0x%x", (unsigned)req_rc);
return req_rc; return req_rc;
} }
} else { } else {
@@ -646,21 +595,19 @@ esp_err_t voice_interaction_tap_start(char *err, size_t err_len) {
} }
} }
voice_log_status_snapshot("tap_start_exit_ok");
return ESP_OK; return ESP_OK;
} }
esp_err_t voice_interaction_tap_cancel(char *err, size_t err_len) { esp_err_t voice_interaction_tap_cancel(char *err, size_t err_len) {
ESP_LOGI(TAG, "[stage] tap_cancel_enter");
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_fill_err(err, err_len, "voice lock timeout"); voice_fill_err(err, err_len, "voice lock timeout");
ESP_LOGW(TAG, "[stage] tap_cancel_abort: lock timeout"); ESP_LOGW(TAG, "tap_cancel_abort: lock timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
if (!s_voice.session_active || !s_voice.ws_connected || !s_voice.started) { if (!s_voice.session_active || !s_voice.ws_connected || !s_voice.started) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] tap_cancel_abort: session_active=%d ws_connected=%d started=%d", "tap_cancel_abort: session_active=%d ws_connected=%d started=%d",
s_voice.session_active, s_voice.session_active,
s_voice.ws_connected, s_voice.ws_connected,
s_voice.started); s_voice.started);
@@ -673,7 +620,6 @@ esp_err_t voice_interaction_tap_cancel(char *err, size_t err_len) {
s_voice.tap_active = false; s_voice.tap_active = false;
s_voice.speech_active = false; s_voice.speech_active = false;
voice_unlock(); voice_unlock();
voice_log_status_snapshot("tap_cancel_marked_inactive");
esp_err_t stop_err = ESP_OK; esp_err_t stop_err = ESP_OK;
if (should_send_stop) { if (should_send_stop) {

View File

@@ -47,50 +47,6 @@ void voice_unlock(void) {
} }
} }
void voice_log_status_snapshot(const char *stage) {
if (!voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
ESP_LOGW(TAG, "[stage] %s: status snapshot lock timeout", stage);
return;
}
ESP_LOGI(TAG,
"[stage] %s: active=%d ws=%d started=%d tap=%d speech=%d state=%s up=%" PRIu32
" down=%" PRIu32 " err=%s",
stage,
s_voice.session_active,
s_voice.ws_connected,
s_voice.started,
s_voice.tap_active,
s_voice.speech_active,
voice_interaction_dialog_state_str(s_voice.dialog_state),
s_voice.upstream_packets,
s_voice.downstream_packets,
s_voice.last_error[0] != '\0' ? s_voice.last_error : "-");
voice_unlock();
}
void voice_log_heap_snapshot(const char *stage) {
size_t free_8bit = heap_caps_get_free_size(MALLOC_CAP_8BIT);
size_t free_internal = heap_caps_get_free_size(MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT);
size_t free_dma = heap_caps_get_free_size(MALLOC_CAP_DMA | MALLOC_CAP_8BIT);
size_t free_spiram = heap_caps_get_free_size(MALLOC_CAP_SPIRAM | MALLOC_CAP_8BIT);
size_t largest_8bit = heap_caps_get_largest_free_block(MALLOC_CAP_8BIT);
size_t largest_internal = heap_caps_get_largest_free_block(MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT);
size_t largest_dma = heap_caps_get_largest_free_block(MALLOC_CAP_DMA | MALLOC_CAP_8BIT);
size_t largest_spiram = heap_caps_get_largest_free_block(MALLOC_CAP_SPIRAM | MALLOC_CAP_8BIT);
ESP_LOGI(TAG,
"[stage] %s heap: free8=%u free_internal=%u free_dma=%u free_spiram=%u largest8=%u largest_internal=%u largest_dma=%u largest_spiram=%u",
stage,
(unsigned)free_8bit,
(unsigned)free_internal,
(unsigned)free_dma,
(unsigned)free_spiram,
(unsigned)largest_8bit,
(unsigned)largest_internal,
(unsigned)largest_dma,
(unsigned)largest_spiram);
}
void voice_wait_audio_playback_done(uint32_t timeout_ms, const char *stage) { void voice_wait_audio_playback_done(uint32_t timeout_ms, const char *stage) {
if (!voice_audio_is_open() || timeout_ms == 0) { if (!voice_audio_is_open() || timeout_ms == 0) {
return; return;
@@ -122,22 +78,11 @@ void voice_wait_audio_playback_done(uint32_t timeout_ms, const char *stage) {
!started || !started ||
dialog_state != VOICE_DIALOG_STATE_RESPONDING; dialog_state != VOICE_DIALOG_STATE_RESPONDING;
if (codec_tail_done && downstream_quiet && remote_not_responding) { if (codec_tail_done && downstream_quiet && remote_not_responding) {
ESP_LOGI(TAG,
"[stage] %s: audio_drain_done now=%" PRId64 " play_deadline=%" PRId64 " last_down=%" PRId64,
stage != NULL ? stage : "audio_drain",
now_ms,
playback_deadline_ms,
last_downstream_ms);
return; return;
} }
vTaskDelay(pdMS_TO_TICKS(30)); vTaskDelay(pdMS_TO_TICKS(30));
} }
ESP_LOGI(TAG,
"[stage] %s: audio_drain_timeout timeout_ms=%u",
stage != NULL ? stage : "audio_drain",
(unsigned)timeout_ms);
} }
void voice_close_audio_with_drain(uint32_t timeout_ms, const char *stage) { void voice_close_audio_with_drain(uint32_t timeout_ms, const char *stage) {
@@ -205,10 +150,9 @@ BaseType_t voice_create_task_prefer_psram(TaskFunction_t task_fn,
if (out_with_caps != NULL) { if (out_with_caps != NULL) {
*out_with_caps = true; *out_with_caps = true;
} }
ESP_LOGI(TAG, "[stage] task_create_psram_ok: name=%s stack=%u", name, (unsigned)stack_size);
return pdPASS; return pdPASS;
} }
ESP_LOGW(TAG, "[stage] task_create_psram_failed: name=%s stack=%u", name, (unsigned)stack_size); ESP_LOGW(TAG, "task_create_psram_failed: name=%s stack=%u", name, (unsigned)stack_size);
#endif #endif
rc = xTaskCreate(task_fn, rc = xTaskCreate(task_fn,
@@ -217,10 +161,8 @@ BaseType_t voice_create_task_prefer_psram(TaskFunction_t task_fn,
NULL, NULL,
priority, priority,
out_task); out_task);
if (rc == pdPASS) { if (rc != pdPASS) {
ESP_LOGI(TAG, "[stage] task_create_internal_ok: name=%s stack=%u", name, (unsigned)stack_size); ESP_LOGE(TAG, "task_create_internal_failed: name=%s stack=%u", name, (unsigned)stack_size);
} else {
ESP_LOGE(TAG, "[stage] task_create_internal_failed: name=%s stack=%u", name, (unsigned)stack_size);
} }
return rc; return rc;
} }
@@ -445,14 +387,12 @@ esp_err_t voice_open_audio_for_dialog(char *err, size_t err_len) {
.input_gain_db = (float)CONFIG_TQ_VOICE_CODEC_MIC_GAIN_DB, .input_gain_db = (float)CONFIG_TQ_VOICE_CODEC_MIC_GAIN_DB,
}; };
ESP_LOGI(TAG, "[stage] audio_open_begin");
esp_err_t open_err = voice_audio_open(&audio_cfg, err, err_len); esp_err_t open_err = voice_audio_open(&audio_cfg, err, err_len);
if (open_err != ESP_OK) { if (open_err != ESP_OK) {
ESP_LOGE(TAG, "[stage] audio_open_failed: %s", esp_err_to_name(open_err)); ESP_LOGE(TAG, "audio_open_failed: %s", esp_err_to_name(open_err));
return open_err; return open_err;
} }
ESP_LOGI(TAG, "[stage] audio_open_ok");
return ESP_OK; return ESP_OK;
} }

View File

@@ -87,22 +87,6 @@ static void voice_marker_image_generation_record_success(const char *prompt,
portEXIT_CRITICAL(&s_marker_image_gen_lock); portEXIT_CRITICAL(&s_marker_image_gen_lock);
} }
static void voice_log_text_preview(const char *stage, const char *text) {
if (stage == NULL || text == NULL || text[0] == '\0') {
return;
}
size_t len = strlen(text);
const int preview = 240;
ESP_LOGI(TAG,
"[stage] %s: len=%u text=%.*s%s",
stage,
(unsigned)len,
preview,
text,
(len > (size_t)preview) ? "..." : "");
}
static bool voice_is_space_char(char c) { static bool voice_is_space_char(char c) {
return isspace((unsigned char)c) != 0; return isspace((unsigned char)c) != 0;
} }
@@ -243,10 +227,6 @@ static void voice_try_preview_marker_png(const voice_image_generation_task_arg_t
preview_err, preview_err,
sizeof(preview_err)); sizeof(preview_err));
if (preview_rc == ESP_OK) { if (preview_rc == ESP_OK) {
ESP_LOGI(TAG,
"[stage] marker_image_preview_ok: dialog_id=%s png_bytes=%u",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)png_len);
return; return;
} }
@@ -255,7 +235,7 @@ static void voice_try_preview_marker_png(const voice_image_generation_task_arg_t
} }
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] marker_image_preview_failed: dialog_id=%s rc=0x%x msg=%s", "marker_image_preview_failed: dialog_id=%s rc=0x%x msg=%s",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-", task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)preview_rc, (unsigned)preview_rc,
preview_err[0] != '\0' ? preview_err : "preview failed"); preview_err[0] != '\0' ? preview_err : "preview failed");
@@ -277,11 +257,6 @@ static esp_err_t voice_submit_marker_generated_image(const voice_image_generatio
uint8_t *raster = NULL; uint8_t *raster = NULL;
size_t raster_len = 0; size_t raster_len = 0;
char decode_err[128] = {0}; char decode_err[128] = {0};
ESP_LOGI(TAG,
"[stage] marker_image_print_decode_start: dialog_id=%s request_id=%s png_bytes=%u",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
result->request_id[0] != '\0' ? result->request_id : "-",
(unsigned)result->png_len);
esp_err_t decode_rc = raster_tools_convert_png_to_raster_384(result->png, esp_err_t decode_rc = raster_tools_convert_png_to_raster_384(result->png,
result->png_len, result->png_len,
true, true,
@@ -299,19 +274,13 @@ static esp_err_t voice_submit_marker_generated_image(const voice_image_generatio
err_len, err_len,
decode_err[0] != '\0' ? decode_err : "decode generated image failed"); decode_err[0] != '\0' ? decode_err : "decode generated image failed");
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] marker_image_print_decode_failed: dialog_id=%s rc=0x%x msg=%s", "marker_image_print_decode_failed: dialog_id=%s rc=0x%x msg=%s",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-", task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)decode_rc, (unsigned)decode_rc,
err != NULL && err[0] != '\0' ? err : "decode generated image failed"); err != NULL && err[0] != '\0' ? err : "decode generated image failed");
return decode_rc; return decode_rc;
} }
ESP_LOGI(TAG,
"[stage] marker_image_print_decode_done: dialog_id=%s raster_size=%ux%u raster_bytes=%u",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)raster_width,
(unsigned)raster_height,
(unsigned)raster_len);
uint32_t job_id = 0; uint32_t job_id = 0;
char submit_err[128] = {0}; char submit_err[128] = {0};
@@ -332,16 +301,11 @@ static esp_err_t voice_submit_marker_generated_image(const voice_image_generatio
err_len, err_len,
submit_err[0] != '\0' ? submit_err : "submit print job failed"); submit_err[0] != '\0' ? submit_err : "submit print job failed");
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] marker_image_print_submit_failed: dialog_id=%s rc=0x%x msg=%s", "marker_image_print_submit_failed: dialog_id=%s rc=0x%x msg=%s",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-", task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)submit_rc, (unsigned)submit_rc,
err != NULL && err[0] != '\0' ? err : "submit print job failed"); err != NULL && err[0] != '\0' ? err : "submit print job failed");
} else { } else {
ESP_LOGI(TAG,
"[stage] marker_image_print_submit_ok: dialog_id=%s request_id=%s job_id=%u",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
result->request_id[0] != '\0' ? result->request_id : "-",
(unsigned)job_id);
} }
free(raster); free(raster);
@@ -370,21 +334,10 @@ static void voice_image_generation_task(void *arg) {
printer_status_poll_pause_token_t status_poll_pause_token = 0; printer_status_poll_pause_token_t status_poll_pause_token = 0;
char gen_err[160] = {0}; char gen_err[160] = {0};
ESP_LOGI(TAG,
"[stage] marker_image_gen_start: dialog_id=%s prompt_len=%u",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)strlen(task_arg->prompt));
status_poll_pause_token = printer_protocol_status_poll_pause_acquire(); status_poll_pause_token = printer_protocol_status_poll_pause_acquire();
esp_err_t rc = image_generation_generate_png(&req, &result, gen_err, sizeof(gen_err)); esp_err_t rc = image_generation_generate_png(&req, &result, gen_err, sizeof(gen_err));
printer_protocol_status_poll_pause_release(&status_poll_pause_token); printer_protocol_status_poll_pause_release(&status_poll_pause_token);
if (rc == ESP_OK) { if (rc == ESP_OK) {
ESP_LOGI(TAG,
"[stage] marker_image_gen_done: dialog_id=%s request_id=%s size=%ux%u png_bytes=%u",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
result.request_id[0] != '\0' ? result.request_id : "-",
(unsigned)result.width,
(unsigned)result.height,
(unsigned)result.png_len);
char submit_err[160] = {0}; char submit_err[160] = {0};
esp_err_t submit_rc = voice_submit_marker_generated_image(task_arg, esp_err_t submit_rc = voice_submit_marker_generated_image(task_arg,
@@ -397,14 +350,14 @@ static void voice_image_generation_task(void *arg) {
voice_now_ms()); voice_now_ms());
} else { } else {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] marker_image_print_failed: dialog_id=%s rc=0x%x msg=%s", "marker_image_print_failed: dialog_id=%s rc=0x%x msg=%s",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-", task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)submit_rc, (unsigned)submit_rc,
submit_err[0] != '\0' ? submit_err : "marker image print failed"); submit_err[0] != '\0' ? submit_err : "marker image print failed");
} }
} else { } else {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] marker_image_gen_failed: dialog_id=%s rc=0x%x msg=%s", "marker_image_gen_failed: dialog_id=%s rc=0x%x msg=%s",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-", task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
(unsigned)rc, (unsigned)rc,
gen_err[0] != '\0' ? gen_err : "image generation failed"); gen_err[0] != '\0' ? gen_err : "image generation failed");
@@ -425,30 +378,22 @@ static void voice_schedule_marker_image_generation(const char *prompt, const cha
size_t prompt_len = strlen(prompt); size_t prompt_len = strlen(prompt);
if (prompt_len > VOICE_IMAGE_MARKER_PROMPT_MAX_LEN) { if (prompt_len > VOICE_IMAGE_MARKER_PROMPT_MAX_LEN) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] marker_image_gen_skip: prompt too long, len=%u", "marker_image_gen_skip: prompt too long, len=%u",
(unsigned)prompt_len); (unsigned)prompt_len);
return; return;
} }
uint32_t repeat_remain_ms = 0;
if (!voice_marker_image_generation_try_acquire(prompt, if (!voice_marker_image_generation_try_acquire(prompt,
dialog_id, dialog_id,
voice_now_ms(), voice_now_ms(),
&repeat_remain_ms)) { NULL)) {
if (repeat_remain_ms > 0) {
ESP_LOGI(TAG,
"[stage] marker_image_gen_skip: duplicate prompt suppressed, remain_ms=%u",
(unsigned)repeat_remain_ms);
} else {
ESP_LOGI(TAG, "[stage] marker_image_gen_skip: previous marker task running");
}
return; return;
} }
voice_image_generation_task_arg_t *task_arg = voice_image_generation_task_arg_t *task_arg =
(voice_image_generation_task_arg_t *)calloc(1, sizeof(*task_arg)); (voice_image_generation_task_arg_t *)calloc(1, sizeof(*task_arg));
if (task_arg == NULL) { if (task_arg == NULL) {
ESP_LOGW(TAG, "[stage] marker_image_gen_skip: no memory for task arg"); ESP_LOGW(TAG, "marker_image_gen_skip: no memory for task arg");
voice_marker_image_generation_release(); voice_marker_image_generation_release();
return; return;
} }
@@ -465,16 +410,11 @@ static void voice_schedule_marker_image_generation(const char *prompt, const cha
VOICE_IMAGE_GEN_TASK_PRIO, VOICE_IMAGE_GEN_TASK_PRIO,
NULL); NULL);
if (ok != pdPASS) { if (ok != pdPASS) {
ESP_LOGW(TAG, "[stage] marker_image_gen_skip: create task failed"); ESP_LOGW(TAG, "marker_image_gen_skip: create task failed");
voice_marker_image_generation_release(); voice_marker_image_generation_release();
free(task_arg); free(task_arg);
return; return;
} }
ESP_LOGI(TAG,
"[stage] marker_image_gen_queued: dialog_id=%s prompt=%s",
task_arg->dialog_id[0] != '\0' ? task_arg->dialog_id : "-",
task_arg->prompt);
} }
void voice_marker_try_trigger_image_generation(const char *dialog_id, const char *final_text) { void voice_marker_try_trigger_image_generation(const char *dialog_id, const char *final_text) {
@@ -497,17 +437,10 @@ void voice_marker_try_trigger_image_generation(const char *dialog_id, const char
templated_prompt, templated_prompt,
sizeof(templated_prompt)); sizeof(templated_prompt));
if (templated_prompt[0] == '\0') { if (templated_prompt[0] == '\0') {
ESP_LOGW(TAG, "[stage] marker_image_gen_skip: build prompt failed"); ESP_LOGW(TAG, "marker_image_gen_skip: build prompt failed");
return; return;
} }
ESP_LOGI(TAG,
"[stage] marker_image_gen_detected: first_sentence=%s",
first_sentence);
ESP_LOGI(TAG,
"[stage] marker_image_gen_subject: keyword=%s",
marker_subject);
voice_log_text_preview("marker_image_gen_prompt_templated", templated_prompt);
voice_schedule_marker_image_generation(templated_prompt, dialog_id); voice_schedule_marker_image_generation(templated_prompt, dialog_id);
} }

View File

@@ -3,26 +3,11 @@
#include <string.h> #include <string.h>
#include "esp_audio_enc.h" #include "esp_audio_enc.h"
#include "esp_log.h"
static const char *TAG = "voice_interaction";
void voice_uplink_task(void *arg) { void voice_uplink_task(void *arg) {
(void)arg; (void)arg;
bool low_stack_warned = false;
UBaseType_t start_hwm = uxTaskGetStackHighWaterMark(NULL);
ESP_LOGI(TAG, "[stage] uplink_task_started: stack_hwm_words=%u", (unsigned)start_hwm);
while (true) { while (true) {
if (!low_stack_warned) {
UBaseType_t hwm = uxTaskGetStackHighWaterMark(NULL);
if (hwm < 256) {
low_stack_warned = true;
ESP_LOGW(TAG, "[stage] uplink_task_low_stack: hwm_words=%u", (unsigned)hwm);
}
}
bool active = false; bool active = false;
bool connected = false; bool connected = false;
bool started = false; bool started = false;
@@ -88,7 +73,6 @@ void voice_uplink_task(void *arg) {
s_voice.speech_active = false; s_voice.speech_active = false;
s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE; s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE;
s_voice.last_event_ms = voice_now_ms(); s_voice.last_event_ms = voice_now_ms();
ESP_LOGW(TAG, "[stage] uplink_detected_ws_disconnected");
} }
voice_unlock(); voice_unlock();
} }
@@ -139,7 +123,6 @@ void voice_heartbeat_task(void *arg) {
} }
if (connected && started) { if (connected && started) {
ESP_LOGI(TAG, "[stage] heartbeat_send");
(void)voice_send_directive("continue-task", "HeartBeat", true); (void)voice_send_directive("continue-task", "HeartBeat", true);
} }

View File

@@ -135,13 +135,11 @@ static esp_err_t voice_send_text_immediate(const char *text, int len) {
s_voice.speech_active = false; s_voice.speech_active = false;
s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE; s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE;
s_voice.last_event_ms = voice_now_ms(); s_voice.last_event_ms = voice_now_ms();
ESP_LOGW(TAG, "[stage] ws_state_reconciled: transport disconnected");
} }
voice_unlock(); voice_unlock();
} }
if (ws == NULL || !connected || !transport_connected) { if (ws == NULL || !connected || !transport_connected) {
ESP_LOGW(TAG, "[stage] ws_send_text skipped: ws=%p connected=%d len=%d", (void *)ws, connected, len);
return ESP_ERR_INVALID_STATE; return ESP_ERR_INVALID_STATE;
} }
@@ -150,10 +148,9 @@ static esp_err_t voice_send_text_immediate(const char *text, int len) {
len, len,
pdMS_TO_TICKS(VOICE_WS_SEND_TIMEOUT_MS)); pdMS_TO_TICKS(VOICE_WS_SEND_TIMEOUT_MS));
if (ret < 0) { if (ret < 0) {
ESP_LOGW(TAG, "[stage] ws_send_text failed: len=%d", len); ESP_LOGW(TAG, "ws_send_text failed: len=%d", len);
return ESP_FAIL; return ESP_FAIL;
} }
ESP_LOGI(TAG, "[stage] ws_send_text ok: len=%d", len);
return ESP_OK; return ESP_OK;
} }
@@ -209,12 +206,6 @@ esp_err_t voice_send_directive(const char *action,
} }
esp_err_t err = voice_send_text(text, (int)strlen(text)); esp_err_t err = voice_send_text(text, (int)strlen(text));
ESP_LOGI(TAG,
"[stage] directive: action=%s directive=%s with_dialog_id=%d result=%s",
action,
directive,
with_dialog_id,
esp_err_to_name(err));
cJSON_free(text); cJSON_free(text);
return err; return err;
} }
@@ -293,7 +284,7 @@ static void voice_handle_text_chunk(esp_websocket_event_data_t *data) {
s_voice.text_agg = (uint8_t *)voice_calloc_prefer_psram(1, (size_t)data->payload_len + 1); s_voice.text_agg = (uint8_t *)voice_calloc_prefer_psram(1, (size_t)data->payload_len + 1);
if (s_voice.text_agg == NULL) { if (s_voice.text_agg == NULL) {
ESP_LOGW(TAG, "[stage] text_agg_alloc_failed: len=%d", data->payload_len); ESP_LOGW(TAG, "text_agg_alloc_failed: len=%d", data->payload_len);
return; return;
} }
s_voice.text_agg_size = (size_t)data->payload_len; s_voice.text_agg_size = (size_t)data->payload_len;
@@ -336,7 +327,7 @@ static void voice_handle_binary_chunk(esp_websocket_event_data_t *data) {
s_voice.bin_agg = (uint8_t *)voice_malloc_prefer_psram((size_t)data->payload_len); s_voice.bin_agg = (uint8_t *)voice_malloc_prefer_psram((size_t)data->payload_len);
if (s_voice.bin_agg == NULL) { if (s_voice.bin_agg == NULL) {
ESP_LOGW(TAG, "[stage] bin_agg_alloc_failed: len=%d", data->payload_len); ESP_LOGW(TAG, "bin_agg_alloc_failed: len=%d", data->payload_len);
return; return;
} }
s_voice.bin_agg_size = (size_t)data->payload_len; s_voice.bin_agg_size = (size_t)data->payload_len;
@@ -374,16 +365,9 @@ void voice_websocket_event_handler(void *handler_args,
(void)handler_args; (void)handler_args;
(void)base; (void)base;
UBaseType_t ws_hwm = uxTaskGetStackHighWaterMark(NULL);
if (!s_voice.ws_low_stack_warned && ws_hwm < 256) {
s_voice.ws_low_stack_warned = true;
ESP_LOGW(TAG, "[stage] ws_task_low_stack: hwm_words=%u", (unsigned)ws_hwm);
}
esp_websocket_event_data_t *data = (esp_websocket_event_data_t *)event_data; esp_websocket_event_data_t *data = (esp_websocket_event_data_t *)event_data;
switch ((esp_websocket_event_id_t)event_id) { switch ((esp_websocket_event_id_t)event_id) {
case WEBSOCKET_EVENT_CONNECTED: { case WEBSOCKET_EVENT_CONNECTED: {
ESP_LOGI(TAG, "[stage] ws_connected");
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
s_voice.ws_connected = true; s_voice.ws_connected = true;
s_voice.last_event_ms = voice_now_ms(); s_voice.last_event_ms = voice_now_ms();
@@ -396,16 +380,15 @@ void voice_websocket_event_handler(void *handler_args,
voice_unlock(); voice_unlock();
} }
if (start_msg != NULL) { if (start_msg != NULL) {
esp_err_t send_err = voice_send_text(start_msg, (int)strlen(start_msg)); (void)voice_send_text(start_msg, (int)strlen(start_msg));
ESP_LOGI(TAG, "[stage] start_message_sent: result=%s", esp_err_to_name(send_err));
cJSON_free(start_msg); cJSON_free(start_msg);
} else { } else {
ESP_LOGE(TAG, "[stage] start_message_build_failed"); ESP_LOGE(TAG, "start_message_build_failed");
} }
break; break;
} }
case WEBSOCKET_EVENT_DISCONNECTED: case WEBSOCKET_EVENT_DISCONNECTED:
ESP_LOGW(TAG, "[stage] ws_disconnected"); ESP_LOGW(TAG, "ws_disconnected");
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
s_voice.ws_connected = false; s_voice.ws_connected = false;
s_voice.started = false; s_voice.started = false;
@@ -428,7 +411,7 @@ void voice_websocket_event_handler(void *handler_args,
} }
break; break;
case WEBSOCKET_EVENT_ERROR: case WEBSOCKET_EVENT_ERROR:
ESP_LOGW(TAG, "[stage] ws_error"); ESP_LOGW(TAG, "ws_error");
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_set_last_error_locked("websocket error"); voice_set_last_error_locked("websocket error");
s_voice.last_event_ms = voice_now_ms(); s_voice.last_event_ms = voice_now_ms();

View File

@@ -85,7 +85,7 @@ void voice_ws_audio_handle_downstream_packet(const uint8_t *data, size_t len) {
} }
} else { } else {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] audio_downstream_write_failed: rc=0x%x err=%s samples=%u", "audio_downstream_write_failed: rc=0x%x err=%s samples=%u",
(unsigned)write_err, (unsigned)write_err,
audio_err[0] != '\0' ? audio_err : "-", audio_err[0] != '\0' ? audio_err : "-",
(unsigned)samples); (unsigned)samples);

View File

@@ -58,16 +58,13 @@ static void voice_response_finalize_task(void *arg) {
(void)arg; (void)arg;
uint32_t playback_wait_ms = voice_calc_response_finalize_wait_ms(); uint32_t playback_wait_ms = voice_calc_response_finalize_wait_ms();
ESP_LOGI(TAG,
"[stage] responding_ended_local_playback_wait: timeout_ms=%u",
(unsigned)playback_wait_ms);
voice_wait_audio_playback_done(playback_wait_ms, "responding_ended_local_playback"); voice_wait_audio_playback_done(playback_wait_ms, "responding_ended_local_playback");
esp_err_t local_end_rc = esp_err_t local_end_rc =
voice_send_directive_with_retry("continue-task", "LocalRespondingEnded", true); voice_send_directive_with_retry("continue-task", "LocalRespondingEnded", true);
if (local_end_rc != ESP_OK) { if (local_end_rc != ESP_OK) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] responding_ended_local_end_failed: rc=0x%x", "responding_ended_local_end_failed: rc=0x%x",
(unsigned)local_end_rc); (unsigned)local_end_rc);
} }
@@ -75,7 +72,7 @@ static void voice_response_finalize_task(void *arg) {
voice_send_directive_with_retry("finish-task", "Stop", true); voice_send_directive_with_retry("finish-task", "Stop", true);
if (stop_rc != ESP_OK) { if (stop_rc != ESP_OK) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] responding_ended_stop_failed: rc=0x%x", "responding_ended_stop_failed: rc=0x%x",
(unsigned)stop_rc); (unsigned)stop_rc);
} }
@@ -96,7 +93,6 @@ static void voice_schedule_response_finalize(void) {
portEXIT_CRITICAL(&s_response_finalize_lock); portEXIT_CRITICAL(&s_response_finalize_lock);
if (!should_start) { if (!should_start) {
ESP_LOGI(TAG, "[stage] responding_ended_finalize_skip: task already running");
return; return;
} }
@@ -110,9 +106,8 @@ static void voice_schedule_response_finalize(void) {
portENTER_CRITICAL(&s_response_finalize_lock); portENTER_CRITICAL(&s_response_finalize_lock);
s_response_finalize_running = false; s_response_finalize_running = false;
portEXIT_CRITICAL(&s_response_finalize_lock); portEXIT_CRITICAL(&s_response_finalize_lock);
ESP_LOGW(TAG, "[stage] responding_ended_finalize_start_failed"); ESP_LOGW(TAG, "responding_ended_finalize_start_failed");
} else { } else {
ESP_LOGI(TAG, "[stage] responding_ended_finalize_task_started");
} }
} }
@@ -141,22 +136,6 @@ static bool voice_get_json_bool(cJSON *obj, const char *name, bool *out_value) {
return true; return true;
} }
static void voice_log_final_text(const char *stage, const char *text) {
if (stage == NULL || text == NULL || text[0] == '\0') {
return;
}
size_t len = strlen(text);
const int preview = 240;
ESP_LOGI(TAG,
"[stage] %s: len=%u text=%.*s%s",
stage,
(unsigned)len,
preview,
text,
(len > (size_t)preview) ? "..." : "");
}
static void voice_handle_output_event(cJSON *output) { static void voice_handle_output_event(cJSON *output) {
const char *event_name = voice_get_json_str(output, "event"); const char *event_name = voice_get_json_str(output, "event");
if (event_name == NULL) { if (event_name == NULL) {
@@ -168,11 +147,6 @@ static void voice_handle_output_event(cJSON *output) {
if (strcmp(event_name, "DialogStateChanged") == 0) { if (strcmp(event_name, "DialogStateChanged") == 0) {
state = voice_get_json_str(output, "state"); state = voice_get_json_str(output, "state");
} }
ESP_LOGI(TAG,
"[stage] ws_event_output: event=%s dialog_id=%s state=%s",
event_name,
dialog_id != NULL ? dialog_id : "-",
state != NULL ? state : "-");
bool finished = false; bool finished = false;
bool has_finished = voice_get_json_bool(output, "finished", &finished); bool has_finished = voice_get_json_bool(output, "finished", &finished);
@@ -180,14 +154,11 @@ static void voice_handle_output_event(cJSON *output) {
bool should_check_marker_in_first_sentence = false; bool should_check_marker_in_first_sentence = false;
bool should_try_send_speech = false; bool should_try_send_speech = false;
if (has_finished && finished) { if (has_finished && finished) {
if (strcmp(event_name, "SpeechContent") == 0) { if (strcmp(event_name, "RespondingContent") == 0) {
voice_log_final_text("asr_final_text", voice_get_json_str(output, "text"));
} else if (strcmp(event_name, "RespondingContent") == 0) {
const char *final_text = voice_get_json_str(output, "text"); const char *final_text = voice_get_json_str(output, "text");
if (final_text == NULL || final_text[0] == '\0') { if (final_text == NULL || final_text[0] == '\0') {
final_text = voice_get_json_str(output, "spoken"); final_text = voice_get_json_str(output, "spoken");
} }
voice_log_final_text("response_final_text", final_text);
responding_final_text = final_text; responding_final_text = final_text;
if (responding_final_text != NULL && responding_final_text[0] != '\0' && if (responding_final_text != NULL && responding_final_text[0] != '\0' &&
voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
@@ -211,7 +182,6 @@ static void voice_handle_output_event(cJSON *output) {
s_voice.started = true; s_voice.started = true;
s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE; s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE;
s_voice.response_first_sentence_checked = false; s_voice.response_first_sentence_checked = false;
ESP_LOGI(TAG, "[stage] session_started: dialog_id=%s", s_voice.dialog_id);
} else if (strcmp(event_name, "DialogStateChanged") == 0) { } else if (strcmp(event_name, "DialogStateChanged") == 0) {
if (state != NULL) { if (state != NULL) {
voice_dialog_state_t prev_state = s_voice.dialog_state; voice_dialog_state_t prev_state = s_voice.dialog_state;
@@ -235,15 +205,8 @@ static void voice_handle_output_event(cJSON *output) {
} }
} }
} }
ESP_LOGI(TAG,
"[stage] dialog_state_changed: state=%s current=%s",
state != NULL ? state : "-",
voice_interaction_dialog_state_str(s_voice.dialog_state));
} else if (strcmp(event_name, "SpeechEnded") == 0) { } else if (strcmp(event_name, "SpeechEnded") == 0) {
s_voice.speech_active = false; s_voice.speech_active = false;
ESP_LOGI(TAG, "[stage] speech_ended: stop uplink");
} else if (strcmp(event_name, "RespondingEnded") == 0) {
ESP_LOGI(TAG, "[stage] responding_ended: schedule_local_playback_finalize");
} else if (strcmp(event_name, "Stopped") == 0) { } else if (strcmp(event_name, "Stopped") == 0) {
s_voice.started = false; s_voice.started = false;
s_voice.tap_active = false; s_voice.tap_active = false;
@@ -251,12 +214,11 @@ static void voice_handle_output_event(cJSON *output) {
s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE; s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE;
s_voice.response_first_sentence_checked = false; s_voice.response_first_sentence_checked = false;
should_close_audio = true; should_close_audio = true;
ESP_LOGI(TAG, "[stage] session_stopped_by_server");
} else if (strcmp(event_name, "Error") == 0) { } else if (strcmp(event_name, "Error") == 0) {
const char *error_msg = voice_get_json_str(output, "error_message"); const char *error_msg = voice_get_json_str(output, "error_message");
if (error_msg != NULL) { if (error_msg != NULL) {
voice_set_last_error_locked(error_msg); voice_set_last_error_locked(error_msg);
ESP_LOGW(TAG, "[stage] server_error: %s", error_msg); ESP_LOGW(TAG, "server_error: %s", error_msg);
} }
s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE; s_voice.dialog_state = VOICE_DIALOG_STATE_IDLE;
s_voice.tap_active = false; s_voice.tap_active = false;
@@ -280,7 +242,7 @@ static void voice_handle_output_event(cJSON *output) {
esp_err_t rc = voice_interaction_try_send_speech(speech_err, sizeof(speech_err)); esp_err_t rc = voice_interaction_try_send_speech(speech_err, sizeof(speech_err));
if (rc != ESP_OK && rc != ESP_ERR_INVALID_STATE) { if (rc != ESP_OK && rc != ESP_ERR_INVALID_STATE) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] auto_send_speech_failed: rc=0x%x err=%s", "auto_send_speech_failed: rc=0x%x err=%s",
(unsigned)rc, (unsigned)rc,
speech_err[0] != '\0' ? speech_err : "-"); speech_err[0] != '\0' ? speech_err : "-");
} }
@@ -320,7 +282,7 @@ void voice_ws_protocol_handle_text_message(const char *text, size_t len) {
cJSON *status_msg = cJSON_GetObjectItemCaseSensitive(header, "status_message"); cJSON *status_msg = cJSON_GetObjectItemCaseSensitive(header, "status_message");
if (cJSON_IsNumber(status_code) && status_code->valueint >= 400) { if (cJSON_IsNumber(status_code) && status_code->valueint >= 400) {
ESP_LOGW(TAG, ESP_LOGW(TAG,
"[stage] ws_header_error: status_code=%d status_message=%s", "ws_header_error: status_code=%d status_message=%s",
status_code->valueint, status_code->valueint,
(cJSON_IsString(status_msg) && status_msg->valuestring != NULL) ? status_msg->valuestring : "-"); (cJSON_IsString(status_msg) && status_msg->valuestring != NULL) ? status_msg->valuestring : "-");
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
@@ -338,7 +300,7 @@ void voice_ws_protocol_handle_text_message(const char *text, size_t len) {
voice_handle_output_event(output); voice_handle_output_event(output);
} else if (header_event != NULL && strcmp(header_event, "task-failed") == 0) { } else if (header_event != NULL && strcmp(header_event, "task-failed") == 0) {
const char *error_msg = voice_get_json_str(header, "error_message"); const char *error_msg = voice_get_json_str(header, "error_message");
ESP_LOGW(TAG, "[stage] ws_task_failed: %s", error_msg != NULL ? error_msg : "task failed"); ESP_LOGW(TAG, "ws_task_failed: %s", error_msg != NULL ? error_msg : "task failed");
if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) { if (voice_lock(VOICE_STATUS_LOCK_TIMEOUT_MS)) {
voice_set_last_error_locked(error_msg != NULL ? error_msg : "task failed"); voice_set_last_error_locked(error_msg != NULL ? error_msg : "task failed");
s_voice.started = false; s_voice.started = false;

View File

@@ -10,7 +10,6 @@ idf_component_register(
"src/platform_mic_key.c" "src/platform_mic_key.c"
"src/voice_audio.c" "src/voice_audio.c"
"src/runtime_policy.c" "src/runtime_policy.c"
"src/runtime_diagnostics.c"
INCLUDE_DIRS INCLUDE_DIRS
"include" "include"
PRIV_INCLUDE_DIRS PRIV_INCLUDE_DIRS

View File

@@ -150,40 +150,6 @@ uint32_t runtime_policy_image_download_timeout_default_ms(void);
uint32_t runtime_policy_image_download_timeout_min_ms(void); uint32_t runtime_policy_image_download_timeout_min_ms(void);
uint32_t runtime_policy_image_download_timeout_max_ms(void); uint32_t runtime_policy_image_download_timeout_max_ms(void);
// ---------- runtime_diagnostics ----------
typedef enum {
RUNTIME_DIAG_COUNTER_LIFECYCLE_START_ATTEMPT = 0,
RUNTIME_DIAG_COUNTER_LIFECYCLE_START_SUCCESS,
RUNTIME_DIAG_COUNTER_LIFECYCLE_START_FAILED,
RUNTIME_DIAG_COUNTER_LIFECYCLE_START_RETRY,
RUNTIME_DIAG_COUNTER_LIFECYCLE_STOP_ATTEMPT,
RUNTIME_DIAG_COUNTER_LIFECYCLE_STOP_SUCCESS,
RUNTIME_DIAG_COUNTER_LIFECYCLE_STOP_FAILED,
RUNTIME_DIAG_COUNTER_WIFI_CONNECT_SUCCESS,
RUNTIME_DIAG_COUNTER_WIFI_CONNECT_FAILED,
RUNTIME_DIAG_COUNTER_WIFI_CONNECT_TIMEOUT,
RUNTIME_DIAG_COUNTER_PRINTER_JOB_SUBMITTED,
RUNTIME_DIAG_COUNTER_PRINTER_JOB_SUCCESS,
RUNTIME_DIAG_COUNTER_PRINTER_JOB_FAILED,
RUNTIME_DIAG_COUNTER_PRINTER_JOB_CANCELED,
RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_ATTEMPT,
RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_SUCCESS,
RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_FAILED,
RUNTIME_DIAG_COUNTER_IMAGE_GENERATE_TIMEOUT,
RUNTIME_DIAG_COUNTER_MAX,
} runtime_diag_counter_t;
typedef enum {
RUNTIME_DIAG_GAUGE_LIFECYCLE_STATE = 0,
RUNTIME_DIAG_GAUGE_STATUS_POLL_PAUSE_DEPTH,
RUNTIME_DIAG_GAUGE_PRINTER_QUEUE_DEPTH,
RUNTIME_DIAG_GAUGE_MAX,
} runtime_diag_gauge_t;
void runtime_diag_counter_add(runtime_diag_counter_t counter, uint32_t delta);
void runtime_diag_set_gauge(runtime_diag_gauge_t gauge, int32_t value);
void runtime_diag_record_error(const char *source, esp_err_t code, const char *message);
#ifdef __cplusplus #ifdef __cplusplus
} }
#endif #endif

View File

@@ -1,81 +0,0 @@
#include "platform.h"
#include <string.h>
#include "esp_timer.h"
#include "freertos/FreeRTOS.h"
#include "freertos/semphr.h"
static SemaphoreHandle_t s_lock;
typedef struct {
uint64_t counters[RUNTIME_DIAG_COUNTER_MAX];
int32_t gauges[RUNTIME_DIAG_GAUGE_MAX];
int64_t last_error_ms;
esp_err_t last_error_code;
char last_error_source[32];
char last_error_message[96];
} runtime_diag_state_t;
static runtime_diag_state_t s_snapshot;
static void runtime_diag_ensure_lock(void) {
if (s_lock == NULL) {
s_lock = xSemaphoreCreateMutex();
}
}
void runtime_diag_counter_add(runtime_diag_counter_t counter, uint32_t delta) {
if (counter < 0 || counter >= RUNTIME_DIAG_COUNTER_MAX || delta == 0) {
return;
}
runtime_diag_ensure_lock();
if (s_lock == NULL) {
return;
}
if (xSemaphoreTake(s_lock, pdMS_TO_TICKS(50)) != pdTRUE) {
return;
}
s_snapshot.counters[counter] += delta;
xSemaphoreGive(s_lock);
}
void runtime_diag_set_gauge(runtime_diag_gauge_t gauge, int32_t value) {
if (gauge < 0 || gauge >= RUNTIME_DIAG_GAUGE_MAX) {
return;
}
runtime_diag_ensure_lock();
if (s_lock == NULL) {
return;
}
if (xSemaphoreTake(s_lock, pdMS_TO_TICKS(50)) != pdTRUE) {
return;
}
s_snapshot.gauges[gauge] = value;
xSemaphoreGive(s_lock);
}
void runtime_diag_record_error(const char *source, esp_err_t code, const char *message) {
runtime_diag_ensure_lock();
if (s_lock == NULL) {
return;
}
if (xSemaphoreTake(s_lock, pdMS_TO_TICKS(100)) != pdTRUE) {
return;
}
s_snapshot.last_error_ms = esp_timer_get_time() / 1000;
s_snapshot.last_error_code = code;
strlcpy(s_snapshot.last_error_source,
source != NULL ? source : "unknown",
sizeof(s_snapshot.last_error_source));
strlcpy(s_snapshot.last_error_message,
message != NULL ? message : "unknown",
sizeof(s_snapshot.last_error_message));
xSemaphoreGive(s_lock);
}

View File

@@ -150,21 +150,6 @@ static esp_err_t wifi_manager_load_credentials(wifi_sta_credentials_t *out_creds
return ESP_OK; return ESP_OK;
} }
static void wifi_manager_record_connect_result(esp_err_t err, const char *stage) {
if (err == ESP_OK) {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_WIFI_CONNECT_SUCCESS, 1);
return;
}
if (err == ESP_ERR_TIMEOUT) {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_WIFI_CONNECT_TIMEOUT, 1);
} else {
runtime_diag_counter_add(RUNTIME_DIAG_COUNTER_WIFI_CONNECT_FAILED, 1);
}
runtime_diag_record_error("wifi_connect", err, stage);
}
static void wifi_event_handler(void *arg, static void wifi_event_handler(void *arg,
esp_event_base_t event_base, esp_event_base_t event_base,
int32_t event_id, int32_t event_id,
@@ -373,14 +358,12 @@ static esp_err_t wifi_manager_scan_get_handler(httpd_req_t *req) {
esp_err_t err = esp_wifi_scan_start(&scan_cfg, true); esp_err_t err = esp_wifi_scan_start(&scan_cfg, true);
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_scan", err, "esp_wifi_scan_start failed");
return wifi_manager_send_prov_json(req, false, "scan_failed"); return wifi_manager_send_prov_json(req, false, "scan_failed");
} }
uint16_t ap_count = 0; uint16_t ap_count = 0;
err = esp_wifi_scan_get_ap_num(&ap_count); err = esp_wifi_scan_get_ap_num(&ap_count);
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_scan", err, "esp_wifi_scan_get_ap_num failed");
return wifi_manager_send_prov_json(req, false, "scan_failed"); return wifi_manager_send_prov_json(req, false, "scan_failed");
} }
@@ -399,7 +382,6 @@ static esp_err_t wifi_manager_scan_get_handler(httpd_req_t *req) {
err = esp_wifi_scan_get_ap_records(&fetch_num, records); err = esp_wifi_scan_get_ap_records(&fetch_num, records);
if (err != ESP_OK) { if (err != ESP_OK) {
free(records); free(records);
runtime_diag_record_error("wifi_scan", err, "esp_wifi_scan_get_ap_records failed");
return wifi_manager_send_prov_json(req, false, "scan_failed"); return wifi_manager_send_prov_json(req, false, "scan_failed");
} }
ap_count = fetch_num; ap_count = fetch_num;
@@ -494,25 +476,21 @@ static esp_err_t wifi_manager_connect_sta(const wifi_sta_credentials_t *creds, b
err = esp_wifi_set_mode(keep_softap ? WIFI_MODE_APSTA : WIFI_MODE_STA); err = esp_wifi_set_mode(keep_softap ? WIFI_MODE_APSTA : WIFI_MODE_STA);
if (err != ESP_OK) { if (err != ESP_OK) {
wifi_manager_record_connect_result(err, "set mode failed");
return err; return err;
} }
err = esp_wifi_set_config(WIFI_IF_STA, &wifi_config); err = esp_wifi_set_config(WIFI_IF_STA, &wifi_config);
if (err != ESP_OK) { if (err != ESP_OK) {
wifi_manager_record_connect_result(err, "set sta config failed");
return err; return err;
} }
err = esp_wifi_start(); err = esp_wifi_start();
if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) { if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) {
wifi_manager_record_connect_result(err, "wifi start failed");
return err; return err;
} }
err = esp_wifi_connect(); err = esp_wifi_connect();
if (err != ESP_OK && err != ESP_ERR_WIFI_CONN) { if (err != ESP_OK && err != ESP_ERR_WIFI_CONN) {
wifi_manager_record_connect_result(err, "wifi connect failed");
return err; return err;
} }
ESP_LOGI(TAG, "trying to connect to SSID:%s", creds->ssid); ESP_LOGI(TAG, "trying to connect to SSID:%s", creds->ssid);
@@ -533,18 +511,15 @@ static esp_err_t wifi_manager_connect_sta(const wifi_sta_credentials_t *creds, b
ESP_LOGW(TAG, "failed to set WIFI_PS_NONE, rc=0x%x", (unsigned)ps_rc); ESP_LOGW(TAG, "failed to set WIFI_PS_NONE, rc=0x%x", (unsigned)ps_rc);
} }
s_ready = true; s_ready = true;
wifi_manager_record_connect_result(ESP_OK, "connect success");
return ESP_OK; return ESP_OK;
} }
if (bits & WIFI_FAIL_BIT) { if (bits & WIFI_FAIL_BIT) {
ESP_LOGW(TAG, "failed to connect to SSID:%s", creds->ssid); ESP_LOGW(TAG, "failed to connect to SSID:%s", creds->ssid);
wifi_manager_record_connect_result(ESP_FAIL, "connect failed after retries");
return ESP_FAIL; return ESP_FAIL;
} }
ESP_LOGW(TAG, "Wi-Fi connect timeout, SSID:%s", creds->ssid); ESP_LOGW(TAG, "Wi-Fi connect timeout, SSID:%s", creds->ssid);
wifi_manager_record_connect_result(ESP_ERR_TIMEOUT, "connect timeout");
return ESP_ERR_TIMEOUT; return ESP_ERR_TIMEOUT;
} }
@@ -555,6 +530,12 @@ static esp_err_t wifi_manager_prov_index_get_handler(httpd_req_t *req) {
return httpd_resp_send(req, (const char *)s_provision_page_start, page_len); return httpd_resp_send(req, (const char *)s_provision_page_start, page_len);
} }
static esp_err_t wifi_manager_prov_favicon_get_handler(httpd_req_t *req) {
httpd_resp_set_status(req, "204 No Content");
httpd_resp_set_hdr(req, "Cache-Control", "max-age=86400");
return httpd_resp_send(req, NULL, 0);
}
static esp_err_t wifi_manager_prov_submit_post_handler(httpd_req_t *req) { static esp_err_t wifi_manager_prov_submit_post_handler(httpd_req_t *req) {
if (req->content_len <= 0 || req->content_len >= WIFI_PROV_HTTP_BODY_MAX_LEN) { if (req->content_len <= 0 || req->content_len >= WIFI_PROV_HTTP_BODY_MAX_LEN) {
return wifi_manager_send_prov_json(req, false, "invalid_payload"); return wifi_manager_send_prov_json(req, false, "invalid_payload");
@@ -597,7 +578,6 @@ static esp_err_t wifi_manager_prov_submit_post_handler(httpd_req_t *req) {
err = wifi_manager_save_credentials(&creds); err = wifi_manager_save_credentials(&creds);
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_provision", err, "save credentials failed");
s_ready = false; s_ready = false;
(void)esp_wifi_disconnect(); (void)esp_wifi_disconnect();
return wifi_manager_send_prov_json(req, false, "save_failed"); return wifi_manager_send_prov_json(req, false, "save_failed");
@@ -638,6 +618,19 @@ static esp_err_t wifi_manager_start_prov_http_server(void) {
return err; return err;
} }
const httpd_uri_t favicon_uri = {
.uri = "/favicon.ico",
.method = HTTP_GET,
.handler = wifi_manager_prov_favicon_get_handler,
.user_ctx = NULL,
};
err = httpd_register_uri_handler(s_prov_httpd, &favicon_uri);
if (err != ESP_OK) {
httpd_stop(s_prov_httpd);
s_prov_httpd = NULL;
return err;
}
const httpd_uri_t scan_uri = { const httpd_uri_t scan_uri = {
.uri = "/scan", .uri = "/scan",
.method = HTTP_GET, .method = HTTP_GET,
@@ -790,20 +783,17 @@ esp_err_t wifi_manager_start(void) {
esp_err_t err = esp_netif_init(); esp_err_t err = esp_netif_init();
if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) { if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) {
runtime_diag_record_error("wifi_start", err, "esp_netif_init failed");
return err; return err;
} }
err = esp_event_loop_create_default(); err = esp_event_loop_create_default();
if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) { if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) {
runtime_diag_record_error("wifi_start", err, "event loop init failed");
return err; return err;
} }
if (s_sta_netif == NULL) { if (s_sta_netif == NULL) {
s_sta_netif = esp_netif_create_default_wifi_sta(); s_sta_netif = esp_netif_create_default_wifi_sta();
if (s_sta_netif == NULL) { if (s_sta_netif == NULL) {
runtime_diag_record_error("wifi_start", ESP_ERR_NO_MEM, "create sta netif failed");
return ESP_ERR_NO_MEM; return ESP_ERR_NO_MEM;
} }
} }
@@ -811,7 +801,6 @@ esp_err_t wifi_manager_start(void) {
if (s_ap_netif == NULL) { if (s_ap_netif == NULL) {
s_ap_netif = esp_netif_create_default_wifi_ap(); s_ap_netif = esp_netif_create_default_wifi_ap();
if (s_ap_netif == NULL) { if (s_ap_netif == NULL) {
runtime_diag_record_error("wifi_start", ESP_ERR_NO_MEM, "create ap netif failed");
return ESP_ERR_NO_MEM; return ESP_ERR_NO_MEM;
} }
} }
@@ -819,13 +808,11 @@ esp_err_t wifi_manager_start(void) {
wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT(); wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
err = esp_wifi_init(&cfg); err = esp_wifi_init(&cfg);
if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) { if (err != ESP_OK && err != ESP_ERR_INVALID_STATE) {
runtime_diag_record_error("wifi_start", err, "esp_wifi_init failed");
return err; return err;
} }
err = esp_wifi_set_storage(WIFI_STORAGE_RAM); err = esp_wifi_set_storage(WIFI_STORAGE_RAM);
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_start", err, "esp_wifi_set_storage RAM failed");
return err; return err;
} }
@@ -836,7 +823,6 @@ esp_err_t wifi_manager_start(void) {
NULL, NULL,
&s_wifi_event_inst); &s_wifi_event_inst);
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_start", err, "register WIFI event failed");
return err; return err;
} }
} }
@@ -848,7 +834,6 @@ esp_err_t wifi_manager_start(void) {
NULL, NULL,
&s_ip_event_inst); &s_ip_event_inst);
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_start", err, "register IP event failed");
return err; return err;
} }
} }
@@ -870,7 +855,6 @@ esp_err_t wifi_manager_start(void) {
err = wifi_manager_run_softap_provisioning(); err = wifi_manager_run_softap_provisioning();
if (err != ESP_OK) { if (err != ESP_OK) {
runtime_diag_record_error("wifi_start", err, "SoftAP provisioning failed");
(void)wifi_manager_stop(); (void)wifi_manager_stop();
} }
@@ -949,7 +933,6 @@ esp_err_t wifi_manager_stop(void) {
s_started = false; s_started = false;
if (first_err != ESP_OK) { if (first_err != ESP_OK) {
runtime_diag_record_error("wifi_stop", first_err, "wifi stop failed");
} }
return first_err; return first_err;

View File

@@ -14,6 +14,8 @@ CONFIG_LWIP_TCP_SND_BUF_DEFAULT=57344
CONFIG_LWIP_TCP_WND_DEFAULT=262144 CONFIG_LWIP_TCP_WND_DEFAULT=262144
CONFIG_LWIP_TCP_RECVMBOX_SIZE=192 CONFIG_LWIP_TCP_RECVMBOX_SIZE=192
CONFIG_LWIP_TCPIP_RECVMBOX_SIZE=256 CONFIG_LWIP_TCPIP_RECVMBOX_SIZE=256
CONFIG_LOG_DEFAULT_LEVEL_WARN=y
CONFIG_BOOTLOADER_LOG_LEVEL_WARN=y
CONFIG_TQ_WIFI_PROV_SOFTAP_SSID="TalkingQ-Setup" CONFIG_TQ_WIFI_PROV_SOFTAP_SSID="TalkingQ-Setup"
CONFIG_TQ_WIFI_PROV_SOFTAP_PASSWORD="" CONFIG_TQ_WIFI_PROV_SOFTAP_PASSWORD=""
CONFIG_TQ_WIFI_PROV_SOFTAP_CHANNEL=1 CONFIG_TQ_WIFI_PROV_SOFTAP_CHANNEL=1