记一次App异常kill分析处理

由于Android版本的迭代更新速度非常快，所以Android版本上的一些新功能可能会导致你以前OK的代码，会发生一些意想不到的的问题，今天这里所说的就是一次由于Android时间的设置改变然后导致App被异常kill的情况。我在这里只想说这个问题，开始的时候弄得我都要给整疯了，咋也找不出原因。

注意：该问题讲解是在Android版本7.xx

问题现象描述

最近测试开发组，反馈一个问题说在测试部App中调用时间设置接口先将时间设置到2000年，然后再将时间设置回当前时间，在这个过程中会出现测试App异常退出，被kill掉了。原来是以为Native错误或者是AndroidRuntime错误，可是这些都不是。然后测试部将问题提给固件组，然我们进行解决。下面就开始分析一下相关的解决步骤：

1.异常日志

12-31 23:59:59.467   578  1234 W CustomerManager/OsCustomerMade: ++++xxxtest setSpTime result = 0
12-31 23:59:59.468   578  1234 E AlarmManager: set time workaroud logd restart!!! oldMillis 1573460821291 millis 978278399289
12-31 23:59:59.468   578   668 V AlarmManager: Time changed notification from kernel; rebatching
12-31 23:59:59.468   578   668 V AlarmManager: remove(operation) changed bounds; rebatching
12-31 23:59:59.470  2515  2901 D xxxlog  : Java_xxx_util_OsXxxApi_SetTime result=0
12-31 23:59:59.470  2515  2901 E DBG     : RtcTest-> setTime after
12-31 23:59:59.470  2515  2901 E RtcTest : setTime after
12-31 23:59:59.469   578   668 V AlarmManager: remove(operation) changed bounds; rebatching
12-31 23:59:59.471   578   668 V AlarmManager: set(PendingIntent{5160c70: PendingIntentRecord{cd9be9 android broadcastIntent}}) : type=3 triggerAtTime=1811335 win=0 tElapsed=1815806 maxElapsed=1815806 interval=0 flags=0x1
12-31 23:59:59.472   578   668 D AlarmManagerService: set alarm to kernel: 1815.806000000, type=3
12-31 23:59:59.472   578   668 V AlarmManager: set(PendingIntent{c42906e: PendingIntentRecord{36d330f android broadcastIntent}}) : type=1 triggerAtTime=978278400000 win=0 tElapsed=1815806 maxElapsed=1815806 interval=0 flags=0x1
12-31 23:59:59.473   578   668 D BroadcastQueue: Add broadcast <BroadcastRecord{960b8da u-1 android.intent.action.TIME_SET}> into [parallel | background], pending size 0
12-31 23:59:59.473   578   668 D BroadcastQueue: Add broadcast <BroadcastRecord{91d510b u-1 android.intent.action.TIME_SET}> into [ordered | background], pending size 0
12-31 23:59:59.473   578   668 D BroadcastQueue: Header is BroadcastRecord{91d510b u-1 android.intent.action.TIME_SET} now
12-31 23:59:59.474   578   668 D AlarmManager: triggerList.size = 0, hasWakeup = false
12-31 23:59:59.475   578   578 D ConditionProviders.SCP: onReceive android.intent.action.TIME_SET
12-31 23:59:59.475   578   592 D BroadcastQueue: Done with parallel broadcast [background] [BroadcastRecord{960b8da u-1 android.intent.action.TIME_SET}]
12-31 23:59:59.476   578   578 D ConditionProviders.SCP: notifyCondition condition://android/schedule?days=6.7&start=23.30&end=10.0&exitAtAlarm=false STATE_FALSE reason=!meetsSchedule
12-31 23:59:59.475   765   765 D KeyguardUpdateMonitor: received broadcast android.intent.action.TIME_SET
12-31 23:59:59.476   765   951 D Clock   : onReceive action=android.intent.action.TIME_SET
12-31 23:59:59.477   765   951 D Clock   : onReceive action=android.intent.action.TIME_SET
12-31 23:59:59.480  1164  1164 D ServiceReceiver: action android.intent.action.TIME_SET
12-31 23:59:59.483   578   578 D ConditionProviders.SCP: notifyCondition condition://android/schedule?days=1.2.3.4.5&start=22.0&end=7.0&exitAtAlarm=false STATE_TRUE reason=meetsSchedule
12-31 23:59:59.503   578   592 I ActivityManager: Start proc 2902:com.android.deskclock/1000 for broadcast com.android.deskclock/.AlarmInitReceiver
12-31 23:59:59.505   578   578 V AlarmManager: remove(operation) changed bounds; rebatching
12-31 23:59:59.506   578   578 D AlarmManagerService: set alarm to kernel: 1811.334000000, type=3
12-31 23:59:59.506   765   765 D KeyguardUpdateMonitor: handleTimeUpdate
12-31 23:59:59.506   578  1234 V AlarmManager: set(PendingIntent{9af0be8: PendingIntentRecord{298f201 com.android.providers.calendar broadcastIntent}}) : type=2 triggerAtTime=1815840 win=0 tElapsed=1815840 maxElapsed=1815840 interval=0 flags=0x1
12-31 23:59:59.506   578   578 D ConditionProviders.SCP: Scheduling evaluate for Mon Jan 01 07:00:00 GMT+08:00 2001 (978303600000), in +7h0m0s525ms, now=Sun Dec 31 23:59:59 GMT+08:00 2000 (978278399475)
12-31 23:59:59.507   578  1234 D AlarmManagerService: set alarm to kernel: 1815.840000000, type=2
12-31 23:59:59.507   578   578 V AlarmManager: set(PendingIntent{2a188a6: PendingIntentRecord{5287781 android broadcastIntent}}) : type=0 triggerAtTime=978303600000 win=0 tElapsed=27011334 maxElapsed=27011334 interval=0 flags=0x9//异常被杀
12-31 23:59:59.510   578   810 I ActivityManager: remove task id:16, callingUid:10021, callingPid:765
12-31 23:59:59.512  2902  2902 W zygote  : Using default instruction set features for ARM CPU variant (generic) using conservative defaults
12-31 23:59:59.513   765   765 D Clock   : updateClock updateClock=下午11:59
12-31 23:59:59.516   765   765 D Clock   : updateClock updateClock=下午11:59
12-31 23:59:59.527  2515  2515 E DBG     : BaseActivity-> onDestroy MainActivity
12-31 23:59:59.557   578   810 I ActivityManager: remove task id:17, callingUid:10021, callingPid:765
12-31 23:59:59.803   578   948 D PowerController.AppState: - reportAppProcStateInfo() E -
12-31 23:59:59.804   578   949 D PowerController.RecogA: handleMessage(MSG_REPORT_EVENT)
12-31 23:59:59.827  2902  2902 I AlarmClock: AlarmInitReceiver android.intent.action.TIME_SET//通过kill  -9 将2515进程杀掉
12-31 23:59:59.843  2515  2515 I Process : Sending signal. PID: 2515 SIG: 9
12-31 23:59:59.984   578   663 I ActivityManager: Process com.xxx.ft (pid 2515) has died: fore +7TOP

2.异常日志分析

刚看到这段异常日志你是否也感到懵逼，怎么好好的App就异常退出了(从实际感官来看)，然后日志里面没有任何的DEBUG和AndroidRuntime错误，从日志12-31 23:59:59.527 2515 2515 E DBG : BaseActivity-> onDestroy MainActivity可以看到Activity走到了onDestroy 的流程，这个看像是正常退出，但是这个是谁发出的指令将该App杀了呢。我真个日志足足分析了一天然后没有任何进展，但是bug要解决，怎么办呢，继续啃日志，然后突然看到一段日志，如下：

12-31 23:59:59.510   578   810 I ActivityManager: remove task id:16, callingUid:10021, callingPid:765
11-11 16:26:58.651   578  1234 I ActivityManager: START u0 {flg=0x10804000 cmp=com.android.systemui/.recents.RecentsActivity} from uid 10021, pid 765

可以看到ActivityManager有将task id为16的进程remove了，然后接着查找日志可以看到10021为SystemUI进程，且id:16恰好是我们的异常kill的App了，那么这就好办了。搜寻SystemUI看哪里调用到了removeTask。

3.确定原因

最后在frameworks/base/packages/SystemUI/./src/com/android/systemui/recents/RecentsActivity.java找到了如下的代码，可以看到监听了时间的变化，然后根据oldLastStackActiveTime 来判断是否需要将当前的task要remove掉。

    /*** Broadcast receiver to handle messages from the system*/final BroadcastReceiver mSystemBroadcastReceiver = new BroadcastReceiver() {@Overridepublic void onReceive(Context ctx, Intent intent) {String action = intent.getAction();if (action.equals(Intent.ACTION_SCREEN_OFF)) {// When the screen turns off, dismiss Recents to HomedismissRecentsToHomeIfVisible(false);} else if (action.equals(Intent.ACTION_TIME_CHANGED)) {// If the time shifts but the currentTime >= lastStackActiveTime, then that boundary// is still valid.  Otherwise, we need to reset the lastStackactiveTime to the// currentTime and remove the old tasks in between which would not be previously// visible, but currently would be in the new currentTimeint currentUser = SystemServicesProxy.getInstance(RecentsActivity.this).getCurrentUser();long oldLastStackActiveTime = Settings.Secure.getLongForUser(getContentResolver(),Secure.OVERVIEW_LAST_STACK_ACTIVE_TIME, -1, currentUser);if (oldLastStackActiveTime != -1) {long currentTime = System.currentTimeMillis();if (currentTime < oldLastStackActiveTime) {// We are only removing tasks that are between the new current time// and the old last stack active time, they were not visible and in the// TaskStack so we don't need to remove any associated TaskViews but we do// need to load the task id's from the systemRecentsTaskLoadPlan loadPlan = Recents.getTaskLoader().createLoadPlan(ctx);loadPlan.preloadRawTasks(false /* includeFrontMostExcludedTask */);List<ActivityManager.RecentTaskInfo> tasks = loadPlan.getRawTasks();for (int i = tasks.size() - 1; i >= 0; i--) {ActivityManager.RecentTaskInfo task = tasks.get(i);if (currentTime <= task.lastActiveTime && task.lastActiveTime <oldLastStackActiveTime) {Recents.getSystemServices().removeTask(task.persistentId);}}Settings.Secure.putLongForUser(RecentsActivity.this.getContentResolver(),Secure.OVERVIEW_LAST_STACK_ACTIVE_TIME, currentTime, currentUser);}}}}};

写在最后

各位如果在Android 7上面有莫名其妙的应用进程被kill掉，可以看看是否是时间异常的原因导致的！