휴일 아침 유튜브를 보고 있는데 갑자기 화면이 멈추는 증상이 발생하였습니다. 엥 무슨일이지... 일어나서 로그를 남겨서 분석해 보았습니다.
로그를 남기는 방법은 단말 제조사 마다 다르기 때문에 여기에서는 언급 하지 않겠습니다. 일반적으로 adb가 연결가능한 상황이면 adb bugreport > 파일명 형태를 사용하면 됩니다.
단말기 : 삼성 SM-G930 (갤럭시 S7)
운영체제 : android 8.0 O OS
1. 문제의 시점을 알아야 하기때문에 event log를 확인합니다.
아래와 같이 표기되는 부분입니다.------ EVENT LOG (logcat -b events -v threadtime -v printable -v uid -d *:v) ------
그중 on_resume으로 검색해서 android activity의 실행 과정을 보고 언제쯤 문제가 발생한것인지 시각대를 확인합니다.
Line 137043: 09-26 07:27:39.634 10066 5121 5121 I am_on_resume_called: [0,com.sec.android.app.launcher.activities.LauncherActivity,RESUME_ACTIVITY] Line 137144: 09-26 07:27:58.968 10160 5194 5194 I am_on_resume_called: [0,com.google.android.apps.youtube.app.WatchWhileActivity,RESUME_ACTIVITY] Line 138868: 09-26 07:59:09.868 10160 5194 5194 I am_on_resume_called: [0,com.google.android.apps.youtube.app.WatchWhileActivity,RESUME_ACTIVITY] Line 139427: 09-26 08:05:44.199 10066 5121 5121 I am_on_resume_called: [0,com.sec.android.app.launcher.activities.LauncherActivity,RESUME_ACTIVITY]
해당 시각 근처 로그를 확인 해 봤습니다.
09-26 08:05:39.041 1000 3646 3665 I am_proc_start: [0,13615,10415,com.roidus.iblugpartial,service,com.roidus.iblugpartial/.service.MediaService] 09-26 08:05:39.131 1000 3646 18226 I am_proc_bound: [0,13615,com.roidus.iblugpartial] 09-26 08:05:39.326 1000 3646 3646 I power_partial_wake_state: [1,*alarm*:android] 09-26 08:05:39.393 1000 3646 3664 I am_pss : [13186,10015,com.google.android.gms.unstable,36718592,24051712,187392] 09-26 08:05:39.956 1000 3646 4342 I am_uid_running: 99310 09-26 08:05:39.988 1000 3646 4342 I am_proc_start: [0,13667,99310,com.android.chrome:sandboxed_process0,webview_service,com.roidus.iblugpartial/org.chromium.content.app.SandboxedProcessService0] 09-26 08:05:40.125 1000 3646 4342 I am_proc_bound: [0,13667,com.android.chrome:sandboxed_process0] 09-26 08:05:40.751 1000 3646 3646 I notification_cancel: [10415,13615,com.roidus.iblugpartial,10436,NULL,0,0,1088,8,NULL] 09-26 08:05:43.558 1000 3646 4342 I power_partial_wake_state: [3010,AudioMix:audioserver] 09-26 08:05:43.645 1000 3646 4342 I power_partial_wake_state: [2878,AudioMix:audioserver] 09-26 08:05:43.984 1000 3646 3788 I am_new_intent: [0,45004642,23983,com.sec.android.app.launcher/.activities.LauncherActivity,android.intent.action.MAIN,NULL,NULL,276824320,NULL] 09-26 08:05:43.986 1000 3646 3788 I wm_task_moved: [23983,1,0] 09-26 08:05:43.987 1000 3646 3788 I am_focused_stack: [0,0,1,bringingFoundTaskToFront] 09-26 08:05:43.988 1000 3646 3788 I wm_task_moved: [23983,1,0] 09-26 08:05:43.989 1000 3646 3788 I am_pause_activity: [0,34765044,com.google.android.youtube/com.google.android.apps.youtube.app.WatchWhileActivity] 09-26 08:05:43.990 1000 3646 3788 I am_task_to_front: [0,23983] 09-26 08:05:43.993 10160 5194 5194 I am_on_paused_called: [0,com.google.android.apps.youtube.app.WatchWhileActivity,handlePauseActivity] 09-26 08:05:44.007 1000 3646 4342 I am_set_resumed_activity: [0,com.sec.android.app.launcher/.activities.LauncherActivity,resumeTopActivityInnerLocked] 09-26 08:05:44.088 1000 3646 4342 I am_resume_activity: [0,45004642,23983,com.sec.android.app.launcher/.activities.LauncherActivity] 09-26 08:05:44.108 1000 3646 3665 I sysui_count: [window_time_0,394] 09-26 08:05:44.109 1000 3646 3665 I sysui_multi_action: [757,803,799,window_time_0,802,394] 09-26 08:05:44.109 1000 3646 3665 I am_uid_running: 10157 09-26 08:05:44.140 1000 3646 3665 I am_proc_start: [0,13742,10157,com.sec.android.daemonapp,broadcast,com.sec.android.daemonapp/.appwidget.WeatherAppWidget2x1] 09-26 08:05:44.185 1000 3646 3664 I am_pss : [13594,10010378,com.sds.BizAppLauncher,6145024,4603904,205824]
해당 시간에 생성된 process 정보들은 am_proc_start 로그를 보면 됩니다. intent나 service를 받아서 실행됩니다.
2. 이제 main log를 확인 합니다.
09-26 08:05:40.436 10415 13615 13686 W cr_media: Requires BLUETOOTH permission 09-26 08:05:40.544 10415 13615 13615 I MediaPlayer: Need to enable context aware info 09-26 08:05:40.544 10415 13615 13615 V MediaPlayer-JNI: native_setup 09-26 08:05:40.545 10415 13615 13615 V MediaPlayerNative: constructor 09-26 08:05:40.547 10415 13615 13615 V MediaPlayerNative: setListener 09-26 08:05:40.554 root 3322 3631 D DnsProxyListener: DNSDBG::dns addrinfo af 2 09-26 08:05:40.562 10415 13615 13615 W AudioManager: Use of stream types is deprecated for operations other than volume control 09-26 08:05:40.562 10415 13615 13615 W AudioManager: See the documentation of requestAudioFocus() for what to use instead with android.media.AudioAttributes to qualify your playback use case 09-26 08:05:40.565 1000 3646 4342 I MediaFocusControl: AudioFocus requestAudioFocus() from uid/pid 10415/13615 clientId=android.media.AudioManager$f9594c3com.roidus.iblugpartial.service.MediaService$7$7d5f140 req=1 flags=0x0
AudioFocus requestAudioFocus() 로그가 보입니다.
om.roidus.iblugpartial 앱에서 audio를 요청하고 있습니다.
3. 범인은 하나야
DUMP OF SERVICE audio: MediaFocusControl dump time: 오전 8:07:15 Audio Focus stack entries (last is top of stack): MultiFocusStack: size:3 device:2 ------------------------------ device = 0 source:android.os.BinderProxy@7c0403 -- pack: com.google.android.youtube -- client: android.media.AudioManager$8076d7aacpa$4e0f92b -- gain: GAIN -- flags: -- loss: LOSS -- notified: true -- uid: 10160 -- device: 0 -- attr: AudioAttributes: usage=1 content=2 flags=0x0 tags= bundle=null -- sdk:26 source:android.os.BinderProxy@b58cf80 -- pack: com.roidus.iblugpartial -- client: android.media.AudioManager$f9594c3com.roidus.iblugpartial.service.MediaService$7$7d5f140 -- gain: GAIN -- flags: -- loss: none -- notified: true -- uid: 10415 -- device: 0 -- attr: AudioAttributes: usage=1 content=2 flags=0x0 tags= bundle=null -- sdk:23 ------------------------------ device = 2 ------------------------------ device = 80 ------------------------------
DUMP OF SERVICE audio 로그를 확인하면 audio focus가 요청되어진것을 알 수 있습니다.
사건의 중심에 있는 앱은 com.roidus.iblugpartial 앱입니다. 영어 공부하는 앱인데....
로그 확인한봐로는 해당 앱이 kill 되었다가 (안드로이드에서는 background에 있는 앱들이 죽는 경우가 많이 있습니다.) 살아나면서 문제가 발생하고 있습니다. 추가 분석을 하려면 해당 앱에서 깨어난 사유 와 그리고 audio사용을 요청하는데 정상적인 상황인것인지 확인이 필요합니다.
주로 사용하는 앱이라 삭제 하지 말고 현상태로 사용 해야 할 것 같습니다.
댓글 없음:
댓글 쓰기