feature: Transfer debug tracing

This adds togglable debug tracing for data transfers, however the toggle is universal and can be adapted to toggle more tracing in the future.

Several issues with the implementation of transfer debug tracing were addressed, namely:
1. Data was printed regardless of the send/receive operation success, which could mislead users
2. Tracing was not togglable from the users side, as it was toggled by defines in the library source code
3. serial_debug_print() was not present in all ports, used manual hex formatting and refered to transfered data as serial data

.github/ISSUE_TEMPLATE/bug_report.yml

@@ -36,7 +36,7 @@ body:
   - type: textarea
     attributes:
       label: Log output
-      description: Provide the full output log.
+      description: Enable tracing with SERIAL_FLASHER_DEBUG_TRACE and provide the full log.
       render: plain
     validations:
       required: true

CMakeLists.txt

@@ -93,6 +93,10 @@ elseif (DEFINED SERIAL_FLASHER_INTERFACE_SPI OR CONFIG_SERIAL_FLASHER_INTERFACE_
     )
 endif()
 
+if(DEFINED SERIAL_FLASHER_DEBUG_TRACE OR CONFIG_SERIAL_FLASHER_DEBUG_TRACE)
+    target_compile_definitions(${target} PUBLIC SERIAL_FLASHER_DEBUG_TRACE)
+endif()
+
 if(DEFINED CONFIG_SERIAL_FLASHER_RESET_HOLD_TIME_MS AND DEFINED CONFIG_SERIAL_FLASHER_BOOT_HOLD_TIME_MS)
     target_compile_definitions(${target}
     PUBLIC

Kconfig

@@ -27,4 +27,8 @@ menu "ESP serial flasher"
         int "Time for which the boot pin is asserted when doing a hard reset"
         default 50
 
+    config SERIAL_FLASHER_DEBUG_TRACE
+        bool "Enable debug tracing output (only transfer data tracing is supported at the time)"
+        default n
+
 endmenu

idf_component.yml

@@ -1,3 +1,3 @@
-version: "0.1.0"
+version: "0.2.0"
 description: Serial flasher component provides portable library for flashing or loading ram loadble app to Espressif SoCs from other host microcontroller
 url: https://github.com/espressif/esp-serial-flasher

port/esp32_port.c

@@ -21,42 +21,20 @@
 #include "esp_idf_version.h"
 #include <unistd.h>
 
-// #define SERIAL_DEBUG_ENABLE
-
-#ifdef SERIAL_DEBUG_ENABLE
-
-static void dec_to_hex_str(const uint8_t dec, uint8_t hex_str[3])
-{
-    static const uint8_t dec_to_hex[] = {
-        '0', '1', '2', '3', '4', '5', '6', '7',
-        '8', '9', 'a', 'b', 'c', 'd', 'e', 'f'
-    };
-
-    hex_str[0] = dec_to_hex[dec >> 4];
-    hex_str[1] = dec_to_hex[dec & 0xF];
-    hex_str[2] = '\0';
-}
-
-static void serial_debug_print(const uint8_t *data, uint16_t size, bool write)
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+static void transfer_debug_print(const uint8_t *data, uint16_t size, bool write)
 {
     static bool write_prev = false;
-    uint8_t hex_str[3];
 
-    if(write_prev != write) {
+    if (write_prev != write) {
         write_prev = write;
         printf("\n--- %s ---\n", write ? "WRITE" : "READ");
     }
 
-    for(uint32_t i = 0; i < size; i++) {
-        dec_to_hex_str(data[i], hex_str);
-        printf("%s ", hex_str);
+    for (uint32_t i = 0; i < size; i++) {
+        printf("%02x ", data[i]);
     }
 }
-
-#else
-
-static void serial_debug_print(const uint8_t *data, uint16_t size, bool write) { }
-
 #endif
 
 static int64_t s_time_end;
@@ -117,12 +95,13 @@ void loader_port_esp32_deinit(void)
 
 esp_loader_error_t loader_port_write(const uint8_t *data, uint16_t size, uint32_t timeout)
 {
-    serial_debug_print(data, size, true);
-
     uart_write_bytes(s_uart_port, (const char *)data, size);
     esp_err_t err = uart_wait_tx_done(s_uart_port, pdMS_TO_TICKS(timeout));
 
     if (err == ESP_OK) {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, size, true);
+#endif
         return ESP_LOADER_SUCCESS;
     } else if (err == ESP_ERR_TIMEOUT) {
         return ESP_LOADER_ERROR_TIMEOUT;
@@ -136,13 +115,17 @@ esp_loader_error_t loader_port_read(uint8_t *data, uint16_t size, uint32_t timeo
 {
     int read = uart_read_bytes(s_uart_port, data, size, pdMS_TO_TICKS(timeout));
 
-    serial_debug_print(data, read, false);
-
     if (read < 0) {
         return ESP_LOADER_ERROR_FAIL;
     } else if (read < size) {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, read, false);
+#endif
         return ESP_LOADER_ERROR_TIMEOUT;
     } else {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, read, false);
+#endif
         return ESP_LOADER_SUCCESS;
     }
 }

port/raspberry_port.c

@@ -33,14 +33,10 @@
 #include <sys/stat.h>
 #include <sys/param.h>
 
-// #define SERIAL_DEBUG_ENABLE
-
-#ifdef SERIAL_DEBUG_ENABLE
-
-static void serial_debug_print(const uint8_t *data, uint16_t size, bool write)
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+static void transfer_debug_print(const uint8_t *data, uint16_t size, bool write)
 {
     static bool write_prev = false;
-    uint8_t hex_str[3];
 
     if (write_prev != write) {
         write_prev = write;
@@ -51,11 +47,6 @@ static void serial_debug_print(const uint8_t *data, uint16_t size, bool write)
         printf("%02x ", data[i]);
     }
 }
-
-#else
-
-static void serial_debug_print(const uint8_t *data, uint16_t size, bool write) { }
-
 #endif
 
 static int serial;
@@ -233,15 +224,19 @@ esp_loader_error_t loader_port_raspberry_init(const loader_raspberry_config_t *c
 
 esp_loader_error_t loader_port_write(const uint8_t *data, uint16_t size, uint32_t timeout)
 {
-    serial_debug_print(data, size, true);
-
     int written = write(serial, data, size);
 
     if (written < 0) {
         return ESP_LOADER_ERROR_FAIL;
     } else if (written < size) {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, written, true);
+#endif
         return ESP_LOADER_ERROR_TIMEOUT;
     } else {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, written, true);
+#endif
         return ESP_LOADER_SUCCESS;
     }
 }
@@ -251,7 +246,9 @@ esp_loader_error_t loader_port_read(uint8_t *data, uint16_t size, uint32_t timeo
 {
     RETURN_ON_ERROR( read_data(data, size) );
 
-    serial_debug_print(data, size, false);
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+    transfer_debug_print(data, size, false);
+#endif
 
     return ESP_LOADER_SUCCESS;
 }

port/stm32_port.c

@@ -20,57 +20,36 @@
 #include <stdio.h>
 #include "stm32_port.h"
 
-// #define SERIAL_DEBUG_ENABLE
-
 static UART_HandleTypeDef *uart;
 static GPIO_TypeDef* gpio_port_io0, *gpio_port_rst;
 static uint16_t gpio_num_io0, gpio_num_rst;
 
-#ifdef SERIAL_DEBUG_ENABLE
-
-static void dec_to_hex_str(const uint8_t dec, uint8_t hex_str[3])
-{
-    static const uint8_t dec_to_hex[] = {
-        '0', '1', '2', '3', '4', '5', '6', '7',
-        '8', '9', 'a', 'b', 'c', 'd', 'e', 'f'
-    };
-
-    hex_str[0] = dec_to_hex[(dec >> 4)];
-    hex_str[1] = dec_to_hex[(dec & 0xF)];
-    hex_str[2] = '\0';
-}
-
-static void serial_debug_print(const uint8_t *data, uint16_t size, bool write)
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+static void transfer_debug_print(const uint8_t *data, uint16_t size, bool write)
 {
     static bool write_prev = false;
-    uint8_t hex_str[3];
 
-    if(write_prev != write) {
+    if (write_prev != write) {
         write_prev = write;
         printf("\n--- %s ---\n", write ? "WRITE" : "READ");
     }
 
-    for(uint32_t i = 0; i < size; i++) {
-        dec_to_hex_str(data[i], hex_str);
-        printf("%s ", hex_str);
+    for (uint32_t i = 0; i < size; i++) {
+        printf("%02x ", data[i]);
     }
 }
-
-#else
-
-static void serial_debug_print(const uint8_t *data, uint16_t size, bool write) { }
-
 #endif
 
 static uint32_t s_time_end;
 
 esp_loader_error_t loader_port_write(const uint8_t *data, uint16_t size, uint32_t timeout)
 {
-    serial_debug_print(data, size, true);
-
     HAL_StatusTypeDef err = HAL_UART_Transmit(uart, (uint8_t *)data, size, timeout);
 
     if (err == HAL_OK) {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, size, true);
+#endif
         return ESP_LOADER_SUCCESS;
     } else if (err == HAL_TIMEOUT) {
         return ESP_LOADER_ERROR_TIMEOUT;
@@ -84,9 +63,10 @@ esp_loader_error_t loader_port_read(uint8_t *data, uint16_t size, uint32_t timeo
 {
     HAL_StatusTypeDef err = HAL_UART_Receive(uart, data, size, timeout);
 
-    serial_debug_print(data, size, false);
-
     if (err == HAL_OK) {
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, size, false);
+#endif
         return ESP_LOADER_SUCCESS;
     } else if (err == HAL_TIMEOUT) {
         return ESP_LOADER_ERROR_TIMEOUT;

port/zephyr_port.c

@@ -26,6 +26,22 @@ static struct tty_serial tty;
 static char tty_rx_buf[CONFIG_ESP_SERIAL_FLASHER_UART_BUFSIZE];
 static char tty_tx_buf[CONFIG_ESP_SERIAL_FLASHER_UART_BUFSIZE];
 
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+static void transfer_debug_print(const uint8_t *data, uint16_t size, bool write)
+{
+    static bool write_prev = false;
+
+    if (write_prev != write) {
+        write_prev = write;
+        printk("\n--- %s ---\n", write ? "WRITE" : "READ");
+    }
+
+    for (uint32_t i = 0; i < size; i++) {
+        printk("%02x ", data[i]);
+    }
+}
+#endif
+
 esp_loader_error_t configure_tty()
 {
     if (tty_init(&tty, uart_dev) < 0 ||
@@ -54,6 +70,9 @@ esp_loader_error_t loader_port_read(uint8_t *data, const uint16_t size, const ui
         if (read < 0) {
             return ESP_LOADER_ERROR_TIMEOUT;
         }
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, read, false);
+#endif
         total_read += read;
         remaining -= read;
     }
@@ -78,6 +97,9 @@ esp_loader_error_t loader_port_write(const uint8_t *data, const uint16_t size, c
         if (written < 0) {
             return ESP_LOADER_ERROR_TIMEOUT;
         }
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, written, true);
+#endif
         total_written += written;
         remaining -= written;
     }

test/CMakeLists.txt

@@ -22,4 +22,8 @@ else()
     target_sources(${PROJECT_NAME} PRIVATE serial_io_mock.cpp test.cpp)
 endif()
 
-target_compile_definitions(${PROJECT_NAME} PRIVATE MD5_ENABLED=1 SERIAL_FLASHER_INTERFACE_UART)
+target_compile_definitions(${PROJECT_NAME} PRIVATE
+	MD5_ENABLED=1
+	SERIAL_FLASHER_INTERFACE_UART
+	SERIAL_FLASHER_DEBUG_TRACE
+)

test/qemu_test.cpp

@@ -64,7 +64,8 @@ void flash_application(ifstream& image)
 
         ESP_ERR_CHECK( esp_loader_flash_write(payload, to_read) );
 
-        cout << "packet: " << count++ <<  " written: " << to_read << endl;
+        cout << endl << "--- FLASH DATA PACKET: " << count++
+             <<  " DATA WRITTEN: " << to_read << " ---" << endl;
 
         image_size -= to_read;
     };

test/serial_io_tcp.cpp

@@ -33,6 +33,22 @@ const uint32_t PORT = 5555;
 static int sock = 0;
 ofstream file;
 
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+static void transfer_debug_print(const uint8_t *data, uint16_t size, bool write)
+{
+    static bool write_prev = false;
+
+    if (write_prev != write) {
+        write_prev = write;
+        cout << endl << "--- " << (write ? "WRITE" : "READ") << " ---" << endl;
+    }
+
+    for (uint32_t i = 0; i < size; i++) {
+        cout << hex << static_cast<unsigned int>(data[i]) << dec << ' ';
+    }
+}
+#endif
+
 esp_loader_error_t loader_port_mock_init(const loader_serial_config_t *config)
 {
     struct sockaddr_in serv_addr;
@@ -89,6 +105,9 @@ esp_loader_error_t loader_port_write(const uint8_t *data, uint16_t size, uint32_
             cout << "Socket send failed\n";
             return ESP_LOADER_ERROR_FAIL;
         }
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, bytes_written, true);
+#endif
         written += bytes_written;
     } while (written != size);
     return ESP_LOADER_SUCCESS;
@@ -106,6 +125,10 @@ esp_loader_error_t loader_port_read(uint8_t *data, uint16_t size, uint32_t timeo
             return ESP_LOADER_ERROR_FAIL;
         }
 
+#ifdef SERIAL_FLASHER_DEBUG_TRACE
+        transfer_debug_print(data, bytes_read, false);
+#endif
+
         file.write((const char*)&data[written], bytes_read);
         file.flush();