diff --git a/main/control_plane/src/rest_server_print.c b/main/control_plane/src/rest_server_print.c index 83e6678..dcba339 100644 --- a/main/control_plane/src/rest_server_print.c +++ b/main/control_plane/src/rest_server_print.c @@ -5,16 +5,34 @@ #include #include +#include "esp_log.h" #include "image_generation.h" #include "printer_protocol.h" #include "raster_tools.h" + +static const char *TAG = "rest_print"; + +static const char *trace_id_or_default(const char *trace_id) { + return (trace_id != NULL && trace_id[0] != '\0') ? trace_id : "-"; +} + static esp_err_t submit_raster_job_and_reply(httpd_req_t *req, const uint8_t *raw, size_t raw_len, uint16_t width, uint16_t height, const char *density, - const char *warning) { + const char *warning, + const char *trace_id) { + const char *trace = trace_id_or_default(trace_id); + ESP_LOGI(TAG, + "print submit start, trace=%s, raster_bytes=%u, size=%ux%u, density=%s", + trace, + (unsigned)raw_len, + (unsigned)width, + (unsigned)height, + density != NULL ? density : "中等"); + char submit_err[128] = {0}; uint32_t job_id = 0; esp_err_t submit_rc = printer_protocol_submit_raster_job(raw, @@ -26,11 +44,18 @@ static esp_err_t submit_raster_job_and_reply(httpd_req_t *req, submit_err, sizeof(submit_err)); if (submit_rc != ESP_OK) { + ESP_LOGW(TAG, + "print submit failed, trace=%s, rc=0x%x, msg=%s", + trace, + (unsigned)submit_rc, + submit_err[0] != '\0' ? submit_err : "submit failed"); return rest_server_send_error(req, "400 Bad Request", submit_err[0] != '\0' ? submit_err : "submit failed"); } + ESP_LOGI(TAG, "print submit done, trace=%s, job_id=%u", trace, (unsigned)job_id); + cJSON *root = cJSON_CreateObject(); cJSON_AddBoolToObject(root, "ok", true); cJSON_AddNumberToObject(root, "job_id", job_id); @@ -524,6 +549,7 @@ esp_err_t rest_server_print_raster_post(httpd_req_t *req) { (uint16_t)jwidth->valuedouble, (uint16_t)jheight->valuedouble, density, + NULL, NULL); free(raw); cJSON_Delete(json); @@ -562,6 +588,15 @@ static esp_err_t rest_server_print_image_binary(httpd_req_t *req) { &max_height, &density); + ESP_LOGI(TAG, + "image process start (upload), png_bytes=%u, scale_to_width=%d, threshold=%u, invert=%d, max_height=%u, density=%s", + (unsigned)req->content_len, + scale_to_width, + (unsigned)threshold, + invert, + (unsigned)max_height, + density != NULL ? density : "中等"); + char *body = NULL; esp_err_t body_err = rest_server_read_body(req, &body); if (body_err != ESP_OK) { @@ -587,17 +622,28 @@ static esp_err_t rest_server_print_image_binary(httpd_req_t *req) { sizeof(decode_err)); free(body); if (decode_rc != ESP_OK) { + ESP_LOGW(TAG, + "image process failed (upload), rc=0x%x, msg=%s", + (unsigned)decode_rc, + decode_err[0] != '\0' ? decode_err : "decode png failed"); return rest_server_send_error(req, "400 Bad Request", decode_err[0] != '\0' ? decode_err : "decode png failed"); } + ESP_LOGI(TAG, + "image process done (upload), raster_size=%ux%u, raster_bytes=%u", + (unsigned)width, + (unsigned)height, + (unsigned)raster_len); + esp_err_t submit_rc = submit_raster_job_and_reply(req, raster, raster_len, width, height, density, + NULL, NULL); free(raster); return submit_rc; @@ -638,6 +684,22 @@ static esp_err_t rest_server_print_image_generate(httpd_req_t *req) { cJSON_Delete(json); json = NULL; + ESP_LOGI(TAG, + "image generate start, prompt_len=%u, size=%s, prompt_extend=%d, seed=%s, timeout_ms=%u, fetch_timeout_ms=%u", + (unsigned)strlen(gen_opt.prompt), + gen_opt.has_size ? gen_opt.size : "default", + gen_opt.prompt_extend, + gen_opt.has_seed ? "set" : "auto", + (unsigned)gen_opt.timeout_ms, + (unsigned)gen_opt.fetch_timeout_ms); + ESP_LOGI(TAG, + "image process config, scale_to_width=%d, threshold=%u, invert=%d, max_height=%u, density=%s", + print_opt.scale_to_width, + (unsigned)print_opt.threshold, + print_opt.invert, + (unsigned)print_opt.max_height, + print_opt.density != NULL ? print_opt.density : "中等"); + image_generation_request_t gen_req = { .prompt = gen_opt.prompt, .size = gen_opt.has_size ? gen_opt.size : NULL, @@ -661,6 +723,10 @@ static esp_err_t rest_server_print_image_generate(httpd_req_t *req) { model_err, sizeof(model_err)); if (gen_rc != ESP_OK) { + ESP_LOGW(TAG, + "image generate failed, rc=0x%x, msg=%s", + (unsigned)gen_rc, + model_err[0] != '\0' ? model_err : "image generation failed"); ret = rest_server_send_image_generation_error(req, gen_rc, model_err); goto cleanup; } @@ -669,6 +735,13 @@ static esp_err_t rest_server_print_image_generate(httpd_req_t *req) { strlcpy(request_id, gen_result->request_id, sizeof(request_id)); } + ESP_LOGI(TAG, + "image generate done, request_id=%s, model_size=%ux%u, png_bytes=%u", + request_id[0] != '\0' ? request_id : "-", + (unsigned)gen_result->width, + (unsigned)gen_result->height, + (unsigned)gen_result->png_len); + uint16_t width = 0; uint16_t height = 0; size_t raster_len = 0; @@ -686,12 +759,22 @@ static esp_err_t rest_server_print_image_generate(httpd_req_t *req) { decode_err, sizeof(decode_err)); if (decode_rc != ESP_OK) { + ESP_LOGW(TAG, + "image process failed (generated), rc=0x%x, msg=%s", + (unsigned)decode_rc, + decode_err[0] != '\0' ? decode_err : "decode generated image failed"); ret = rest_server_send_error(req, "400 Bad Request", decode_err[0] != '\0' ? decode_err : "decode generated image failed"); goto cleanup; } + ESP_LOGI(TAG, + "image process done (generated), raster_size=%ux%u, raster_bytes=%u", + (unsigned)width, + (unsigned)height, + (unsigned)raster_len); + char warning[160] = {0}; if (request_id[0] != '\0') { snprintf(warning, sizeof(warning), "z-image request_id=%s", request_id); @@ -703,7 +786,8 @@ static esp_err_t rest_server_print_image_generate(httpd_req_t *req) { width, height, print_opt.density, - warning); + warning, + request_id); cleanup: if (body != NULL) { @@ -826,6 +910,7 @@ esp_err_t rest_server_print_qr_post(httpd_req_t *req) { width, height, density, + NULL, NULL); free(raster); return submit_rc; @@ -914,6 +999,7 @@ esp_err_t rest_server_print_label_post(httpd_req_t *req) { width, height, density, + NULL, NULL); free(raster); return submit_rc; @@ -992,7 +1078,8 @@ esp_err_t rest_server_print_text_post(httpd_req_t *req) { width, height, density, - render_msg); + render_msg, + NULL); free(raster); return submit_rc; } @@ -1111,7 +1198,8 @@ esp_err_t rest_server_print_receipt_post(httpd_req_t *req) { width, height, density, - render_msg); + render_msg, + NULL); free(raster); return submit_rc; } diff --git a/main/domain/src/image_generation.c b/main/domain/src/image_generation.c index 09ee7f9..a421a9d 100644 --- a/main/domain/src/image_generation.c +++ b/main/domain/src/image_generation.c @@ -394,6 +394,10 @@ static esp_err_t image_generation_invoke_model(const image_generation_request_t char auth_header[192] = {0}; snprintf(auth_header, sizeof(auth_header), "Bearer %s", api_key); + ESP_LOGI(TAG, + "z-image request start, timeout_ms=%u", + (unsigned)req->generation_timeout_ms); + esp_http_client_config_t config = { .url = CONFIG_TQ_Z_IMAGE_API_ENDPOINT, .method = HTTP_METHOD_POST, @@ -420,6 +424,10 @@ static esp_err_t image_generation_invoke_model(const image_generation_request_t err_len); cJSON_free(req_body); if (rc != ESP_OK) { + ESP_LOGW(TAG, + "z-image request failed, rc=0x%x, msg=%s", + (unsigned)rc, + (err != NULL && err[0] != '\0') ? err : "http request failed"); bytes_buffer_free(&resp); return rc; } @@ -433,6 +441,10 @@ static esp_err_t image_generation_invoke_model(const image_generation_request_t if (http_status < 200 || http_status >= 300) { extract_remote_error_message((const char *)resp.data, http_status, err, err_len); + ESP_LOGW(TAG, + "z-image http status=%d, msg=%s", + http_status, + (err != NULL && err[0] != '\0') ? err : "upstream request failed"); bytes_buffer_free(&resp); return ESP_FAIL; } @@ -472,10 +484,20 @@ static esp_err_t image_generation_invoke_model(const image_generation_request_t } else { image_generation_fill_err(err, err_len, "generation response has no image url"); } + ESP_LOGW(TAG, + "z-image response parse failed, msg=%s", + (err != NULL && err[0] != '\0') ? err : "generation response has no image url"); cJSON_Delete(root); return ESP_FAIL; } + ESP_LOGI(TAG, + "z-image response ready, request_id=%s, model_size=%ux%u, image_url_len=%u", + out_result->request_id[0] != '\0' ? out_result->request_id : "-", + (unsigned)out_result->width, + (unsigned)out_result->height, + (unsigned)strlen(out_result->image_url)); + cJSON_Delete(root); return ESP_OK; } @@ -484,6 +506,8 @@ static esp_err_t image_generation_download_png(image_generation_result_t *out_re uint32_t timeout_ms, char *err, size_t err_len) { + ESP_LOGI(TAG, "generated image download start, timeout_ms=%u", (unsigned)timeout_ms); + esp_http_client_config_t config = { .url = out_result->image_url, .method = HTTP_METHOD_GET, @@ -508,6 +532,10 @@ static esp_err_t image_generation_download_png(image_generation_result_t *out_re err, err_len); if (rc != ESP_OK) { + ESP_LOGW(TAG, + "generated image download failed, rc=0x%x, msg=%s", + (unsigned)rc, + (err != NULL && err[0] != '\0') ? err : "download failed"); bytes_buffer_free(&resp); return rc; } @@ -520,6 +548,10 @@ static esp_err_t image_generation_download_png(image_generation_result_t *out_re return ESP_FAIL; } extract_remote_error_message((const char *)resp.data, http_status, err, err_len); + ESP_LOGW(TAG, + "generated image download http status=%d, msg=%s", + http_status, + (err != NULL && err[0] != '\0') ? err : "image download failed"); bytes_buffer_free(&resp); return ESP_FAIL; } @@ -530,11 +562,13 @@ static esp_err_t image_generation_download_png(image_generation_result_t *out_re if (resp.len < sizeof(png_header) || memcmp(resp.data, png_header, sizeof(png_header)) != 0) { bytes_buffer_free(&resp); image_generation_fill_err(err, err_len, "downloaded image is not png"); + ESP_LOGW(TAG, "generated image download invalid png signature"); return ESP_FAIL; } out_result->png = resp.data; out_result->png_len = resp.len; + ESP_LOGI(TAG, "generated image download done, png_bytes=%u", (unsigned)out_result->png_len); return ESP_OK; } @@ -573,19 +607,39 @@ esp_err_t image_generation_generate_png(const image_generation_request_t *req, actual.download_timeout_ms = CONFIG_TQ_Z_IMAGE_DOWNLOAD_TIMEOUT_MS; } - ESP_LOGI(TAG, "invoke z-image, prompt_len=%u", (unsigned)strlen(actual.prompt)); + ESP_LOGI(TAG, + "image generate start, prompt_len=%u, size=%s, prompt_extend=%d, seed=%s, gen_timeout_ms=%u, fetch_timeout_ms=%u", + (unsigned)strlen(actual.prompt), + (actual.size != NULL && actual.size[0] != '\0') ? actual.size : "default", + actual.prompt_extend, + actual.has_seed ? "set" : "auto", + (unsigned)actual.generation_timeout_ms, + (unsigned)actual.download_timeout_ms); esp_err_t gen_rc = image_generation_invoke_model(&actual, out_result, err, err_len); if (gen_rc != ESP_OK) { + ESP_LOGW(TAG, + "image generate stage failed, rc=0x%x, msg=%s", + (unsigned)gen_rc, + (err != NULL && err[0] != '\0') ? err : "model invoke failed"); image_generation_result_free(out_result); return gen_rc; } - ESP_LOGI(TAG, "download image from model output"); + ESP_LOGI(TAG, "image generate stage done, request_id=%s", out_result->request_id[0] != '\0' ? out_result->request_id : "-"); esp_err_t dl_rc = image_generation_download_png(out_result, actual.download_timeout_ms, err, err_len); if (dl_rc != ESP_OK) { + ESP_LOGW(TAG, + "image download stage failed, rc=0x%x, msg=%s", + (unsigned)dl_rc, + (err != NULL && err[0] != '\0') ? err : "download failed"); image_generation_result_free(out_result); return dl_rc; } + ESP_LOGI(TAG, + "image generation pipeline done, request_id=%s, png_bytes=%u", + out_result->request_id[0] != '\0' ? out_result->request_id : "-", + (unsigned)out_result->png_len); + return ESP_OK; } diff --git a/main/domain/src/printer_protocol.c b/main/domain/src/printer_protocol.c index cf3599c..8622bf4 100644 --- a/main/domain/src/printer_protocol.c +++ b/main/domain/src/printer_protocol.c @@ -7,6 +7,7 @@ #include #include "ble_printer_client.h" +#include "esp_log.h" #include "esp_timer.h" #include "freertos/FreeRTOS.h" #include "freertos/event_groups.h" @@ -71,6 +72,7 @@ static uint8_t s_last_rsp_payload[252]; static uint32_t s_next_job_id = 1; static job_slot_t s_jobs[JOB_SLOT_MAX]; +static const char *TAG = "printer_protocol"; static int find_job_idx_locked(uint32_t id) { for (int i = 0; i < JOB_SLOT_MAX; ++i) { @@ -387,25 +389,38 @@ static bool precheck_printer_ready(char *err, size_t err_len) { static bool run_print_job(job_slot_t *job) { char err[96]; err[0] = '\0'; + uint8_t next_progress_log = 25; + + ESP_LOGI(TAG, + "job %u print start, raster_bytes=%u, size=%ux%u, density=%s", + (unsigned)job->id, + (unsigned)job->data_len, + (unsigned)job->width, + (unsigned)job->height, + job->density); if (!ble_printer_client_is_connected()) { snprintf(job->error, sizeof(job->error), "printer not connected"); + ESP_LOGW(TAG, "job %u print aborted: %s", (unsigned)job->id, job->error); return false; } if (!precheck_printer_ready(err, sizeof(err))) { snprintf(job->error, sizeof(job->error), "%s", err); + ESP_LOGW(TAG, "job %u print aborted: %s", (unsigned)job->id, job->error); return false; } if (job->cancel_requested) { snprintf(job->error, sizeof(job->error), "job canceled"); + ESP_LOGW(TAG, "job %u print canceled before start", (unsigned)job->id); return false; } uint8_t power_on = 0x01; if (!send_cmd_with_ack(CMD_POWER, &power_on, 1, true, 1500)) { snprintf(job->error, sizeof(job->error), "power on failed"); + ESP_LOGW(TAG, "job %u print aborted: %s", (unsigned)job->id, job->error); return false; } @@ -419,15 +434,23 @@ static bool run_print_job(job_slot_t *job) { if (!send_cmd_with_ack(CMD_SET_PARAM, param, sizeof(param), true, 1500)) { snprintf(job->error, sizeof(job->error), "set print param failed"); + ESP_LOGW(TAG, "job %u print aborted: %s", (unsigned)job->id, job->error); return false; } const size_t chunk_max = 240; size_t total_chunks = (size_t)ceil((double)job->data_len / (double)chunk_max); + ESP_LOGI(TAG, + "job %u data transfer start, chunks=%u, chunk_bytes=%u, hot_time=%u", + (unsigned)job->id, + (unsigned)total_chunks, + (unsigned)chunk_max, + (unsigned)hot_time); for (size_t i = 0; i < total_chunks; ++i) { if (job->cancel_requested) { snprintf(job->error, sizeof(job->error), "job canceled"); + ESP_LOGW(TAG, "job %u print canceled at chunk %u/%u", (unsigned)job->id, (unsigned)(i + 1), (unsigned)total_chunks); return false; } @@ -441,6 +464,7 @@ static bool run_print_job(job_slot_t *job) { false, 2500)) { snprintf(job->error, sizeof(job->error), "send chunk timeout at %u", (unsigned)i); + ESP_LOGW(TAG, "job %u print aborted: %s", (unsigned)job->id, job->error); return false; } @@ -451,14 +475,27 @@ static bool run_print_job(job_slot_t *job) { } xSemaphoreGive(s_mutex); } + + while (job->progress >= next_progress_log && next_progress_log <= 90) { + ESP_LOGI(TAG, + "job %u print progress=%u%% (%u/%u chunks)", + (unsigned)job->id, + (unsigned)job->progress, + (unsigned)(i + 1), + (unsigned)total_chunks); + next_progress_log = (uint8_t)(next_progress_log + 25); + } } + ESP_LOGI(TAG, "job %u data transfer done", (unsigned)job->id); + uint8_t power_off = 0x00; (void)send_cmd_with_ack(CMD_POWER, &power_off, 1, true, 1200); uint8_t feed_payload[3] = {0x2B, 0x00, 0x0C}; (void)send_cmd_with_ack(CMD_SET_DISTANCE, feed_payload, sizeof(feed_payload), true, 1200); + ESP_LOGI(TAG, "job %u print command sequence done", (unsigned)job->id); return true; } @@ -498,13 +535,26 @@ static void worker_task(void *arg) { continue; } - s_jobs[idx].state = PRINT_JOB_STATE_RUNNING; - s_jobs[idx].started_ms = esp_timer_get_time() / 1000; - s_jobs[idx].progress = 1; + job_slot_t *job = &s_jobs[idx]; + job->state = PRINT_JOB_STATE_RUNNING; + job->started_ms = esp_timer_get_time() / 1000; + job->progress = 1; s_busy_refcnt = 1; + int64_t queue_wait_ms = 0; + if (job->started_ms >= job->created_ms) { + queue_wait_ms = job->started_ms - job->created_ms; + } + ESP_LOGI(TAG, + "job %u running, queue_wait_ms=%lld, raster_bytes=%u, size=%ux%u, density=%s", + (unsigned)job->id, + (long long)queue_wait_ms, + (unsigned)job->data_len, + (unsigned)job->width, + (unsigned)job->height, + job->density); xSemaphoreGive(s_mutex); - bool ok = run_print_job(&s_jobs[idx]); + bool ok = run_print_job(job); if (xSemaphoreTake(s_mutex, pdMS_TO_TICKS(1000)) != pdTRUE) { continue; @@ -530,6 +580,25 @@ static void worker_task(void *arg) { s_jobs[idx].state = PRINT_JOB_STATE_FAILED; } + int64_t duration_ms = 0; + if (s_jobs[idx].finished_ms >= s_jobs[idx].started_ms) { + duration_ms = s_jobs[idx].finished_ms - s_jobs[idx].started_ms; + } + if (s_jobs[idx].state == PRINT_JOB_STATE_SUCCESS) { + ESP_LOGI(TAG, + "job %u done, state=%s, duration_ms=%lld", + (unsigned)s_jobs[idx].id, + printer_protocol_job_state_str(s_jobs[idx].state), + (long long)duration_ms); + } else { + ESP_LOGW(TAG, + "job %u done, state=%s, duration_ms=%lld, error=%s", + (unsigned)s_jobs[idx].id, + printer_protocol_job_state_str(s_jobs[idx].state), + (long long)duration_ms, + s_jobs[idx].error[0] != '\0' ? s_jobs[idx].error : "-"); + } + free(s_jobs[idx].data); s_jobs[idx].data = NULL; xSemaphoreGive(s_mutex); @@ -768,6 +837,10 @@ esp_err_t printer_protocol_submit_raster_job(const uint8_t *raster, if (err != NULL && err_len > 0) { snprintf(err, err_len, "job queue full"); } + ESP_LOGW(TAG, + "job enqueue failed, job_id=%u, reason=%s", + (unsigned)id, + (err != NULL && err[0] != '\0') ? err : "job queue full"); return ESP_ERR_TIMEOUT; } @@ -775,6 +848,16 @@ esp_err_t printer_protocol_submit_raster_job(const uint8_t *raster, *out_job_id = id; } + UBaseType_t queue_depth = uxQueueMessagesWaiting(s_job_queue); + ESP_LOGI(TAG, + "job queued, job_id=%u, raster_bytes=%u, size=%ux%u, density=%s, queue_depth=%u", + (unsigned)id, + (unsigned)raster_len, + (unsigned)width, + (unsigned)height, + density != NULL ? density : "中等", + (unsigned)queue_depth); + return ESP_OK; }