After power-down and powerUp, Airpods connect automatically and then disconnect

[Mechi Fendel]

Hello,

I've been reading the posts about reconnecting devices. 

I've written a small test program that just connects, disconnects, scans, forgets and quits.

Most of the headsets and other audio devices reconnect to our device if they were connected before power-down.

With the Apple Airpods, though, a connection is established and then :

HCI_EVENT_DISCONNECTION_COMPLETE status 0x00 reason 0x13 (ERROR_CODE_REMOTE_USER_TERMINATED_CONNECTION).

What happens right before this is a misread in uart_posix_dev_process_read (in bluekitchen_lib/platform/posix/btstack_uart_block_posix_chardev.c):

    if (bytes_read < 0) {

       log_error("read returned error len %d\n", read_bytes_len);

                 btstack_run_loop_enable_data_source_callbacks(ds,

                                         DATA_SOURCE_CALLBACK_READ);

                 return;

         }

I put in lines to renable the read callback similar to those in the write function. I receive another 7 characters:

BK: ../../platform/posix/btstack_uart_block_posix_chardev.c.182: read returned error len 1

BK: ../../platform/posix/btstack_uart_block_posix_chardev.c.204: uart_posix_dev_process_read: bytes_read 1 [04]
BK: ../../platform/posix/btstack_uart_block_posix_chardev.c.201: uart_posix_dev_process_read: bytes_read 2 [05 04]
BK: ../../platform/posix/btstack_uart_block_posix_chardev.c.195: uart_posix_dev_process_read: bytes_read 4 [00 05 00 13]
BK: hci.c.2811: HCI_EVENT_DISCONNECTION_COMPLETE status 0x00 reason 0x13

Which is exactly the DISCONNECT event received from the Airpods:

   2287 08:45:43.133 controller            host                  HCI_EVT  7      Rcvd Disconnect Complete

Frame 2287: 7 bytes on wire (56 bits), 7 bytes captured (56 bits)
    Encapsulation type: Apple Bluetooth PacketLogger (118)
    Arrival Time: Jul  4, 2022 11:45:43.133277000 IDT
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1656924343.133277000 seconds
    [Time delta from previous captured frame: 0.000143000 seconds]
    [Time delta from previous displayed frame: 0.000143000 seconds]
    [Time since reference or first frame: 394.654408000 seconds]
    Frame Number: 2287
    Frame Length: 7 bytes (56 bits)
    Capture Length: 7 bytes (56 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: bluetooth:packetlogger:bthci_evt]
    [Coloring Rule Name: HCI_EVT]
    [Coloring Rule String: bthci_evt]
Bluetooth
    [Source: controller]
    [Destination: host]
PacketLogger HCI Event
    Type: HCI Event (0x01)
Bluetooth HCI Event - Disconnect Complete
    Event Code: Disconnect Complete (0x05)
    Parameter Total Length: 4
    Status: Success (0x00)
    Connection Handle: 0x0001
    Reason: Remote User Terminated Connection (0x13)

0000  01 05 04 00 01 00 13  

And now the question - which came first? The faulty read or the Airpods disconnect?       

            Is the faulty read caused by the Airpods disconnection? 

Or (more unlikely) 

            Is the fact that a byte is not read correctly, the Airpods sends a disconnect event?

And the REAL question - why is the Airpods disconnecting?

I can send the test program, thae hci_dump.pklg and also the terminal printouts, if needed (though how is this done? There isn't a way to attach to this message.)

Thanks for any idea,

Mechi

[Matthias Ringwald]

Hi Mechi

From your debug output, it looks like the UART driver is derived from our POSIX driver (ours is just called btstack_uart_posix.c) and the problem might be somehow related to this.
Could you try to run your app or a suitable example like a2dp_sink on a desktop system for comparison using port/libusb or port/windows-winusb?

Please also try to figure out why there's a read error on the UART.

Anyway, I don't think the read error is causing the disconnect directly. My best guess is that there could be a request from the AirPods which gets lost due to the read error, and then some timeout kicks in, triggering the disconnect.
In this case, the disconnect happens probably much later. The pklg should shed some light on this.

I'm using this Google Group with my regular eMail Client, so it's trivial to attach files. I don't think I've ever posted via the web interface. If it doesn't allow for .pklg, you might need to zip it first (at least that's the case on the GitHub Issue tracker).
You may send me the logs directly in this case as well.

Best regards
Matthias

> --
> You received this message because you are subscribed to the Google Groups "btstack-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to btstack-dev...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/27354b7f-5c53-4738-85fd-5e36cd25ae2en%40googlegroups.com.

[Mechi Fendel]

On our device (based on posix-h4-scsc) - the Apple Airpods disconnect even though they've been paired before and security is not the issue.

I merged the hci pklg with the terminal output, so all activity is seen.

The disconnect happens after the SDP connection (psm 0x01) - it didn't even advance to AVDP (psm 0x19).

I'm continuing to learn more about this issue.

What I'm probably going to do, if I have no other choice, is to have our device initiate a connection with the external speaker if it disconnects. 

We need the reconnect after power on to be as seamless as possible to the end user.

If you have any other ideas, I'd appreciate any direction to investigate and solve this.

Thanks,

Mechi

On Sun, Jul 10, 2022 at 11:57 AM Mechi Fendel <mechi....@orcam.com> wrote:

Thanks for your answer. It took me a while to get the PC running with the BT dongle.

The PC BT also gets the disconnect - but because of an ERROR_CODE_AUTHENTICATION_FAILURE - reason 0x16.

With our posix-h4-scsc device, authentication is not the problem, since the devices have been paired in the past and authentication passes correctly. Also, the disconnect comes from the device (reason 0x13) while here it's from the host (0x16).

Attached are the files using the PC CSR BT dongle.

To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/0DD04021-1B18-4E68-BD8B-E7C8F0211F6D%40gmail.com.

[Mechi Fendel]

I finally received a disconnect similar to what I experience with our proprietary device - I ran the/bluekitchen_lib/example/a2dp_sink_demo.c

Can you figure out why the Airpods disconnect from the PC in this demo?

In my test application, I don't have these rows...

BK: l2cap.c.1052: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr F4:AF:E7:1D:2D:D5 handle 0x48 psm 0x1 local_cid 0x41 remote_cid 0x202 local_mtu 1691, remote_mtu 256, flush_timeout 0
BK: l2cap.c.1069: ERTM mode 0, fcs enabled 1
BK: avdtp.c.556: sink_supported
BK: avdtp.c.590: avdtp version 0x103
BK: l2cap.c.2078: L2CAP_DISCONNECT local_cid 0x41 reason 0x0
BK: l2cap.c.2850: L2CAP signaling handler code 7, state 13
BK: l2cap.c.1082: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41
BK: sdp_client.c.529: SDP Client disconnected.
BK: avdtp.c.88: avdtp_emit_sink_and_source: HCI_EVENT_PACKET EB size 14
BK: avdtp_util.c.1402: a2dp_replace_subevent_id_and_emit_cmd: HCI_EVENT_PACKET HCI_EVENT_AVDTP_META subevent_id 14
A2DP  Sink      : Not parsed 0x0e
BK: a2dp_sink.c.233: A2DP sink signaling connection failed status 130
BK: avdtp.c.633: SDP query failed with status 0x82.
BK: l2cap.c.2007: free channel 0x559c32ef8210, local_cid 0x0041
BK: l2cap.c.1246: l2cap_stop_rtx for local cid 0x41
BK: l2cap.c.320: Stop Retransmission timer
BK: l2cap.c.306: Stop Monitor timer
BK: hci.c.2816: HCI_EVENT_DISCONNECTION_COMPLETE status 0x00 reason 0x13

BK: hci.c.2835: b4 conn->state RECEIVED_DISCONNECTION_COMPLETE

BK: hci.c.2995: b4 hci_shutdown_connection status

BK: hci.c.969: Connection closed: handle 0x48, F4:AF:E7:1D:2D:D5

[Matthias Ringwald]

Hi Mechi

Thanks for the logs.

In the first one AP_connectDisconnect_authFail, the pairing fails because the AirPods are not in pairing mode
Jul 10 08:18:22.254 HCI Event Simple Pairing Complete - F4:AF:E7:1D:2D:D5 - Pairing Not Allowed RECV
Jul 10 08:18:22.256 HCI Event Authentication Complete - Pairing Not Allowed RECV

In the second one, AP_reconnectFail_hci_dump, there's an read error on the UART. I have no idea what triggers the disconnect - it's only 150 ms after the connection is established.

In the third one, AP_disconnect_sink_demo_hci_dump, BTstack makes an SDP request which gives a valid SDP response for an A2DP Sink. Then, BTstack stops for no apparent reason.

What version do you use? Could update to current develop, or at least current master and re-try this?

Cheers
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/CA%2BtmT73yAAKsUG9XsKU0YdbV18WvXcxGZ0E-2M%3DY%3DbHT8GJaxQ%40mail.gmail.com.
> <AP_disconnect_sink_demo.txt><AP_disconnect_sink_demo_hci_dump.pklg>

[Mechi Fendel]

Thanks for your answer.

The first log is irrelevant, that's why I deleted it from the forum (or I thought I did).

The 2nd and 3rd logs (test program from our proprietary device on posix-h4-scsc and BK demo program run on PC, respectively) are where the problem has been observed. 

I will check that the version is updated. I've added many printouts into the code in order to try to understand this phenomenon.

Thanks again,

Mechi

To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/E0985EAC-2BE8-41CB-8AF4-5C7D7E8BC32C%40gmail.com.

[Mechi Fendel]

We're using BK version 1.4 from May 2021.

Were there any changes that are relevant to this problem?

Has anyone else experienced reconnecting problems with Apple Airpods?

Thanks,

Mechi

[Matthias Ringwald]

Hi Mechi

Looking at the CHANGELOG.md there's nothing that pops out for the A2DP Source Role, but there has been significant work on A2DP in general.
Anyway, it's good to keep up-to-date. In v1.5. both run loop and logging have been reworked, but in mosts cases, you only need update your build files and make single-line changes to use the newer APIs for these.

I don't remember specific issues with Airpods.

Please update to v1.5.3 and send another log file. If the problem persists, we need to dig deeper.

Best regards
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/3e052426-6ed2-4b1a-9dc5-f81f87ed99b6n%40googlegroups.com.

[Mechi Fendel]

I've been working on the code in order to compile the 1.53 version. I had to make some very minor changes since warnings are treated as errors with our compiler.

Something strange, though. None of the functions in a2pd.c are defined in the libbluekitchen.so!

Please see the attached terminal output.

I "touch" the a2pd.c file, and then when the library is compiled, the a2pd.o is NOT included! When running the program, I get 
                       symbol lookup error: /usr/lib/libbluekitchen.so: undefined symbol: a2dp_register_source_packet_handler

How can I fix this? Why does this occur?

Thanks,

Mechi

 V mechif@orcam4 ~/ws/bluekitchen_lib/port/posix-h4-scsc$ (v1.53) objdump -T ~/ws/bluekitchen_lib/port/posix-h4-scsc/install/lib/libbluekitchen.so > objdump.txt

 V mechif@orcam4 ~/ws/bluekitchen_lib/port/posix-h4-scsc$ (v1.53) less objdump.txt | grep "a2dp"

0007e63c g    DF .text  00000090  Base        a2dp_source_create_sdp_record
0007f878 g    DF .text  00000054  Base        a2dp_sink_set_config_atrac
0007f244 g    DF .text  00000090  Base        a2dp_sink_create_sdp_record
00000000      D  *UND*  00000000              a2dp_config_process_set_mpeg_aac
0007f7d0 g    DF .text  00000054  Base        a2dp_sink_set_config_mpeg_audio
0007f4b8 g    DF .text  00000024  Base        a2dp_sink_finalize_stream_endpoint
0007ea6c g    DF .text  00000030  Base        a2dp_source_disconnect
0007e838 g    DF .text  000000c4  Base        a2dp_source_create_stream_endpoint
0007ecec g    DF .text  00000054  Base        a2dp_source_set_config_mpeg_audio
0007f4dc g    DF .text  0000010c  Base        a2dp_sink_establish_stream
0007e80c g    DF .text  0000002c  Base        a2dp_source_deinit
0007ec98 g    DF .text  00000054  Base        a2dp_source_set_config_sbc
0007eb64 g    DF .text  00000044  Base        a2dp_max_media_payload_size
0007f8cc g    DF .text  0000005c  Base        a2dp_sink_set_config_other
0007e7f8 g    DF .text  00000014  Base        a2dp_source_init
00000000      D  *UND*  00000000              a2dp_register_source_packet_handler
0007eba8 g    DF .text  0000005c  Base        a2dp_source_stream_send_media_payload
0007f400 g    DF .text  000000b8  Base        a2dp_sink_create_stream_endpoint
00000000      D  *UND*  00000000              a2dp_config_process_set_sbc
0007e8fc g    DF .text  00000024  Base        a2dp_source_finalize_stream_endpoint
0007f1d8 g    DF .text  00000044  Base        a2dp_source_register_media_config_validator
0007e788 g    DF .text  00000070  Base        a2dp_source_register_packet_handler
0007ede8 g    DF .text  0000005c  Base        a2dp_source_set_config_other
0007ec54 g    DF .text  00000044  Base        a2dp_source_stream_send_media_packet
00000000      D  *UND*  00000000              a2dp_config_process_avdtp_event_handler
0007ec04 g    DF .text  00000050  Base        a2dp_source_stream_send_media_payload_rtp
0007e920 g    DF .text  0000014c  Base        a2dp_source_establish_stream
00000000      D  *UND*  00000000              a2dp_config_process_set_atrac
00000000      D  *UND*  00000000              a2dp_deinit
0007f77c g    DF .text  00000054  Base        a2dp_sink_set_config_sbc
0007ed94 g    DF .text  00000054  Base        a2dp_source_set_config_atrac
0007f344 g    DF .text  00000054  Base        a2dp_sink_register_media_handler
00000000      D  *UND*  00000000              a2dp_replace_subevent_id_and_emit_source
0007eae0 g    DF .text  00000044  Base        a2dp_source_pause_stream
00000000      D  *UND*  00000000              a2dp_register_sink_packet_handler
0007ea9c g    DF .text  00000044  Base        a2dp_source_start_stream
00000000      D  *UND*  00000000              a2dp_subevent_id_for_avdtp_subevent_id
0007ed40 g    DF .text  00000054  Base        a2dp_source_set_config_mpeg_aac
0007f824 g    DF .text  00000054  Base        a2dp_sink_set_config_mpeg_aac
0007eb24 g    DF .text  00000040  Base        a2dp_source_stream_endpoint_request_can_send_now
0007f3ac g    DF .text  00000054  Base        a2dp_sink_deinit
0007f2d4 g    DF .text  00000070  Base        a2dp_sink_register_packet_handler
00000000      D  *UND*  00000000              a2dp_config_process_set_mpeg_audio
0007ee44 g    DF .text  000002dc  Base        a2dp_source_reconfigure_stream_sampling_frequency
0007f738 g    DF .text  00000044  Base        a2dp_sink_register_media_config_validator
0007f5e8 g    DF .text  0000002c  Base        a2dp_sink_disconnect
00000000      D  *UND*  00000000              a2dp_config_process_set_other
00000000      D  *UND*  00000000              a2dp_create_sdp_record
00000000      D  *UND*  00000000              a2dp_config_process_ready_for_sep_discovery
0007f398 g    DF .text  00000014  Base        a2dp_sink_init

To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/AE968A1A-5B84-4C5A-AA45-3BF18D997204%40gmail.com.

[Matthias Ringwald]

Hi Mechi

port/posix-h4-scsc is not part of the official BTstack distribution. It seems to be a custom port by you. Because of this, it looks like you need to add a2dp.c to the list of files that are compiled into your libbluekitchen.so.
The missing source from the build script explains why a) touch of a2dp.c has no consequences, b) the symbols for a2dp.c are missing in the compiled library.

Cheers
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/CA%2BtmT72KOZxHj_o5t3oTVn5WfbT_oH7t34XdP6FEqgjAj4ax1g%40mail.gmail.com.
> <link_wo_a2dp.odt>

[Mechi Fendel]

I downloaded and compiled the libbluekitchen.so v1.53.

I had to make very slight changes in order to be compatible with our setup.

One change that I added (which is what allowed me to see the problem) is in btstack_uart_posix.c:

static void btstack_uart_block_posix_process_read(btstack_data_source_t *ds) {

...

...

if (bytes_read < 0) {

log_error("read returned error\n");

btstack_run_loop_enable_data_source_callbacks(ds, DATA_SOURCE_CALLBACK_READ);

return;

}

...

...

}

I used the a2dp_source_demo.
After connecting the Airpods, hearing the "music" adjusting the volume, etc. I exited the program using Cntrl-C.

When I ran the a2dp_source_demo again, I would expect the Airpods to try to reconnect. Since I didn't "forget" the pairing information, there shouldn't be security issues.

As you can see in the logs, the Airpods tries to establish a connection (2022-07-17 13:27:12.584) and very quickly (2022-07-17 13:27:12.976) requests to close the connection.

This repeats each time I open the Airpods "box" and the green LED "searching for connection" is on (2022-07-17 13:27:15.358 - 2022-07-17 13:27:15.770)

The "reconnect" feature works for other BT devices that were already connected. The device itself initiates the connection.

See the EP good reconnect files attached - dumped from our device using v1.53.

This doesn't work with the Airpods.

Any help would be appreciated.

Thanks,

Mechi

To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/97039FB6-80D1-4559-A5F4-38800DB8F084%40gmail.com.

[Matthias Ringwald]

Hi Mechi

Thanks for updating to the current version.

1. We assume that the UART connection is error free, that's why the code just gives up. What error do you get? If it's reasonable to continue in that case, we can extend the code to handle that particular error.

2. Looking at the AirPod reconnect log, there's no obvious error: it reconnects, the role is changed such that your device becomes Central (some headsets require that), then they do an SDP query. After the SDP query, encryption is enabled, but then the connection is aborted by the remote.

The question now is why. During the SDP query, AirPod asks for PnP, HFP, A2DP and AVRCP. Your device doesn't implement HFP, so a possible hypothesis could be that it expects that your device also supports HFP.

Could you run the hfp_ag_demo, pair again, then power cycle the AirPods and send us the log for that? Alternatively, you could register the HFP SDP record from the HFP AG demo without actually implementing HFP AG functionality to see if the AirPods at least try to open an HFP connection.

Could you also send one log with A2DP where you first pair, then power cycle the AirPods then let them reconnect (just to double check that the link key is valid and to see if there's anything suspicious during pairing).

Best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/CA%2BtmT708jpJUo-4zGO7FzB5Yd19YXBPtfeTY5t0i6o%2BVrPD_bg%40mail.gmail.com.
> <a2dp_source_tryReconnect_log.txt><a2dp_source_tryReconnect_hci_dump.pklg><EP_goodReconnect_hci_dump.pklg><EP_Good_Reconnect_hcilog.txt>

[Mechi Fendel]

I added in some logs and all hci logs are printed to the terminal.

1. Definitely a good idea - since as mentioned in previous email, the read error may come because something is (not) happening on another thread, but then the read UART resumes with more (important) data.

2. The Airpods, AP, reconnect log was using the a2dp_source_demo and the PC CSR dongle. I sent another device reconnect log using our device - it's named EP with MAC addr 11:11:11:00:FE:A6 - where the reconnect goes as expected.

3. I tried the hfp_ag_demo with the AP and received similar results. When first trying to connect (without initial pairing) connection is closed because of authentication failure.

203 12:21:03.473 PKTLOG 28 hfp_ag_demo.c.200: USER:'a'

336 12:21:05.053 PKTLOG 82 l2cap.c.2842: channel 0x56364800f420, cid 0042 - state 6: actual 0 >= required 2?

350 12:21:08.149 PKTLOG 70 hci.c.3539: HCI_EVENT_DISCONNECTION_COMPLETE status 0x00 reason 0x13   // ERROR_CODE_REMOTE_USER_TERMINATED_CONNECTION

I then put the AP in pairing mode (long press on button, white flashing light), the connection is established correctly. .

357 12:22:45.521 PKTLOG 28 hfp_ag_demo.c.200: USER:'a'

513 12:22:54.773 PKTLOG 57 l2cap.c.2857: l2cap_ready_to_connect, authentication OK

656 12:22:54.943 PKTLOG 117 rfcomm.c.264: RFCOMM_EVENT_CHANNEL_OPENED status 0x0 addr F4:AF:E7:1D:2D:D5 handle 0x47 channel #7 cid 0x02 mtu 1018

Then I return the earplugs to the case and close the AP case. the connection is closed (as expected).

43968 12:23:21.076 PKTLOG 70 hci.c.3539: HCI_EVENT_DISCONNECTION_COMPLETE status 0x00 reason 0x08

When I open the AP case and try to connect to audio, AP starts connection and then immediately disconnects.

43997 12:23:21.792 PKTLOG 28 hfp_ag_demo.c.211: USER:'b'

44008 12:25:00.317 PKTLOG 51 hci.c.6747: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

44040 12:25:00.511 PKTLOG 70 hci.c.3539: HCI_EVENT_DISCONNECTION_COMPLETE status 0x00 reason 0x13 

44044 12:25:00.512 PKTLOG 51 hci.c.6747: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0

I then restart the example program, and open up the AP case in order for the reconnect - the results are at the end of AP_hfp_ag_demo_terminal.txt and in AP_hfp_ag_tryReconnect_hci_dump.pklg, attached.

4. Do you have a set of Airpods to try out?

Thanks for any more ideas...

Sincerely,

Mechi

To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/36BDB580-EEC0-4637-814A-29CE2810DA52%40gmail.com.

[Matthias Ringwald]

Hi Mechi

Thanks for the additional info.

1. I'd like to learn what error you get in the POSIX UART driver. I haven't seen any on a desktop mac/linux system and would like to learn which error you get that could be ignored.

2. I was curious about pairing and reconnect of the same AirPods, I know that it works with all/most other devices.

3. In the reconnect case, nothing happens, but there's also no role change. Could you switch to the current develop branch or add this at the beginning of btstack_main() in hfp_ag_demo.c

// Request role change on reconnecting headset to always use them in slave mode
hci_set_master_slave_policy(0);

and then try one more reconnect and send the log.

4. No, we've got a few other headsets of different kind including some true-wirelss in-ears by other brands. Which generation and model do you have problems with?
Please contact me directly at matt...@bluetkitchen-gmbh.com if this is for a commercial project to figure out how to move forward here.

Best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/CA%2BtmT714LwC2nyhZW%3D5dFk2LCP5CkP5h27tvN5VQerj%2BjrXOww%40mail.gmail.com.
> <AP_hfp_ag_demo_terminal.txt><AP_hfp_ag_demo_hci_dump.pklg><AP_hfp_ag_tryReconnect_hci_dump.pklg>

[Mechi Fendel]

It is for a commercial application.

We've bought the library and have a support contract with you.

I couldn't send the email you requested: 

Address not found

Your message wasn't delivered to matthias@bluetkitchen-gmbh.com because the domain bluetkitchen-gmbh.com couldn't be found. Check for typos or unnecessary spaces and try again

To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/51725943-4162-4CB5-8CA4-B11F60916CCA%40gmail.com.