BT A2DP sink doesn't handle AVRC commands during playback (IDFGH-4920)

[playduck]

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

Environment

• Development Kit: ESP32-Wrover-Kit
• Kit version: v1 (?)
• Module or chip used: ESP32-WROOM-32D
• IDF version: v4.4-dev-473-gc49d03b8e
• Build System: idf.py
• Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
• Operating System: macOS (Apple M1)
• Using an IDE?: VSCode, compiling and flashing over commandline (zsh)
• Power Supply: USB or External

Problem Description

I'm using the ESP as a Bluetooth A2DP Sink, like in the official example.
Playback works fine.
However, once a device is connected and playing audio back through the ESP no AVRC Commands, like absolute volume, from the Host/Source are neither executed nor logged (to the monitor).
Only after the Audio Stream has been paused or suspended will all cued AVRC Commands be handled.

Expected Behavior

AVRC Commands should be handled during playback and printed to the monitor as soon as the arrive.

Actual Behavior

AVRC Commands are not executed during playback.
But after the Audio Stream has been suspended.

Steps to reproduce

1. build, flash and monitor the official A2DP Sink example
2. Connect a BT Host Device
3. Start playing an Audio Stream
4. Change the Volume on the Host
5. Stop the Audio Stream

Code to reproduce this issue

Just the aforementioned Example.

Debug Logs

>>> Startup above, Host Device is connected
I (11074) BT_AV: ESP_BT_GAP_MODE_CHG_EVT mode:2
I (16224) BT_AV: ESP_BT_GAP_MODE_CHG_EVT mode:0
I (16244) BT_LOG: bta_av_link_role_ok hndl:x41 role:1 conn_audio:x1 bits:1 features:x824b

W (16244) BT_APPL: new conn_srvc id:19, app_id:1
I (16244) BT_AV: A2DP audio state: Started
I (16344) RCCT: AVRC event notification: 1
I (16344) BT_AV: Playback status changed: 0x1
>>> At this point the Audio Stream has started and I'm changing Volume
I (18894) BT_AV: Audio packet count 100
I (17824) RCTG: Volume is set locally to: 48%
I (21224) BT_AV: Audio packet count 200
I (23544) BT_AV: Audio packet count 300
I (25864) BT_AV: Audio packet count 400
I (27824) RCTG: Volume is set locally to: 52%
I (28184) BT_AV: Audio packet count 500
>>> I've now stopped the Audio Stream, the following output appears instantly
I (28264) RCTG: AVRC set absolute volume: 38%
I (28264) RCTG: Volume is set by remote controller 38%

I (28264) RCTG: AVRC set absolute volume: 32%
I (28264) RCTG: Volume is set by remote controller 32%

...

I (28304) RCTG: AVRC set absolute volume: 7%
I (28314) RCTG: Volume is set by remote controller 7%

I (28314) RCCT: AVRC event notification: 1
I (28324) BT_AV: Playback status changed: 0x2
I (28334) BT_AV: A2DP audio state: Suspended
I (28334) RCTG: AVRC register event notification: 13, param: 0x0

>>> These Volume changes reflect my input accurately, however way too late

Thing I've tried

I've used two different Source Devices (an Iphone and a Macbook).
Both of which have delivered the same results.

When commenting out line ./main/bt_app_core.c:128

i2s_write(0, data, item_size, &bytes_written, portMAX_DELAY);

The AVRC events work as expected.

By measuring this line's execution time by saving calls to esp_timer_get_time()
before and after the line and printing the difference I've received a nominal time of around 23ms.
With a packet size of 4096 Stereo Samples, we get 4096 / 2 = 2048 Samples per channel per function call.
At fs = 44100Hz this is equal to 2048 * (1/44100Hz) = 46.44ms per Channel.
Thus the function call takes only half the amount of time as our audio samples represent.
I don't think i2s_write is too slow to handle the ammount of data nor should it block any AVRC events from being handled.

When changing the portMAX_DELAY of the i2s_write to something like pdMS_TO_TICKS(10) the AVRC events work again in real time, however the audio is now choppy, since not all samples are pushed out.

[Alvin1Zhang]

Thanks for the detailed report, we will look into.

[boblane1]

Hi @playduck,

Please try the following patch, and check the problem is still exist.

Thanks!

patch.zip

[playduck]

Hi @boblane1,
this patch almost works! Thank you.

Good news is, that volume events are handled during playback.
However when I send a lot of events quickly there's some problems.
(This is using the a2dp sink example again)

Rarely these errors come up (this seems to be the first error displayed)

E (13435) BT_APP_CORE: bt_app_send_msg xQueue send failed
I (13435) RCTG: AVRC set absolute volume: 24%
I (13445) RCTG: Volume is set by remote controller 24%

After that, more often there's this:

E (13505) BT_L2CAP: l2cab is_cong_cback_context
I (13505) RCTG: AVRC set absolute volume: 47%
I (13515) RCTG: Volume is set by remote controller 47%

And after a while the audio stream cuts off and a seemingly never-ending stream of dropped Packers are printed.

W (15335) BT_APPL: Pkt dropped

W (15365) BT_APPL: Pkt dropped

W (15385) BT_APPL: Pkt dropped

I've applied the patch using

git am ./patch
cd examples/bluetooth/bluedroid/classic_bt/a2dp_sink
idf.py -p /dev/tty.usbserial-0001 clean build flash monitor

[boblane1]

Hi @playduck,

E (13435) BT_APP_CORE: bt_app_send_msg xQueue send failed
I (13435) RCTG: AVRC set absolute volume: 24%
I (13445) RCTG: Volume is set by remote controller 24%

These logs indicate that the s_bt_app_task_queue can not cache more data at that moment. The capacity of the s_bt_app_task_queue is only 10, you can increase the number appropriately.

E (13505) BT_L2CAP: l2cab is_cong_cback_context

This means that the congestion has occurred in Bluetooth L2CAP layer which caused by your quickly sending. In fact, for the reason of limited resources, the Bluetooth stack on the ESP32 handle AVRC and A2DP data in the same task which known as BTC_TASK. The AVRC is more prior than A2DP, so if there are too many AVRC data, or some delay operation in the callback, then the A2DP will be affected. To solve this problem, it seems that it is better to slow down sending events.

By the way, if the audio packet dropping still exists. You can try to increase the RX_SBC_LEN in btc_a2dp_sink.c a little bit more.

Thanks!

[playduck]

Thanks for the helpful feedback @boblane1

Increasing s_bt_app_task_queue worked perfectly.

I couldn't find anything labeled RX_SBC_LEN in the entire repository.
I've instead tried changing MAX_OUTPUT_A2DP_SNK_FRAME_QUEUE_SZ in btc_a2dp_sink.c since it seems to be related to packet dropping (as evident in line 660).
However this had no apparent effect.

Slowing down events isn't really an option.
I'd like the ESP to gracefully handle any adverse conditions (e.g. not interrupting the audio stream and preferably ignoring volume commands instead). I understand how resource limited the ESP is so handling all events is not always possible.
As it stands right now, once the first packet is dropped the device does't recover on it's own. I have to pause and start the track again for the stream to restart.

Is there some solution to mitigate congestion, like ignoring AVRC commands if they're too frequent to be dealt with?
Maybe raising the A2DP priority above AVRC - or is that a bad idea?

[playduck]

I've just noticed I modified the unpatched version.
Modifying the patched version now and setting RX_SBC_LEN to 7 works.
No more dropped packets!

Only after sending a, quite frankly, ridiculous amount of volume events in quick succession do i get

E (41034) BT_BTC: send_metamsg_rsp: failed to build metamsg response. status: 0x03
W (41034) BT_APPL: btc_a2dp_sink_enque_buf No Buffer left -
E (41314) BT_HCI: host_recv_pkt_cb couldn't aquire memory for inbound data buffer.

It'd be nice if there was some way to handle these errors and ignore too many events, however I believe I can happily live with this solution.

Thank you very much!

[boblane1]

It'd be nice if there was some way to handle these errors and ignore too many events

We will do some optimization in the future. Thanks for your advice!

[playduck]

Awesome!
Thank you for the swift and helpful responses.

[Alvin1Zhang]

@playduck Thanks for sharing the updates, reopen now, will close until the fix is available on GitHub, thanks.

[mitchjs]

@playduck does this patch work with current IDF v4.4.1? i have the issue that iphone sends many volume commands very fast, and that causes audio packet drops, i just wonder if the A2DP sink is still broken in this aspect
(well it does the drops)

@boblane1 , i am having audio packet drops on the A2DP.sink example, when the iphone makes rapid volume changes
and i see some patch you did, i cant see to get that patch to work on v4.4.1 idf. oddly rapid volume changes from my android tab a, doesnt cause the issue, just the iPhone

[playduck]

@mitchjs I'm afraid I can't help you with that as my project isn't using IDF v4.4.1
The patch however in conjunction with increasing s_bt_app_task_queue has worked flawlessly for months now.

[mitchjs]

@playduck what version of IDF did you program under?
the patch, patches "btc_a2dp_sink.c" file, but it wont apply to v4.4.1
or i dont know what im doing with git
could you attach your patched "btc_a2dp_sink.c"
then i can do file compares, and maybe get the patch into newer idf

i set the size of s_bt_app_task_queue to 20, didnt seem to change anything

[pad52]

I am receiving the same
"E (43382) BT_BTC: send_metamsg_rsp: failed to build metamsg response. status: 0x03"
and crashing with iPhone on-screen volume change (that is sending volume change notices super fast)

I am using the latest esp-adf version (2.6) together with the shipped esp-idf release (4.4 - commit 3c8bc22)
Everything works if i disable both BT LOGS and common LOGS

[mitchjs]

@pad52 did you check the task priority?
if youre using the bt-sink demo check bt_app_task_start_up()
xTaskCreate(bt_app_task_handler, "BtAppTask", 3072, NULL, configMAX_PRIORITIES - 10, &s_bt_app_task_handle);

[boblane1]

Hi @pad52,
"E (43382) BT_BTC: send_metamsg_rsp: failed to build metamsg response. status: 0x03" means that the stack can not allocate AVRC packet buffer. Frequent iPhone on-screen volume change is part of the reason.
My suggestions are:

1. use PSRAM as much as possible for your application
2. reduce the unnecessary LOG printing, especially in stack callback

[pad52]

Thank you for your fast reply.
Since I have not the PSRAM (using the WROOM module) and I am using esp-adf (so I have no control over bt_app_task_handler task priority) I resolved disabling both BT LOGS and common LOGS.