{"action":"created","issue":{"url":"https://api.github.com/repos/bluekitchen/btstack/issues/161","repository_url":"https://api.github.com/repos/bluekitchen/btstack","labels_url":"https://api.github.com/repos/bluekitchen/btstack/issues/161/labels{/name}","comments_url":"https://api.github.com/repos/bluekitchen/btstack/issues/161/comments","events_url":"https://api.github.com/repos/bluekitchen/btstack/issues/161/events","html_url":"https://github.com/bluekitchen/btstack/issues/161","id":352385413,"node_id":"MDU6SXNzdWUzNTIzODU0MTM=","number":161,"title":"hsp_ag_ audio connection establishment issue","user":{"login":"sapthas","id":25267544,"node_id":"MDQ6VXNlcjI1MjY3NTQ0","avatar_url":"https://avatars2.githubusercontent.com/u/25267544?v=4","gravatar_id":"","url":"https://api.github.com/users/sapthas","html_url":"https://github.com/sapthas","followers_url":"https://api.github.com/users/sapthas/followers","following_url":"https://api.github.com/users/sapthas/following{/other_user}","gists_url":"https://api.github.com/users/sapthas/gists{/gist_id}","starred_url":"https://api.github.com/users/sapthas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/sapthas/subscriptions","organizations_url":"https://api.github.com/users/sapthas/orgs","repos_url":"https://api.github.com/users/sapthas/repos","events_url":"https://api.github.com/users/sapthas/events{/privacy}","received_events_url":"https://api.github.com/users/sapthas/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2018-08-21T04:54:40Z","updated_at":"2018-08-23T11:49:27Z","closed_at":null,"author_association":"NONE","body":"hi,\r\nI was unable to communicate with a headset using the hsp_ag_demo example code.\r\nI am getting an error message \r\n[00:00:23.465] LOG -- hsp_ag.c.602: (e)SCO Connection failed, status 26         \r\nAudio connection establishment failed with status 26 \r\n full statement is given below.\r\nBTstack: setup                                                                  \r\n[00:00:00.032] LOG -- btstack_run_loop_freertos.c.260: run loop task 0x3ffcf3e8 \r\n[00:00:00.034] LOG -- btstack_run_loop_freertos.c.263: run loop init, queue ite8\r\n[00:00:00.042] LOG -- main.c.272: transport_register_packet_handler             \r\n[00:00:00.053] LOG -- btstack_tlv.c.48: TLV Instance 0x3f407290                 \r\n[00:00:00.053] LOG -- btstack_tlv_esp32.c.54: tag 42544400 -> 42544400          \r\n[00:00:00.060] LOG -- btstack_tlv_esp32.c.68: read tag 42544400                 \r\n[00:00:00.065] LOG -- btstack_tlv_esp32.c.54: tag 42544401 -> 42544401          \r\n[00:00:00.071] LOG -- btstack_tlv_esp32.c.68: read tag 42544401                 \r\n[00:00:00.077] LOG -- btstack_tlv_esp32.c.54: tag 42544402 -> 42544402          \r\n[00:00:00.083] LOG -- btstack_tlv_esp32.c.68: read tag 42544402                 \r\n[00:00:00.089] LOG -- btstack_tlv_esp32.c.54: tag 42544403 -> 42544403          \r\n[00:00:00.095] LOG -- btstack_tlv_esp32.c.68: read tag 42544403                 \r\n[00:00:00.101] LOG -- btstack_tlv_esp32.c.54: tag 42544404 -> 42544404          \r\n[00:00:00.107] LOG -- btstack_tlv_esp32.c.68: read tag 42544404                 \r\n[00:00:00.113] LOG -- btstack_tlv_esp32.c.54: tag 42544405 -> 42544405          \r\n[00:00:00.119] LOG -- btstack_tlv_esp32.c.68: read tag 42544405                 \r\n[00:00:00.125] LOG -- btstack_tlv_esp32.c.54: tag 42544406 -> 42544406          \r\n[00:00:00.131] LOG -- btstack_tlv_esp32.c.68: read tag 42544406                 \r\n[00:00:00.137] LOG -- btstack_tlv_esp32.c.54: tag 42544407 -> 42544407          \r\n[00:00:00.143] LOG -- btstack_tlv_esp32.c.68: read tag 42544407                 \r\n[00:00:00.149] LOG -- btstack_tlv_esp32.c.54: tag 42544408 -> 42544408          \r\n[00:00:00.155] LOG -- btstack_tlv_esp32.c.68: read tag 42544408                 \r\n[00:00:00.160] LOG -- btstack_tlv_esp32.c.54: tag 42544409 -> 42544409          \r\n[00:00:00.167] LOG -- btstack_tlv_esp32.c.68: read tag 42544409                 \r\n[00:00:00.172] LOG -- btstack_tlv_esp32.c.54: tag 4254440a -> 4254440A          \r\n[00:00:00.179] LOG -- btstack_tlv_esp32.c.68: read tag 4254440A                 \r\n[00:00:00.184] LOG -- btstack_tlv_esp32.c.54: tag 4254440b -> 4254440B          \r\n[00:00:00.190] LOG -- btstack_tlv_esp32.c.68: read tag 4254440B                 \r\n[00:00:00.196] LOG -- btstack_tlv_esp32.c.54: tag 4254440c -> 4254440C          \r\n[00:00:00.202] LOG -- btstack_tlv_esp32.c.68: read tag 4254440C                 \r\n[00:00:00.208] LOG -- btstack_tlv_esp32.c.54: tag 4254440d -> 4254440D          \r\n[00:00:00.214] LOG -- btstack_tlv_esp32.c.68: read tag 4254440D                 \r\n[00:00:00.220] LOG -- btstack_tlv_esp32.c.54: tag 4254440e -> 4254440E          \r\n[00:00:00.226] LOG -- btstack_tlv_esp32.c.68: read tag 4254440E                 \r\n[00:00:00.232] LOG -- btstack_tlv_esp32.c.54: tag 4254440f -> 4254440F          \r\n[00:00:00.238] LOG -- btstack_tlv_esp32.c.68: read tag 4254440F                 \r\n[00:00:00.244] LOG -- le_device_db_tlv.c.160: num valid le device entries 0     \r\nSCO Demo: Sending sine wave, hexdump received data.                             \r\n[00:00:00.255] LOG -- l2cap.c.3400: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535    \r\nSDP service record size: 90                                                     \r\n[00:00:00.264] LOG -- rfcomm.c.2301: RFCOMM_REGISTER_SERVICE channel #1 mtu 6550\r\n[00:00:00.274] LOG -- l2cap.c.3400: L2CAP_REGISTER_SERVICE psm 0x3 mtu 65535    \r\n[00:00:00.281] LOG -- hci.c.2800: hci_power_control: 1, current mode 0          \r\n[00:00:00.287] LOG -- main.c.204: transport_init                                \r\n[00:00:00.291] LOG -- main.c.220: transport_open                                \r\nI (295) BTDM_INIT: BT controller compile version [9525061]                      \r\n                                                                                \r\nI (302) system_api: Base MAC address is not set, read default base MAC address E\r\nI (528) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0            \r\n[00:00:00.529] LOG -- main.c.251: transport: configure SCO over HCI, result 0x00\r\n[00:00:00.531] LOG -- hci.c.3859: BTSTACK_EVENT_STATE 1                         \r\nBTstack: execute run loop                                                       \r\n[00:00:00.539] LOG -- hci.c.1902: Manufacturer: 0x0060                          \r\n[00:00:00.544] LOG -- hci.c.1816: local name:                                   \r\n[00:00:00.548] LOG -- hci.c.1605: Received local name, need baud change 0       \r\n[00:00:00.555] LOG -- hci.c.1912: Local supported commands summary 0x3f         \r\n[00:00:00.561] LOG -- hci.c.1864: Local Address, Status: 0x00: Addr: 30:AE:A4:02\r\n[00:00:00.568] LOG -- hci.c.1833: hci_read_buffer_size: ACL size module 1021 ->4\r\n[00:00:00.579] LOG -- hci.c.1891: Packet types cc18, eSCO 1                     \r\n[00:00:00.584] LOG -- hci.c.1894: BR/EDR support 1, LE support 1                \r\n[00:00:00.593] LOG -- hci.c.3971: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1          \r\n[00:00:00.597] LOG -- hci.c.1844: hci_le_read_buffer_size: size 251, count 10   \r\n[00:00:00.603] LOG -- hci.c.1713: Supported commands 30                         \r\n[00:00:00.609] LOG -- hci.c.1851: hci_le_read_maximum_data_length: tx octets 25s\r\n[00:00:00.617] LOG -- hci.c.1857: hci_le_read_white_list_size: size 12          \r\n[00:00:00.623] LOG -- hci.c.1469: hci_init_done -> HCI_STATE_WORKING            \r\n[00:00:00.629] LOG -- hci.c.3859: BTSTACK_EVENT_STATE 2                         \r\nBTstack: up and running.                                                        \r\n[00:00:10.219] LOG -- hci.c.1982: Connection_incoming: 48:C1:AC:C3:4F:70, type 1\r\n[00:00:10.219] LOG -- hci.c.185: create_connection_for_addr 48:C1:AC:C3:4F:70, f\r\n[00:00:10.223] LOG -- hci.c.3292: sending hci_accept_connection_request, remote0\r\n[00:00:10.231] LOG -- hsp_ag.c.392: HSP: sending hci_accept_connection_request. \r\n[00:00:10.237] LOG -- hsp_ag.c.411: HFP: sending hci_accept_connection_request,0\r\n[00:00:10.246] LOG -- hci.c.2006: Connection_complete (status=0) 48:C1:AC:C3:4F0\r\n[00:00:10.254] LOG -- hci.c.2019: New connection: handle 128, 48:C1:AC:C3:4F:70 \r\n[00:00:10.261] LOG -- hci.c.3922: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1        \r\n[00:00:10.268] LOG -- hci.c.2085: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMP1\r\n[00:00:10.277] LOG -- hci.c.2092: HCI_EVENT_LINK_KEY_REQUEST                    \r\n[00:00:10.282] LOG -- hci.c.3318: responding to link key request                \r\n[00:00:10.288] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00          \r\n[00:00:10.294] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00                 \r\n[00:00:10.300] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01          \r\n[00:00:10.306] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01                 \r\n[00:00:10.311] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02          \r\n[00:00:10.318] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02                 \r\n[00:00:10.323] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03          \r\n[00:00:10.330] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03                 \r\n[00:00:10.335] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04          \r\n[00:00:10.341] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04                 \r\n[00:00:10.347] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05          \r\n[00:00:10.353] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05                 \r\n[00:00:10.359] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06          \r\n[00:00:10.365] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06                 \r\n[00:00:10.371] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07          \r\n[00:00:10.377] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07                 \r\n[00:00:10.383] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08          \r\n[00:00:10.389] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08                 \r\n[00:00:10.395] LOG -- btstack_tlv_esp32.c.54: tag 42544c09 -> 42544C09          \r\n[00:00:10.401] LOG -- btstack_tlv_esp32.c.68: read tag 42544C09                 \r\n[00:00:10.407] LOG -- btstack_tlv_esp32.c.54: tag 42544c0a -> 42544C0A          \r\n[00:00:10.413] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0A                 \r\n[00:00:10.418] LOG -- btstack_tlv_esp32.c.54: tag 42544c0b -> 42544C0B          \r\n[00:00:10.425] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0B                 \r\n[00:00:10.430] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C          \r\n[00:00:10.437] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0C                 \r\n[00:00:10.442] LOG -- btstack_tlv_esp32.c.54: tag 42544c0d -> 42544C0D          \r\n[00:00:10.448] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0D                 \r\n[00:00:10.454] LOG -- btstack_tlv_esp32.c.54: tag 42544c0e -> 42544C0E          \r\n[00:00:10.460] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0E                 \r\n[00:00:10.466] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F          \r\n[00:00:10.472] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0F                 \r\n[00:00:10.478] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c0f, addr 48:C1:AC0\r\n[00:00:10.512] LOG -- hci.c.3953: hci_emit_security_level 2 for handle 80       \r\n[00:00:10.512] LOG -- l2cap.c.2140: l2cap - security level update               \r\n[00:00:10.519] LOG -- hci.c.4056: gap_request_security_level requested level 0,2\r\n[00:00:10.523] LOG -- hci.c.3953: hci_emit_security_level 2 for handle 80       \r\n[00:00:10.529] LOG -- l2cap.c.2140: l2cap - security level update               \r\n[00:00:10.535] LOG -- l2cap.c.2150: channel state 5: actual 2 >= required 0?    \r\n[00:00:10.542] LOG -- l2cap.c.912: L2CAP_EVENT_INCOMING_CONNECTION addr 48:C1:A0\r\n[00:00:10.554] LOG -- l2cap.c.2261: L2CAP_ACCEPT_CONNECTION local_cid 0x40      \r\n[00:00:10.562] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x40           \r\n[00:00:10.567] LOG -- l2cap.c.1062: l2cap_start_rtx for local cid 0x40          \r\n[00:00:10.575] LOG -- l2cap.c.2465: L2CAP signaling handler code 4, state 11    \r\n[00:00:10.580] LOG -- l2cap.c.2317: Remote MTU 48                               \r\n[00:00:10.585] LOG -- l2cap.c.2465: L2CAP signaling handler code 5, state 11    \r\n[00:00:10.591] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x40           \r\n[00:00:10.597] LOG -- l2cap.c.2397: l2cap_signaling_handle_configure_response   \r\n[00:00:10.604] LOG -- l2cap.c.884: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 40\r\n[00:00:10.629] LOG -- l2cap.c.2465: L2CAP signaling handler code 6, state 12    \r\n[00:00:10.629] LOG -- l2cap.c.906: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x40    \r\n[00:00:10.635] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x40           \r\n[00:00:10.641] LOG -- hci.c.4056: gap_request_security_level requested level 2,2\r\n[00:00:10.651] LOG -- hci.c.3953: hci_emit_security_level 2 for handle 80       \r\n[00:00:10.657] LOG -- l2cap.c.2140: l2cap - security level update               \r\n[00:00:10.663] LOG -- l2cap.c.2150: channel state 5: actual 2 >= required 2?    \r\n[00:00:10.670] LOG -- l2cap.c.912: L2CAP_EVENT_INCOMING_CONNECTION addr 48:C1:A0\r\n[00:00:10.682] LOG -- rfcomm.c.282: rfcomm_max_frame_size_for_l2cap_mtu:  1691 6\r\n[00:00:10.690] LOG -- rfcomm.c.960: L2CAP_EVENT_INCOMING_CONNECTION (l2cap_cid t\r\n[00:00:10.701] LOG -- l2cap.c.2261: L2CAP_ACCEPT_CONNECTION local_cid 0x41      \r\n[00:00:10.708] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x41           \r\n[00:00:10.714] LOG -- l2cap.c.1062: l2cap_start_rtx for local cid 0x41          \r\n[00:00:10.720] LOG -- l2cap.c.2465: L2CAP signaling handler code 4, state 11    \r\n[00:00:10.727] LOG -- l2cap.c.2317: Remote MTU 4022                             \r\n[00:00:10.731] LOG -- l2cap.c.2319: Remote MTU 4022 larger than outgoing buffer1\r\n[00:00:10.740] LOG -- l2cap.c.2465: L2CAP signaling handler code 5, state 11    \r\n[00:00:10.747] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x41           \r\n[00:00:10.753] LOG -- l2cap.c.2397: l2cap_signaling_handle_configure_response   \r\n[00:00:10.760] LOG -- l2cap.c.884: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 40\r\n[00:00:10.777] LOG -- rfcomm.c.970: L2CAP_EVENT_CHANNEL_OPENED for BLUETOOTH_PR0\r\n[00:00:10.786] LOG -- rfcomm.c.282: rfcomm_max_frame_size_for_l2cap_mtu:  1691 6\r\n[00:00:10.794] LOG -- rfcomm.c.1076: Received SABM #0                           \r\n[00:00:10.799] LOG -- rfcomm.c.1216: Sending UA #0                              \r\n[00:00:10.803] LOG -- rfcomm.c.829: Multiplexer up and running                  \r\n[00:00:10.810] LOG -- rfcomm.c.1486: Received UIH Parameter Negotiation Command1\r\n[00:00:10.817] LOG -- rfcomm.c.409: rfcomm_channel_create for service 0x3ffd15a:\r\n[00:00:10.827] LOG -- rfcomm.c.1802: -> Inform app                              \r\n[00:00:10.832] LOG -- rfcomm.c.151: RFCOMM_EVENT_INCOMING_CONNECTION addr 48:C11\r\n[00:00:10.842] LOG -- hsp_ag.c.651: RFCOMM channel 1 requested for 48:C1:AC:C3:0\r\n[00:00:10.849] LOG -- rfcomm.c.2360: RFCOMM_ACCEPT_CONNECTION cid 0x01          \r\n[00:00:10.855] LOG -- rfcomm.c.1830: Sending UIH Parameter Negotiation Respond 2\r\n[00:00:10.863] LOG -- rfcomm.c.1623: rfcomm_channel_ready_for_incoming_dlc_setu3\r\n[00:00:10.872] LOG -- rfcomm.c.1452: Received SABM #2                           \r\n[00:00:10.876] LOG -- rfcomm.c.1834: Sending UA #2                              \r\n[00:00:10.881] LOG -- rfcomm.c.1623: rfcomm_channel_ready_for_incoming_dlc_setub\r\n[00:00:10.889] LOG -- rfcomm.c.1839: Incomping setup done, requesting send MSC s\r\n[00:00:10.898] LOG -- rfcomm.c.1505: Received MSC CMD for #2,                   \r\n[00:00:10.903] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, fla1\r\n[00:00:10.914] LOG -- rfcomm.c.1762: Sending MSC RSP for #2                     \r\n[00:00:10.920] LOG -- rfcomm.c.1925: Sending MSC CMD for #2                     \r\n[00:00:10.925] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, fla1\r\n[00:00:10.935] LOG -- rfcomm.c.1512: Received MSC RSP for #2                    \r\n[00:00:10.941] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, fla1\r\n[00:00:10.951] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 2, now 3  \r\n[00:00:10.958] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, fla3\r\n[00:00:10.969] LOG -- rfcomm.c.1932: Providing credits for #2                   \r\n[00:00:10.975] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, fla3\r\n[00:00:10.985] LOG -- rfcomm.c.1266: rfcomm_channel_opened!                     \r\n[00:00:10.990] LOG -- rfcomm.c.169: RFCOMM_EVENT_CHANNEL_OPENED status 0x0 addr4\r\n[00:00:11.002] LOG -- hsp_ag.c.657: RFCOMM_EVENT_CHANNEL_OPENED packet_handler 0\r\n[00:00:11.011] LOG -- hsp_ag.c.668: RFCOMM channel open succeeded. New RFCOMM C3\r\nRFCOMM connection established.                                                  \r\nReceived speaker gain change 8                                                  \r\n[00:00:11.040] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 1, now 3  \r\nReceived microphone gain change 15                                              \r\n[00:00:11.051] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 1, now 3  \r\nConnect to 48:C1:AC:C3:4F:70                                                    \r\n[00:00:23.436] LOG -- hsp_ag.c.551: Received button press AT+CKPD=200           \r\n[00:00:23.465] LOG -- hci.c.2048: Synchronous Connection Complete (status=26) 40\r\n[00:00:23.465] LOG -- hsp_ag.c.602: (e)SCO Connection failed, status 26         \r\nAudio connection establishment failed with status 26                            \r\n[00:00:23.474] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 1, now 3\r\n "},"comment":{"url":"https://api.github.com/repos/bluekitchen/btstack/issues/comments/415387008","html_url":"https://github.com/bluekitchen/btstack/issues/161#issuecomment-415387008","issue_url":"https://api.github.com/repos/bluekitchen/btstack/issues/161","id":415387008,"node_id":"MDEyOklzc3VlQ29tbWVudDQxNTM4NzAwOA==","user":{"login":"sapthas","id":25267544,"node_id":"MDQ6VXNlcjI1MjY3NTQ0","avatar_url":"https://avatars2.githubusercontent.com/u/25267544?v=4","gravatar_id":"","url":"https://api.github.com/users/sapthas","html_url":"https://github.com/sapthas","followers_url":"https://api.github.com/users/sapthas/followers","following_url":"https://api.github.com/users/sapthas/following{/other_user}","gists_url":"https://api.github.com/users/sapthas/gists{/gist_id}","starred_url":"https://api.github.com/users/sapthas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/sapthas/subscriptions","organizations_url":"https://api.github.com/users/sapthas/orgs","repos_url":"https://api.github.com/users/sapthas/repos","events_url":"https://api.github.com/users/sapthas/events{/privacy}","received_events_url":"https://api.github.com/users/sapthas/received_events","type":"User","site_admin":false},"created_at":"2018-08-23T11:49:27Z","updated_at":"2018-08-23T11:49:27Z","author_association":"NONE","body":"Hi, \r\nI am new to btstack. is there any method to enable hsp.\r\nI commented the  sco_demo_init(); function from Bt stack main .\r\n\r\nhere is the new log\r\n\r\n\r\nBTstack: setup\r\n[00:00:00.032] LOG -- btstack_run_loop_freertos.c.260: run loop task 0x3ffcf3e8\r\n[00:00:00.034] LOG -- btstack_run_loop_freertos.c.263: run loop init, queue item size 8\r\n[00:00:00.042] LOG -- main.c.272: transport_register_packet_handler\r\n[00:00:00.051] LOG -- btstack_tlv.c.48: TLV Instance 0x3f407290\r\n[00:00:00.053] LOG -- btstack_tlv_esp32.c.54: tag 42544400 -> 42544400\r\n[00:00:00.060] LOG -- btstack_tlv_esp32.c.68: read tag 42544400\r\n[00:00:00.065] LOG -- btstack_tlv_esp32.c.54: tag 42544401 -> 42544401\r\n[00:00:00.071] LOG -- btstack_tlv_esp32.c.68: read tag 42544401\r\n[00:00:00.077] LOG -- btstack_tlv_esp32.c.54: tag 42544402 -> 42544402\r\n[00:00:00.083] LOG -- btstack_tlv_esp32.c.68: read tag 42544402\r\n[00:00:00.089] LOG -- btstack_tlv_esp32.c.54: tag 42544403 -> 42544403\r\n[00:00:00.095] LOG -- btstack_tlv_esp32.c.68: read tag 42544403\r\n[00:00:00.101] LOG -- btstack_tlv_esp32.c.54: tag 42544404 -> 42544404\r\n[00:00:00.107] LOG -- btstack_tlv_esp32.c.68: read tag 42544404\r\n[00:00:00.113] LOG -- btstack_tlv_esp32.c.54: tag 42544405 -> 42544405\r\n[00:00:00.119] LOG -- btstack_tlv_esp32.c.68: read tag 42544405\r\n[00:00:00.125] LOG -- btstack_tlv_esp32.c.54: tag 42544406 -> 42544406\r\n[00:00:00.131] LOG -- btstack_tlv_esp32.c.68: read tag 42544406\r\n[00:00:00.137] LOG -- btstack_tlv_esp32.c.54: tag 42544407 -> 42544407\r\n[00:00:00.143] LOG -- btstack_tlv_esp32.c.68: read tag 42544407\r\n[00:00:00.149] LOG -- btstack_tlv_esp32.c.54: tag 42544408 -> 42544408\r\n[00:00:00.155] LOG -- btstack_tlv_esp32.c.68: read tag 42544408\r\n[00:00:00.160] LOG -- btstack_tlv_esp32.c.54: tag 42544409 -> 42544409\r\n[00:00:00.167] LOG -- btstack_tlv_esp32.c.68: read tag 42544409\r\n[00:00:00.172] LOG -- btstack_tlv_esp32.c.54: tag 4254440a -> 4254440A\r\n[00:00:00.179] LOG -- btstack_tlv_esp32.c.68: read tag 4254440A\r\n[00:00:00.184] LOG -- btstack_tlv_esp32.c.54: tag 4254440b -> 4254440B\r\n[00:00:00.190] LOG -- btstack_tlv_esp32.c.68: read tag 4254440B\r\n[00:00:00.196] LOG -- btstack_tlv_esp32.c.54: tag 4254440c -> 4254440C\r\n[00:00:00.202] LOG -- btstack_tlv_esp32.c.68: read tag 4254440C\r\n[00:00:00.208] LOG -- btstack_tlv_esp32.c.54: tag 4254440d -> 4254440D\r\n[00:00:00.214] LOG -- btstack_tlv_esp32.c.68: read tag 4254440D\r\n[00:00:00.220] LOG -- btstack_tlv_esp32.c.54: tag 4254440e -> 4254440E\r\n[00:00:00.226] LOG -- btstack_tlv_esp32.c.68: read tag 4254440E\r\n[00:00:00.232] LOG -- btstack_tlv_esp32.c.54: tag 4254440f -> 4254440F\r\n[00:00:00.238] LOG -- btstack_tlv_esp32.c.68: read tag 4254440F\r\n[00:00:00.244] LOG -- le_device_db_tlv.c.160: num valid le device entries 0\r\n[00:00:00.250] LOG -- l2cap.c.3400: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535\r\nSDP service record size: 82\r\n[00:00:00.260] LOG -- rfcomm.c.2301: RFCOMM_REGISTER_SERVICE channel #1 mtu 65535 flow_control 0 credits 10\r\n[00:00:00.269] LOG -- l2cap.c.3400: L2CAP_REGISTER_SERVICE psm 0x3 mtu 65535\r\nhsp ag init completed------|[00:00:00.277] LOG -- hci.c.2800: hci_power_control: 1, current mode 0\r\n[00:00:00.285] LOG -- main.c.204: transport_init\r\n[00:00:00.289] LOG -- main.c.220: transport_open\r\nI (293) BTDM_INIT: BT controller compile version [9525061]\r\n\r\nI (300) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE\r\nI (522) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0\r\n[00:00:00.523] LOG -- main.c.251: transport: configure SCO over HCI, result 0x0000\r\n[00:00:00.525] LOG -- hci.c.3859: BTSTACK_EVENT_STATE 1\r\nhci power controlee is enabledBTstack: execute run loop\r\n[00:00:00.536] LOG -- hci.c.1902: Manufacturer: 0x0060\r\n[00:00:00.540] LOG -- hci.c.1816: local name: \r\n[00:00:00.544] LOG -- hci.c.1605: Received local name, need baud change 0\r\n[00:00:00.551] LOG -- hci.c.1912: Local supported commands summary 0x3f\r\n[00:00:00.558] LOG -- hci.c.1864: Local Address, Status: 0x00: Addr: 30:AE:A4:0A:63:42\r\n[00:00:00.565] LOG -- hci.c.1833: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4\r\n[00:00:00.576] LOG -- hci.c.1891: Packet types cc18, eSCO 1\r\n[00:00:00.581] LOG -- hci.c.1894: BR/EDR support 1, LE support 1\r\n[00:00:00.590] LOG -- hci.c.3971: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1\r\n[00:00:00.594] LOG -- hci.c.1844: hci_le_read_buffer_size: size 251, count 10\r\n[00:00:00.600] LOG -- hci.c.1713: Supported commands 30\r\n[00:00:00.605] LOG -- hci.c.1851: hci_le_read_maximum_data_length: tx octets 251, tx time 2120 us\r\n[00:00:00.614] LOG -- hci.c.1857: hci_le_read_white_list_size: size 12\r\n[00:00:00.620] LOG -- hci.c.1469: hci_init_done -> HCI_STATE_WORKING\r\n[00:00:00.625] LOG -- hci.c.3859: BTSTACK_EVENT_STATE 2\r\nBTstack: up and running.\r\n[00:00:19.173] LOG -- hci.c.1982: Connection_incoming: 48:C1:AC:C3:4F:70, type 1\r\n[00:00:19.174] LOG -- hci.c.185: create_connection_for_addr 48:C1:AC:C3:4F:70, type ff\r\n[00:00:19.177] LOG -- hci.c.3292: sending hci_accept_connection_request, remote eSCO 0\r\n[00:00:19.185] LOG -- hsp_ag.c.392: HSP: sending hci_accept_connection_request.\r\n[00:00:19.192] LOG -- hsp_ag.c.411: HFP: sending hci_accept_connection_request, sco_voice_setting 60\r\n[00:00:19.201] LOG -- hci.c.2006: Connection_complete (status=0) 48:C1:AC:C3:4F:70\r\n[00:00:19.208] LOG -- hci.c.2019: New connection: handle 128, 48:C1:AC:C3:4F:70\r\n[00:00:19.215] LOG -- hci.c.3922: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1\r\n[00:00:19.222] LOG -- hci.c.2085: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMPLETE, bonding flags 6, eSCO 1\r\n[00:00:19.231] LOG -- hci.c.2092: HCI_EVENT_LINK_KEY_REQUEST\r\n[00:00:19.237] LOG -- hci.c.3318: responding to link key request\r\n[00:00:19.242] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00\r\n[00:00:19.248] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00\r\n[00:00:19.254] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01\r\n[00:00:19.260] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01\r\n[00:00:19.266] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02\r\n[00:00:19.272] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02\r\n[00:00:19.278] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03\r\n[00:00:19.284] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03\r\n[00:00:19.290] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04\r\n[00:00:19.296] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04\r\n[00:00:19.302] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05\r\n[00:00:19.308] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05\r\n[00:00:19.314] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06\r\n[00:00:19.320] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06\r\n[00:00:19.325] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07\r\n[00:00:19.332] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07\r\n[00:00:19.337] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08\r\n[00:00:19.343] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08\r\n[00:00:19.349] LOG -- btstack_tlv_esp32.c.54: tag 42544c09 -> 42544C09\r\n[00:00:19.355] LOG -- btstack_tlv_esp32.c.68: read tag 42544C09\r\n[00:00:19.361] LOG -- btstack_tlv_esp32.c.54: tag 42544c0a -> 42544C0A\r\n[00:00:19.367] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0A\r\n[00:00:19.373] LOG -- btstack_tlv_esp32.c.54: tag 42544c0b -> 42544C0B\r\n[00:00:19.379] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0B\r\n[00:00:19.385] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C\r\n[00:00:19.391] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0C\r\n[00:00:19.397] LOG -- btstack_tlv_esp32.c.54: tag 42544c0d -> 42544C0D\r\n[00:00:19.403] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0D\r\n[00:00:19.409] LOG -- btstack_tlv_esp32.c.54: tag 42544c0e -> 42544C0E\r\n[00:00:19.415] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0E\r\n[00:00:19.421] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F\r\n[00:00:19.427] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0F\r\n[00:00:19.433] LOG -- btstack_link_key_db_tlv.c.95: tag 42544c0f, addr 48:C1:AC:C3:4F:70\r\n[00:00:19.465] LOG -- hci.c.3953: hci_emit_security_level 2 for handle 80\r\n[00:00:19.465] LOG -- l2cap.c.2140: l2cap - security level update\r\n[00:00:19.472] LOG -- hci.c.4056: gap_request_security_level requested level 0, planned level 0, current level 2\r\n[00:00:19.476] LOG -- hci.c.3953: hci_emit_security_level 2 for handle 80\r\n[00:00:19.483] LOG -- l2cap.c.2140: l2cap - security level update\r\n[00:00:19.489] LOG -- l2cap.c.2150: channel state 5: actual 2 >= required 0?\r\n[00:00:19.495] LOG -- l2cap.c.912: L2CAP_EVENT_INCOMING_CONNECTION addr 48:C1:AC:C3:4F:70 handle 0x80 psm 0x1 local_cid 0x40 remote_cid 0x2900\r\n[00:00:19.508] LOG -- l2cap.c.2261: L2CAP_ACCEPT_CONNECTION local_cid 0x40\r\n[00:00:19.515] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x40\r\n[00:00:19.521] LOG -- l2cap.c.1062: l2cap_start_rtx for local cid 0x40\r\n[00:00:19.528] LOG -- l2cap.c.2465: L2CAP signaling handler code 4, state 11\r\n[00:00:19.534] LOG -- l2cap.c.2317: Remote MTU 48\r\n[00:00:19.538] LOG -- l2cap.c.2465: L2CAP signaling handler code 5, state 11\r\n[00:00:19.545] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x40\r\n[00:00:19.551] LOG -- l2cap.c.2397: l2cap_signaling_handle_configure_response\r\n[00:00:19.558] LOG -- l2cap.c.884: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 48:C1:AC:C3:4F:70 handle 0x80 psm 0x1 local_cid 0x40 remote_cid 0\r\n[00:00:19.582] LOG -- l2cap.c.2465: L2CAP signaling handler code 6, state 12\r\n[00:00:19.583] LOG -- l2cap.c.906: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x40\r\n[00:00:19.588] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x40\r\n[00:00:19.595] LOG -- hci.c.4056: gap_request_security_level requested level 2, planned level 0, current level 2\r\n[00:00:19.604] LOG -- hci.c.3953: hci_emit_security_level 2 for handle 80\r\n[00:00:19.611] LOG -- l2cap.c.2140: l2cap - security level update\r\n[00:00:19.617] LOG -- l2cap.c.2150: channel state 5: actual 2 >= required 2?\r\n[00:00:19.624] LOG -- l2cap.c.912: L2CAP_EVENT_INCOMING_CONNECTION addr 48:C1:AC:C3:4F:70 handle 0x80 psm 0x3 local_cid 0x41 remote_cid 0x2940\r\n[00:00:19.636] LOG -- rfcomm.c.282: rfcomm_max_frame_size_for_l2cap_mtu:  1691 -> 1686\r\n[00:00:19.644] LOG -- rfcomm.c.960: L2CAP_EVENT_INCOMING_CONNECTION (l2cap_cid 0x41) for BLUETOOTH_PROTOCOL_RFCOMM => accept\r\n[00:00:19.655] LOG -- l2cap.c.2261: L2CAP_ACCEPT_CONNECTION local_cid 0x41\r\n[00:00:19.662] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x41\r\n[00:00:19.667] LOG -- l2cap.c.1062: l2cap_start_rtx for local cid 0x41\r\n[00:00:19.683] LOG -- l2cap.c.2465: L2CAP signaling handler code 4, state 11\r\n[00:00:19.683] LOG -- l2cap.c.2317: Remote MTU 4022\r\n[00:00:19.685] LOG -- l2cap.c.2319: Remote MTU 4022 larger than outgoing buffer, only using MTU = 1691\r\n[00:00:19.694] LOG -- l2cap.c.2465: L2CAP signaling handler code 5, state 11\r\n[00:00:19.701] LOG -- l2cap.c.1053: l2cap_stop_rtx for local cid 0x41\r\n[00:00:19.707] LOG -- l2cap.c.2397: l2cap_signaling_handle_configure_response\r\n[00:00:19.714] LOG -- l2cap.c.884: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 48:C1:AC:C3:4F:70 handle 0x80 psm 0x3 local_cid 0x41 remote_cid 0\r\n[00:00:19.731] LOG -- rfcomm.c.970: L2CAP_EVENT_CHANNEL_OPENED for BLUETOOTH_PROTOCOL_RFCOMM, status 0\r\n[00:00:19.740] LOG -- rfcomm.c.282: rfcomm_max_frame_size_for_l2cap_mtu:  1691 -> 1686\r\n[00:00:19.748] LOG -- rfcomm.c.1076: Received SABM #0\r\n[00:00:19.753] LOG -- rfcomm.c.1216: Sending UA #0\r\n[00:00:19.757] LOG -- rfcomm.c.829: Multiplexer up and running\r\n[00:00:19.777] LOG -- rfcomm.c.1486: Received UIH Parameter Negotiation Command for #2, credits 1\r\n[00:00:19.778] LOG -- rfcomm.c.409: rfcomm_channel_create for service 0x3ffd1628, channel 1 --- list of channels:\r\n[00:00:19.785] LOG -- rfcomm.c.1802: -> Inform app\r\n[00:00:19.789] LOG -- rfcomm.c.151: RFCOMM_EVENT_INCOMING_CONNECTION addr 48:C1:AC:C3:4F:70 channel #1 cid 0x01\r\n[00:00:19.799] LOG -- hsp_ag.c.651: RFCOMM channel 1 requested for 48:C1:AC:C3:4F:70\r\n[00:00:19.807] LOG -- rfcomm.c.2360: RFCOMM_ACCEPT_CONNECTION cid 0x01\r\n[00:00:19.813] LOG -- rfcomm.c.1830: Sending UIH Parameter Negotiation Respond for #2\r\n[00:00:19.821] LOG -- rfcomm.c.1623: rfcomm_channel_ready_for_incoming_dlc_setup state var 0003\r\n[00:00:19.838] LOG -- rfcomm.c.1452: Received SABM #2\r\n[00:00:19.839] LOG -- rfcomm.c.1834: Sending UA #2\r\n[00:00:19.839] LOG -- rfcomm.c.1623: rfcomm_channel_ready_for_incoming_dlc_setup state var 000b\r\n[00:00:19.847] LOG -- rfcomm.c.1839: Incomping setup done, requesting send MSC CMD and send Credits\r\n[00:00:19.855] LOG -- rfcomm.c.1505: Received MSC CMD for #2, \r\n[00:00:19.861] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, flags needed 0020, current 1c1b, rf credits 1\r\n[00:00:19.872] LOG -- rfcomm.c.1762: Sending MSC RSP for #2\r\n[00:00:19.877] LOG -- rfcomm.c.1925: Sending MSC CMD for #2\r\n[00:00:19.882] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, flags needed 0020, current 701b, rf credits 1\r\n[00:00:19.893] LOG -- rfcomm.c.1512: Received MSC RSP for #2\r\n[00:00:19.898] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, flags needed 0020, current 703b, rf credits 1\r\n[00:00:19.909] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 2, now 3\r\n[00:00:19.916] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, flags needed 0020, current 703b, rf credits 3\r\n[00:00:19.927] LOG -- rfcomm.c.1932: Providing credits for #2\r\n[00:00:19.932] LOG -- rfcomm.c.1615: rfcomm_channel_ready_for_open state 8, flags needed 0020, current e03b, rf credits 3\r\n[00:00:19.943] LOG -- rfcomm.c.1266: rfcomm_channel_opened!\r\n[00:00:19.948] LOG -- rfcomm.c.169: RFCOMM_EVENT_CHANNEL_OPENED status 0x0 addr 48:C1:AC:C3:4F:70 handle 0x80 channel #1 cid 0x01 mtu 884\r\n[00:00:19.960] LOG -- hsp_ag.c.657: RFCOMM_EVENT_CHANNEL_OPENED packet_handler type 4, packet[0] 80\r\n[00:00:19.969] LOG -- hsp_ag.c.668: RFCOMM channel open succeeded. New RFCOMM Channel ID 1, max frame size 884, state 3\r\nRFCOMM connection established.\r\nReceived speaker gain change 8\r\n[00:00:19.998] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 1, now 3\r\nReceived microphone gain change 15\r\n[00:00:20.008] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 1, now 3\r\n[00:00:23.570] LOG -- hsp_ag.c.551: Received button press AT+CKPD=200\r\n[00:00:23.596] LOG -- rfcomm.c.1302: RFCOMM data UIH_PF, new credits: 1, now 3\r\n[00:00:23.597] LOG -- hci.c.2048: Synchronous Connection Complete (status=26) 48:C1:AC:C3:4F:70\r\n[00:00:23.600] LOG -- hsp_ag.c.602: (e)SCO Connection failed, status 26\r\nAudio connection establishment failed with status 26\r\n"}}
{"actor":{"display_login":"sapthas"}}