hfp connection doesn't establish for pbap

[pravverma]

Hi,

We are connecting our custom device(IMX6q based) to car entertainment system to transfer the phone book contacts over Bluetooth PBAP.

It seems that before transferring the contacts, our device expects the HFP connection to establish with car entertainment & there it fails.

We tested the car entertainment device with nexus 4 phone, there PBAP is woking fine & HFP connection is also established.

We found that in logcat of nexus4, Event 0x0508 is received & after that connection state is successfully changing from 1 --> 2.

D/bt-btif ( 8981): bta_ag_hdl_event: p_scb 0xa2a8bf4c

D/bt-btif ( 8981): AG evt (hdl 0x0001): State 1, Event 0x0508

W/bt-l2cap( 8981): L2CA_SetDesireRole() new:x0, disallow_switch:0

W/bt-btif ( 8981): new conn_srvc id:5, app_id:0

W/bt-btif ( 8981): new conn_srvc id:5, app_id:0 count:1

W/bt-btif ( 8981): bta_dm_pm_ssr conn_srvc id:5, app_id:0

W/bt-btif ( 8981): bta_dm_pm_ssr:2, lat:1200

D/bt-btif ( 8981): btif_hf_upstreams_evt: event=BTA_AG_OPEN_EVT

I/BluetoothHeadsetServiceJni( 8981): connection_state_callback

D/HeadsetStateMachine( 8981): Pending process message: 101, size: 0

D/HeadsetStateMachine( 8981): event type: 1

D/bt-btif ( 8981): BTA ag sco evt (hdl 0xffff): State 0, Event 0

D/bt-btif ( 8981): ag create sco: orig 0, inx 0x0000, status 0x1, pkt types 0x038f

D/bt-btif ( 8981): BTA AG SCO State Change: [0] -> [1] after Event [0]

D/bt-btif ( 8981): BTA AG State Change: [1] -> [2]

D/HeadsetStateMachine( 8981): remove connect timeout for device = 00:07:04:B4:83:E1

D/HeadsetStateMachine( 8981): processConnectionEvent state = 2, device = 00:07:04:B4:83:E1

D/HeadsetStateMachine( 8981): device 00:07:04:B4:83:E1 is added in Pending state

D/HeadsetStateMachine( 8981): Connection state 00:07:04:B4:83:E1: 1->2

But in our device, We are not receiving event 0x0508 when we paired with car entertainment device.

Please let us know our understanding regarding issue is correct? How does event pass in bluedroid from application? Do we need to explicitly send this event from application or this is a implicit event?

To test the HFP alone, we connected our custom device with samsung bluetooth headset.

In that case we see that event 0x0508 is received & connection is successfully established between our device & bluetooth headset.

D/bt-sdp  (  958): SDP_FindServiceInDb - p_sattr value = 0x1108 serviceuuid = 0x1131

D/bt-sdp  (  958): SDP_FindServiceInDb - p_sattr value = 0x1203 serviceuuid = 0x1131

D/bt-sdp  (  958): SDP_FindServiceInDb - p_sattr value = 0x1108 serviceuuid = 0x1108

I/bt-btif (  958): AG evt (hdl 0x0001): State 1, Event 0x0510

I/bt-btm  (  958): BTM_SEC_REG[3]: id 12, is_orig 1, psm 0x0003, proto_id 3, chan_id 1

I/bt-btm  (  958):                : sec: 0x30b6, service name [] (up to 21 chars saved)

D/bt-rfcomm(  958): port_find_mcb: not found, bd_addr:80:57:19:8a:b4:0d

I/bt-rfcomm(  958): RFCOMM_CreateConnection()  BDA: 80-57-19-8a-b4-0d

I/bt-rfcomm(  958): RFCOMM_CreateConnection(): scn:1, dlci:2, is_server:0 mtu:256, p_mcb:0x0

D/bt-rfcomm(  958): rfc_cb.port.port[5]:0x655fb8d8 allocated, last_port:5

D/bt-rfcomm(  958): port_allocate_port:bd_addr:80:57:19:8a:b4:0d

I/bt-rfcomm(  958): RFCOMM_CreateConnection(): scn:1, dlci:2, is_server:0 mtu:256, p_mcb:0x0, p_port:0x655fb8d8

I/bt-rfcomm(  958): RFCOMM_CreateConnection dlci:2 signal state:0xb

I/bt-rfcomm(  958): port_open_continue, p_port:0x655fb8d8

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel: bd_addr:80:57:19:8a:b4:0d

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel:is_initiator:1

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[0].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[1].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[2].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[3].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[4].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[5].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[6].state:0

D/bt-rfcomm(  958): (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00

D/bt-rfcomm(  958): rfc_alloc_multiplexer_channel:is_initiator:1, create new p_mcb:0x655fca6c, index:0

I/bt-rfcomm(  958): rfc_timer_start - timeout:60

D/bt-rfcomm(  958): port_select_mtu application selected 256

D/bt-rfcomm(  958): port_select_mtu credit_rx_max 10, credit_rx_low 4, rx_buf_critical 15

I/bt-rfcomm(  958): rfc_mx_sm_state_idle - evt:6

I/bt-l2cap(  958): L2CA_ErtmConnectReq()  PSM: 0x0003  BDA: 8057198ab40d  p_ertm_info: 0x00000000 allowed:0x0 preferred:0

D/bt-l2cap(  958): l2cu_allocate_ccb: cid 0x0000

D/bt-l2cap(  958): l2cu_enqueue_ccb CID: 0x0042  priority: 2

D/bt-l2cap(  958): l2c_link_adjust_chnl_allocation

D/bt-l2cap(  958): POOL ID:3, GKI_poolcount = 200, reserved_buff = 0, weighted_chnls = 2, quota_per_weighted_chnls = 101

I/bt-l2cap(  958): CID:0x0042 Priority:2 TxDataRate:1 Quota:101

I/bt-l2cap(  958): L2CAP - LCID: 0x0042  st: CLOSED  evt: UPPER_LAYER_CONNECT_REQ

I/bt-btm  (  958): BTM_SetPowerMode: pm_id 128 BDA: 198ab40d mode:0x0

D/bt-btm  (  958): BTM_SetPowerMode: mode:0x0 interval 0 max:0, min:0

D/bt-btm  (  958): btm_sec_l2cap_access_req is_originator:1, 0x655f7ea8

I/bt-btm  (  958): btm_find_or_alloc_dev

D/bt-btm  (  958): btm_sec_find_mx_serv

D/bt-btm  (  958): btm_sec_check_upgrade...

D/bt-btm  (  958): btm_sec_is_upgrade_possible id:12, link_key_typet:4, rmt_io_caps:0, chk flags:x2000, flags:x30b6

D/bt-btm  (  958): btm_sec_is_upgrade_possible is_possible:0 sec_flags:0x9e

I/bt-btm  (  958): Security Manager: mx_access_req proto_id:3 chan_id:1 State:0 Flags:0x9e Required:0x30b6 Service ID:12

I/bt-btm  (  958): btm_sec_execute_procedure: Required:0x30b6 Flags:0x9e State:0

I/bt-btm  (  958): Security Manager: trusted:0x00000000

I/bt-btm  (  958): Security Manager: access granted

I/bt-l2cap(  958): L2CA_DataWrite()  CID: 0x0042  Len: 4

I/bt-l2cap(  958): L2CAP - LCID: 0x0042  st: OPEN  evt: UPPER_LAYER_DATA_WRITE

D/bt-l2cap(  958): RR scan pri=2, lcid=0x0042, q_cout=1

D/bt-l2cap(  958): RR service pri=2, quota=4, lcid=0x0042

D/bt-l2cap(  958): TotalWin=7,Hndl=0xc,Quota=8,Unack=1,RRQuota=0,RRUnack=0

D/bt-l2cap(  958): RR scan pri=2, lcid=0x0042, q_cout=0

I/bt-rfcomm(  958): rfc_port_timer_start - timeout:60

D/AlarmScheduler( 1134): No events found starting within 1 week.

I/bt-l2cap(  958): L2CAP - LCID: 0x0042  st: OPEN  evt: PEER_DATA

I/bt-rfcomm(  958): rfc_port_timer_stop

I/bt-rfcomm(  958): PORT_DlcEstablishCnf dlci:2 mtu:1685 result:0

I/bt-rfcomm(  958): rfc_timer_stop

D/bt-btif (  958): ag_mgmt_cback : code = 0, port_handle = 6, handle = 1

I/bt-l2cap(  958): L2CA_DataWrite()  CID: 0x0042  Len: 8

I/bt-l2cap(  958): L2CAP - LCID: 0x0042  st: OPEN  evt: UPPER_LAYER_DATA_WRITE

D/bt-l2cap(  958): RR scan pri=2, lcid=0x0042, q_cout=1

D/bt-l2cap(  958): RR service pri=2, quota=4, lcid=0x0042

D/bt-l2cap(  958): TotalWin=6,Hndl=0xc,Quota=8,Unack=2,RRQuota=0,RRUnack=0

D/bt-l2cap(  958): RR scan pri=2, lcid=0x0042, q_cout=0

I/bt-rfcomm(  958): rfc_port_timer_start - timeout:20

I/bt-btif (  958): BTA got event 0x508

D/bt-btif (  958): bta_ag_hdl_event: Event 0x0508

D/bt-btif (  958): bta_ag_hdl_event: p_scb 0x65603ee0

I/bt-btif (  958): AG evt (hdl 0x0001): State 1, Event 0x0508

D/bt-btif (  958): bta_ag_co_data_open handle:1 service:5

I/bt-l2cap(  958): L2CA_SetDesireRole() new:x1, disallow_switch:0

D/bt-btif (  958): bta_dm_pm_cback: st(0), id(5), app(0)

W/bt-btif (  958): new conn_srvc id:5, app_id:0

W/bt-btif (  958): bta_dm_pm_ssr conn_srvc id:5, app_id:0

W/bt-btif (  958): bta_dm_pm_ssr:2, lat:1200

D/bt-btif (  958): bta_dm_pm_set_mode: srvcsid: 5, state: 0, j: 1

D/bt-btif (  958): start dm_pm_timer:0, 5000

D/bt-btif (  958): btif_transfer_context event 2, len 12

D/bt-btif (  958): btif_transfer_context event 4, len 14

D/bt-btif (  958): BTA ag sco evt (hdl 0xffff):

I/bt-btif (  958): BTA ag sco evt (hdl 0xffff): State 0, Event 0

D/bt-btif (  958): ag create sco: orig 0

I/bt-btif (  958): btif_hf_upstreams_evt: event=BTA_AG_OPEN_EVT

D/bt-btif (  958): btif_hf_upstreams_evt: event=BTA_AG_OPEN_EVT

I/bt-btif (  958): HAL bt_hf_callbacks->connection_state_cb

I/BluetoothHeadsetServiceJni(  958): connection_state_callback

D/bt-l2cap(  958): RR scan pri=2, lcid=0x0042, q_cout=0

D/bt-l2cap(  958): TotalWin=8,LinkUnack(0xc)=0,RRCheck=0,RRUnack=0

D/bt-btif (  958): HC lib lpm deassertion return 0

D/bt-btif (  958): HC lib lpm deassertion return 0

D/bt-btif (  958): btif task fetched event a001

D/bt-btif (  958): btif_context_switched

D/bt-btif (  958): btif_hf_upstreams_evt: event=BTA_AG_CONN_EVT

D/bt-btif (  958): btif_hf_upstreams_evt: BTA_AG_CONN_EVT, idx = 0

I/bt-btif (  958): HAL bt_hf_callbacks->connection_state_cb

I/BluetoothHeadsetServiceJni(  958): connection_state_callback

D/HeadsetStateMachine(  958): Pending process message: 101, size: 0

D/HeadsetStateMachine(  958): event type: 1

D/HeadsetStateMachine(  958): getDeviceForMessage: returning mTargetDevice for what=201

D/HeadsetStateMachine(  958): remove connect timeout for device = 80:57:19:8A:B4:0D

D/HeadsetStateMachine(  958): hfp 1. processConnectionEvent state = 2, device = 80:57:19:8A:B4:0D

Please help us to debug the problem. Why we are not getting event 0x0508 when we connect our custom device with car entertainment system?

Thanks.

Praveen