fix: stop the log lock lifting loop() above the radio task

The log lock was a mutex, so when async_tcp waited on it loop() inherited
async_tcp's priority and could preempt the radio task mid-frame.  Use a
binary semaphore, which has no priority inheritance, track the holder so
a nested log doesn't wait on itself, and cap the wait at 20ms.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
cjkas 2026-10-12 17:57:33 +02:00
parent a8bb377957
commit 6cec411fa8

View file

@ -9,6 +9,10 @@
// ESP_LOGx/log_x call to the ESP Insights hook in libesp_diagnostics, and that
// hook prints through log_printfv(). platformio.ini adds
// -Wl,--wrap=log_printfv so that call lands here and takes this lock.
//
// The lock is a binary semaphore, not a mutex. A mutex passes its waiter's
// priority to the holder, so async_tcp waiting on loop() would lift loop()
// above the radio task and let it break into a frame on the air.
#include <Arduino.h>
#include <stdarg.h>
#include "freertos/FreeRTOS.h"
@ -17,18 +21,31 @@
extern "C" int __real_log_printfv(const char *format, va_list arg);
static SemaphoreHandle_t createLogLock() {
SemaphoreHandle_t sem = xSemaphoreCreateBinary();
if(sem) xSemaphoreGive(sem);
return sem;
}
// 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();
static SemaphoreHandle_t logLock = createLogLock();
// The task holding the lock, so a log from inside a log doesn't wait on itself.
static volatile TaskHandle_t logOwner = nullptr;
// 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
// task stuck mid-log can only garble output, not hang another task. A long
// line takes about 20ms at 115200 baud.
#define LOG_LOCK_WAIT_MS 20
extern "C" int __wrap_log_printfv(const char *format, va_list arg) {
// 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;
const bool canLock = logLock && xTaskGetSchedulerState() == taskSCHEDULER_RUNNING && xPortCanYield() &&
logOwner != xTaskGetCurrentTaskHandle();
const bool locked = canLock && xSemaphoreTake(logLock, pdMS_TO_TICKS(LOG_LOCK_WAIT_MS)) == pdTRUE;
if(locked) logOwner = xTaskGetCurrentTaskHandle();
int len = __real_log_printfv(format, arg);
if(locked) xSemaphoreGiveRecursive(logMutex);
if(locked) {
logOwner = nullptr;
xSemaphoreGive(logLock);
}
return len;
}