fix(esp_trace): send trace data over usb-serial-jtag reliably

examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/include/trace_FreeRTOS.h

@@ -36,6 +36,9 @@ void init_trace_lib(esp_trace_encoder_t *enc);
 void trace_lib_start(void);
 void trace_lib_stop(void);
 
+/* @brief Get the number of trace lines written to and dropped by the transport */
+void trace_lib_get_stats(uint32_t *written, uint32_t *dropped);
+
 /* Hook implementations — defined in trace_FreeRTOS.c.
  * Kept void*-typed to avoid depending on FreeRTOS types in this header. */
 void trace_lib_task_switched_in(void);

examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/adapter_encoder_ext_trace_lib.c

@@ -85,14 +85,6 @@ static esp_err_t stop(esp_trace_encoder_t *enc)
     return ESP_OK;
 }
 
-static esp_err_t flush(esp_trace_encoder_t *enc)
-{
-    if (!enc || !enc->tp || !enc->tp->vt->flush_nolock) {
-        return ESP_ERR_NOT_SUPPORTED;
-    }
-    return enc->tp->vt->flush_nolock(enc->tp);
-}
-
 /**
  * @brief Panic handler
  *
@@ -104,7 +96,11 @@ static esp_err_t flush(esp_trace_encoder_t *enc)
 static void panic_handler(esp_trace_encoder_t *enc, const void *info)
 {
     (void)info;
-    flush(enc);
+
+    /* No lock here, the panicking core may already hold it */
+    if (enc && enc->tp && enc->tp->vt->flush_nolock) {
+        enc->tp->vt->flush_nolock(enc->tp);
+    }
 }
 
 static unsigned int take_lock(esp_trace_encoder_t *enc, uint32_t tmo_us)
@@ -127,6 +123,34 @@ static void give_lock(esp_trace_encoder_t *enc, unsigned int int_state)
     esp_trace_lock_give(&ctx->lock);
 }
 
+/* Total time for the flush, split over several flush_nolock() calls */
+#define EXT_TRACE_LIB_FLUSH_TMO_US  (1000000)
+
+static esp_err_t flush(esp_trace_encoder_t *enc)
+{
+    if (!enc || !enc->tp || !enc->tp->vt->flush_nolock) {
+        return ESP_ERR_NOT_SUPPORTED;
+    }
+
+    /* One call may be too short to send all the data, so repeat it and release
+     * the lock in between to keep interrupts enabled */
+    esp_trace_tmo_t tmo;
+    esp_trace_tmo_init(&tmo, EXT_TRACE_LIB_FLUSH_TMO_US);
+
+    esp_err_t err;
+    do {
+        unsigned int int_state = take_lock(enc, ESP_TRACE_TMO_INFINITE);
+        err = enc->tp->vt->flush_nolock(enc->tp);
+        give_lock(enc, int_state);
+
+        if (err != ESP_ERR_TIMEOUT) {
+            break;  /* done, or an error that repeating cannot fix */
+        }
+    } while (esp_trace_tmo_check(&tmo) == ESP_OK);
+
+    return err;
+}
+
 static const esp_trace_encoder_vtable_t s_ext_trace_lib_vt = {
     .init                  = init,
     .write                 = write,

examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/trace_FreeRTOS.c

@@ -35,6 +35,8 @@ static esp_trace_encoder_t *s_enc = NULL;
 static uint32_t s_ts_freq_hz = 1000000;   /* default assume 1 MHz */
 static uint32_t s_last_ts = 0;
 static volatile bool s_enabled = false;
+static uint32_t s_written = 0;
+static uint32_t s_dropped = 0;
 
 void init_trace_lib(esp_trace_encoder_t *enc)
 {
@@ -87,12 +89,26 @@ static void encode(const char *type, const char *detail)
         if (n >= (int)sizeof(line)) {
             n = (int)sizeof(line) - 1;
         }
-        esp_trace_write(s_esp_trace_handle, line, (size_t)n, 0);
+        if (esp_trace_write(s_esp_trace_handle, line, (size_t)n, 0) == ESP_OK) {
+            s_written++;
+        } else {
+            s_dropped++;  /* transport buffer was full, line dropped */
+        }
     }
 
     s_enc->vt->give_lock(s_enc, int_state);
 }
 
+void trace_lib_get_stats(uint32_t *written, uint32_t *dropped)
+{
+    if (written) {
+        *written = s_written;
+    }
+    if (dropped) {
+        *dropped = s_dropped;
+    }
+}
+
 void trace_lib_task_switched_in(void)
 {
     TaskHandle_t h = xTaskGetCurrentTaskHandle();

examples/system/tracing/esp_trace_custom_library/main/app_main.c

@@ -5,6 +5,7 @@
  */
 #include "sdkconfig.h"
 
+#include <inttypes.h>
 #include <stdio.h>
 #include <string.h>
 
@@ -13,6 +14,7 @@
 #include "freertos/queue.h"
 #include "esp_log.h"
 #include "esp_trace.h"
+#include "trace_FreeRTOS.h"
 
 static const char *TAG = "main";
 
@@ -70,7 +72,16 @@ void app_main(void)
     vTaskDelay(1000 / portTICK_PERIOD_MS);
 
     esp_trace_stop();
-    esp_trace_flush();
+    esp_err_t err = esp_trace_flush();
+
+    /* Logged from task context, so it goes to the console UART and not to the
+     * trace port. Shows whether the device sent the trace data or not. */
+    uint32_t written = 0;
+    uint32_t dropped = 0;
+    trace_lib_get_stats(&written, &dropped);
+    ESP_LOGI(TAG, "Trace flush: %s, host connected: %d, lines written: %" PRIu32 ", dropped: %" PRIu32,
+             esp_err_to_name(err), (int)esp_trace_is_host_connected(esp_trace_get_active_handle()),
+             written, dropped);
 
     ESP_LOGI(TAG, "End of trace session");
 }

examples/system/tracing/esp_trace_custom_library/pytest_esp_trace_custom_library.py

@@ -76,7 +76,6 @@ def _validate_trace_data(trace_log_path: str) -> None:
 
 def _capture_trace(ser: serial.Serial, trace_log_path: str, capture_s: float = 5.0) -> None:
     """Capture trace output from the USB-Serial-JTAG endpoint."""
-    ser.reset_input_buffer()
     with open(trace_log_path, 'w+b') as f:
         end_time = time.time() + capture_s
         while time.time() < end_time:
@@ -106,10 +105,13 @@ def _capture_trace(ser: serial.Serial, trace_log_path: str, capture_s: float = 5
 def test_esp_trace_ext_lib_usj(dut: IdfDut) -> None:
     dut.expect('Start of trace session', timeout=5)
 
-    time.sleep(1)  # wait for USJ port to be ready
+    # Open the port before the DUT starts tracing
     usj_port = '/dev/serial_ports/ttyACM-esp32'
-    ser = serial.Serial(usj_port, baudrate=1000000, timeout=10)
     trace_log_path = os.path.join(dut.logdir, 'ext_trace.log')
+    time.sleep(1)  # Wait for the USJ port to be ready
+    with serial.Serial(usj_port, baudrate=1000000, timeout=10) as ser:
+        # Discard data from before this test, the DUT is not tracing yet
+        ser.reset_input_buffer()
+        _capture_trace(ser, trace_log_path)
 
-    _capture_trace(ser, trace_log_path)
     _validate_trace_data(trace_log_path)

examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py

@@ -242,7 +242,7 @@ def test_sysview_tracing_uart_c2(dut: IdfDut) -> None:
 def test_sysview_tracing_usj_serial(dut: IdfDut) -> None:
     time.sleep(1)  # wait for USJ port to be ready
     usj_port = '/dev/serial_ports/ttyACM-esp32'
-    ser = serial.Serial(usj_port, baudrate=1000000, timeout=10)
     trace_log = os.path.join(dut.logdir, 'sys_log_usj.svdat')  # pylint: disable=protected-access
-    _capture_sysview_trace(ser, trace_log)
-    _validate_trace_data(trace_log, dut.target, is_uart=True)
+    with serial.Serial(usj_port, baudrate=1000000, timeout=10) as ser:
+        _capture_sysview_trace(ser, trace_log)
+        _validate_trace_data(trace_log, dut.target, is_uart=True)