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 <noreply@anthropic.com>
This commit is contained in:
cjkas 2026-10-11 20:50:41 +02:00
parent dd47c04905
commit 6b19d24eb4
2 changed files with 38 additions and 0 deletions

View file

@ -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

36
src/LogLock.cpp Normal file
View file

@ -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 <Arduino.h>
#include <stdarg.h>
#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;
}