From 9c988b2980a3f8c6dcb83e6ca7812fdf7d823f13 Mon Sep 17 00:00:00 2001 From: Santos Cordon Date: Thu, 23 Apr 2020 17:08:40 +0100 Subject: [PATCH] Add logging to Dream stop. Unexpected stop in dreams get logged very generically and are difficult to debug. Additionally, in many cases of stopping, DreamController requests the dream to stop wherein the dream finishes itself. This ultimately gets logged as a normal finish. Added code to save the context of the original request to stop so that it gets logged appropriately. Bug: 150436621 Test: Manually tested the new logged reasons. Change-Id: I25e348026b514dffe540cf8c4cf3a9b87d385fde --- .../server/dreams/DreamController.java | 26 ++++++++++++------- .../server/dreams/DreamManagerService.java | 18 ++++++------- 2 files changed, 25 insertions(+), 19 deletions(-) diff --git a/services/core/java/com/android/server/dreams/DreamController.java b/services/core/java/com/android/server/dreams/DreamController.java index 532045320988f..5bc69943033e0 100644 --- a/services/core/java/com/android/server/dreams/DreamController.java +++ b/services/core/java/com/android/server/dreams/DreamController.java @@ -62,6 +62,7 @@ final class DreamController { private final Listener mListener; private final IWindowManager mIWindowManager; private long mDreamStartTime; + private String mSavedStopReason; private final Intent mDreamingStartedIntent = new Intent(Intent.ACTION_DREAMING_STARTED) .addFlags(Intent.FLAG_RECEIVER_REGISTERED_ONLY); @@ -77,14 +78,15 @@ final class DreamController { public void run() { if (mCurrentDream != null && mCurrentDream.mBound && !mCurrentDream.mConnected) { Slog.w(TAG, "Bound dream did not connect in the time allotted"); - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "slow to connect"); } } }; private final Runnable mStopStubbornDreamRunnable = () -> { Slog.w(TAG, "Stubborn dream did not finish itself in the time allotted"); - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "slow to finish"); + mSavedStopReason = null; }; public DreamController(Context context, Handler handler, Listener listener) { @@ -116,7 +118,7 @@ final class DreamController { public void startDream(Binder token, ComponentName name, boolean isTest, boolean canDoze, int userId, PowerManager.WakeLock wakeLock) { - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "starting new dream"); Trace.traceBegin(Trace.TRACE_TAG_POWER, "startDream"); try { @@ -141,12 +143,12 @@ final class DreamController { Context.BIND_AUTO_CREATE | Context.BIND_FOREGROUND_SERVICE, new UserHandle(userId))) { Slog.e(TAG, "Unable to bind dream service: " + intent); - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "bindService failed"); return; } } catch (SecurityException ex) { Slog.e(TAG, "Unable to bind dream service: " + intent, ex); - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "unable to bind service: SecExp."); return; } @@ -157,7 +159,7 @@ final class DreamController { } } - public void stopDream(boolean immediate) { + public void stopDream(boolean immediate, String reason) { if (mCurrentDream == null) { return; } @@ -173,6 +175,7 @@ final class DreamController { // Give the dream a moment to wake up and finish itself gently. mCurrentDream.mWakingGently = true; try { + mSavedStopReason = reason; mCurrentDream.mService.wakeUp(); mHandler.postDelayed(mStopStubbornDreamRunnable, DREAM_FINISH_TIMEOUT); return; @@ -186,7 +189,9 @@ final class DreamController { mCurrentDream = null; Slog.i(TAG, "Stopping dream: name=" + oldDream.mName + ", isTest=" + oldDream.mIsTest + ", canDoze=" + oldDream.mCanDoze - + ", userId=" + oldDream.mUserId); + + ", userId=" + oldDream.mUserId + + ", reason='" + reason + "'" + + (mSavedStopReason == null ? "" : "(from '" + mSavedStopReason + "')")); MetricsLogger.hidden(mContext, oldDream.mCanDoze ? MetricsEvent.DOZING : MetricsEvent.DREAMING); MetricsLogger.histogram(mContext, @@ -195,6 +200,7 @@ final class DreamController { mHandler.removeCallbacks(mStopUnconnectedDreamRunnable); mHandler.removeCallbacks(mStopStubbornDreamRunnable); + mSavedStopReason = null; if (oldDream.mSentStartBroadcast) { mContext.sendBroadcastAsUser(mDreamingStoppedIntent, UserHandle.ALL); @@ -233,7 +239,7 @@ final class DreamController { mCurrentDream.mDreamingStartedCallback); } catch (RemoteException ex) { Slog.e(TAG, "The dream service died unexpectedly.", ex); - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "attach failed"); return; } @@ -287,7 +293,7 @@ final class DreamController { mHandler.post(() -> { mService = null; if (mCurrentDream == DreamRecord.this) { - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "binder died"); } }); } @@ -312,7 +318,7 @@ final class DreamController { mHandler.post(() -> { mService = null; if (mCurrentDream == DreamRecord.this) { - stopDream(true /*immediate*/); + stopDream(true /*immediate*/, "service disconnected"); } }); } diff --git a/services/core/java/com/android/server/dreams/DreamManagerService.java b/services/core/java/com/android/server/dreams/DreamManagerService.java index eb0257e95b6c3..70b2cd4edb579 100644 --- a/services/core/java/com/android/server/dreams/DreamManagerService.java +++ b/services/core/java/com/android/server/dreams/DreamManagerService.java @@ -118,7 +118,7 @@ public final class DreamManagerService extends SystemService { public void onReceive(Context context, Intent intent) { writePulseGestureEnabled(); synchronized (mLock) { - stopDreamLocked(false /*immediate*/); + stopDreamLocked(false /*immediate*/, "user switched"); } } }, new IntentFilter(Intent.ACTION_USER_SWITCHED), null, mHandler); @@ -177,7 +177,7 @@ public final class DreamManagerService extends SystemService { // for example when being undocked. long time = SystemClock.uptimeMillis(); mPowerManager.userActivity(time, false /*noChangeLights*/); - stopDreamInternal(false /*immediate*/); + stopDreamInternal(false /*immediate*/, "request awaken"); } private void finishSelfInternal(IBinder token, boolean immediate) { @@ -194,7 +194,7 @@ public final class DreamManagerService extends SystemService { // device may simply go to sleep. synchronized (mLock) { if (mCurrentDreamToken == token) { - stopDreamLocked(immediate); + stopDreamLocked(immediate, "finished self"); } } } @@ -215,9 +215,9 @@ public final class DreamManagerService extends SystemService { } } - private void stopDreamInternal(boolean immediate) { + private void stopDreamInternal(boolean immediate, String reason) { synchronized (mLock) { - stopDreamLocked(immediate); + stopDreamLocked(immediate, reason); } } @@ -370,7 +370,7 @@ public final class DreamManagerService extends SystemService { return; } - stopDreamLocked(true /*immediate*/); + stopDreamLocked(true /*immediate*/, "starting new dream"); Slog.i(TAG, "Entering dreamland."); @@ -387,7 +387,7 @@ public final class DreamManagerService extends SystemService { () -> mController.startDream(newToken, name, isTest, canDoze, userId, wakeLock))); } - private void stopDreamLocked(final boolean immediate) { + private void stopDreamLocked(final boolean immediate, String reason) { if (mCurrentDreamToken != null) { if (immediate) { Slog.i(TAG, "Leaving dreamland."); @@ -403,7 +403,7 @@ public final class DreamManagerService extends SystemService { @Override public void run() { Slog.i(TAG, "Performing gentle wake from dream."); - mController.stopDream(immediate); + mController.stopDream(immediate, reason); } }); } @@ -690,7 +690,7 @@ public final class DreamManagerService extends SystemService { @Override public void stopDream(boolean immediate) { - stopDreamInternal(immediate); + stopDreamInternal(immediate, "requested stopDream"); } @Override