From 6b19d24eb4bc65a052202078c776137c39f9ee9a Mon Sep 17 00:00:00 2001 From: cjkas Date: Sun, 11 Oct 2026 20:50:41 +0200 Subject: [PATCH] fix: print each log line whole The Arduino core's log_printf() has its UART lock commented out and writes with ets_printf(), so lines logged at the same time from async_tcp and loop() came out interleaved character by character. It also formats short lines into one static buffer shared by every task. Wrap log_printf at link time and hold a mutex around the core's log_printfv(). It never blocks before the scheduler runs, in an ISR or in a critical section, and waits at most 50ms before printing anyway. Co-Authored-By: Claude Opus 5.5 --- platformio.ini | 2 ++ src/LogLock.cpp | 36 ++++++++++++++++++++++++++++++++++++ 2 files changed, 38 insertions(+) create mode 100644 src/LogLock.cpp diff --git a/platformio.ini b/platformio.ini index 1890425..428ba61 100644 --- a/platformio.ini +++ b/platformio.ini @@ -37,6 +37,8 @@ build_flags = -DCONFIG_ESP_COREDUMP_CHECKSUM_CRC32=1 -DCONFIG_ESP_TASK_WDT_PANIC=1 -DCONFIG_ESP_COREDUMP_DECODE_INFO=1 + ; Route log_printf through src/LogLock.cpp so lines from both cores don't interleave. + -Wl,--wrap=log_printf monitor_speed = 115200 monitor_filters = time diff --git a/src/LogLock.cpp b/src/LogLock.cpp new file mode 100644 index 0000000..2c06388 --- /dev/null +++ b/src/LogLock.cpp @@ -0,0 +1,36 @@ +// Prints each log line whole. +// +// The Arduino core's log_printf() writes with ets_printf() and has its UART +// lock commented out, so lines logged at the same time from async_tcp (core 0) +// and loop() (core 1) come out interleaved character by character. It also +// formats short lines into one static buffer shared by every task. +// +// platformio.ini links with -Wl,--wrap=log_printf so every ESP_LOGx/log_x call +// lands here and takes this lock around the core's log_printfv(). +#include +#include +#include "freertos/FreeRTOS.h" +#include "freertos/semphr.h" +#include "freertos/task.h" + +// Defined in the core's esp32-hal-uart.c but not declared in a header. +extern "C" int log_printfv(const char *format, va_list arg); + +// Created during static initialisation, before anything can race for it. A +// constructor that logs before this runs simply goes unlocked. +static SemaphoreHandle_t logMutex = xSemaphoreCreateRecursiveMutex(); +// Never wait longer than this for the lock; the line is printed anyway, so a +// task stuck mid-log can only garble output, not hang another task. +#define LOG_LOCK_WAIT_MS 50 + +extern "C" int __wrap_log_printf(const char *format, ...) { + // No blocking before the scheduler runs, in an ISR or in a critical section. + const bool canLock = logMutex && xTaskGetSchedulerState() == taskSCHEDULER_RUNNING && xPortCanYield(); + const bool locked = canLock && xSemaphoreTakeRecursive(logMutex, pdMS_TO_TICKS(LOG_LOCK_WAIT_MS)) == pdTRUE; + va_list arg; + va_start(arg, format); + int len = log_printfv(format, arg); + va_end(arg); + if(locked) xSemaphoreGiveRecursive(logMutex); + return len; +}