Lock when executing LOGD

[liusida]

Problem Description

I found a bug here:

arduino-audio-tools/src/AudioTools/CoreAudio/AudioHttp/URLStream.h

Line 252 in e30c138

LOGD("available: %d", request.available());

It was so strange that the program just hang at this point, and I discovered that this is a deadlock issue.

    int avail = request.available();
    LOGD("available: %d", avail);    

this is safe.

I've made a minimal main.cpp that can reproduce the deadlock. I think it'll be good if we first get the value, and then only pass value to LOGD as arguments. (I thought functions would be executed first and the result then is passed to the LOGD, but it turns out that my compiler doesn't do that.)

Device Description

PLATFORM: Espressif 32 (55.3.30) > Espressif ESP32-S3-Box-3
HARDWARE: ESP32S3 240MHz, 320KB RAM, 16MB Flash
DEBUG: Current (cmsis-dap) External (cmsis-dap, esp-bridge, esp-builtin, esp-prog, iot-bus-jtag, jlink, minimodule, olimex-arm-usb-ocd, olimex-arm-usb-ocd-h, olimex-arm-usb-tiny-h, olimex-jtag-tiny, tumpa)
PACKAGES:

• contrib-piohome @ 3.4.4
• framework-arduinoespressif32 @ 3.3.0
• framework-arduinoespressif32-libs @ 5.5.0+sha.b66b5448e0
• tool-esptoolpy @ 5.0.2
• tool-mklittlefs @ 3.2.0
• toolchain-xtensa-esp-elf @ 14.2.0+20241119
  LDF: Library Dependency Finder -> https://bit.ly/configure-pio-ldf
  LDF Modes: Finder ~ chain, Compatibility ~ soft
  Found 50 compatible libraries
  Scanning dependencies...
  Dependency Graph
  |-- TFT_eSPI @ 2.5.43
  |-- lvgl @ 9.1.0
  |-- GT911 @ 0.2.1+sha.85875b2
  |-- NimBLE-Arduino @ 2.3.6+sha.dfb4ac5
  |-- audio-driver @ 0.1.4+sha.7026dc2
  |-- audio-tools @ 1.1.3+sha.e2d02aa
  |-- libhelix @ 0.8.9+sha.17c28c8
  |-- ArduinoJson @ 7.4.2
  |-- HTTPClient @ 3.3.0
  |-- WiFi @ 3.3.0
  |-- NetworkClientSecure @ 3.3.0
  |-- Preferences @ 3.3.0
  |-- Wire @ 3.3.0
  Building in release mode

Sketch

#include <Arduino.h>
#include "AudioTools/CoreAudio/AudioLogger.h"

// Toggle this to true to reproduce the deadlock (will hang on purpose)
static const bool ENABLE_DEADLOCK_TEST = true;

static int innerLog() {
  LOGD("innerLog()\n");
  return 42;
}

// Deadlocks: outer LOGD locks, then evaluates varargs -> innerLog() -> LOGD again
static void reproduce_deadlock() {
  LOGD("outer with inner: %d\n", innerLog());
}

// Safe: evaluate first, then LOGD (no nested logging while lock is held)
static void reproduce_safe() {
  int v = innerLog();
  LOGD("outer safe: %d\n", v);
}

void setup() {
  Serial.begin(115200);
  while (!Serial) { delay(10); }

  audio_tools::AudioLogger::instance().begin(Serial, audio_tools::AudioLogger::Debug);

  // Demonstrate safe sequence (works)
  reproduce_safe();

  // Uncomment or set ENABLE_DEADLOCK_TEST to true to reproduce the lockup
  if (ENABLE_DEADLOCK_TEST) {
    reproduce_deadlock();
  }
}

void loop() {
  // no-op
}

Other Steps to Reproduce

No response

What is your development environment (incl. core version info)

No response

I have checked existing issues, discussions and online documentation (incl. the Wiki)

• I confirm I have checked existing issues, discussions and online documentation

[liusida]

reproduced output:

[D] main.cpp : 8 - innerLog()

[D] main.cpp : 20 - outer safe: 42

[D] main.cpp : 14 -