Bug #118077
IOVDEV-29253【VC1】【0095】【台架】【EE环境】【副屏】【蓝牙】副屏蓝牙播放音乐暂停，蓝牙耳机连接后，偶现音乐自动播放
| Status: | CLOSED | Start date: | 2023-05-18 | |
|---|---|---|---|---|
| Priority: | Normal | Due date: | ||
| Assignee: | 物联网测试组_CDTS 唐霞 | % Done: | 0% | |
| Category: | LC | |||
| Target version: | - | |||
| Need_Info: | -- | Found Version: | 01.00.0095.c103 | |
| Resolution: | -- | Degrated: | -- | |
| Severity: | Normal | Verified Version: | ||
| Reproducibility: | Occasionally | Fixed Version: | ||
| Test Type: | User Experience | Root cause: |
Description
环境信息】EE环境
【问题出现时间】：20230518 19：05
【前提条件】：副屏上电，QQ音乐播放暂停
【操作步骤】
1.点击开启副屏蓝牙，
2.点击蓝牙耳机设备名称进行配对
【实际结果】
1.副屏蓝牙与蓝牙耳机连接成功后，音乐自动播放
【期望结果】
1.副屏蓝牙与蓝牙耳机连接成功后，音乐不会自动播放
【备注】：
第131次开机
偶现事件，10次大概1、2次左右
日志、视频地址：https://ofs.human-horizons.com/#/download/index/nODJE9sBWH0%3D
中控VIN号：HRYTTESTVINMGM817
【中控版本号】：03.02.0080.c101
【副屏版本号】：01.00.0095.c103
History
#1 Updated by CD APP-王营 about 2 years ago
- Category changed from CD-APP to CD-FW
#2 Updated by CD FW 曹覃刚 about 2 years ago
- Status changed from New to ASSIGNED
- Assignee changed from CD FW 曹覃刚 to CD FW王武军
#3 Updated by CD FW王武军 about 2 years ago
【】当前状态
1、分析日志
从测试提供的日志文件，如：
000131_manual_00040_230518_190234.log
000131_manual_00010_230518_185550.log
000131_manual_00016_230518_185746.log等
获取到了如下的一些日志：
05-18 19:02:35.237 21614 21641 I BluetoothAvrcpControllerJni: btavrcp_connection_state_callback: conn state: rc: 1 br: 0
05-18 19:02:35.237 21614 21641 D AvrcpControllerService: onConnectionStateChanged true false34:9F:F4:45:0F:AA
05-18 19:02:35.267 1503 1792 D BluetoothA2dp: getCodecStatus(34:9F:F4:45:0F:AA)
05-18 19:02:35.267 21614 21646 D BluetoothActiveDeviceManager: handleMessage(MESSAGE_A2DP_ACTION_ACTIVE_DEVICE_CHANGED): device= 34:9F:F4:45:0F:AA
05-18 19:02:35.267 21614 21646 D BluetoothActiveDeviceManager: set mA2dpActiveDevice to 34:9F:F4:45:0F:AA
05-18 19:02:35.324 1855 1855 V MediaRouter: Audio routes updated: AudioRoutesInfo{ type=SPEAKER, bluetoothName=i12 }, a2dp=true
05-18 19:02:35.324 1855 1855 V MediaRouter: Selecting route: RouteInfo{ name=i12, description=蓝牙音频, status=null, category=RouteCategory{ name=系统 types=ROUTE_TYPE_LIVE_AUDIO ROUTE_TYPE_LIVE_VIDEO groupable=false }, supportedTypes=ROUTE_TYPE_LIVE_AUDIO , presentationDisplay=null }
05-18 19:02:35.325 17420 17420 V MediaRouter: Audio routes updated: AudioRoutesInfo{ type=SPEAKER, bluetoothName=i12 }, a2dp=true
05-18 19:02:35.325 17420 17420 V MediaRouter: Selecting route: RouteInfo{ name=i12, description=蓝牙音频, status=null, category=RouteCategory{ name=系统 types=ROUTE_TYPE_LIVE_AUDIO ROUTE_TYPE_LIVE_VIDEO groupable=false }, supportedTypes=ROUTE_TYPE_LIVE_AUDIO , presentationDisplay=null }
05-18 19:02:35.325 1855 1855 I MediaRouter: Skip setBluetoothA2dpOn(): types=1, isPlaybackActive()=false, BT route=RouteInfo{ name=i12, description=蓝牙音频, status=null, category=RouteCategory{ name=系统 types=ROUTE_TYPE_LIVE_AUDIO ROUTE_TYPE_LIVE_VIDEO groupable=false }, supportedTypes=ROUTE_TYPE_LIVE_AUDIO , presentationDisplay=null }
05-18 19:02:35.325 17420 17420 I MediaRouter: Skip setBluetoothA2dpOn(): types=1, isPlaybackActive()=false, BT route=RouteInfo{ name=i12, description=蓝牙音频, status=null, category=RouteCategory{ name=系统 types=ROUTE_TYPE_LIVE_AUDIO ROUTE_TYPE_LIVE_VIDEO groupable=false }, supportedTypes=ROUTE_TYPE_LIVE_AUDIO , presentationDisplay=null }
05-18 19:02:35.328 21614 21646 D BluetoothActiveDeviceManager: onAudioDevicesAdded
05-18 19:02:35.328 21614 21646 D BluetoothActiveDeviceManager: Audio device added: i12 type: 8
05-18 19:02:37.216 813 21666 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
05-18 19:02:37.216 813 21666 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK ON
05-18 19:02:37.216 813 21666 D vendor.qti.bluetooth@1.0-wake_lock: Acquire wakelock is acquired
05-18 19:02:37.216 813 21666 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Writing IBS_WAKE_ACK
05-18 19:02:37.220 813 813 I vendor.qti.bluetooth@1.0-ibs_handler: DeviceWakeUp: Writing IBS_WAKE_IND
05-18 19:02:37.220 813 21666 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_WAKE_ACK: 0xFC
05-18 19:02:37.220 813 21666 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Signal wack_cond_
05-18 19:02:37.221 813 813 D vendor.qti.bluetooth@1.0-ibs_handler: DeviceWakeUp: Unblocked from waiting for FC, pthread_cond_timedwait ret = 0
05-18 19:02:37.221 21614 21641 D Avrcp_ext: Enter handlePassthroughCmdRequestFromNative
05-18 19:02:37.221 21614 21641 D Avrcp_ext: Exit handlePassthroughCmdRequestFromNative
05-18 19:02:37.221 21614 21678 V Avrcp_ext: AvrcpMessageHandler: received message=13
05-18 19:02:37.221 21614 21678 V Avrcp_ext: MSG_NATIVE_REQ_PASS_THROUGH: id = 68 st = 1
05-18 19:02:37.222 21614 21678 V Avrcp_ext: MSG_NATIVE_REQ_PASS_THROUGH 34:9F:F4:45:0F:AA
05-18 19:02:37.222 21614 21678 I Avrcp_ext: device found at index 0
05-18 19:02:37.222 21614 21678 D Avrcp_ext: passthrough from device: 34:9F:F4:45:0F:AA
05-18 19:02:37.222 21614 21678 I Avrcp_ext: A2dpSupported true AvrcpSupported true
05-18 19:02:37.224 21614 21678 D Avrcp_ext: Active device: 34:9F:F4:45:0F:AA
05-18 19:02:37.225 21614 21678 I Avrcp_ext: A2dpSupported true AvrcpSupported true
05-18 19:02:37.225 21614 21678 D Avrcp_ext: ignore_play: false
05-18 19:02:37.225 21614 21678 D Avrcp_ext: Avrcp current play state: 2 isMusicActive: false A2dp state: 11 Cached passthrough command: 0
05-18 19:02:37.226 21614 21678 D BATService: getBATService(): service is NULL
05-18 19:02:37.226 21614 21678 D Avrcp_ext: cached passthrough: 0current passthrough: 126
05-18 19:02:37.227 1503 14059 D MediaSessionService: Sending KeyEvent { action=ACTION_DOWN, keyCode=KEYCODE_MEDIA_PLAY, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=0, downTime=0, deviceId=-1, source=0x0, displayId=0 } to com.tencent.qqmusic/QQMusicMediaSession (userId=0)
05-18 19:02:37.227 1503 14059 D MediaSessionService: tempAllowlistTargetPkgIfPossible callingPackage:com.android.bluetooth targetPackage:com.tencent.qqmusic reason:action=ACTION_DOWN;code=KEYCODE_MEDIA_PLAY
05-18 19:02:37.243 1503 14009 I MediaFocusControl: requestAudioFocus() from uid/pid 10095/20074 AA=USAGE_MEDIA/CONTENT_TYPE_MUSIC clientId=android.media.AudioManager@7393723com.tencent.qqmusicplayerprocess.servicenew.listener.AudioFocusListener$a@a3b5420 callingPack=com.tencent.qqmusic req=1 flags=0x0 sdk=29大致分析出如下信息：
蓝牙连接状态：根据 btavrcp_connection_state_callback 的日志，蓝牙 AVRCP 控制器的连接状态被回调为已建立。
A2DP 设备变化：通过 BluetoothA2dp 和 BluetoothActiveDeviceManager 的日志，可以看到 A2DP 设备状态的改变。当蓝牙设备 34:9F:F4:45:0F:AA 成为活动设备时，音频路由被选择到了蓝牙设备上。
媒体会话服务：MediaSessionService 的日志显示了按下播放键的事件，并将腾讯音乐播放器添加到了临时白名单中。
事件顺序大致是：蓝牙设备连接建立 -> A2DP 设备变为活动设备 -> 媒体会话服务发送播放键事件给腾讯音乐播放器。
可以看出是蓝牙模块发送了KeyEvent，从而触发了音频焦点，触发了音乐的播放，为什么在蓝牙连接成功之后，会有概率发送KEYCODE_MEDIA_PLAY
的KeyEvent，这个需要蓝牙模块的同事进行分析。
【】下一步策略
从fw的角度，结合测试的视屏和日志以及测试的步骤，大致分析了整个流程：
从蓝牙连接的方面，蓝牙是正常连接的；音乐播放的方面，audio是在收到焦点请求之后，开始了播放，
而发生问题时，大概是蓝牙设备发送了播放的事件，导致音乐播放，所以需要从蓝牙设备的角度来继续分析下该问题的发生原因。
@LC 请LC的同事，陶洪普跟进调查下该问题，谢谢。（日志文件可以找测试提供）
#4 Updated by CD FW王武军 about 2 years ago
- Category changed from CD-FW to LC
- Assignee changed from CD FW王武军 to CD LC 陶洪普
#5 Updated by CD LC涂宇 about 2 years ago
- Category changed from LC to AUDIO-FW
- Assignee changed from CD LC 陶洪普 to Multimedia组-RD3_TSCD 梁卿山
Hi MM team，
根据以上日志分析，keyevent由MediaSessionService发送，请确认是否是正常行为。
05-18 19:02:37.227 1503 14059 D MediaSessionService: Sending KeyEvent { action=ACTION_DOWN, keyCode=KEYCODE_MEDIA_PLAY, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=0, downTime=0, deviceId=-1, source=0x0, displayId=0 } to com.tencent.qqmusic/QQMusicMediaSession (userId=0)
Thanks
#6 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
- Assignee changed from Multimedia组-RD3_TSCD 梁卿山 to CD LC涂宇
HI 涂宇
当前分析：
000131_manual_00016_230518_185746.log
我们对比了正常的蓝牙按键时间触发音乐播放，发现和以下日志一样，
MediaSessionService是收到了蓝牙的按键事件才触发的keyevent，
1014:05-18 19:02:37.319 21614 21678 I Avrcp_ext: A2dpSupported true AvrcpSupported true
1015:05-18 19:02:37.319 21614 21678 D Avrcp_ext: ignore_play: false
1017:05-18 19:02:37.319 21614 21678 D Avrcp_ext: Avrcp current play state: 2 isMusicActive: true A2dp state: 11 Cached passthrough command: 126
1025:05-18 19:02:37.319 21614 21641 D bt_btif : btif_av_state_opened_handler: event: UNKNOWN_EVENT, flags: 0, peer_sep: 1, index: 0 reconfig_event: 0, codec_cfg_change: 0, reconfig_pending: 0, reconfig_a2dp: 0, is_retry_reconfig: 0
1026:05-18 19:02:37.319 21614 21641 W bt_btif : btif_av_state_opened_handler : unhandled event:UNKNOWN_EVENT
1028:05-18 19:02:37.319 21614 21641 D bt_btif : btif_av_state_opened_handler: event: BTIF_AV_START_STREAM_REQ_EVT, flags: 0, peer_sep: 1, index: 0 reconfig_event: 0, codec_cfg_change: 0, reconfig_pending: 0, reconfig_a2dp: 0, is_retry_reconfig: 0
1030:05-18 19:02:37.319 21614 21668 D bt_btif : bta_av_ssm_execute(): AV Sevent(0x41)=0x120b(AP_START) state=3(OPEN)
1034:05-18 19:02:37.319 21614 21668 W bt_btif : bta_dm_rm_cback:1, status:7
1035:05-18 19:02:37.319 21614 21668 W bt_btif : new conn_srvc id:18, app_id:0
1036:05-18 19:02:37.319 21614 21668 W bt_btif : bta_dm_pm_cback: new conn_srvc id:18, app_id:0 count:3
1037:05-18 19:02:37.320 21614 21678 D Avrcp_ext: cached passthrough: 126current passthrough: 126
1040:05-18 19:02:37.320 1503 14009 D MediaSessionService: Sending KeyEvent { action=ACTION_UP, keyCode=KEYCODE_MEDIA_PLAY, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=0, downTime=0, deviceId=-1, source=0x0, displayId=0 } to com.tencent.qqmusic/QQMusicMediaSession (userId=0)
下一步
请继续调查蓝牙连接时，是否发送了按键事件。
#7 Updated by Multimedia组-RD3_TSCD 梁卿山 about 2 years ago
- Category changed from AUDIO-FW to LC
- Assignee changed from CD LC涂宇 to CD LC 陶洪普
#8 Updated by CD LC 陶洪普 about 2 years ago
Hi
从日志看，有接收到耳机设备传输的passthrough command，对端行为．
05-18 19:02:37.222 21614 21678 V Avrcp_ext: MSG_NATIVE_REQ_PASS_THROUGH 34:9F:F4:45:0F:AA
05-18 19:02:37.222 21614 21678 I Avrcp_ext: device found at index 0
05-18 19:02:37.222 21614 21678 D Avrcp_ext: passthrough from device: 34:9F:F4:45:0F:AA
05-18 19:02:37.222 21614 21678 I Avrcp_ext: A2dpSupported true AvrcpSupported true
05-18 19:02:37.224 21614 21678 D Avrcp_ext: Active device: 34:9F:F4:45:0F:AA
请确认该耳机型号，在其他对比机上测试结果．
谢谢！
#9 Updated by CD LC 陶洪普 about 2 years ago
- Status changed from ASSIGNED to NEED_INFO
- Assignee changed from CD LC 陶洪普 to 物联网测试组_CDTS 唐霞
#10 Updated by CDTS-TEST 周婷 about 2 years ago
洪普 请继续分析日志，请在日志分析确认是否收到耳机的播放指令
#11 Updated by CD TEST-方永红 about 2 years ago
- Status changed from NEED_INFO to ASSIGNED
- Assignee changed from 物联网测试组_CDTS 唐霞 to CD LC 陶洪普
#12 Updated by CD LC 陶洪普 about 2 years ago
- Status changed from ASSIGNED to NEED_INFO
- Assignee changed from CD LC 陶洪普 to 物联网测试组_CDTS 唐霞
Hi
如上分析，在连接耳机后，收到了passthrough command，进而播放了音乐．
05-18 19:02:37.222 21614 21678 D Avrcp_ext: passthrough from device: 34:9F:F4:45:0F:AA
05-18 19:02:37.222 21614 21678 I Avrcp_ext: A2dpSupported true AvrcpSupported true
05-18 19:02:37.224 21614 21678 D Avrcp_ext: Active device: 34:9F:F4:45:0F:AA
该现象是耳机侧行为．
请同步该信息给客户测试同事，谢谢！
#13 Updated by CDTS_Test 吴诗雨 about 2 years ago
已同步
#14 Updated by CDTS_TEST 王成 about 2 years ago
- Status changed from NEED_INFO to RESOLVED
在连接耳机后，收到了passthrough command，进而播放了音乐．
05-18 19:02:37.222 21614 21678 D Avrcp_ext: passthrough from device: 34:9F:F4:45:0F:AA
05-18 19:02:37.222 21614 21678 I Avrcp_ext: A2dpSupported true AvrcpSupported true
05-18 19:02:37.224 21614 21678 D Avrcp_ext: Active device: 34:9F:F4:45:0F:AA
该现象是耳机侧行为．
#15 Updated by CDTS_TEST 王成 about 2 years ago
- Status changed from RESOLVED to VERIFIED
#16 Updated by CDTS_TEST 王成 about 2 years ago
- Status changed from VERIFIED to CLOSED