set_volume does not change the volume until the music is paused (on iPhone iOS >= 15.7.9)

[mrhempman69]

Problem Description

Volume changes are received by the device, but the actual volume doesn't change until the music is paused then played. It doesn't update the volume during streaming.

Based on serial logs, the set_volume inside A2DPVolumeControl doesn't fire when music is playing. Only when you pause the song, will "set_volume" function be fired.

Device Description

ESP32 Wroom https://www.amazon.com/gp/product/B0C7C2HQ7P/ref=ppx_yo_dt_b_search_asin_title?ie=UTF8&psc=1

Sketch

#include "BluetoothA2DPSink.h"
#include "./data/mrhemVolumeControl.h"
BluetoothA2DPSink a2dp_sink;
A2DPMrhemVolumeControl mrhemVolumeControl;
void setup() {   
 
  Serial.begin(9600);
  int mclkPin=3;
  i2s_pin_config_t external_pin_config = {
        .mck_io_num = mclkPin,
        .bck_io_num =33,
        .ws_io_num = 32,
        .data_out_num = 22,
        .data_in_num = I2S_PIN_NO_CHANGE,
    };
  static const i2s_config_t externalDAC_config = {
        .mode = (i2s_mode_t) (I2S_MODE_MASTER | I2S_MODE_TX),
        .sample_rate =  44100, // corrected by info from bluetooth
        .bits_per_sample = (i2s_bits_per_sample_t) 16, 
        .channel_format = I2S_CHANNEL_FMT_RIGHT_LEFT,
        .communication_format = (i2s_comm_format_t)I2S_COMM_FORMAT_STAND_MSB,
        .intr_alloc_flags = 0, // default interrupt priority
        .dma_buf_count = 8,
        .dma_buf_len = 64,
        .use_apll = true,
        .tx_desc_auto_clear = true, // avoiding noise in case of data unavailability
        .mclk_multiple=(i2s_mclk_multiple_t) 256,

  };

  a2dp_sink.set_volume_control(&mrhemVolumeControl); 

  a2dp_sink.set_avrc_metadata_callback(avrc_metadata_callback);
  bool externalDAC=true;

    a2dp_sink.set_pin_config(external_pin_config);
    a2dp_sink.set_i2s_config(externalDAC_config);
    a2dp_sink.i2s_mclk_pin_select(mclkPin);

  a2dp_sink.start("mrhemMusicBasic");
}

./data/mrhemVolumeControl.h:

#include "BluetoothA2DPSink.h"
#include "SoundData.h"
#include "esp_log.h"

class A2DPMrhemVolumeControl : public A2DPVolumeControl {

        public: A2DPMrhemVolumeControl() {
            volumeFactorMax = 4096;
        }

        virtual void set_volume(uint8_t volume) override {
            constexpr double base = 1.4;
            constexpr double bits = 12;
            constexpr double zero_ofs = pow(base, -bits);
            constexpr double scale = pow(2.0, bits);
            double volumeFactorFloat = (pow(base, volume * bits / 127.0 - bits) - zero_ofs) * scale / (1.0 - zero_ofs);
            volumeFactor = volumeFactorFloat;
            if (volumeFactor > 0x1000) {
                volumeFactor = 0x1000;
            }
            Serial.print("mrhem default Volume is now"); 
            Serial.println(volumeFactor);
        }
};

Other Steps to Reproduce

I monitored the serial output in the Arduino IDE's Serial Monitor. I press the volume change buttons on the iphone, but "mrhem default Volume is now" does not output. It only outputs much later with the newest value when I pause the stream.

Provide your Version of the EP32 Arduino Core (or the IDF Version)

esp32 by Espressif: 2.0.11

I have checked existing issues, discussions and online documentation

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

[pschatzmann]

In the light that this is working perfectly with the provided default implementation, I tend to assume that you messed something up!

What are you doing in the loop ?
What is your reason to provide your own implementation ?
Did you activate the logging to verify what you receive from the IPhone? Maybe your phone (application) is not sending any ESP_AVRC_TG_SET_ABSOLUTE_VOLUME_CMD_EVT properly...

[mrhempman69]

The loop is nothing:

int8_t IntStat = 0;
int8_t IntConnected = 0;
int16_t runningMean=0;
int16_t absRunningMean=0;
void loop() {

   if (a2dp_sink.is_connected() != IntConnected) {
    IntConnected = a2dp_sink.is_connected();
    if (IntConnected == 0) {
      Serial.println("Not Connected");
    }
    if (IntConnected == 1) {
      Serial.println("Connected");
    }
  }
  if (a2dp_sink.get_audio_state() != IntStat) {
    IntStat = a2dp_sink.get_audio_state();
    if (IntStat == 0) {
      Serial.println("Stop");
    }
    if (IntStat == 2) {
      Serial.println("Play");
    }
  }

}
// btw, I have commented out the following function & the line in the "setup" function that references it, and problem still persists too:
void avrc_metadata_callback(uint8_t data1, const uint8_t *data2) {
  Serial.printf("AVRC metadata rsp: attribute id 0x%x, %s\n", data1, data2);
}

The reason for providing my own implementation, was only to determine why the volume wasn't working 😆. I have trimmed down to basically just the default implementation.

When I activate the verbose logging, there is a huge delay in the volume being changed. Also, the music is skipping because the controller seems like it is logging too much to also be able to stream correctly. However, the volume does change without me pressing pause, it just is like a 10 second delay.

With "Info" logging i'd say there's a mix of the last two problems....

[pschatzmann]

Did you double check that you are not starving the A2DP task with your loop ?
Just add some delay calls in your loop.

Maybe you better use some callbacks instead of polling the states in your loop....

[mrhempman69]

I thought that was going to fix it but even using void loop() { } did not help...

Here is some of the log from when I press "play" and tap "volume up" about once per second. Unfortunately I can't paste the full log because I am choosing to work in the IDE instead of linux terminal, and IDEs in general are trash (https://forum.arduino.cc/t/copy-paste-data-from-the-serial-monitor/1041585/36)

16:18:12.065 -> [455564][D][BluetoothA2DPSink.cpp:1435] ccall_av_hdl_avrc_tg_evt(): [BT_AV] ccall_av_hdl_avrc_tg_evt
16:18:12.162 -> [455670][D][BluetoothA2DPSink.cpp:570] app_rc_ct_callback(): [BT_AV] app_rc_ct_callback
16:18:12.258 -> [455776][D][BluetoothA2DPSink.cpp:1443] av_hdl_avrc_tg_evt(): [BT_AV] av_hdl_avrc_tg_evt evt 3
16:18:12.354 -> [455869][D][BluetoothA2DPSink.cpp:587] app_rc_ct_callback(): [BT_AV] app_rc_ct_callback ESP_AVRC_CT_CHANGE_NOTIFY_EVT
16:18:12.483 -> [455969][I][BluetoothA2DPSink.cpp:1459] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote set absolute volume: 87%
16:18:12.611 -> [456093][D][BluetoothA2DPSink.cpp:358] app_work_dispatch(): [BT_API] app_work_dispatch event 0x4, param len 12
16:18:12.707 -> [456205][I][BluetoothA2DPSink.cpp:1399] volume_set_by_controller(): [BT_AV] Volume is set by remote controller to 87
16:18:12.835 -> [456322][D][BluetoothA2DPSink.cpp:390] app_send_msg(): [BT_AV] app_send_msg
16:18:12.931 -> mrhem default Volume is now2433
16:18:12.963 -> [456528][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:13.059 -> [456648][D][BluetoothA2DPSink.cpp:413] app_task_handler(): [BT_API] app_task_handler, sig 0x1, 0x3
16:18:13.155 -> [456656][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:13.250 -> [456760][I][BluetoothA2DPSink.cpp:416] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:18:13.379 -> [456870][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:13.476 -> [456976][D][BluetoothA2DPSink.cpp:381] app_work_dispatched(): [BT_AV] app_work_dispatched
16:18:13.572 -> [457072][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:13.668 -> [457167][D][BluetoothA2DPSink.cpp:1435] ccall_av_hdl_avrc_tg_evt(): [BT_AV] ccall_av_hdl_avrc_tg_evt
16:18:13.765 -> [457278][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:13.861 -> [457369][D][BluetoothA2DPSink.cpp:1443] av_hdl_avrc_tg_evt(): [BT_AV] av_hdl_avrc_tg_evt evt 3
16:18:13.957 -> [457465][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:14.052 -> [457565][I][BluetoothA2DPSink.cpp:1459] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote set absolute volume: 93%
16:18:14.181 -> [457677][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:14.277 -> [457773][I][BluetoothA2DPSink.cpp:1399] volume_set_by_controller(): [BT_AV] Volume is set by remote controller to 93
16:18:14.405 -> [457869][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:14.500 -> mrhem default Volume is now3159
16:18:14.533 -> [458103][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:14.628 -> [458211][D][BluetoothA2DPSink.cpp:413] app_task_handler(): [BT_API] app_task_handler, sig 0x1, 0x3
16:18:14.724 -> [458218][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:14.820 -> [458322][I][BluetoothA2DPSink.cpp:416] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:18:14.948 -> [458433][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:15.044 -> [458539][D][BluetoothA2DPSink.cpp:381] app_work_dispatched(): [BT_AV] app_work_dispatched
16:18:15.140 -> [458635][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:15.237 -> [458729][D][BluetoothA2DPSink.cpp:1435] ccall_av_hdl_avrc_tg_evt(): [BT_AV] ccall_av_hdl_avrc_tg_evt
16:18:15.333 -> [458841][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:15.430 -> [458932][D][BluetoothA2DPSink.cpp:1443] av_hdl_avrc_tg_evt(): [BT_AV] av_hdl_avrc_tg_evt evt 3
16:18:15.525 -> [459027][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:15.621 -> [459127][I][BluetoothA2DPSink.cpp:1459] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote set absolute volume: 100%
16:18:15.749 -> [459238][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:15.845 -> [459337][I][BluetoothA2DPSink.cpp:1399] volume_set_by_controller(): [BT_AV] Volume is set by remote controller to 100
16:18:15.941 -> [459433][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:16.037 -> mrhem default Volume is now4096
16:18:16.102 -> [459668][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:16.165 -> [459775][D][BluetoothA2DPSink.cpp:413] app_task_handler(): [BT_API] app_task_handler, sig 0x1, 0x4
16:18:16.293 -> [459783][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:16.390 -> [459887][I][BluetoothA2DPSink.cpp:416] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:18:16.487 -> [459997][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:18:16.583 -> [460103][D][BluetoothA2DPSink.cpp:381] app_work_dispatched(): [BT_AV] app_work_dispatched
16:18:16.678 -> [460199][D][A2DPVolumeControl.h:43] update_audio_data(): [VolumeControl] update_audio_data
16:18:16.774 -> [460294][D][BluetoothA2DPSink.cpp:1316] ccall_av_hdl_avrc_evt(): [BT_AV] ccall_av_hdl_avrc_evt
16:18:16.903 -> [460405][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback

The volume change is about 10 seconds late

[pschatzmann]

Yes: an empty loop is equally bad!

[mrhempman69]

Right true, I got that from the homepage, but i also just tried void loop(){ delay(100); } and it also did not help...

I will try a different ESP32 board...

[pschatzmann]

Did you check the log it you get the events in time from the IPhone ?
With Android and my very old IPhone it's working w/o issues. Maybe you can also try BluetoothA2DPSinkQueued

[mrhempman69]

Well, I don't know how to check the timing of those events, but I just tried it, and it works on my android tablet, also the audio quality is much better..... My iphone is fairly old too (iphone 6S) but it's not surprising knowing Apple that it would make up a problem like this for non-Apple bluetooth.... I will try that class.

I tried setting the bluetooth to type "Headphone" in apple settings, and surprisingly, the device rebooted after a few seconds of streaming (may be due to "Queued" class though):

16:53:27.522 -> [ 27427][D][BluetoothA2DPSink.cpp:1435] ccall_av_hdl_avrc_tg_evt(): [BT_AV] ccall_av_hdl_avrc_tg_evt
16:53:27.618 -> [ 27521][D][BluetoothA2DPSink.cpp:358] app_work_dispatch(): [BT_API] app_work_dispatch event 0x1, param len 12
16:53:27.746 -> [ 27627][D][BluetoothA2DPSink.cpp:1443] av_hdl_avrc_tg_evt(): [BT_AV] av_hdl_avrc_tg_evt evt 1
16:53:27.841 -> [ 27744][D][BluetoothA2DPSink.cpp:390] app_send_msg(): [BT_AV] app_send_msg
16:53:27.905 -> [ 27844][I][BluetoothA2DPSink.cpp:1480] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote features 25b, CT features 2
16:53:28.033 -> [ 27928][D][BluetoothA2DPSink.cpp:1116] audio_data_callback(): [BT_AV] audio_data_callback
16:53:28.130 -> [ 28040][D][BluetoothA2DPSink.cpp:413] app_task_handler(): [BT_API] app_task_handler, sig 0x1, 0x0
16:53:28.226 -> [ 28136][E][BluetoothA2DPSinkQueued.cpp:59] write_audio(): [BT_AV] s_ringbuf_i2s is null
16:53:28.323 -> 
16:53:28.323 -> assert failed: xRingbufferSend ringbuf.c:1027 (pxRingbuffer)
16:53:28.387 -> 
16:53:28.387 -> 
16:53:28.387 -> Backtrace: 0x400837ed:0x3ffd1390 0x400931e9:0x3ffd13b0 0x40098a11:0x3ffd13d0 0x40092dd6:0x3ffd1500 0x400d6db2:0x3ffd1530 0x400d3c5a:0x3ffd1570 0x400d31f3:0x3ffd15b0 0x40111e81:0x3ffd15d0 0x40109129:0x3ffd1610 0x401090bf:0x3ffd1630
16:53:28.644 -> 
16:53:28.644 -> 
16:53:28.644 -> 
16:53:28.644 -> 
16:53:28.644 -> ELF file SHA256: 431d63af4beb7841
16:53:28.676 -> 
16:53:28.676 -> Rebooting...
16:53:28.708 -> �P����BLV�&8��3��W� �[    36][D][BluetoothA2DPSink.cpp:160] start(): [BT_AV] start
16:53:29.255 -> [    36][I][BluetoothA2DPCommon.cpp:246] log_free_heap(): [BT_AV] Available Heap: 222332
16:53:29.351 -> [   143][I][BluetoothA2DPSink.cpp:172] start(): [BT_AV] Device name will be set to 'mrhemMusicBasic3'

[mrhempman69]

The problem persists when using Apple Music (perhaps not related to #485, i used it on files that I added from my computer, not the streaming service) and YouTube Music. Probably the music app is not making a difference.

The problem persists in iOS 16.6 (iPhone SE, newer-ish iphone compared to my iphone 6S)....

[mrhempman69]

This issue is likely related to the last few detailed comments in #87, as the behaviors are quite similar

[pschatzmann]

I committed a new version of BluetoothA2DPSinkQueued which might resolve your issues...
You will need to run your sketch with this class instead of the simple BluetoothA2DPSink!

Since I don't have any recent IPhone, please let me know if this help ?

[mrhempman69]

I will do some more investigation, but I wanted to paste this log after doing what you suggested, in case there is an easy fix. Edit: Though it's 11:08 in Sweden, so hopefully i can have some more info by morning there....
Edit2: I updated the log, please ignore the changes in timestamp midway through

You must understand, it was highly inconvenient to copy and paste these, because the arduino-ide is total trash, and doesn't enable copying and pasting more than ~30 lines at a time from the serial monitor.

16:59:08.404 -> ��ѽ�ѡ�): [BT_AV] bluedroid initialized
16:59:08.489 -> [   838][I][BluetoothA2DPSink.cpp:338] init_bluetooth(): [BT_AV] bluedroid enabled
16:59:08.531 -> [   838][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:59:08.659 -> [   935][I][BluetoothA2DPCommon.cpp:289] set_scan_mode_connectable(): [BT_AV] set_scan_mode_connectable true
16:59:08.787 -> [   940][I][BluetoothA2DPSink.cpp:566] app_gap_callback(): [BT_AV] event: 10
16:59:08.850 -> [  1050][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:59:08.978 -> [  1131][I][BluetoothA2DPSink.cpp:566] app_gap_callback(): [BT_AV] event: 10
16:59:09.075 -> [  1252][I][BluetoothA2DPSink.cpp:643] av_hdl_a2d_evt(): [BT_AV] A2DP PROF STATE: Init Compl
16:59:09.171 -> 
16:59:09.171 -> [  1333][I][BluetoothA2DPSink.cpp:566] app_gap_callback(): [BT_AV] event: 10
16:59:09.235 -> [  1050][I][BluetoothA2DPCommon.cpp:246] log_free_heap(): [BT_AV] Available Heap: 117540
16:59:09.330 -> [  1514][I][BluetoothA2DPSink.cpp:566] app_gap_callback(): [BT_AV] event: 10
16:59:13.905 -> [  6314][I][BluetoothA2DPSink.cpp:566] app_gap_callback(): [BT_AV] event: 16
16:59:14.306 -> [  6699][I][BluetoothA2DPSink.cpp:497] app_gap_callback(): [BT_AV] authentication success: iPhone (16)
16:59:14.402 -> [  6813][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:59:14.530 -> [  6813][I][BluetoothA2DPSink.cpp:753] handle_connection_state(): [BT_AV] partner address: c0:b6:58:63:bf:5d
16:59:14.657 -> [  6913][I][BluetoothA2DPSink.cpp:755] handle_connection_state(): [BT_AV] A2DP connection state: Connecting, [c0:b6:58:63:bf:5d]
16:59:14.785 -> [  7049][I][BluetoothA2DPSink.cpp:814] handle_connection_state(): [BT_AV] ESP_A2D_CONNECTION_STATE_CONNECTING
16:59:14.881 -> [  7164][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
16:59:15.009 -> [  7285][I][BluetoothA2DPSink.cpp:661] handle_audio_cfg(): [BT_AV] a2dp audio_cfg_cb , codec type 0
17:26:53.116 -> [ 43314][I][BluetoothA2DPSink.cpp:692] handle_audio_cfg(): [BT_AV] audio player configured, samplerate=44100
17:26:53.212 -> [ 43428][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:53.341 -> [ 43549][I][BluetoothA2DPSink.cpp:753] handle_connection_state(): [BT_AV] partner address: c0:b6:58:63:bf:5d
17:26:53.469 -> [ 43664][I][BluetoothA2DPSink.cpp:755] handle_connection_state(): [BT_AV] A2DP connection state: Connected, [c0:b6:58:63:bf:5d]
17:26:53.596 -> [ 43798][I][BluetoothA2DPSink.cpp:819] handle_connection_state(): [BT_AV] ESP_A2D_CONNECTION_STATE_CONNECTED
17:26:53.693 -> [ 43913][I][BluetoothA2DPCommon.cpp:289] set_scan_mode_connectable(): [BT_AV] set_scan_mode_connectable false
17:26:53.821 -> [ 44028][I][BluetoothA2DPSinkQueued.cpp:6] bt_i2s_task_start_up(): [BT_API] ringbuffer data empty! mode changed: RINGBUFFER_MODE_PREFETCHING
17:26:53.982 -> [ 44176][I][BluetoothA2DPSinkQueued.cpp:21] bt_i2s_task_start_up(): [BT_AV] BtI2STask Started
17:26:54.078 -> [ 44275][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:54.174 -> [ 44300][I][BluetoothA2DPSink.cpp:550] app_gap_callback(): [BT_AV] ESP_BT_GAP_READ_REMOTE_NAME_EVT stat:0
17:26:54.302 -> [ 44396][I][BluetoothA2DPSink.cpp:984] av_hdl_avrc_evt(): [BT_AV] AVRC remote features 25b
17:26:54.398 -> [ 44507][I][BluetoothA2DPSink.cpp:552] app_gap_callback(): [BT_AV] ESP_BT_GAP_READ_REMOTE_NAME_EVT remote name:iPhone (16)
17:26:54.527 -> [ 44603][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:54.655 -> [ 44741][I][BluetoothA2DPSink.cpp:559] app_gap_callback(): [BT_AV] ESP_BT_GAP_MODE_CHG_EVT
17:26:54.752 -> [ 44853][I][BluetoothA2DPSink.cpp:1494] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote features 25b, CT features 2
17:26:54.848 -> [ 44949][I][BluetoothA2DPCommon.cpp:246] log_free_heap(): [BT_AV] Available Heap: 71896
17:26:54.944 -> [ 45065][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:55.073 -> [ 45278][I][BluetoothA2DPSink.cpp:992] av_hdl_avrc_evt(): [BT_AV] remote rn_cap: count 7, bitmask 0x1f06
17:26:56.871 -> [ 47199][I][BluetoothA2DPSink.cpp:559] app_gap_callback(): [BT_AV] ESP_BT_GAP_MODE_CHG_EVT
17:26:56.967 -> [ 47200][I][BluetoothA2DPCommon.cpp:246] log_free_heap(): [BT_AV] Available Heap: 72080
17:26:57.031 -> [ 47254][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:57.159 -> [ 47374][I][BluetoothA2DPSink.cpp:1473] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote set absolute volume: 100%
17:26:57.287 -> [ 47412][I][BluetoothA2DPSinkQueued.cpp:100] write_audio(): [BT_API] ringbuffer data increased! mode changed: RINGBUFFER_MODE_PROCESSING
17:26:57.415 -> [ 47488][I][BluetoothA2DPSink.cpp:1413] volume_set_by_controller(): [BT_AV] Volume is set by remote controller to 100
17:26:57.544 -> [ 47632][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:57.639 -> [ 47641][W][BluetoothA2DPSinkQueued.cpp:93] write_audio(): [BT_API] ringbuffer overflowed, ready to decrease data! mode changed: RINGBUFFER_MODE_DROPPING
17:26:57.799 -> [ 47860][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:57.927 -> [ 48024][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:26:58.023 -> [ 48126][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:58.119 -> [ 48239][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:26:58.248 -> [ 48342][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:58.344 -> [ 48455][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!

The last few lines repeat... until:

17:40:19.031 -> mrhem default Volume is now[ 80303][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:40:19.160 -> 4096[ 80435][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:40:19.287 -> 
17:40:19.287 -> [ 80558][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:40:19.417 -> [ 80558][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:40:19.512 -> [ 80770][I][BluetoothA2DPSink.cpp:712] handle_audio_state(): [BT_AV] A2DP audio state: Started
17:40:19.609 -> [ 80771][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:40:19.705 -> [ 80975][I][BluetoothA2DPSink.cpp:724] handle_audio_state(): [BT_AV] i2s_start
17:40:19.801 -> [ 80975][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:40:19.897 -> [ 81082][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:20.025 -> [ 81267][I][BluetoothA2DPSinkQueued.cpp:62] i2s_task_handler(): [BT_API] ringbuffer underflowed! mode changed: RINGBUFFER_MODE_PREFETCHING
17:40:20.153 -> [ 81274][I][BluetoothA2DPSinkQueued.cpp:84] write_audio(): [BT_API] ringbuffer data decreased! mode changed: RINGBUFFER_MODE_PROCESSING
17:40:20.312 -> [ 81162][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:40:20.409 -> [ 81587][W][BluetoothA2DPSinkQueued.cpp:93] write_audio(): [BT_API] ringbuffer overflowed, ready to decrease data! mode changed: RINGBUFFER_MODE_DROPPING
17:40:20.569 -> [ 81683][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:40:20.697 -> [ 81847][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:20.825 -> [ 81965][I][BluetoothA2DPSink.cpp:712] handle_audio_state(): [BT_AV] A2DP audio state: Suspended
17:40:20.921 -> [ 82079][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:21.017 -> [ 82179][W][BluetoothA2DPSink.cpp:732] handle_audio_state(): [BT_AV] i2s_stop
17:40:21.112 -> [ 82293][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:21.209 -> [ 82372][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:40:21.336 -> [ 82487][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:21.465 -> [ 82605][I][BluetoothA2DPSink.cpp:712] handle_audio_state(): [BT_AV] A2DP audio state: Started
17:40:21.560 -> [ 82719][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:21.657 -> [ 82816][I][BluetoothA2DPSink.cpp:724] handle_audio_state(): [BT_AV] i2s_start
17:40:21.753 -> [ 82930][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:26.554 -> [ 87806][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:40:26.650 -> [ 87919][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, droE (104650) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
17:40:26.842 -> E (104650) task_wdt:  - IDLE (CPU 0)
17:40:26.907 -> E (104650) task_wdt: Tasks currently running:
17:40:26.938 -> E (104650) task_wdt: CPU 0: BTC_TASK
17:40:26.971 -> E (104650) task_wdt: CPU 1: IDLE
17:40:27.035 -> E (104650) task_wdt: AbGuru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0). 
17:40:27.131 -> 
17:40:27.131 -> Core  0 register dump:
17:40:27.163 -> PC      : 0x4000921a  PS      : 0x00060035  A0      : 0x80007d16  A1      : 0x3ffbe9ac  
17:40:27.259 -> A2      : 0x00800000  A3      : 0x10000000  A4      : 0x00000000  A5      : 0x00000020  
17:40:27.323 -> A6      : 0x3ffc68c0  A7      : 0x00000002  A8      : 0x3ff40000  A9      : 0x0000006f  
17:40:27.419 -> A10     : 0x00800000  A11     : 0x3ff4001c  A12     : 0x3ffced50  A13     : 0x3ffced30  
17:40:27.514 -> A14     : 0x00000000  A15     : 0x3ffced50  SAR     : 0x00000004  EXCCAUSE: 0x00000005  
17:40:27.610 -> EXCVADDR: 0x00000000  LBEG    : 0x40090fad  LEND    : 0x40090fbd  LCOUNT  : 0xfffffffe  
17:40:27.707 -> Core  0 was running in ISR context:
17:40:27.738 -> EPC1    : 0x400e31cf  EPC2    : 0x00000000  EPC3    : 0x4000921a  EPC4    : 0x4000921a

There is audio, but there is no instant volume changes....

[pschatzmann]

Strange: I tested it on Android and there it was working. It seems that the I2S writes are not working, so the queue is never consumed.

After i2s_start() is_i2s_active, should be true!

I will compare your log with mine tomorrow...

[mrhempman69]

The last log was using the PCM5102 breakout board from the wiki. I actually am not getting audio from that board. But this is what happens using a different external DAC (NAU8402) where i am getting audio (still i2s_write_data failed).

17:26:53.116 -> [ 43314][I][BluetoothA2DPSink.cpp:692] handle_audio_cfg(): [BT_AV] audio player configured, samplerate=44100
17:26:53.212 -> [ 43428][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:53.341 -> [ 43549][I][BluetoothA2DPSink.cpp:753] handle_connection_state(): [BT_AV] partner address: c0:b6:58:63:bf:5d
17:26:53.469 -> [ 43664][I][BluetoothA2DPSink.cpp:755] handle_connection_state(): [BT_AV] A2DP connection state: Connected, [c0:b6:58:63:bf:5d]
17:26:53.596 -> [ 43798][I][BluetoothA2DPSink.cpp:819] handle_connection_state(): [BT_AV] ESP_A2D_CONNECTION_STATE_CONNECTED
17:26:53.693 -> [ 43913][I][BluetoothA2DPCommon.cpp:289] set_scan_mode_connectable(): [BT_AV] set_scan_mode_connectable false
17:26:53.821 -> [ 44028][I][BluetoothA2DPSinkQueued.cpp:6] bt_i2s_task_start_up(): [BT_API] ringbuffer data empty! mode changed: RINGBUFFER_MODE_PREFETCHING
17:26:53.982 -> [ 44176][I][BluetoothA2DPSinkQueued.cpp:21] bt_i2s_task_start_up(): [BT_AV] BtI2STask Started
17:26:54.078 -> [ 44275][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:54.174 -> [ 44300][I][BluetoothA2DPSink.cpp:550] app_gap_callback(): [BT_AV] ESP_BT_GAP_READ_REMOTE_NAME_EVT stat:0
17:26:54.302 -> [ 44396][I][BluetoothA2DPSink.cpp:984] av_hdl_avrc_evt(): [BT_AV] AVRC remote features 25b
17:26:54.398 -> [ 44507][I][BluetoothA2DPSink.cpp:552] app_gap_callback(): [BT_AV] ESP_BT_GAP_READ_REMOTE_NAME_EVT remote name:iPhone (16)
17:26:54.527 -> [ 44603][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:54.655 -> [ 44741][I][BluetoothA2DPSink.cpp:559] app_gap_callback(): [BT_AV] ESP_BT_GAP_MODE_CHG_EVT
17:26:54.752 -> [ 44853][I][BluetoothA2DPSink.cpp:1494] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote features 25b, CT features 2
17:26:54.848 -> [ 44949][I][BluetoothA2DPCommon.cpp:246] log_free_heap(): [BT_AV] Available Heap: 71896
17:26:54.944 -> [ 45065][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:55.073 -> [ 45278][I][BluetoothA2DPSink.cpp:992] av_hdl_avrc_evt(): [BT_AV] remote rn_cap: count 7, bitmask 0x1f06
17:26:56.871 -> [ 47199][I][BluetoothA2DPSink.cpp:559] app_gap_callback(): [BT_AV] ESP_BT_GAP_MODE_CHG_EVT
17:26:56.967 -> [ 47200][I][BluetoothA2DPCommon.cpp:246] log_free_heap(): [BT_AV] Available Heap: 72080
17:26:57.031 -> [ 47254][I][BluetoothA2DPSink.cpp:421] app_task_handler(): [BT_API] app_task_handler, APP_SIG_WORK_DISPATCH sig: 1
17:26:57.159 -> [ 47374][I][BluetoothA2DPSink.cpp:1473] av_hdl_avrc_tg_evt(): [BT_AV] AVRC remote set absolute volume: 100%
17:26:57.287 -> [ 47412][I][BluetoothA2DPSinkQueued.cpp:100] write_audio(): [BT_API] ringbuffer data increased! mode changed: RINGBUFFER_MODE_PROCESSING
17:26:57.415 -> [ 47488][I][BluetoothA2DPSink.cpp:1413] volume_set_by_controller(): [BT_AV] Volume is set by remote controller to 100
17:26:57.544 -> [ 47632][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:57.639 -> [ 47641][W][BluetoothA2DPSinkQueued.cpp:93] write_audio(): [BT_API] ringbuffer overflowed, ready to decrease data! mode changed: RINGBUFFER_MODE_DROPPING
17:26:57.799 -> [ 47860][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:57.927 -> [ 48024][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:26:58.023 -> [ 48126][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:58.119 -> [ 48239][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!
17:26:58.248 -> [ 48342][E][BluetoothA2DPSink.cpp:1344] i2s_write_data(): [BT_AV] i2s_write_data failed - inactive
17:26:58.344 -> [ 48455][W][BluetoothA2DPSinkQueued.cpp:81] write_audio(): [BT_API] ringbuffer is full, drop this packet!

The last few lines repeat...

I am pretty concerned based on your last message that there is some kind of hardware error here. Almost like the breadboards that I'm using are flawed, or the jumper wires are too thin, or something like that. So many potential variables... However perhaps this is unlikely... Since it does play audio outside the Queued class, just the volume changes don't work immediately...

// Tried normal , with android, 9600 baud, , info log, NAU circuit, staticy but audio and volume works....
// Tried normal , with iphone, 9600 baud, , info log, NAU circuit, staticy but audio works, but volume does not....
// Tried queued , with iphone, 9600 baud, , info log, PCM circuit, no work
// Tried queued , with android, 9600 baud, , info log, PCM circuit, no work
// Tried normal, with android, 9600 baud, , info log, PCM circuit, no audio but volume changes in the log are immediate