AVRCP not connecting (sdp_client_notify_callbacks related bug?)

[amorniroli]

Bug Description

I'm trying to establish a connection to the AVRCP profile on a smartphone after the A2DP sink has been connected.

The AVRCP connection is not being established (L2CAP create connection channel is not triggered). Besides A2DP/AVRCP, other profiles like HFP/PBAP are also connected (without them, it seems everything works fine).

After debugging, it seems that sdp_client_notify_callbacks is not being properly called. The sdp_client_query_requests list still contains avrcp_handle_start_sdp_client_query, but it’s not being executed.

Steps to Reproduce

I'm trying to build a clean 'example' in order to reproduce it. I'll update the issue with the example (I hope that the problem is observable checking the HCI logs)

31/10/2024: isolated example to reproduce the issue (rename to .c) example.txt

Expected Behavior

The AVRCP profile should connect, or at least signal a connection failure.

HCI Packet Logs log.txt (rename to pklg)

As you can see, after

[00:00:03.807] LOG -- avrcp.c.569: avrcp_create_connection, role 0 [00:00:03.808] LOG -- avrcp.c.569: avrcp_create_connection, role 1

L2CAP channel is not created.

This is the status of sdp_client_query_requests (callback not executed)

Environment: (please complete the following information):

• develop (af411b3ff8e06dca547124b751362f141c390f98 )
• Infineon CUW20706
• Samsung A33 Android 14

Additional context /

[mringwal]

Hm. No idea from the log. sdp_client_register_query_callback adds it to the query list if it's not already in there (please check). After that it's directly calling sdp_client_notify_callbacks(). So, that should be called. Now, that checks sdp_client_state if it's INIT. Could you let me know where it fails on that path?

[amorniroli]

Hi,

thanks for the feedback. I'll provide you all info next days: a bit busy today unfortunately.

[amorniroli]

Hi @mringwal I was able to isolate the problem. See example attached (rename to .c).

You should be able to reproduce the issue almost systematically.

example.txt

The example just connect to HFP / A2DP (when established, AVRCP is connected too) / PBAP.

As (hopefully) you will see, AVRCP remains in connecting state. I think the issue is related to PBAP profile (maybe something is missing from the last multi instances feature). Without it, the example works as expected.

Please feel free to ask for more details.

Thanks.

Alessandro

[mringwal]

Hi @amorniroli I've fixed minor issues and added \n for every printf. I've then run into an issue with your example. The good news: it uncovered a bug in RFCOMM that must have been there since ever - if you try to open 2 RFCOMM channels in parallel, BTstack did try to setup 2 L2CAP channels for it, which is wrong. I've fixed this issue on develop and re-tested. The bad news: your issue does not reprodue here. So far, the example works as expected with my Pixel 7a / Android 14.

Updated example:
example.txt Example HCI Log: android-ok.pklg.zip

Could you double check with the slighly updated example code? The log files look pretty similar. In both logs, BTstack actually does an SDP query for ACVRCP. In your log, it then stops, whereas in mine it continues. Could you check if you have provided enough L2CAP Channels if you're not using dynamic memory?

Have a nice weekend, Matthias

[amorniroli]

Hi @amorniroli I've fixed minor issues and added \n for every printf. I've then run into an issue with your example. The good news: it uncovered a bug in RFCOMM that must have been there since ever - if you try to open 2 RFCOMM channels in parallel, BTstack did try to setup 2 L2CAP channels for it, which is wrong. I've fixed this issue on develop and re-tested. The bad news: your issue does not reprodue here. So far, the example works as expected with my Pixel 7a / Android 14.

Updated example: example.txt Example HCI Log: android-ok.pklg.zip

Could you double check with the slighly updated example code? The log files look pretty similar. In both logs, BTstack actually does an SDP query for ACVRCP. In your log, it then stops, whereas in mine it continues. Could you check if you have provided enough L2CAP Channels if you're not using dynamic memory?

Have a nice weekend, Matthias

Hi @mringwal ,

thanks for the feedback. The channels should be large enough (I’ve put an assertion inside btstack_memory_pool_get in case of a return NULL, and it never triggers).

The strange thing is that, in my scenario, I almost consistently encounter the same issue on three different phones (Android with different versions and iOS). I'll try to investigate further and provide you with more details.

Just in case, here is my btstack_config.h btstack_config.txt

[amorniroli]

Hi @amorniroli I've fixed minor issues and added \n for every printf. I've then run into an issue with your example. The good news: it uncovered a bug in RFCOMM that must have been there since ever - if you try to open 2 RFCOMM channels in parallel, BTstack did try to setup 2 L2CAP channels for it, which is wrong. I've fixed this issue on develop and re-tested. The bad news: your issue does not reprodue here. So far, the example works as expected with my Pixel 7a / Android 14. Updated example: example.txt Example HCI Log: android-ok.pklg.zip Could you double check with the slighly updated example code? The log files look pretty similar. In both logs, BTstack actually does an SDP query for ACVRCP. In your log, it then stops, whereas in mine it continues. Could you check if you have provided enough L2CAP Channels if you're not using dynamic memory? Have a nice weekend, Matthias

Hi @mringwal ,

thanks for the feedback. The channels should be large enough (I’ve put an assertion inside btstack_memory_pool_get in case of a return NULL, and it never triggers).

The strange thing is that, in my scenario, I almost consistently encounter the same issue on three different phones (Android with different versions and iOS). I'll try to investigate further and provide you with more details.

Just in case, here is my btstack_config.h btstack_config.txt

Hi @mringwal ,

I was able to resolve the problem changing sdp_client_notify_callbacks to this (while loop).

static void sdp_client_notify_callbacks(void){
    while (sdp_client_ready() == true)
    {
        btstack_context_callback_registration_t * callback = (btstack_context_callback_registration_t*) btstack_linked_list_pop(&sdp_client_query_requests);
        if (callback == NULL) {
            return;
        }
        (*callback->callback)(callback->context);
    }
}

I don't know why, but on my setup I'm able to replicate the issue almost every time. In my case, at some point the A2DP is connected and I call avrcp_connect routine

sdp_client_query_requests list still have avdtp_handle_sdp_client_query_request to be managed, so avrcp_sdp_query_registration is added to tail.

sdp_client_notify_callbacks pops avdtp_handle_sdp_client_query_request callback, and execute it.

connection->initiator_connection_state is AVDTP_SIGNALING_CONNECTION_INITIATOR_IDLE, so nothing is done and the function just returns.

avrcp_sdp_query_registration then remains in the list since sdp_client_notify_callbacks is not called anymore

[mringwal]

Thanks for the debugging. Thewhile (sdp_client_ready()) will certainly get the SDP query for AVRCP started, but it would hide/cover a bug. avdtp_handle_start_sdp_client_query search for avdtp_connection_t that requested an SDP query.

Hm. Could you add some log_info to both places that call sdp_client_register_query_callback and log connection->state and also log connection->state + connection->initiator_connection_state and send a new pklg?

Coming from avdtp_connect(), the connection->state should be AVDTP_SIGNALING_W2_SEND_SDP_QUERYFOR* but according to your comment, it seems to be AVDTP_SIGNALING_CONNECTION_OPENED. To get to opened, for an outgoing connection, it must have passed avdtp_handle_sdp_query_succeeded() - which requires the SDP connection to have completed. I'm a bit puzzled how the SDP query can be complete before it gets sent...

Please add another log_info at avdtp_connect() to track that as well - although the code there ignores the request if state is less than AVDTP_SIGNALING_CONNECTION_OPENED.

We'll figure it out!

[amorniroli]

Hi @mringwal, I'll try to send new pklg tomorrow.

Meanwhile, I've noticed that avdtp_handle_sdp_query_succeeded is called and connection state is AVDTP_SIGNALING_W4_SDP_QUERY_FOR_REMOTE_SOURCE_COMPLETE.

Calling avdtp_handle_sdp_query_succeeded will put connection state to AVDTP_SIGNALING_CONNECTION_W4_L2CAP_CONNECTED and then avdtp_handle_sdp_client_query_request is put back into list.

ASAP L2CAP channel is connected the state change to AVDTP_SIGNALING_CONNECTION_OPENED, but avdtp_handle_sdp_client_query_request is still queued

[mringwal]

Hi @amorniroli Excellent observation. sdp_client_register_query_callback calling without checking first if there are other pending outgoing SDP Client queries violates the contract between SDP Client and its user. You don't need to add the log_infos for now.

I think I've come up with a corner case where we register a query in good faith and later realize that it's not needed anymore (e.g. for the initial connect, we need to do a SDP query to get remote L2CAP PSM. However, if the remote opens an AVDTP connection in the meantime, we don't need the L2CAP PSM for the connection). In the general case, we either need to provide a way to unregistered a request, or, just keep trying as you've shown with your quick fix.

We will discuss this internally (and probably just add the while loop), but also update the code to only register SDP query if there's one pending.

[amorniroli]

I'll keep the while loop at the moment.

Just for you interest, I think l'll open another issue regarding A2DP/AVRCP tomorrow/next day :)

Thanks for the support

Alessandro

[mringwal]

Hi Alessandro.

So, I've made two changes this morning: a) fixed the AVDTP code to not register an SDP query if there isn't one, b) updated SDP Client to iterate over registered client like in your code.

Could you try 89f10e1 with your test setup and confirm that this fixes your issue? After that, feel free to update to 166d44a or newer which contains the while loop in sdp_client.

Cheers Matthias

[amorniroli]

Hi Alessandro.

So, I've made two changes this morning: a) fixed the AVDTP code to not register an SDP query if there isn't one, b) updated SDP Client to iterate over registered client like in your code.

Could you try 89f10e1 with your test setup and confirm that this fixes your issue? After that, feel free to update to 166d44a or newer which contains the while loop in sdp_client.

Cheers Matthias

Hi,

I confirm that a) fixes my issue. Thank you very much