This commit is contained in:
J. Nick Koston 2025-06-29 18:30:00 -05:00
parent 98c18517e2
commit 0005aad5b5
No known key found for this signature in database
4 changed files with 21 additions and 45 deletions

View File

@ -160,9 +160,9 @@ void OTARequestHandler::handleUpload(AsyncWebServerRequest *request, const Strin
// Log first chunk of data received by OTA handler
if (this->ota_read_length_ == 0 && len >= 8) {
ESP_LOGD(TAG, "First data received by OTA handler: %02x %02x %02x %02x %02x %02x %02x %02x", data[0], data[1],
ESP_LOGV(TAG, "First data received by OTA handler: %02x %02x %02x %02x %02x %02x %02x %02x", data[0], data[1],
data[2], data[3], data[4], data[5], data[6], data[7]);
ESP_LOGD(TAG, "Data pointer in OTA handler: %p, len: %zu, index: %zu", data, len, index);
ESP_LOGV(TAG, "Data pointer in OTA handler: %p, len: %zu, index: %zu", data, len, index);
}
// Feed watchdog and yield periodically to prevent timeout during OTA
@ -214,7 +214,7 @@ void OTARequestHandler::handleUpload(AsyncWebServerRequest *request, const Strin
}
void OTARequestHandler::handleRequest(AsyncWebServerRequest *request) {
#ifdef USE_WEBSERVER_OTA
ESP_LOGD(TAG, "OTA handleRequest called");
ESP_LOGV(TAG, "OTA handleRequest called");
AsyncWebServerResponse *response;
#ifdef USE_ARDUINO
if (!Update.hasError()) {
@ -237,7 +237,7 @@ void OTARequestHandler::handleRequest(AsyncWebServerRequest *request) {
// 2. The server is shutting down and can't process new requests
// These warnings are harmless and expected during OTA reboot.
if (this->ota_success_) {
ESP_LOGD(TAG, "Sending OTA success response before reboot");
ESP_LOGV(TAG, "Sending OTA success response before reboot");
request->send(200, "text/plain", "Update Successful!");
} else {
request->send(200, "text/plain", "Update Failed!");

View File

@ -184,7 +184,7 @@ bool parse_multipart_boundary(const char *content_type, const char **boundary_st
*boundary_start = start;
// Debug log the extracted boundary
ESP_LOGD("multipart_utils", "Extracted boundary: '%.*s' (len: %zu)", (int) *boundary_len, start, *boundary_len);
ESP_LOGV("multipart_utils", "Extracted boundary: '%.*s' (len: %zu)", (int) *boundary_len, start, *boundary_len);
return true;
}

View File

@ -48,15 +48,15 @@ size_t MultipartReader::parse(const char *data, size_t len) {
size_t parsed = multipart_parser_execute(parser_, data, len);
if (parsed != len) {
ESP_LOGD(TAG, "Parser consumed %zu of %zu bytes", parsed, len);
ESP_LOGW(TAG, "Parser consumed %zu of %zu bytes - possible error", parsed, len);
// Log the data around the error point
if (parsed < len && parsed < 32) {
ESP_LOGD(TAG, "Data at error point (offset %zu): %02x %02x %02x %02x", parsed,
ESP_LOGV(TAG, "Data at error point (offset %zu): %02x %02x %02x %02x", parsed,
parsed > 0 ? (uint8_t) data[parsed - 1] : 0, (uint8_t) data[parsed],
parsed + 1 < len ? (uint8_t) data[parsed + 1] : 0, parsed + 2 < len ? (uint8_t) data[parsed + 2] : 0);
// Log what we have vs what parser expects
ESP_LOGD(TAG, "Parser error at position %zu: got '%c' (0x%02x)", parsed, data[parsed], (uint8_t) data[parsed]);
ESP_LOGV(TAG, "Parser error at position %zu: got '%c' (0x%02x)", parsed, data[parsed], (uint8_t) data[parsed]);
}
}
@ -107,7 +107,7 @@ int MultipartReader::on_headers_complete(multipart_parser *parser) {
reader->current_header_field_.clear();
reader->current_header_value_.clear();
ESP_LOGD(TAG, "Part headers complete: name='%s', filename='%s', content_type='%s'",
ESP_LOGV(TAG, "Part headers complete: name='%s', filename='%s', content_type='%s'",
reader->current_part_.name.c_str(), reader->current_part_.filename.c_str(),
reader->current_part_.content_type.c_str());
@ -131,7 +131,7 @@ int MultipartReader::on_part_data(multipart_parser *parser, const char *at, size
// later use as the buffer will be overwritten.
// Log first data bytes from multipart parser
if (!reader->first_data_logged_ && length >= 8) {
ESP_LOGD(TAG, "First part data from parser: %02x %02x %02x %02x %02x %02x %02x %02x", (uint8_t) at[0],
ESP_LOGV(TAG, "First part data from parser: %02x %02x %02x %02x %02x %02x %02x %02x", (uint8_t) at[0],
(uint8_t) at[1], (uint8_t) at[2], (uint8_t) at[3], (uint8_t) at[4], (uint8_t) at[5], (uint8_t) at[6],
(uint8_t) at[7]);
reader->first_data_logged_ = true;

View File

@ -96,7 +96,7 @@ esp_err_t AsyncWebServer::request_post_handler(httpd_req_t *r) {
if (parse_multipart_boundary(ct.c_str(), &boundary_start, &boundary_len)) {
boundary.assign(boundary_start, boundary_len);
is_multipart = true;
ESP_LOGD(TAG, "Multipart upload detected, boundary: '%s' (len: %zu)", boundary.c_str(), boundary_len);
ESP_LOGV(TAG, "Multipart upload detected, boundary: '%s' (len: %zu)", boundary.c_str(), boundary_len);
} else if (!is_form_urlencoded(ct.c_str())) {
ESP_LOGW(TAG, "Unsupported content type for POST: %s", ct.c_str());
// fallback to get handler to support backward compatibility
@ -143,7 +143,7 @@ esp_err_t AsyncWebServer::request_post_handler(httpd_req_t *r) {
// Handle multipart upload using the multipart-parser library
// The multipart data starts with "--" + boundary, so we need to prepend it
std::string full_boundary = "--" + boundary;
ESP_LOGV(TAG, "Initializing multipart reader with full boundary: '%s'", full_boundary.c_str());
ESP_LOGVV(TAG, "Initializing multipart reader with full boundary: '%s'", full_boundary.c_str());
MultipartReader reader(full_boundary);
static constexpr size_t CHUNK_SIZE = 1024;
// IMPORTANT: chunk_buf is reused for each chunk read from the socket.
@ -172,20 +172,12 @@ esp_err_t AsyncWebServer::request_post_handler(httpd_req_t *r) {
if (current_filename.empty()) {
// First time we see data for this file
current_filename = reader.get_current_part().filename;
ESP_LOGD(TAG, "Processing file part: '%s'", current_filename.c_str());
}
// Log first few bytes of firmware data (only once)
static bool firmware_data_logged = false;
if (!firmware_data_logged && len >= 8) {
ESP_LOGD(TAG, "First firmware bytes from callback: %02x %02x %02x %02x %02x %02x %02x %02x", data[0], data[1],
data[2], data[3], data[4], data[5], data[6], data[7]);
firmware_data_logged = true;
ESP_LOGV(TAG, "Processing file part: '%s'", current_filename.c_str());
}
if (!file_started) {
// Initialize the upload with index=0
ESP_LOGD(TAG, "Starting upload for: '%s'", current_filename.c_str());
ESP_LOGV(TAG, "Starting upload for: '%s'", current_filename.c_str());
found_handler->handleUpload(&req, current_filename, 0, nullptr, 0, false);
file_started = true;
upload_started = true;
@ -201,7 +193,7 @@ esp_err_t AsyncWebServer::request_post_handler(httpd_req_t *r) {
reader.set_part_complete_callback([&]() {
if (!current_filename.empty() && upload_started) {
ESP_LOGD(TAG, "Part complete callback called for: '%s'", current_filename.c_str());
ESP_LOGV(TAG, "Part complete callback called for: '%s'", current_filename.c_str());
// Signal end of this part - final=true signals completion
found_handler->handleUpload(&req, current_filename, 2, nullptr, 0, true);
current_filename.clear();
@ -243,30 +235,14 @@ esp_err_t AsyncWebServer::request_post_handler(httpd_req_t *r) {
static size_t bytes_logged = 0;
bytes_logged += recv_len;
if (bytes_logged > 100000) {
ESP_LOGD(TAG, "OTA progress: %zu bytes remaining", remaining);
ESP_LOGV(TAG, "OTA progress: %zu bytes remaining", remaining);
bytes_logged = 0;
}
// Log first few bytes for debugging
if (total_len == remaining) {
ESP_LOGD(TAG, "First chunk data (hex): %02x %02x %02x %02x %02x %02x %02x %02x", (uint8_t) chunk_buf[0],
(uint8_t) chunk_buf[1], (uint8_t) chunk_buf[2], (uint8_t) chunk_buf[3], (uint8_t) chunk_buf[4],
(uint8_t) chunk_buf[5], (uint8_t) chunk_buf[6], (uint8_t) chunk_buf[7]);
ESP_LOGD(TAG, "First chunk data (ascii): %.8s", chunk_buf.get());
ESP_LOGD(TAG, "Expected boundary start: %.8s", full_boundary.c_str());
// Log more of the first chunk to see the headers
ESP_LOGD(TAG, "First 256 bytes of upload:");
for (int i = 0; i < std::min(recv_len, 256); i += 16) {
char hex_buf[50];
char ascii_buf[17];
int n = std::min(16, recv_len - i);
for (int j = 0; j < n; j++) {
sprintf(hex_buf + j * 3, "%02x ", (uint8_t) chunk_buf[i + j]);
ascii_buf[j] = isprint(chunk_buf[i + j]) ? chunk_buf[i + j] : '.';
}
ascii_buf[n] = '\0';
ESP_LOGD(TAG, "%04x: %-48s %s", i, hex_buf, ascii_buf);
}
ESP_LOGVV(TAG, "First chunk data (hex): %02x %02x %02x %02x %02x %02x %02x %02x", (uint8_t) chunk_buf[0],
(uint8_t) chunk_buf[1], (uint8_t) chunk_buf[2], (uint8_t) chunk_buf[3], (uint8_t) chunk_buf[4],
(uint8_t) chunk_buf[5], (uint8_t) chunk_buf[6], (uint8_t) chunk_buf[7]);
}
size_t parsed = reader.parse(chunk_buf.get(), recv_len);
@ -289,9 +265,9 @@ esp_err_t AsyncWebServer::request_post_handler(httpd_req_t *r) {
}
// Let handler send response
ESP_LOGD(TAG, "Calling handleRequest for OTA response");
ESP_LOGV(TAG, "Calling handleRequest for OTA response");
found_handler->handleRequest(&req);
ESP_LOGD(TAG, "handleRequest completed");
ESP_LOGV(TAG, "handleRequest completed");
return ESP_OK;
}
#endif // USE_WEBSERVER_OTA