search

bluekitchen / btstack

Dual-mode Bluetooth stack, with small memory footprint.
http://bluekitchen-gmbh.com
Other
1.73k stars 611 forks source link

Non-compatible BT audio devices (BT v3.0/v4.2) #165

Open rob-bits opened 6 years ago

rob-bits commented 6 years ago

Hi @mringwal ,

I was unable to use two types of bluetooth audio devices with the btstack on esp32 (esp-idf v3.1). I have already used this stack with three different vendors well but with LG PH1, and SONY WH500 I have some troubles. The BT devices what works uses BT v2.1 protocoll while the new devices use v3.0 or v4.2 and they do not seem work.

I am using this code: A2DP source

With LG PH1 the devices connects and starts the stream and shows no error/ warning in the debug log. But no pleasurable audio comes out from the speaker. Instead of the music only some spike, loud, random noise can be heard. Like in every 1-2 sec this spike noise appear. It sounds like a codec problem. The speaker supports the SBC so it should work.

The other device, the SONY WH500 plays the music but with interruptions. It plays a bit of music for 1 sec then stops for another 1 sec and this is repeating. During audio play I got this message in debug:

LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved 1

Any hints what can be the problem or how can I track it back?

Thank you in advance!

Regards,

Rob

mringwal commented 6 years ago

Hi @rob-bits Interesting. Could you run a2dp_source on a desktop system (mac,linux,win) and post the full packet log?

For the LG, maybe they cannot agree on a codec config. If music pauses, you could check if the audio data is send at regular intervals. If the ESP32 runs a bit too slow, this would cause repeated pauses. -- just blind guesses.

mringwal commented 6 years ago

FWIW, the Bluetooth spec version is not relevant for this. If anything, the A2DP or AVDTP spec might be relevant.

rob-bits commented 6 years ago

Hi @mringwal,

Thank you very much for the input. Unfortunately I do not have time and energy to play on different platform with the BTStack for now. I can share the ESP32 log file and some measurement result. But if you really need the linux testing then I can do some test later.

I did a small modification for the a2dp_source_demo application to debug the problem. When the software enters into the a2dp_demo_send_media_packet() function then it toggles a GPIO pin. So when it first steps into this function then it sets the GPIO. When next time it enters it resets the GPIO ... and so on.

And you can see a scope shot from this GPIO for a normal operation (please ignore the orange spots on the screen :)):

playback_on_peaq

And this is when the Sony WH500 is connected:

playback_on_sony_wh500

Log:

I (208) cpu_start: Pro cpu up.
I (208) cpu_start: Single core mode
I (209) heap_init: Initializing. RAM available for dynamic allocation:
I (212) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (218) heap_init: At 3FFCFA30 len 000105D0 (65 KiB): DRAM
I (224) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (230) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (237) heap_init: At 40091C20 len 0000E3E0 (56 KiB): IRAM
I (243) cpu_start: Pro cpu start user code
I (37) cpu_start: Starting scheduler on PRO CPU.
BTstack: setup
[00:00:00.038] LOG -- btstack_run_loop_freertos.c.260: run loop task 0x3ffd2a14
[00:00:00.040] LOG -- btstack_run_loop_freertos.c.263: run loop init, queue item
 size 8
[00:00:00.048] LOG -- main.c.266: transport_register_packet_handler
[00:00:00.059] LOG -- btstack_tlv.c.48: TLV Instance 0x3f404820
[00:00:00.060] LOG -- btstack_tlv_esp32.c.54: tag 42544400 -> 42544400
[00:00:00.066] LOG -- btstack_tlv_esp32.c.68: read tag 42544400
[00:00:00.071] LOG -- btstack_tlv_esp32.c.54: tag 42544401 -> 42544401
[00:00:00.077] LOG -- btstack_tlv_esp32.c.68: read tag 42544401
[00:00:00.083] LOG -- btstack_tlv_esp32.c.54: tag 42544402 -> 42544402
[00:00:00.089] LOG -- btstack_tlv_esp32.c.68: read tag 42544402
[00:00:00.095] LOG -- btstack_tlv_esp32.c.54: tag 42544403 -> 42544403
[00:00:00.101] LOG -- btstack_tlv_esp32.c.68: read tag 42544403
[00:00:00.107] LOG -- btstack_tlv_esp32.c.54: tag 42544404 -> 42544404
[00:00:00.113] LOG -- btstack_tlv_esp32.c.68: read tag 42544404
[00:00:00.119] LOG -- btstack_tlv_esp32.c.54: tag 42544405 -> 42544405
[00:00:00.125] LOG -- btstack_tlv_esp32.c.68: read tag 42544405
[00:00:00.131] LOG -- btstack_tlv_esp32.c.54: tag 42544406 -> 42544406
[00:00:00.137] LOG -- btstack_tlv_esp32.c.68: read tag 42544406
[00:00:00.143] LOG -- btstack_tlv_esp32.c.54: tag 42544407 -> 42544407
[00:00:00.149] LOG -- btstack_tlv_esp32.c.68: read tag 42544407
[00:00:00.155] LOG -- btstack_tlv_esp32.c.54: tag 42544408 -> 42544408
[00:00:00.161] LOG -- btstack_tlv_esp32.c.68: read tag 42544408
[00:00:00.166] LOG -- btstack_tlv_esp32.c.54: tag 42544409 -> 42544409
[00:00:00.173] LOG -- btstack_tlv_esp32.c.68: read tag 42544409
[00:00:00.178] LOG -- btstack_tlv_esp32.c.54: tag 4254440a -> 4254440A
[00:00:00.185] LOG -- btstack_tlv_esp32.c.68: read tag 4254440A
[00:00:00.190] LOG -- btstack_tlv_esp32.c.54: tag 4254440b -> 4254440B
[00:00:00.196] LOG -- btstack_tlv_esp32.c.68: read tag 4254440B
[00:00:00.202] LOG -- btstack_tlv_esp32.c.54: tag 4254440c -> 4254440C
[00:00:00.208] LOG -- btstack_tlv_esp32.c.68: read tag 4254440C
[00:00:00.214] LOG -- btstack_tlv_esp32.c.54: tag 4254440d -> 4254440D
[00:00:00.220] LOG -- btstack_tlv_esp32.c.68: read tag 4254440D
[00:00:00.226] LOG -- btstack_tlv_esp32.c.54: tag 4254440e -> 4254440E
[00:00:00.232] LOG -- btstack_tlv_esp32.c.68: read tag 4254440E
[00:00:00.238] LOG -- btstack_tlv_esp32.c.54: tag 4254440f -> 4254440F
[00:00:00.244] LOG -- btstack_tlv_esp32.c.68: read tag 4254440F
[00:00:00.250] LOG -- le_device_db_tlv.c.157: num valid le device entries 0
[00:00:00.256] LOG -- l2cap.c.3404: L2CAP_REGISTER_SERVICE psm 0x19 mtu 65535
[00:00:00.263] LOG -- l2cap.c.3404: L2CAP_REGISTER_SERVICE psm 0x17 mtu 65535
[00:00:00.270] LOG -- l2cap.c.3404: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535
loaded mod 'nao-deceased by disease', size 7600
[00:00:00.282] LOG -- hci.c.2805: hci_power_control: 1, current mode 0
[00:00:00.287] LOG -- main.c.203: transport_init
[00:00:00.292] LOG -- main.c.219: transport_open
I (296) BTDM_INIT: BT controller compile version [bc70352]

I (303) system_api: Base MAC address is not set, read default base MAC address f
rom BLK0 of EFUSE
I (512) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
[00:00:00.513] LOG -- hci.c.3867: BTSTACK_EVENT_STATE 1
BTstack: execute run loop
[00:00:00.516] LOG -- hci.c.1907: Manufacturer: 0x0060
[00:00:00.521] LOG -- hci.c.1821: local name:
[00:00:00.524] LOG -- hci.c.1610: Received local name, need baud change 0
[00:00:00.531] LOG -- hci.c.1917: Local supported commands summary 0x3f
[00:00:00.538] LOG -- hci.c.1869: Local Address, Status: 0x00: Addr: 30:AE:A4:46
:D4:4A
[00:00:00.545] LOG -- hci.c.1838: hci_read_buffer_size: ACL size module 1021 ->
used 1021, count 9 / SCO size 255, count 4
[00:00:00.556] LOG -- hci.c.1896: Packet types cc18, eSCO 1
[00:00:00.561] LOG -- hci.c.1899: BR/EDR support 1, LE support 1
[00:00:00.570] LOG -- hci.c.3979: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1
[00:00:00.573] LOG -- hci.c.1849: hci_le_read_buffer_size: size 251, count 10
[00:00:00.580] LOG -- hci.c.1718: Supported commands 30
[00:00:00.585] LOG -- hci.c.1856: hci_le_read_maximum_data_length: tx octets 251
, tx time 2120 us
[00:00:00.594] LOG -- hci.c.1862: hci_le_read_white_list_size: size 12
[00:00:00.600] LOG -- hci.c.1474: hci_init_done -> HCI_STATE_WORKING
[00:00:00.606] LOG -- hci.c.3867: BTSTACK_EVENT_STATE 2
BTstack: up and running.
[00:00:13.015] LOG -- l2cap.c.1826: L2CAP_CREATE_CHANNEL addr 00:18:09:76:B9:49
psm 0x1 mtu 1691 -> local mtu 1691
[00:00:13.015] LOG -- hci.c.3571: Create_connection to 00:18:09:76:B9:49
[00:00:13.021] LOG -- hci.c.185: create_connection_for_addr 00:18:09:76:B9:49, t
ype ff
[00:00:13.028] LOG -- hci.c.3583: conn state 0
b - Create AVDTP Source connection to addr 00:18:09:76:B9:49, cid 0x56.
[00:00:21.440] LOG -- hci.c.2011: Connection_complete (status=0) 00:18:09:76:B9:
49
[00:00:21.441] LOG -- hci.c.2024: New connection: handle 129, 00:18:09:76:B9:49
[00:00:21.444] LOG -- hci.c.3930: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1
[00:00:21.450] LOG -- l2cap.c.1734: l2cap_handle_connection_complete expected st
ate
[00:00:21.458] LOG -- hci.c.2090: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMPL
ETE, bonding flags 6, eSCO 1
[00:00:21.467] LOG -- l2cap.c.1762: l2cap received remote supported features, se
c_level_0_allowed for psm 1 = 1
[00:00:21.477] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:21.483] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x40
[00:00:21.534] LOG -- l2cap.c.2468: L2CAP signaling handler code 3, state 10
[00:00:21.535] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:21.537] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:21.543] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x40
[00:00:21.549] LOG -- l2cap.c.2468: L2CAP signaling handler code 4, state 11
[00:00:21.556] LOG -- l2cap.c.2320: Remote MTU 200
[00:00:21.560] LOG -- l2cap.c.2468: L2CAP signaling handler code 5, state 11
[00:00:21.567] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:21.573] LOG -- l2cap.c.2400: l2cap_signaling_handle_configure_response
[00:00:21.580] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 00
:18:09:76:B9:49 handle 0x81 psm 0x1 local_cid 0x40 remote_cid 0x40 local_mtu 169
1, remote_mtu 200, flush_timeout 0
[00:00:21.597] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:21.603] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:21.610] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:21.653] LOG -- l2cap.c.1863: L2CAP_DISCONNECT local_cid 0x40 reason 0x0
[00:00:21.683] LOG -- l2cap.c.2468: L2CAP signaling handler code 7, state 13
[00:00:21.683] LOG -- l2cap.c.907: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x40
[00:00:21.686] LOG -- sdp_client.c.472: SDP Client disconnected.
[00:00:21.691] LOG -- l2cap.c.1826: L2CAP_CREATE_CHANNEL addr 00:18:09:76:B9:49
psm 0x19 mtu 1691 -> local mtu 1691
[00:00:21.702] LOG -- l2cap.c.1848: l2cap_create_channel, hci connection already
 exists
[00:00:21.709] LOG -- l2cap.c.1734: l2cap_handle_connection_complete expected st
ate
[00:00:21.717] LOG -- l2cap.c.1762: l2cap received remote supported features, se
c_level_0_allowed for psm 25 = 0
[00:00:21.727] LOG -- hci.c.4064: gap_request_security_level requested level 2,
planned level 0, current level 0
[00:00:21.737] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:21.743] LOG -- hci.c.2097: HCI_EVENT_LINK_KEY_REQUEST
[00:00:21.748] LOG -- hci.c.3326: responding to link key request
[00:00:21.754] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00
[00:00:21.760] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00
[00:00:21.766] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01
[00:00:21.772] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01
[00:00:21.777] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02
[00:00:21.784] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02
[00:00:21.789] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03
[00:00:21.796] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03
[00:00:21.801] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04
[00:00:21.808] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04
[00:00:21.813] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05
[00:00:21.819] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05
[00:00:21.825] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06
[00:00:21.831] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06
[00:00:21.837] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07
[00:00:21.843] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07
[00:00:21.849] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08
[00:00:21.855] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08
[00:00:21.861] LOG -- btstack_tlv_esp32.c.54: tag 42544c09 -> 42544C09
[00:00:21.867] LOG -- btstack_tlv_esp32.c.68: read tag 42544C09
[00:00:21.873] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c09, addr FC:58:FA:
29:29:61
[00:00:21.880] LOG -- btstack_tlv_esp32.c.54: tag 42544c0a -> 42544C0A
[00:00:21.887] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0A
[00:00:21.892] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c0a, addr FC:58:FA:
29:5E:47
[00:00:21.900] LOG -- btstack_tlv_esp32.c.54: tag 42544c0b -> 42544C0B
[00:00:21.906] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0B
[00:00:21.912] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c0b, addr FC:58:FA:
AA:3E:60
[00:00:21.920] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C
[00:00:21.926] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0C
[00:00:21.932] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c0c, addr 00:18:09:
76:B9:49
[00:00:21.979] LOG -- hci.c.3350: IO Capability Request received, stack bondable
 1, io cap 3
[00:00:21.980] LOG -- hci.c.4039: gap_mitm_protection_required_for_security_leve
l 2
[00:00:22.699] LOG -- hci.c.384: gap_store_link_key_for_bd_addr: 00:18:09:76:B9:
49, type 4
[00:00:22.700] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00
[00:00:22.703] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00
[00:00:22.709] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01
[00:00:22.715] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01
[00:00:22.720] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02
[00:00:22.727] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02
[00:00:22.732] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03
[00:00:22.739] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03
[00:00:22.744] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04
[00:00:22.750] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04
[00:00:22.756] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05
[00:00:22.762] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05
[00:00:22.768] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06
[00:00:22.774] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06
[00:00:22.780] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07
[00:00:22.786] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07
[00:00:22.792] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08
[00:00:22.798] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08
[00:00:22.804] LOG -- btstack_tlv_esp32.c.54: tag 42544c09 -> 42544C09
[00:00:22.810] LOG -- btstack_tlv_esp32.c.68: read tag 42544C09
[00:00:22.816] LOG -- btstack_tlv_esp32.c.54: tag 42544c0a -> 42544C0A
[00:00:22.822] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0A
[00:00:22.828] LOG -- btstack_tlv_esp32.c.54: tag 42544c0b -> 42544C0B
[00:00:22.834] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0B
[00:00:22.840] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C
[00:00:22.846] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0C
[00:00:22.851] LOG -- btstack_tlv_esp32.c.54: tag 42544c0d -> 42544C0D
[00:00:22.857] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0D
[00:00:22.863] LOG -- btstack_tlv_esp32.c.54: tag 42544c0e -> 42544C0E
[00:00:22.869] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0E
[00:00:22.875] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F
[00:00:22.881] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0F
[00:00:22.887] LOG -- btstack_link_key_db_tlv.c.151: tag_for_addr 42544c0c, tag_
for_empy 42544c08, tag_for_lowest_seq_nr 42544c0f
[00:00:22.898] LOG -- btstack_link_key_db_tlv.c.165: store with tag 42544c0c
[00:00:22.905] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C
[00:00:22.911] LOG -- btstack_tlv_esp32.c.98: store tag 42544C0C
[00:00:23.020] LOG -- hci.c.3961: hci_emit_security_level 2 for handle 81
[00:00:23.021] LOG -- l2cap.c.2143: l2cap - security level update
[00:00:23.022] LOG -- l2cap.c.2153: channel state 6: actual 2 >= required 2?
[00:00:23.029] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x41
[00:00:23.035] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x41
[00:00:23.043] LOG -- hci.c.4064: gap_request_security_level requested level 0,
planned level 2, current level 2
[00:00:23.051] LOG -- hci.c.3961: hci_emit_security_level 2 for handle 81
[00:00:23.058] LOG -- l2cap.c.2143: l2cap - security level update
[00:00:23.063] LOG -- l2cap.c.2153: channel state 5: actual 2 >= required 0?
[00:00:23.070] LOG -- l2cap.c.913: L2CAP_EVENT_INCOMING_CONNECTION addr 00:18:09
:76:B9:49 handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x42
[00:00:23.082] LOG -- l2cap.c.2264: L2CAP_ACCEPT_CONNECTION local_cid 0x42
[00:00:23.089] LOG -- l2cap.c.2153: channel state 10: actual 2 >= required 2?
[00:00:23.096] LOG -- l2cap.c.2468: L2CAP signaling handler code 3, state 10
[00:00:23.103] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x41
[00:00:23.109] LOG -- l2cap.c.2468: L2CAP signaling handler code 4, state 11
[00:00:23.116] LOG -- l2cap.c.2320: Remote MTU 200
[00:00:23.120] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x42
[00:00:23.126] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x42
[00:00:23.133] LOG -- l2cap.c.2468: L2CAP signaling handler code 4, state 11
[00:00:23.139] LOG -- l2cap.c.2320: Remote MTU 200
[00:00:23.144] LOG -- l2cap.c.2468: L2CAP signaling handler code 5, state 11
[00:00:23.151] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x42
[00:00:23.157] LOG -- l2cap.c.2400: l2cap_signaling_handle_configure_response
[00:00:23.164] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 00
:18:09:76:B9:49 handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x42 local_mtu 169
1, remote_mtu 200, flush_timeout 0
[00:00:23.181] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x41
[00:00:23.187] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x41
[00:00:23.193] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.200] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.206] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.213] LOG -- l2cap.c.2468: L2CAP signaling handler code 5, state 11
[00:00:23.219] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x41
[00:00:23.226] LOG -- l2cap.c.2400: l2cap_signaling_handle_configure_response
[00:00:23.232] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 00
:18:09:76:B9:49 handle 0x81 psm 0x19 local_cid 0x41 remote_cid 0x41 local_mtu 16
91, remote_mtu 200, flush_timeout 0
[00:00:23.250] LOG -- avdtp.c.596: L2CAP_EVENT_CHANNEL_OPENED: status 0, cid 0x4
1 , signaling connection 0x3ffd7170
[00:00:23.260] LOG -- avdtp.c.619: AVDTP_SIGNALING_CONNECTION_OPENED, connection
 0x3ffd7170, l2cap_signaling_cid 0x41, avdtp_cid 0x56
[00:00:23.271] LOG -- a2dp_source.c.245: A2DP_SUBEVENT_SIGNALING_CONNECTION esta
blished avdtp_cid 0x56 ---
[00:00:23.281] LOG -- a2dp_source.c.246: cid: 0x56 ---
A2DP Source: Connected to address 00:18:09:76:B9:49, a2dp cid 0x56.
[00:00:23.292] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.298] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.305] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.311] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.318] LOG -- avdtp_initiator.c.275: INT: AVDTP_SIGNALING_CONNECTION_INI
TIATOR_W2_DISCOVER_SEPS
[00:00:23.347] LOG -- a2dp_source.c.357: Found sep: seid 1, in_use 0, media type
 0, sep type 1 (1-SNK)
[00:00:23.347] LOG -- a2dp_source.c.357: Found sep: seid 2, in_use 0, media type
 0, sep type 1 (1-SNK)
[00:00:23.354] LOG -- a2dp_source.c.370: A2DP Accepted 1, state 3
[00:00:23.360] LOG -- avdtp_initiator.c.280: INT: AVDTP_SIGNALING_CONNECTION_INI
TIATOR_W2_GET_CAPABILITIES
[00:00:23.370] LOG -- a2dp_source.c.388: A2DP_W2_GET_CAPABILITIES status: 0
[00:00:23.429] LOG -- a2dp_source.c.259: A2DP received SBC capability.
[00:00:23.430] LOG -- a2dp_source.c.264: A2DP received SBC capability.
[00:00:23.431] LOG -- a2dp_source.c.292: received, but not forwarded: AVDTP_SUBE
VENT_SIGNALING_MEDIA_TRANSPORT_CAPABILITY, remote seid 1

[00:00:23.443] LOG -- a2dp_source.c.304: received, but not forwarded: AVDTP_SUBE
VENT_SIGNALING_CONTENT_PROTECTION_CAPABILITY, remote seid 1

[00:00:23.456] LOG -- a2dp_source.c.370: A2DP Accepted 2, state 5
[00:00:23.461] LOG -- a2dp_source.c.393: A2DP initiate set configuration locally
 and wait for response ...
[00:00:23.471] LOG -- avdtp.c.985: Connection OK for AVDTP cid 0x56 requesting A
VDTP_INITIATOR_W2_SET_CONFIGURATION, connection->l2cap_signaling_cid = 65
[00:00:23.485] LOG -- avdtp_initiator.c.382: The stream_endpoint_state: 1
[00:00:23.491] LOG -- avdtp_initiator.c.391: initiator SM prepare SET_CONFIGURAT
ION cmd
[00:00:23.499] LOG -- avdtp_initiator.c.393: INT: AVDTP_INITIATOR_W2_(RE)CONFIGU
RATION bitmap, int seid 1, acp seid 1
[00:00:23.509] LOG -- a2dp_source.c.396: A2DP_W2_SET_CONFIGURATION status: 0, lo
cal_seid: 1
[00:00:23.518] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.524] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.533] LOG -- avdtp_initiator.c.177: INT: configured remote seid 1, to 0
x3ffd4c44
[00:00:23.538] LOG -- a2dp_source.c.324: A2DP received SBC Config: sample rate 4
4100, max bitpool 53.
A2DP Source: Received SBC codec configuration.
[00:00:23.551] LOG -- a2dp_source.c.370: A2DP Accepted 3, state 10
[00:00:23.557] LOG -- a2dp_source.c.400: A2DP open stream
[00:00:23.562] LOG -- avdtp_initiator.c.382: The stream_endpoint_state: 4
[00:00:23.569] LOG -- avdtp_initiator.c.429: INT: AVDTP_STREAM_ENDPOINT_W2_REQUE
ST_OPEN_STREAM
[00:00:23.578] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.584] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:23.596] LOG -- l2cap.c.1826: L2CAP_CREATE_CHANNEL addr 00:18:09:76:B9:49
psm 0x19 mtu 65535 -> local mtu 1691
[00:00:23.600] LOG -- l2cap.c.1848: l2cap_create_channel, hci connection already
 exists
[00:00:23.608] LOG -- l2cap.c.1734: l2cap_handle_connection_complete expected st
ate
[00:00:23.615] LOG -- l2cap.c.1762: l2cap received remote supported features, se
c_level_0_allowed for psm 25 = 0
[00:00:23.625] LOG -- hci.c.4064: gap_request_security_level requested level 2,
planned level 2, current level 2
[00:00:23.635] LOG -- hci.c.3961: hci_emit_security_level 2 for handle 81
[00:00:23.642] LOG -- l2cap.c.2143: l2cap - security level update
[00:00:23.648] LOG -- l2cap.c.2153: channel state 6: actual 2 >= required 2?
[00:00:23.654] LOG -- l2cap.c.2153: channel state 12: actual 2 >= required 2?
[00:00:23.661] LOG -- l2cap.c.2153: channel state 12: actual 2 >= required 0?
[00:00:23.668] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x43
[00:00:23.674] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x43
[00:00:23.681] LOG -- l2cap.c.2468: L2CAP signaling handler code 6, state 12
[00:00:23.687] LOG -- l2cap.c.907: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x42
[00:00:23.694] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x42
[00:00:23.700] LOG -- l2cap.c.2468: L2CAP signaling handler code 3, state 10
[00:00:23.707] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x43
[00:00:23.713] LOG -- l2cap.c.2468: L2CAP signaling handler code 4, state 11
[00:00:23.720] LOG -- l2cap.c.2320: Remote MTU 672
[00:00:23.725] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x43
[00:00:23.731] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x43
[00:00:23.775] LOG -- l2cap.c.2468: L2CAP signaling handler code 5, state 11
[00:00:23.776] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x43
[00:00:23.777] LOG -- l2cap.c.2400: l2cap_signaling_handle_configure_response
[00:00:23.784] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 00
:18:09:76:B9:49 handle 0x81 psm 0x19 local_cid 0x43 remote_cid 0x43 local_mtu 16
91, remote_mtu 672, flush_timeout 0
[00:00:23.801] LOG -- avdtp.c.596: L2CAP_EVENT_CHANNEL_OPENED: status 0, cid 0x4
3 , signaling connection 0x3ffd7170
[00:00:23.812] LOG -- avdtp.c.649: AVDTP_STREAM_ENDPOINT_OPENED, avdtp cid 0x56,
 l2cap_media_cid 0x43, local seid 1, remote seid 1
[00:00:23.823] LOG -- a2dp_source.c.346: AVDTP_SUBEVENT_STREAMING_CONNECTION_EST
ABLISHED --- avdtp_cid 0x56, local seid 1, remote seid 1
A2DP Source: Stream established, address 00:18:09:76:B9:49, a2dp cid 0x56, local
 seid 1, remote seid 1.
A2DP Source: Start playing mod, a2dp cid 0x56.
[00:00:23.882] LOG -- a2dp_source.c.370: A2DP Accepted 7, state 15
A2DP Source: Stream started.
[00:00:24.105] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:25.316] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:26.130] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:26.680] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:26.748] LOG -- hci.c.4064: gap_request_security_level requested level 2,
planned level 2, current level 2
[00:00:26.749] LOG -- hci.c.3961: hci_emit_security_level 2 for handle 81
[00:00:26.754] LOG -- l2cap.c.2143: l2cap - security level update
[00:00:26.760] LOG -- l2cap.c.2153: channel state 5: actual 2 >= required 2?
[00:00:26.766] LOG -- l2cap.c.913: L2CAP_EVENT_INCOMING_CONNECTION addr 00:18:09
:76:B9:49 handle 0x81 psm 0x17 local_cid 0x44 remote_cid 0x44
[00:00:26.779] LOG -- avrcp.c.606: L2CAP_EVENT_INCOMING_CONNECTION avrcp_cid 0x0
1, l2cap_signaling_cid 0x44
[00:00:26.788] LOG -- l2cap.c.2264: L2CAP_ACCEPT_CONNECTION local_cid 0x44
[00:00:26.795] LOG -- l2cap.c.2153: channel state 12: actual 2 >= required 2?
[00:00:26.802] LOG -- l2cap.c.2153: channel state 12: actual 2 >= required 2?
[00:00:26.809] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:26.815] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:26.822] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:26.828] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x44
[00:00:26.834] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x44
[00:00:26.841] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.016] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.162] LOG -- l2cap.c.2468: L2CAP signaling handler code 4, state 11
[00:00:27.162] LOG -- l2cap.c.2320: Remote MTU 335
[00:00:27.164] LOG -- l2cap.c.2468: L2CAP signaling handler code 5, state 11
[00:00:27.169] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x44
[00:00:27.175] LOG -- l2cap.c.2400: l2cap_signaling_handle_configure_response
[00:00:27.182] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 00
:18:09:76:B9:49 handle 0x81 psm 0x17 local_cid 0x44 remote_cid 0x44 local_mtu 16
91, remote_mtu 335, flush_timeout 0
[00:00:27.199] LOG -- avrcp.c.643: L2CAP_EVENT_CHANNEL_OPENED avrcp_cid 0x01, l2
cap_signaling_cid 0x44
AVRCP Target: Connected to 00:18:09:76:B9:49, avrcp_cid 0x01
[00:00:27.218] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.306] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.504] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.504] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.543] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.592] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:27.952] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:28.406] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:30.375] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:31.706] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:32.806] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:36.205] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:36.755] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:37.536] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:38.075] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:38.801] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:39.406] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:40.000] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:41.045] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:43.641] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:44.411] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:44.950] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:45.621] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:46.490] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:47.656] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:48.635] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:48.976] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:49.075] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:49.790] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:51.891] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:52.606] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:52.705] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
[00:00:53.376] LOG -- hci.c.565: hci_stack->hci_packet_buffer_reserved  1
rob-bits commented 6 years ago

HI @mringwal,

I have another issue with btstack+esp32. I got a new BT device which unfortunately does not work well. And it is the PEAQ PPA34BT-B. It looks like it cannot set the proper security level for the connection. Sometimes it can be paired and connected to the esp32 and it plays the music. But sometimes it drops connection failed messages.

Any hint for this?

Thank you in advance!

Guessed problemetic part from log:

[00:00:09.305] LOG -- l2cap.c.1762: l2cap received remote supported features, se
c_level_0_allowed for psm 25 = 0
[00:00:09.315] LOG -- hci.c.4064: gap_request_security_level requested level 2,
planned level 0, current level 0
...
[00:00:09.513] LOG -- hci.c.3961: hci_emit_security_level 0 for handle 81
[00:00:09.513] LOG -- l2cap.c.2143: l2cap - security level update
[00:00:09.514] LOG -- l2cap.c.2153: channel state 6: actual 0 >= required 2?
[00:00:09.593] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x41
[00:00:09.593] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x6a addr 0
...

Full log:

BTstack: execute run loop
[00:00:00.524] LOG -- hci.c.1907: Manufacturer: 0x0060
[00:00:00.529] LOG -- hci.c.1821: local name:
[00:00:00.533] LOG -- hci.c.1610: Received local name, need baud change 0
[00:00:00.540] LOG -- hci.c.1917: Local supported commands summary 0x3f
[00:00:00.546] LOG -- hci.c.1869: Local Address, Status: 0x00: Addr: 30:AE:A4:46
:D4:4A
[00:00:00.554] LOG -- hci.c.1838: hci_read_buffer_size: ACL size module 1021 ->
used 1021, count 9 / SCO size 255, count 4
[00:00:00.564] LOG -- hci.c.1896: Packet types cc18, eSCO 1
[00:00:00.569] LOG -- hci.c.1899: BR/EDR support 1, LE support 1
[00:00:00.578] LOG -- hci.c.3979: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1
[00:00:00.582] LOG -- hci.c.1849: hci_le_read_buffer_size: size 251, count 10
[00:00:00.589] LOG -- hci.c.1718: Supported commands 30
[00:00:00.594] LOG -- hci.c.1856: hci_le_read_maximum_data_length: tx octets 251
, tx time 2120 us
[00:00:00.602] LOG -- hci.c.1862: hci_le_read_white_list_size: size 12
[00:00:00.608] LOG -- hci.c.1474: hci_init_done -> HCI_STATE_WORKING
[00:00:00.614] LOG -- hci.c.3867: BTSTACK_EVENT_STATE 2
BTstack: up and running.
[00:00:07.082] LOG -- l2cap.c.1826: L2CAP_CREATE_CHANNEL addr 00:58:56:48:75:20
psm 0x1 mtu 1691 -> local mtu 1691
[00:00:07.082] LOG -- hci.c.3571: Create_connection to 00:58:56:48:75:20
[00:00:07.087] LOG -- hci.c.185: create_connection_for_addr 00:58:56:48:75:20, t
ype ff
[00:00:07.095] LOG -- hci.c.3583: conn state 0
b - Create AVDTP Source connection to addr 00:58:56:48:75:20, cid 0x56.
[00:00:09.001] LOG -- hci.c.2011: Connection_complete (status=0) 00:58:56:48:75:
20
[00:00:09.002] LOG -- hci.c.2024: New connection: handle 129, 00:58:56:48:75:20
[00:00:09.005] LOG -- hci.c.3930: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1
[00:00:09.011] LOG -- l2cap.c.1734: l2cap_handle_connection_complete expected st
ate
[00:00:09.019] LOG -- hci.c.2090: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMPL
ETE, bonding flags 6, eSCO 1
[00:00:09.028] LOG -- l2cap.c.1762: l2cap received remote supported features, se
c_level_0_allowed for psm 1 = 1
[00:00:09.038] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:09.044] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x40
[00:00:09.135] LOG -- l2cap.c.2468: L2CAP signaling handler code 3, state 10
[00:00:09.135] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:09.137] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:09.143] LOG -- l2cap.c.1067: l2cap_start_rtx for local cid 0x40
[00:00:09.150] LOG -- l2cap.c.2468: L2CAP signaling handler code 4, state 11
[00:00:09.156] LOG -- l2cap.c.2320: Remote MTU 128
[00:00:09.161] LOG -- l2cap.c.2330: Flush timeout: 65535 ms
[00:00:09.170] LOG -- l2cap.c.2468: L2CAP signaling handler code 5, state 11
[00:00:09.173] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:09.179] LOG -- l2cap.c.2400: l2cap_signaling_handle_configure_response
[00:00:09.186] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 00
:58:56:48:75:20 handle 0x81 psm 0x1 local_cid 0x40 remote_cid 0x40 local_mtu 169
1, remote_mtu 128, flush_timeout 65535
[00:00:09.241] LOG -- l2cap.c.1863: L2CAP_DISCONNECT local_cid 0x40 reason 0x0
[00:00:09.271] LOG -- l2cap.c.2468: L2CAP signaling handler code 7, state 13
[00:00:09.271] LOG -- l2cap.c.907: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x40
[00:00:09.274] LOG -- sdp_client.c.472: SDP Client disconnected.
[00:00:09.280] LOG -- l2cap.c.1826: L2CAP_CREATE_CHANNEL addr 00:58:56:48:75:20
psm 0x19 mtu 1691 -> local mtu 1691
[00:00:09.290] LOG -- l2cap.c.1848: l2cap_create_channel, hci connection already
 exists
[00:00:09.297] LOG -- l2cap.c.1734: l2cap_handle_connection_complete expected st
ate
[00:00:09.305] LOG -- l2cap.c.1762: l2cap received remote supported features, se
c_level_0_allowed for psm 25 = 0
[00:00:09.315] LOG -- hci.c.4064: gap_request_security_level requested level 2,
planned level 0, current level 0
[00:00:09.325] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x40
[00:00:09.331] LOG -- hci.c.2097: HCI_EVENT_LINK_KEY_REQUEST
[00:00:09.336] LOG -- hci.c.3326: responding to link key request
[00:00:09.342] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00
[00:00:09.348] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00
[00:00:09.354] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01
[00:00:09.360] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01
[00:00:09.366] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02
[00:00:09.372] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02
[00:00:09.378] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03
[00:00:09.384] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03
[00:00:09.389] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04
[00:00:09.396] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04
[00:00:09.401] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05
[00:00:09.408] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05
[00:00:09.413] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06
[00:00:09.419] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06
[00:00:09.425] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07
[00:00:09.431] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07
[00:00:09.437] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08
[00:00:09.443] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08
[00:00:09.449] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c08, addr 00:58:56:
48:75:20
[00:00:09.513] LOG -- hci.c.3961: hci_emit_security_level 0 for handle 81
[00:00:09.513] LOG -- l2cap.c.2143: l2cap - security level update
[00:00:09.514] LOG -- l2cap.c.2153: channel state 6: actual 0 >= required 2?
[00:00:09.593] LOG -- l2cap.c.1058: l2cap_stop_rtx for local cid 0x41
[00:00:09.593] LOG -- l2cap.c.885: L2CAP_EVENT_CHANNEL_OPENED status 0x6a addr 0
0:58:56:48:75:20 handle 0x81 psm 0x19 local_cid 0x41 remote_cid 0x0 local_mtu 16
91, remote_mtu 672, flush_timeout 0
[00:00:09.605] LOG -- avdtp.c.596: L2CAP_EVENT_CHANNEL_OPENED: status 106, cid 0
x41 , signaling connection 0x3ffd7170
[00:00:09.616] LOG -- avdtp.c.605: L2CAP connection to 00:58:56:48:75:20 failed.
 status code 0x6a
[00:00:09.624] LOG -- a2dp_source.c.240: AVDTP_SUBEVENT_SIGNALING_CONNECTION fai
led status 106 ---
A2DP Source: Connection failed, status 0x6a, cid 0x56, a2dp_cid 0x56
[00:00:09.639] LOG -- hci.c.894: Connection closed: handle 0x81, 00:58:56:48:75:
20
[00:00:09.646] LOG -- hci.c.3930: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0
mringwal commented 6 years ago

well. here the HCI log would help. Please enable the call to hci_dump_open in app_main and convert the log with tool/convert_packetlog.py to .pklg and post it here.

rob-bits commented 6 years ago

Okay. At the eve I will do that.

BTW, after this security issue the L2CAP drops a 0x6A status code which defined as L2CAP_SERVICE_ALREADY_REGISTERED.

Does this status code make any sense for you in this context?

mringwal commented 6 years ago

L2CAP_SERVICE_ALREADY_REGISTERED doesn't make sense in this context. The log might shine some light on the details.

rob-bits commented 6 years ago

Hi @mringwal,

I created the logs for you. You will find three usecases.

  1. the connection initied by the A2DP sink device -> connection success, but not played the music
  2. the connection initied by the A2DP source device, from console -> I got the same error as before
  3. the connection initied by the A2DP sink device, then disconnecting from terminal then connecting from terminal -> connection success, and in the end it played the music

log_peaq_PPA34BT-B_000x_20180829.zip

I hope you find something.

Thank you in advance!

Robert

rob-bits commented 6 years ago

Hi @mringwal ,

Have you find something?

Robert

mringwal commented 6 years ago

Sorry, I did get to look at it yet. Thanks for the remainder.

mringwal commented 6 years ago

hi. it looks like in the logs, there have been newlines inside some packets - the tool is not able to process that properly. Could you try to use a tool that does not add additional newlines?

With full packet log enabled, the console output at 115200, but it might help with headset/speakers that don't play music at all.

Could you pick one device that doesn't play music and try to create a new log file without the newlines? You can open the .pklg in Wireshark and check if it looks fine. (undecoded events are ok, these are BTstack internal)