问题现象

去掉蓝牙鼠标“输入设备”功能后,重新勾选“输入设备”后,蓝牙一直处于“正在连接”状态

复现概率

必现

复现步骤

  1. 开机
  2. 打开蓝牙
  3. 搜索蓝牙鼠标
  4. 连接蓝牙鼠标
  5. 连接成功后,正常使用鼠标
  6. 取消“输入设备”功能
  7. 移动鼠标多次
  8. 打开“输入设备”功能
  9. 观察

测试现象

  1. 执行第七步时,移动鼠标,还可以看见鼠标指针在屏幕上闪动,闪动几秒后鼠标不动或消失
  2. 执行第八步时,鼠标一直处于“正在连接”状态,不恢复。
  3. 如果取消第七步,第八步效果正常。

问题分析

  1. 第一次连接蓝牙鼠标后,GATT发起SDP扫描,Android建立gatt_conn_id = 1的channel。完成discovery后,该channel一直存在,没有关闭
  2. 取消“输入设备”功能,GATT断开conn_id=4后,判断当前app是否有hold更多的channel,发现conn_id=1仍在使用,故不disconnect整个链路。
  3. 移动鼠标,由于链路没有断开,协议栈收到鼠标发送的gatt notification。协议栈自动处理,发现该设备依然存在,状态为disconnect。协议栈自动open并init connection。GATT状态正常后,上报至Framework。上层通过判断,发现用户手动取消输入设备功能,所以拒绝本次请求,发送reject。此时输入设备驱动已经add,所以在reject完成之前所收到的GATT包就正常传递到驱动处理。所以屏幕还上能看到鼠标移动或晃动。
  4. Reject完成后,设备再次进入close状态。这时又收到gatt notification,又将重复之前自动重连的操作,由于驱动多次add和remove,协议栈hid设备状态将异常停止在Connected,并不再处理数据上报。此时上层认为设备未连接,驱动认为节点未生成,协议栈认为设备状态已连接。
  5. 重新打开“输入设备”功能,Framework发起connect请求,协议栈接受到init conn请求,但由于协议栈正处于connected状态,对init connect操作为空(ignore)。所以忽略本次请求。
  6. 上层界面邮局发送了connect,变处于connection状态,没有收到stack的回复,便一直处于connection,不能回复。

问题解决方案

该问题再商用7.0上有做对比,依然存在。如果需要修改,可以参照Android M设计。AndroidM在搜索完成后,或异常情况下,都会主动释放掉对应的channel。如果本次测试中,连接完成后就释放掉conn_id=1的channel。那么取消“输入设备”后,APP就不再hold住任何channel,stack便会主动disconnect掉链路。链路disconnect后便不再接受notification,也就没有后面协议栈状态异常问题。

问题思考

本次问题的根本原因还是协议栈状态异常,解决方案只是一种workaround。但是就算解决了协议栈状态异常问题,根据Android N的策略,不让链路断开,那么就会出现,取消“输入设备”功能后,移动鼠标,界面一样有反应,反应为鼠标晃动,停止,晃动不停的重复。因为协议栈一直会不停的重连,应用不停的拒绝。

Log记录

取消“输入设备”:

01-02 06:15:56.352  3489  3489 D BluetoothInputDevice: disconnect(E6:71:40:79:75:FD)
01-02 06:15:56.364  4729  4729 I bt_btif : BTHH: disconnect
01-02 06:15:56.364  4729  4750 I bt_btif : btif_hh_handle_evt: event=1
01-02 06:15:56.364  4729  4750 I bt_btif : btif_hh_handle_evt: event=1
01-02 06:15:56.364  4729  4761 I bt_btif : BTA got event 0x1701
01-02 06:15:56.364  4729  4761 D bt_btif : bta_hh_dev_handle_to_cb_idx dev_handle = 16 index = 0
01-02 06:15:56.364  4729  4761 D bt_btif : bta_hh_hdl_event:: handle = 16 dev_cb[0] 
01-02 06:15:56.364  4729  4761 I bt_btif : bta_hh_sm_execute: State 0x03 [BTA_HH_CONN_ST], Event [BTA_HH_API_CLOSE_EVT]
01-02 06:15:56.364  4729  4761 I bt_btif : BTA got event 0x1f08
01-02 06:15:56.364  4729  4761 D bt_btif : bta_gattc_hdl_event: Event [BTA_GATTC_API_CLOSE_EVT]
01-02 06:15:56.364  4729  4761 D bt_btif : bta_gattc_sm_execute: State 0x02 [GATTC_CONN_ST], Event 0x1f08[BTA_GATTC_API_CLOSE_EVT]
01-02 06:15:56.364  4729  4761 D bt_btif : bta_gattc_close conn_id=4
01-02 06:15:56.364  4729  4761 I bt_att  : GATT_Disconnect conn_id=4 
01-02 06:15:56.364  4729  4761 D bt_att  : gatt_update_app_use_link_flag  is_add=0 chk_link=1
01-02 06:15:56.364  4729  4761 D bt_att  : gatt_update_app_hold_link_status found=1[1-found] idx=2 gatt_if=4 is_add=0
01-02 06:15:56.364  4729  4761 D bt_btm  : BTM_GetHCIConnHandle
01-02 06:15:56.364  4729  4761 D bt_btm  : btm_bda_to_acl found
01-02 06:15:56.364  4729  4761 D bt_att  : gatt_num_apps_hold_link   num=1
01-02 06:15:56.364  4729  4761 D bt_btif : bta_hh_gattc_callback event = 5
01-02 06:15:56.364  4729  4761 D bt_btif : GATTC State Change: [GATTC_CONN_ST] -> [GATTC_IDLE_ST] after Event [BTA_GATTC_API_CLOSE_EVT]
01-02 06:15:56.365  4729  4761 I bt_btif : BTA got event 0x1f02
01-02 06:15:56.365  4729  4761 D bt_btif : bta_gattc_hdl_event: Event [BTA_GATTC_API_CANCEL_OPEN_EVT]

移动鼠标,自动重连:

01-02 06:15:57.159  4729  4755 D bt_snoop_sprd: 22:15:57:159018 kAclPacket
01-02 06:15:57.159  4729  4755 D bt_snoop_sprd: record diff: 193
01-02 06:15:57.159  4729  4761 D bt_btm  : btm_bda_to_acl found
01-02 06:15:57.159  4729  4761 I bt_btm  : btm_find_or_alloc_dev
01-02 06:15:57.159  4729  4761 D bt_att  : gatt_get_ch_state: ch_state=4
01-02 06:15:57.159  4729  4761 D bt_att  : gatt_process_notification 
01-02 06:15:57.159  4729  4761 D bt_att  : gatt_get_link_encrypt_status status=0x8d
01-02 06:15:57.159  4729  4761 I bt_gap  : gap_ble_c_cmpl_cback() - op_code: 0x06  status: 0x8d  read_type: 0x0000
01-02 06:15:57.159  4729  4761 D bt_btif : bta_gattc_cmpl_cback: conn_id = 3 op = 6 status = 141
01-02 06:15:57.159  4729  4761 I bt_att  : GATT_GetConnectionInfor conn_id=3
01-02 06:15:57.159  4729  4761 D bt_btif : bta_gattc_cmpl_cback: conn_id = 4 op = 6 status = 141
01-02 06:15:57.159  4729  4761 I bt_att  : GATT_GetConnectionInfor conn_id=4
01-02 06:15:57.159  4729  4761 D bt_btif : Notification registered!
01-02 06:15:57.159  4729  4761 D bt_btif : bta_gattc_clcb_alloc: found clcb[0] available
01-02 06:15:57.159  4729  4761 D bt_btif : bta_gattc_sm_execute: State 0x00 [GATTC_IDLE_ST], Event 0x1f0d[BTA_GATTC_INT_CONN_EVT]
01-02 06:15:57.159  4729  4761 D bt_btif : bta_gattc_conn server cache state=0
01-02 06:15:57.159  4729  4761 D bt_btif : bta_hh_gattc_callback event = 2
01-02 06:15:57.159  4729  4761 I bt_btif : bta_hh_sm_execute: State 0x01 [BTA_HH_IDLE_ST], Event [BTA_HH_GATT_OPEN_EVT]
01-02 06:15:57.159  4729  4761 D bt_btif : bta_hh_gatt_open BTA_GATTC_OPEN_EVT bda= [e671407975fd] status =0
01-02 06:15:57.159  4729  4761 D bt_btif : hid_handle = 10 conn_id = 0004 cb_index = 0
01-02 06:15:57.159  4729  4761 I bt_btif : bta_hh_sm_execute: State 0x02 [BTA_HH_W4_CONN_ST], Event [BTA_HH_START_ENC_EVT]
01-02 06:15:57.159  4729  4761 I bt_btif : bta_hh_sm_execute: State 0x04 [BTA_HH_W4_SEC], Event [BTA_HH_ENC_CMPL_EVT]
01-02 06:15:57.160  4729  4761 I bt_btif : bta_hh_sm_execute: State 0x02 [BTA_HH_W4_CONN_ST], Event [BTA_HH_OPEN_CMPL_EVT]
01-02 06:15:57.160  4729  4761 W bt_btif : bta_hh_co_open: Found an existing device with the same handle dev_status = 2
01-02 06:15:57.160  4729  4761 W bt_btif : bta_hh_co_open:     bd_addr = [E6:71:40:79:75:]
01-02 06:15:57.160  4729  4761 W bt_btif : bta_hh_co_open:     attr_mask = 0x0000, sub_class = 0x00, app_id = 255
01-02 06:15:57.160  4729  4761 D bt_btif : bta_hh_co_open: uhid fd = 95

APP拒绝本次请求

01-02 06:15:57.165  4729  4729 D HidService: Incoming HID connection rejected
01-02 06:15:57.166  4729  4729 I bt_btif : BTHH: disconnect
01-02 06:15:57.313  4729  4750 I bt_btif : btif_hh_handle_evt: event=1
01-02 06:15:57.313  4729  4750 I bt_btif : btif_hh_handle_evt: event=1
01-02 06:15:57.313  4729  4761 I bt_btif : BTA got event 0x1701

正常情况下,应该不停的上报已连接,APP不停拒绝,但是协议栈出现异常,出现啥异常,不情况,太乱了。

就当一次总结吧,也不枉费这么多时间。