Figure

Hi 唐霞

从复现的日志来看，该问题发生时，获取焦点超时，导致了不能播放视频。
该问题仅发生在，重启后的三秒内播放视频。

详细分析如下：
05-11 10:47:18.135 1394 1937 D AudioIDCMicroNegotiator: idcm_common:onConnectStateChange: 1
05-11 10:47:18.135 1394 1937 D AudioIDCMicroNegotiator: idcm_volume:syncIDCMicroAudioVolume device fist start
05-11 10:47:18.135 1394 1937 D AudioIDCMicroNegotiator: idcm_volume:getIDCMicroVolume
05-11 10:47:18.135 1394 1937 D AudioIDCMicroNegotiator: idcm_common:requestResult method = getVolume parameters = {"functionInfo":{"IDCM_VolumeValue_Media":"MEDIA"}}
05-11 10:47:45.508 4014 4014 W AudioManager: See the documentation of requestAudioFocus() for what to use instead with android.media.AudioAttributes to qualify your playback use case
05-11 10:47:45.510 1394 3014 I MediaFocusControl: requestAudioFocus() from uid/pid 10071/4014 AA=USAGE_MEDIA/CONTENT_TYPE_MUSIC clientId=android.media.AudioManager@44ddb25com.android.gallery3d.app.MoviePlayer$6@189c4fa callingPack=com.android.gallery3d req=1 flags=0x0 sdk=29
05-11 10:47:45.567 1394 2593 D AudioService.PlaybackActivityMonitor: idcm_af:requestAudioFocusToIDCM: event=2(PLAYER_STATE_STARTED)apc =AudioPlaybackConfiguration piid:159 deviceId:0 type:android.media.MediaPlayer u/pid:10071/4014 state:idle attr:AudioAttributes: usage=USAGE_MEDIA content=CONTENT_TYPE_MOVIE flags=0x800 tags= bundle=null sessionId:0 ★★★ 申请焦点
05-11 10:47:45.568 1394 2593 D AudioIDCMicroNegotiator: idcm_af:requestIDCMicroAudioFocus, streamtype = 3
05-11 10:47:45.568 1394 2593 D AudioIDCMicroNegotiator: idcm_af:requestIDCMicroAudioFocus: AudioFocus_Media
05-11 10:47:45.568 1394 2593 D AudioIDCMicroNegotiator: idcm_common:requestResult method = requestAudioFocus parameters = {"functionInfo":{"IDCM_AudioFocus":"AudioFocus_Media"}}
05-11 10:47:45.568 1394 2593 I MicroServiceManager: requestResult(requestAudioFocus) parameters is{"functionInfo":{"IDCM_AudioFocus":"AudioFocus_Media"}}.
05-11 10:47:45.568 1394 2593 D AudioIDCMicroNegotiator: idcm_af:updateAudioInfo
05-11 10:47:45.568 1394 2593 D AudioIDCMicroNegotiator: idcm_af:obtainFocusState
05-11 10:47:45.571 1394 1937 D AudioIDCMicroNegotiator: idcm_volume:getIDCMicroAudioMute
05-11 10:47:45.571 1394 1937 D AudioIDCMicroNegotiator: idcm_common:requestResult method = isMute parameters = {"functionInfo":{"IDCM_VolumeMute_Media":"WHOLE_VEHICLE"}}

05-11 10:47:45.611 2124 4071 I MicroService: onResponse(requestAudioFocus): {"functionInfo":{"IDCM_AudioFocus":"AudioFocus_Media","IDCM_AudioFocus_Result":"AUDIOFOCUS_REQUEST_GRANTED"}} ★★★ 中控回复焦点结果
05-11 10:47:46.169 1394 2593 W AudioIDCMicroNegotiator: idcm_warn: timeout for obtainFocusState: RequestInfosToIDCM{mPid=4014, mUid=10071} ★★★ 焦点机制判断焦点获取超时
05-11 10:47:46.169 1394 2593 D AudioIDCMicroNegotiator: idcm_af:notifyFocusState -> notify
05-11 10:47:46.169 1394 2593 D AudioIDCMicroNegotiator: idcm_af:obtainFocusState, return: 0 mIsTimeout= true time= 601
05-11 10:47:46.169 1394 2593 D AudioService.PlaybackActivityMonitor: idcm_af:requestAudioFocusToIDCM -> stopPlayer: 159 ★★★ 停止视频播放
05-11 10:47:46.169 1394 1857 D AudioIDCMicroNegotiator: idcm_af:wait messsage done -> onAudioFocusRemoteChanged
05-11 10:47:46.169 1394 2593 D AudioService.PlaybackActivityMonitor: idcm_af:stopPlayer apc= AudioPlaybackConfiguration piid:159 deviceId:0 type:android.media.MediaPlayer u/pid:10071/4014 state:idle attr:AudioAttributes: usage=USAGE_MEDIA content=CONTENT_TYPE_MOVIE flags=0x800 tags= bundle=null sessionId:0 ★★★ 视频停止播放

下一步
超时的原因是微服务没有及时分发消息给焦点控制，所以导致焦点超时

05-18 19:42:54.880 1201 1713 I MicroServiceManager: requestResult(requestAudioFocus) parameters is{"functionInfo":{"IDCM_AudioFocus":"AudioFocus_Media"}}.
05-18 19:42:54.880 1201 1713 D AudioIDCMicroNegotiator: idcm_af:updateAudioInfo
05-18 19:42:54.880 1201 1713 D AudioIDCMicroNegotiator: idcm_af:obtainFocusState
05-18 19:42:54.881 1964 2005 E MicroService: Client is not connected.
05-18 19:42:54.881 1964 2005 E MicroService: Client is not connected.
05-18 19:42:54.890 1964 2096 E MicroService: DTC_ETH: BaseMicroSocketClient:createClientSocket()
05-18 19:42:54.890 1964 2096 E MicroService: java.net.NoRouteToHostException: Host unreachable
05-18 19:42:54.890 1964 2096 E MicroService: at libcore.io.IoBridge.connect(IoBridge.java:183)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.PlainSocketImpl.socketConnect(PlainSocketImpl.java:142)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:390)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:230)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:212)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:436)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.Socket.connect(Socket.java:621)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.Socket.connect(Socket.java:570)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.Socket.<init>(Socket.java:450)
05-18 19:42:54.890 1964 2096 E MicroService: at java.net.Socket.<init>(Socket.java:292)
05-18 19:42:54.890 1964 2096 E MicroService: at com.thundercomm.microservice.base.BaseMicroSocketClient.createClientSocket(BaseMicroSocketClient.java:20)
05-18 19:42:54.890 1964 2096 E MicroService: at com.thundercomm.microservice.MicroSocketClient.serialSendMessage(MicroSocketClient.java:79)
05-18 19:42:54.890 1964 2096 E MicroService: at com.thundercomm.microservice.MicroSocketClient.lambda$handShark$1$MicroSocketClient(MicroSocketClient.java:94)
05-18 19:42:54.890 1964 2096 E MicroService: at com.thundercomm.microservice.MicroSocketClient$$ExternalSyntheticLambda0.run(Unknown Source:4)
05-18 19:42:54.890 1964 2096 E MicroService: at java.lang.Thread.run(Thread.java:920)
05-18 19:42:55.480 1201 1713 W AudioIDCMicroNegotiator: idcm_warn: timeout for obtainFocusState: RequestInfosToIDCM{mPid=4953, mUid=10072}
05-18 19:42:55.480 1201 1713 D AudioIDCMicroNegotiator: idcm_af:notifyFocusState -> notify
05-18 19:42:55.481 1201 1713 D AudioIDCMicroNegotiator: idcm_af:obtainFocusState, return: 0 mIsTimeout= tr
根据日志分析，开机刚启动时网络环境未创建完成，无法中控进行通信，导致获取焦点失败

HI ALL

该问题由其他原因导致，在开机时创建mediaplayer后，设置数据资源时报错。
根据流程查看，都是在获取根据URI获取fd时报错导致。

26201:06-08 11:10:52.546  1546  4547 I MediaFocusControl: abandonAudioFocus() from uid/pid 10065/5210 clientId=android.media.AudioManager@7c02012
26403:06-08 11:10:53.005  1926  2870 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:79 deviceId:0 type:android.media.MediaPlayer u/pid:10065/5210 state:idle attr:AudioAttributes: usage=USAGE_UNKNOWN content=CONTENT_TYPE_UNKNOWN flags=0x800 tags= bundle=null sessionId:41
26411:06-08 11:10:53.014  5210  5210 D MediaPlayer: attemptDataSource exception return false: java.io.IOException: Failed to instantiate extractor.
26413:06-08 11:10:53.015  1206  2703 E MediaPlayerService: Couldn't open fd for content://media/external/video/media/796
26414:06-08 11:10:53.015  5210  5210 E MediaPlayerNative: Unable to create media player
26415:06-08 11:10:53.015  5210  5210 W VideoView: Unable to open content: content://media/external/video/media/796
26416:06-08 11:10:53.015  5210  5210 W VideoView: java.io.IOException: setDataSource failed.: status=0x80000000
26417:06-08 11:10:53.015  5210  5210 W VideoView:     at android.media.MediaPlayer.nativeSetDataSource(Native Method)
26418:06-08 11:10:53.015  5210  5210 W VideoView:     at android.media.MediaPlayer.setDataSource(MediaPlayer.java:1210)
26419:06-08 11:10:53.015  5210  5210 W VideoView:     at android.media.MediaPlayer.setDataSource(MediaPlayer.java:1197)
26420:06-08 11:10:53.015  5210  5210 W VideoView:     at android.media.MediaPlayer.setDataSource(MediaPlayer.java:1102)
26421:06-08 11:10:53.015  5210  5210 W VideoView:     at android.media.MediaPlayer.setDataSource(MediaPlayer.java:1123)
26422:06-08 11:10:53.015  5210  5210 W VideoView:     at android.widget.VideoView.openVideo(VideoView.java:412)
26423:06-08 11:10:53.015  5210  5210 W VideoView:     at android.widget.VideoView.access$2200(VideoView.java:83)
26424:06-08 11:10:53.015  5210  5210 W VideoView:     at android.widget.VideoView$7.surfaceCreated(VideoView.java:694)
26425:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.SurfaceView.updateSurface(SurfaceView.java:1204)
26426:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.SurfaceView.setWindowStopped(SurfaceView.java:312)
26427:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.SurfaceView.surfaceCreated(SurfaceView.java:1840)
26428:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.ViewRootImpl.notifySurfaceCreated(ViewRootImpl.java:1935)
26429:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:3208)
26430:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:2146)
26431:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:8676)
26432:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.Choreographer$CallbackRecord.run(Choreographer.java:1120)
26433:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.Choreographer.doCallbacks(Choreographer.java:926)
26434:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.Choreographer.doFrame(Choreographer.java:859)
26435:06-08 11:10:53.015  5210  5210 W VideoView:     at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:1105)
26436:06-08 11:10:53.015  5210  5210 W VideoView:     at android.os.Handler.handleCallback(Handler.java:938)
26437:06-08 11:10:53.015  5210  5210 W VideoView:     at android.os.Handler.dispatchMessage(Handler.java:99)
26438:06-08 11:10:53.015  5210  5210 W VideoView:     at android.os.Looper.loopOnce(Looper.java:201)
26439:06-08 11:10:53.015  5210  5210 W VideoView:     at android.os.Looper.loop(Looper.java:288)
26440:06-08 11:10:53.015  5210  5210 W VideoView:     at android.app.ActivityThread.main(ActivityThread.java:7880)
26441:06-08 11:10:53.015  5210  5210 W VideoView:     at java.lang.reflect.Method.invoke(Native Method)
26442:06-08 11:10:53.015  5210  5210 W VideoView:     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
26443:06-08 11:10:53.015  5210  5210 W VideoView:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)
26444:06-08 11:10:53.015  5210  5210 D VideoView: Error: 1,0

998          int fd = android::openContentProviderFile(url16); ★★★
999          if (fd < 0)
1000          {
1001              ALOGE("Couldn't open fd for %s", url);
1002              return UNKNOWN_ERROR;
1003          }

27  int openContentProviderFile(const String16& uri)
28  {
29      int fd = -1;
30  
31      sp<IServiceManager> sm = defaultServiceManager();
32      sp<IBinder> binder = sm->getService(String16("activity"));
33      sp<IActivityManager> am = interface_cast<IActivityManager>(binder);
34      if (am != NULL) {
35          fd = am->openContentUri(uri); ★★★
36      }
37  
38      return fd;
39  }

38      virtual int openContentUri(const String16& stringUri)
39      {
40          Parcel data, reply;
41          data.writeInterfaceToken(IActivityManager::getInterfaceDescriptor());
42          data.writeString16(stringUri);
43          status_t ret = remote()->transact(OPEN_CONTENT_URI_TRANSACTION, data, & reply);
44          int fd = -1;
45          if (ret == NO_ERROR) {
46              int32_t exceptionCode = reply.readExceptionCode();
47              if (!exceptionCode) {
48                  // Success is indicated here by a nonzero int followed by the fd;
49                  // failure by a zero int with no data following.
50                  if (reply.readInt32() != 0) {
51                      fd = fcntl(reply.readParcelFileDescriptor(), F_DUPFD_CLOEXEC, 0); ★★★
52                  }
53              } else {
54                  // An exception was thrown back; fall through to return failure
55                  ALOGD("openContentUri(%s) caught exception %d\n",
56                          String8(stringUri).string(), exceptionCode);
57              }
58          }
59          return fd;
60      }

下一步：
需要AF组来调查一下为什么获取文件描述符出错。

HI ALL

进一步调查发现，当问题复现时，该视频文件已经出现问题，
拿到电脑端也无法播放，
所以该问题可能是关机时导致视频文件出现了问题。

当前复现步骤：
1.录制屏幕一段时间
2.使用图库播放该视频
3.下电
4.重启后使用图库播放该视频。

在视频录制完成后，手动sync后，不会再出现该问题。
该问题是异常下电导致数据未能完全保存到设备导致。