hfp client role implementation on kitkat

Question

Requirement is to have hfp client role on android device. So we backported hfp client role implementation available in Lollopop version. Except for the audio changes everything went smooth.

Now I am facing a problem where I am not able to dial/receive calls to other phones (Device as HFP client and any Smart phone as AG). I came across scenarios where call did not end properly.

I am listing all my observations down here-

1. if phone (acting as an AG), is jellybean then dialing/receiving calls is not a problem.

2. if phone (acting as an AG), is kitkat then dialing/receiving calls does not happen smoothly (like while dialing, hfp client device does not receive CALL_STATE_DIALING but rather gets CALL_STATE_ALERTING. Although call usually gets established but ending the call from device does not go well). Strangely if user disconnect the AG phone and connects again. Receiving/Dialing a number starts acting fine.

3. if phone (acting as an AG), is lollipop then dialing/receiving call acts similar as explained in #2, however this time disconnect/connect does not have any effect on the behavior.

Let me know if you need more information here on the issue.

Note- This is Dial case, logs are recorded till call is accepted. The difference is that I don't get android.bluetooth.headsetclient.profile.action.AG_CALL_CHANGED State: 2(CALL_STATE_DIALING) in non-working scenario

Edit: Just noticed that JellyBean works because it is bluez, problem lies in sdk which have bluedroid stack. Can someone please share some pointers which can help. Problem still persists. We are not getting ack for Dialing, Accept, and Terminate.

Not Working Case Log

D/BluetoothHeadsetClient( 2403): dial()
D/HeadsetClientStateMachine( 2189): Connected process message: 10
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/HeadsetClientStateMachine( 2189): Connected: addQueuedAction: 10
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): l2cu_allocate_ccb: cid 0x0000
D/bt-l2cap( 2189): l2cu_enqueue_ccb CID: 0x004f  priority: 2
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 4, quota_per_weighted_chnls = 51
D/bt-btm  ( 2189): BTM_SetPowerMode: mode:0x0 interval 0 max:0, min:0
D/bt-btm  ( 2189): btm_sec_l2cap_access_req is_originator:0, 0x54f825c8
D/bt-l2cap( 2189): l2c_link_sec_comp: 17, 0x54f825c8
D/bt-l2cap( 2189): ccb timer ticks: 2147483648
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): TotalWin=4,Hndl=0x100,Quota=6,Unack=2,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): TotalWin=5,LinkUnack(0x100)=1,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-btm  ( 2189): btm_bda_to_acl found
D/bt-btm  ( 2189): btm_get_max_packet_size
D/bt-l2cap( 2189): l2cu_adjust_out_mps use 0   Based on peer_cfg.fcr.mps: 0  packet_size: 1011
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 4, quota_per_weighted_chnls = 51
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=1
D/bt-l2cap( 2189): RR service pri=2, quota=4, lcid=0x004f
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-btif ( 2189): bta_hf_client_esco_connreq_cback 2
D/bt-btif ( 2189): bta_hf_client_sco_conn_rsp
D/bt-btif ( 2189): bta_hf_client_sco_conn_cback 0
D/bt-btif ( 2189): bta_hf_client_sco_conn_open
D/bt-btif ( 2189): bta_hf_client_sco_event state: 2 event: 4
D/bt-btif ( 2189): bta_dm_pm_cback: st(4), id(27), app(1)
D/bt-btm  ( 2189): BTM_SetPowerMode: mode:0x0 interval 0 max:31209, min:21738
D/HeadsetClientStateMachine( 2189): incomingStackEvent {type:EVENT_TYPE_AUDIO_STATE_CHANGED, value1:2, value2:0, value3:0, value4:0, string: "null", device:CC:FA:00:72:B7:D0}
D/HeadsetClientStateMachine( 2189): Connected process message: 100
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004f, q_cout=0
D/bt-l2cap( 2189): l2cu_release_ccb: cid 0x004f  in_use: 1
D/bt-l2cap( 2189): l2cu_dequeue_ccb  CID: 0x004f
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 2, quota_per_weighted_chnls = 101
D/bt-sdp  ( 2189): releasing SDP rsp_list
D/HeadsetClientStateMachine( 2189): Connected: event type: 2
D/HeadsetClientStateMachine( 2189): Connected: Audio state changed: CC:FA:00:72:B7:D0: 2
E/bt-rfcomm( 2189): PORT_DataInd, p_port:0x54f82d5c, p_data_co_callback is null
D/bt-btif ( 2189): bta_hf_client_at_parse offset: 0 len: 6
D/bt-btif ( 2189): bta_hf_client_check_at_complete 1
D/bt-btif ( 2189): bta_hf_client_at_parse_start
D/bt-btif ( 2189): bta_hf_client_handle_ok
D/bt-btif ( 2189): bta_hf_client_send_queued_at
E/bt-rfcomm( 2189): PORT_DataInd, p_port:0x54f82d5c, p_data_co_callback is null
D/bt-btif ( 2189): bta_hf_client_at_parse offset: 0 len: 14
D/bt-btif ( 2189): bta_hf_client_check_at_complete 1
D/bt-btif ( 2189): bta_hf_client_at_parse_start
D/bt-btif ( 2189): bta_hf_client_handle_ciev index: 2 value: 2
D/HeadsetClientStateMachine( 2189): bthf_companion case
D/HeadsetClientStateMachine( 2189): incomingStackEvent {type:EVENT_TYPE_CMD_RESULT, value1:0, value2:0, value3:0, value4:0, string: "null", device:null}
V/Avrcp   ( 2189): New genId = 4, clearing = 1
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/HeadsetClientStateMachine( 2189): setAudioMode Setting audio mode from 0 to 2
D/HeadsetClientStateMachine( 2189): incomingStackEvent {type:EVENT_TYPE_CALLSETUP, value1:2, value2:0, value3:0, value4:0, string: "null", device:null}
D/bt-l2cap( 2189): l2cu_allocate_ccb: cid 0x0000
D/bt-l2cap( 2189): l2cu_enqueue_ccb CID: 0x0040  priority: 2
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 4, quota_per_weighted_chnls = 51
D/bt-btm  ( 2189): BTM_SetPowerMode: mode:0x0 interval 0 max:0, min:0
D/bt-btm  ( 2189): btm_sec_l2cap_access_req is_originator:0, 0x54f81164
D/bt-btm  ( 2189): btm_sec_l2cap_access_req()  sm4:0x11, sec_flags:0xbe, security_required:0x1086 chk:1
D/bt-btm  ( 2189): no next_serv sm4:0x11, chk:1
D/bt-btm  ( 2189): (SM4 to SM4) btm_sec_l2cap_access_req rspd. authenticated: x2, enc: x4
D/bt-btm  ( 2189): btm_sec_check_upgrade...
D/bt-btm  ( 2189): btm_sec_is_upgrade_possible id:37, link_key_typet:5, rmt_io_caps:1, chk flags:x1000, flags:x1082
D/bt-btm  ( 2189): btm_sec_is_upgrade_possible is_possible:0 sec_flags:0xbe
D/bt-l2cap( 2189): l2c_link_sec_comp: 0, 0x54f81164
D/bt-l2cap( 2189): ccb timer ticks: 2147483648
D/bt-btm  ( 2189): btm_sec_mx_access_request is_originator:0
D/bt-btm  ( 2189): btm_sec_find_mx_serv
D/bt-btm  ( 2189): btm_sec_check_upgrade...
D/bt-btm  ( 2189): btm_sec_is_upgrade_possible id:37, link_key_typet:5, rmt_io_caps:1, chk flags:x1000, flags:x1082
D/bt-btm  ( 2189): btm_sec_is_upgrade_possible is_possible:0 sec_flags:0xbe
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): TotalWin=4,Hndl=0x100,Quota=6,Unack=2,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): TotalWin=5,LinkUnack(0x100)=1,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-btm  ( 2189): btm_bda_to_acl found
D/bt-btm  ( 2189): btm_get_max_packet_size
D/bt-l2cap( 2189): l2cu_adjust_out_mps use 0   Based on peer_cfg.fcr.mps: 0  packet_size: 1011
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 4, quota_per_weighted_chnls = 51
D/bt-l2cap( 2189): Update CCB list in logical link
D/bt-l2cap( 2189): l2cu_dequeue_ccb  CID: 0x0040
D/bt-l2cap( 2189): l2cu_enqueue_ccb CID: 0x0040  priority: 0
D/bt-btif ( 2189): CONN_IND is ACP:1
D/bt-btif ( 2189): conn_cback bd_addr:cc-fa-00-72-b7-d0
D/bt-btif ( 2189): bta_av_sig_chg event: 16
D/bt-btif ( 2189): conn_lcb: 0x0
E/bt-btif ( 2189): bta_av_rc_create ACP handle exist for shdl:0
D/bt-btif ( 2189): start sig timer 1
D/bt-btif ( 2189): Incoming L2CAP acquired, set state as incoming
D/bt-btif ( 2189): bta_av_sig_timer
D/bt-btif ( 2189): conn_lcb: 0x1
D/bt-btif ( 2189): btif_av_state_idle_handler event:BTA_AV_PENDING_EVT flags 0
D/bt-btif ( 2189): btif_av_state_idle_handler event:BTIF_SM_EXIT_EVT flags 0
D/bt-btif ( 2189): btif_av_state_opening_handler event:BTIF_SM_ENTER_EVT flags 0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=0, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/A2dpStateMachine( 2189): Disconnected process message: 101
I/A2dpStateMachine( 2189): Incoming A2DP accepted
D/A2dpStateMachine( 2189): Exit Disconnected: 101
D/A2dpStateMachine( 2189): Enter Pending: 101
D/bt-l2cap( 2189): RR scan pri=0, lcid=0x0040, q_cout=1
D/bt-l2cap( 2189): RR service pri=0, quota=14, lcid=0x0040
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=0, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/A2dpStateMachine( 2189): Connection state CC:FA:00:72:B7:D0: 0->1
D/bt-l2cap( 2189): RR scan pri=0, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/CachedBluetoothDevice( 1850): onProfileStateChanged: profile A2DP newProfileState 1
D/bt-btm  ( 2189): BTM_SetPowerMode: mode:0x0 interval 0 max:1, min:0
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=0, lcid=0x0040, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): l2cu_release_ccb: cid 0x0040  in_use: 1
D/bt-l2cap( 2189): l2cu_dequeue_ccb  CID: 0x0040
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 2, quota_per_weighted_chnls = 101
D/bt-btif ( 2189): scb hndl x41, role x0
D/bt-btif ( 2189): conn_cback bd_addr:cc-fa-00-72-b7-d0
D/bt-btif ( 2189): bta_av_sig_chg event: 17
D/bt-btif ( 2189): conn_lcb: 0x0
D/bt-btif ( 2189): conn_lcb: 0x0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/HeadsetClientStateMachine( 2189): hfp_enable=true
D/HeadsetClientStateMachine( 2189): mAudioWbs is false
D/HeadsetClientStateMachine( 2189): Setting sampling rate as 8000
D/HeadsetClientStateMachine( 2189): Audio state CC:FA:00:72:B7:D0: 1->2
D/HeadsetClientStateMachine( 2189): Enter AudioOn: 100
D/HeadsetClientStateMachine( 2189): AudioOn process message: 100
D/HeadsetClientStateMachine( 2189): AudioOn: event type: 16
D/HeadsetClientStateMachine( 2189): Connected process message: 100
D/HeadsetClientStateMachine( 2189): Connected: event type: 16
D/HeadsetClientStateMachine( 2189): EVENT_TYPE_CMD_RESULT 0
D/HeadsetClientStateMachine( 2189): Connected: command result: 0 queuedAction: 7
D/HeadsetClientStateMachine( 2189): AudioOn process message: 100
D/HeadsetClientStateMachine( 2189): AudioOn: event type: 10
D/HeadsetClientStateMachine( 2189): Connected process message: 100
D/HeadsetClientStateMachine( 2189): Connected: event type: 10
D/HeadsetClientStateMachine( 2189): updateCallSetupIndicator 2 0
D/HeadsetClientStateMachine( 2189): updateCallSetupIndicator 52
D/HeadsetClientStateMachine( 2189): AudioOn process message: 50
D/HeadsetClientStateMachine( 2189): Connected process message: 50
D/HeadsetClientStateMachine( 2189): queryCallsStart
D/HeadsetClientStateMachine( 2189): queryCallsStart clearPendingAction
D/HeadsetClientStateMachine( 2189): function clearPendingAction
D/bt-btif ( 2189): bta_hf_client_send_at_clcc
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=1
D/bt-l2cap( 2189): RR service pri=2, quota=4, lcid=0x004a
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/HeadsetClientStateMachine( 2189): queryCallsStart: queryCurrentCallsNative
D/HeadsetClientStateMachine( 2189): action3: 50
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
E/bt-rfcomm( 2189): PORT_DataInd, p_port:0x54f82d5c, p_data_co_callback is null
D/bt-btif ( 2189): bta_hf_client_at_parse offset: 0 len: 37
D/bt-btif ( 2189): bta_hf_client_check_at_complete 1
D/bt-btif ( 2189): bta_hf_client_at_parse_start
D/bt-btif ( 2189): bta_hf_client_handle_clcc idx: 1 dir: 0 status: 2 mode: 0 mpty: 0
D/bt-btif ( 2189): bta_hf_client_handle_clcc number: 9686811761  type: 129
D/HeadsetClientStateMachine( 2189): incoming StackEvent {type:EVENT_TYPE_CURRENT_CALLS, value1:1, value2:0, value3:2, value4:0, string: "9686811761", device:null}
D/HeadsetClientStateMachine( 2189): AudioOn process message: 100
D/HeadsetClientStateMachine( 2189): AudioOn: event type: 14
D/HeadsetClientStateMachine( 2189): Connected process message: 100
D/HeadsetClientStateMachine( 2189): Connected: event type: 14
D/HeadsetClientStateMachine( 2189): queryCallsUpdate: 1
E/bt-rfcomm( 2189): PORT_DataInd, p_port:0x54f82d5c, p_data_co_callback is null
D/bt-btif ( 2189): bta_hf_client_at_parse offset: 0 len: 6
D/bt-btif ( 2189): bta_hf_client_check_at_complete 1
D/bt-btif ( 2189): bta_hf_client_at_parse_start
D/bt-btif ( 2189): bta_hf_client_handle_ok
D/bt-btif ( 2189): bta_hf_client_send_queued_at
D/HeadsetClientStateMachine( 2189): incomingStackEvent {type:EVENT_TYPE_CMD_RESULT, value1:0, value2:0, value3:0, value4:0, string: "null", device:null}
D/HeadsetClientStateMachine( 2189): AudioOn process message: 100
D/HeadsetClientStateMachine( 2189): AudioOn: event type: 16
D/HeadsetClientStateMachine( 2189): Connected process message: 100
D/HeadsetClientStateMachine( 2189): Connected: event type: 16
D/HeadsetClientStateMachine( 2189): EVENT_TYPE_CMD_RESULT 0
D/HeadsetClientStateMachine( 2189): Connected: command result: 0 queuedAction: 10
D/HeadsetClientStateMachine( 2189): Line 1924: 10
E/bt-rfcomm( 2189): PORT_DataInd, p_port:0x54f82d5c, p_data_co_callback is null
D/bt-btif ( 2189): bta_hf_client_at_parse offset: 0 len: 14
D/bt-btif ( 2189): bta_hf_client_check_at_complete 1
D/bt-btif ( 2189): bta_hf_client_at_parse_start
D/bt-btif ( 2189): bta_hf_client_handle_ciev index: 2 value: 3
I/bt-btif ( 2189): HAL bt_hf_client_callbacks->callsetup_cb
D/HeadsetClientStateMachine( 2189): incomingStackEvent {type:EVENT_TYPE_CALLSETUP, value1:3, value2:0, value3:0, value4:0, string: "null", device:null}
D/HeadsetClientStateMachine( 2189): AudioOn process message: 100
D/HeadsetClientStateMachine( 2189): AudioOn: event type: 10
D/HeadsetClientStateMachine( 2189): Connected process message: 100
D/HeadsetClientStateMachine( 2189): Connected: event type: 10
D/HeadsetClientStateMachine( 2189): updateCallSetupIndicator 3 10
D/HeadsetClientStateMachine( 2189): updateCallSetupIndicator 50
D/HeadsetClientStateMachine( 2189): AudioOn process message: 50
D/HeadsetClientStateMachine( 2189): Connected process message: 50
D/HeadsetClientStateMachine( 2189): queryCallsStart
D/HeadsetClientStateMachine( 2189): queryCallsStart clearPendingAction
D/HeadsetClientStateMachine( 2189): function clearPendingAction
D/HeadsetClientStateMachine( 2189): queryCallsStart: mCallsUpdate != null
D/bt-btif ( 2189): bta_av_acp_sig_timer_cback, coll_mask = 0x03
D/bt-btif ( 2189): bta_av_do_disc_a2d use_rc: 1 rs:0, oc:0
D/bt-btm  ( 2189): BTM_GetRole
D/bt-btm  ( 2189): btm_bda_to_acl found
E/bt-btif ( 2189): bta_av_link_role_ok hndl:x41 role:0, conn_audio:x0, bits:2, features:x824b
D/bt-btif ( 2189): ok_continue: 1 wait:x0, q_tag: 0
D/bt-btif ( 2189): bta_av_save_addr r:1, s:1
D/bt-btif ( 2189): bta_dm_pm_cback: st(2), id(18), app(0)
D/bt-l2cap( 2189): l2cu_allocate_ccb: cid 0x0000
D/bt-l2cap( 2189): l2cu_enqueue_ccb CID: 0x0041  priority: 2
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 4, quota_per_weighted_chnls = 51
D/bt-btm  ( 2189): BTM_SetPowerMode: mode:0x0 interval 0 max:0, min:0
D/bt-btm  ( 2189): btm_sec_l2cap_access_req is_originator:1, 0x54f812c0
D/bt-l2cap( 2189): l2c_link_sec_comp: 17, 0x54f812c0
D/bt-l2cap( 2189): ccb timer ticks: 2147483648
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-btm  ( 2189): btm_bda_to_acl found
D/bt-btm  ( 2189): btm_get_max_packet_size
D/bt-l2cap( 2189): l2cu_adjust_out_mps use 0   Based on peer_cfg.fcr.mps: 0  packet_size: 1011
D/bt-l2cap( 2189): TotalWin=4,Hndl=0x100,Quota=6,Unack=2,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): TotalWin=5,LinkUnack(0x100)=1,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 4, quota_per_weighted_chnls = 51
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=1
D/bt-l2cap( 2189): RR service pri=2, quota=4, lcid=0x0041
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
W/bt-sdp  ( 2189): process_service_search_attr_rsp
D/bt-btm  ( 2189): BTM_SetPowerMode: mode:0x0 interval 0 max:8, min:0
D/bt-l2cap( 2189): TotalWin=5,Hndl=0x100,Quota=6,Unack=1,RRQuota=0,RRUnack=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x004a, q_cout=0
D/bt-l2cap( 2189): RR scan pri=2, lcid=0x0041, q_cout=0
D/bt-l2cap( 2189): TotalWin=6,LinkUnack(0x100)=0,RRCheck=0,RRUnack=0
D/bt-l2cap( 2189): l2cu_release_ccb: cid 0x0041  in_use: 1
D/bt-l2cap( 2189): l2cu_dequeue_ccb  CID: 0x0041
D/bt-l2cap( 2189): l2c_link_adjust_chnl_allocation
D/bt-l2cap( 2189): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 2, quota_per_weighted_chnls = 101
D/bt-sdp  ( 2189): releasing SDP rsp_list

Answer 1

I fixed it by upgrading Bluedroid to a newer version. In fact I think I had to backport a specific commit in Nougat Bluedroid back to Marshmallow. Heres the patch for my fix, although it may not work on your version of Bluedroid:

From 39eef6e4ab1f7313d21c93ee94c9d1655e60ddde Mon Sep 17 00:00:00 2001
From: Tyler <tyler@x>
Date: Tue, 06 Sep 2016 17:33:37 -0700
Subject: [PATCH] Headset client: Try to fix parsing errors with iPhone.

Manually patched certain changes from changes in 08337175a34a9694b0d175ca714de3fd8cb5d9ec: tag: android-cts-7.0_r1 tag: android-7.0.0_r1

---

diff --git a/bta/hf_client/bta_hf_client_at.c b/bta/hf_client/bta_hf_client_at.c
index 5674b91..65ff088 100644
--- a/bta/hf_client/bta_hf_client_at.c
+++ b/bta/hf_client/bta_hf_client_at.c
@@ -714,7 +714,7 @@

 static char *bta_hf_client_parse_cind_list(char *buffer)
 {
-    int offset;
+    int offset = 0;
     char name[129];
     UINT32 min, max;
     UINT32 index = 0;
@@ -723,6 +723,12 @@
     while ((res = sscanf(buffer, "(\"%128[^\"]\",(%u%*[-,]%u))%n", name, &min, &max, &offset)) > 2)
     {
         bta_hf_client_handle_cind_list_item(name, min, max, index);
+        if (offset == 0)
+        {
+            APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
+            return NULL;
+        }
+
         buffer += offset;
         index++;

@@ -830,13 +836,19 @@
 {
     UINT32 index, value;
     int res;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+CIEV:");

     res = sscanf(buffer, "%u,%u%n", &index, &value, &offset);
     if(res < 2)
     {
+        return NULL;
+    }
+
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
         return NULL;
     }

@@ -910,7 +922,7 @@
     char number[33];
     UINT32 type = 0;
     int res;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+CLIP:");

@@ -918,6 +930,12 @@
     res = sscanf(buffer, "\"%32[^\"]\",%u%n", number, &type, &offset);
     if(res < 2)
     {
+        return NULL;
+    }
+
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
         return NULL;
     }

@@ -938,7 +956,7 @@
     char number[33];
     UINT32 type = 0;
     int res ;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+CCWA:");

@@ -946,6 +964,12 @@
     res = sscanf(buffer, "\"%32[^\"]\",%u%n", number, &type, &offset);
     if(res < 2)
     {
+        return NULL;
+    }
+
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
         return NULL;
     }

@@ -965,7 +989,7 @@
     /* spec forces 16 chars max, plus \0 here */
     char opstr[17];
     int res;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+COPS:");

@@ -973,6 +997,12 @@
     res = sscanf(buffer, "%hhi,0,\"%16[^\"]\"%n", &mode, opstr, &offset);
     if(res < 2)
     {
+        return NULL;
+    }
+    /* Abort in case offset not set because of format error */
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
         return NULL;
     }

@@ -983,6 +1013,12 @@
     AT_CHECK_RN(buffer);

     bta_hf_client_handle_cops(opstr, mode);
+    // check for OK Response in end
+    AT_CHECK_EVENT(buffer, "OK");
+    AT_CHECK_RN(buffer);
+
+    bta_hf_client_handle_ok();
+
     return buffer;
 }

@@ -992,13 +1028,20 @@
     /* phone number is 32 chars plus one for \0*/
     char numstr[33];
     int res;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+BINP:");

     res = sscanf(buffer, "\"%32[^\"]\"\r\n%n", numstr, &offset);
     if(res < 1)
     {
+        return NULL;
+    }
+
+    /* Abort in case offset not set because of format error */
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
         return NULL;
     }

@@ -1010,6 +1053,13 @@
     AT_CHECK_RN(buffer);

     bta_hf_client_handle_binp(numstr);
+
+    // check for OK response in end
+    AT_CHECK_EVENT(buffer, "OK");
+    AT_CHECK_RN(buffer);
+
+    bta_hf_client_handle_ok();
+
     return buffer;
 }

@@ -1019,7 +1069,7 @@
     char numstr[33];     /* spec forces 32 chars, plus one for \0*/
     UINT16 type;
     int res;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+CLCC:");

@@ -1030,14 +1080,20 @@
         return NULL;
     }

+    /* Abort in case offset not set because of format error */
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
+        return NULL;
+    }
+
     buffer += offset;
+    offset = 0;

     /* check optional part */
     if (*buffer == ',')
     {
-        int res2;
-
-        res2 = sscanf(buffer, ",\"%32[^\"]\",%hu%n", numstr, &type, &offset);
+        int res2 = sscanf(buffer, ",\"%32[^\"]\",%hu%n", numstr, &type, &offset);
         if (res2 < 0)
         {
             return NULL;
@@ -1056,15 +1112,22 @@
             numstr[0] = '\0';
         }

-        if (res2 < 2)
+        if (res2 >= 2)
         {
-            return NULL;
-        }
+            res += res2;
+            /* Abort in case offset not set because of format error */
+            if (offset == 0)
+            {
+                APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
+               return NULL;
+           }

-        res += res2;
-        buffer += offset;
+           buffer += offset;
+       }
     }

+    /* Skip any remaing param,as they are not defined by BT HFP spec */
+    AT_SKIP_REST(buffer);
     AT_CHECK_RN(buffer);

     if(res > 6)
@@ -1078,6 +1141,11 @@
         bta_hf_client_handle_clcc(idx, dir, status, mode, mpty, NULL, 0);
     }

+    // check for OK response in end
+    AT_CHECK_EVENT(buffer, "OK");
+    AT_CHECK_RN(buffer);
+
+    bta_hf_client_handle_ok();
     return buffer;
 }

@@ -1087,7 +1155,7 @@
     UINT16 type;
     UINT16 service = 0; /* 0 in case this optional parameter is not being sent */
     int res;
-    int offset;
+    int offset = 0;

     AT_CHECK_EVENT(buffer, "+CNUM:");

@@ -1115,6 +1183,13 @@
         return NULL;
     }

+    /* Abort in case offset not set because of format error */
+    if (offset == 0)
+    {
+        APPL_TRACE_ERROR("%s: Format Error %s", __func__, buffer);
+        return NULL;
+    }
+
     buffer += offset;

     AT_CHECK_RN(buffer);
@@ -1132,6 +1207,12 @@
     }

     bta_hf_client_handle_cnum(numstr, type, service);
+
+    // check for OK response in end
+    AT_CHECK_EVENT(buffer, "OK");
+    AT_CHECK_RN(buffer);
+
+    bta_hf_client_handle_ok();
     return buffer;
 }

@@ -1459,6 +1540,11 @@
     APPL_TRACE_DEBUG("%s", __FUNCTION__);

     at_len = snprintf(buf, sizeof(buf), "AT+BRSF=%u\r", bta_hf_client_cb.scb.features);
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }

     bta_hf_client_send_at(BTA_HF_CLIENT_AT_BRSF , buf, at_len);
 }
@@ -1489,6 +1575,11 @@
     APPL_TRACE_DEBUG("%s", __FUNCTION__);

     at_len = snprintf(buf, sizeof(buf), "AT+BCS=%u\r", codec);
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }

     bta_hf_client_send_at(BTA_HF_CLIENT_AT_BCS, buf, at_len);
 }
@@ -1539,6 +1630,12 @@
         at_len = snprintf(buf, sizeof(buf), "AT+CHLD=%c%u\r", cmd, idx);
     else
         at_len = snprintf(buf, sizeof(buf), "AT+CHLD=%c\r", cmd);
+
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }

     bta_hf_client_send_at(BTA_HF_CLIENT_AT_CHLD, buf, at_len);
 }
@@ -1633,6 +1730,11 @@
     APPL_TRACE_DEBUG("%s", __FUNCTION__);

     at_len = snprintf(buf, sizeof(buf), "AT+VGS=%u\r", volume);
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }

     bta_hf_client_send_at(BTA_HF_CLIENT_AT_VGS, buf, at_len);
 }
@@ -1645,6 +1747,11 @@
     APPL_TRACE_DEBUG("%s", __FUNCTION__);

     at_len = snprintf(buf, sizeof(buf), "AT+VGM=%u\r", volume);
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }

     bta_hf_client_send_at(BTA_HF_CLIENT_AT_VGM, buf, at_len);
 }
@@ -1662,8 +1769,18 @@
         at_len = snprintf(buf, sizeof(buf), "ATD>%u;\r", memory);
     }

-    at_len = MIN(at_len, sizeof(buf));
+    if (at_len < 0) {
+        APPL_TRACE_ERROR("%s: error preparing ATD command", __func__);
+        return;
+    }

+    at_len = MIN((size_t)at_len, sizeof(buf));
+
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }
     bta_hf_client_send_at(BTA_HF_CLIENT_AT_ATD, buf, at_len);
 }

@@ -1716,6 +1833,12 @@
         at_len = snprintf(buf, sizeof(buf), "AT+BTRH=%u\r", val);
     }

+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }
+
     bta_hf_client_send_at(BTA_HF_CLIENT_AT_BTRH, buf, at_len);
 }

@@ -1727,6 +1850,12 @@
     APPL_TRACE_DEBUG("%s", __FUNCTION__);

     at_len = snprintf(buf, sizeof(buf), "AT+VTS=%c\r", code);
+
+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }

     bta_hf_client_send_at(BTA_HF_CLIENT_AT_VTS, buf, at_len);
 }
@@ -1779,6 +1908,12 @@

     at_len = snprintf(buf, sizeof(buf), "AT+BINP=%u\r", action);

+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }
+
     bta_hf_client_send_at(BTA_HF_CLIENT_AT_BINP, buf, at_len);
 }

@@ -1806,6 +1941,12 @@

     buf[at_len - 1] = '\r';

+    if (at_len < 0)
+    {
+        APPL_TRACE_ERROR("%s: AT command Framing error", __func__);
+        return;
+    }
+
     bta_hf_client_send_at(BTA_HF_CLIENT_AT_BIA, buf, at_len);
 }