添加日志

main/control_plane/src/rest_server_print.c

@@ -5,16 +5,34 @@
 #include <string.h>
 #include <strings.h>
 
+#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;
 }

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;
 }

main/domain/src/printer_protocol.c

@@ -7,6 +7,7 @@
 #include <string.h>
 
 #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,7 +475,19 @@ 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);
@@ -459,6 +495,7 @@ static bool run_print_job(job_slot_t *job) {
     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;
+        job_slot_t *job = &s_jobs[idx];
-        s_jobs[idx].started_ms = esp_timer_get_time() / 1000;
+        job->state = PRINT_JOB_STATE_RUNNING;
-        s_jobs[idx].progress = 1;
+        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;
 }