From ea76d7e31c994c94abad6722a2f6e7e4afb6196b Mon Sep 17 00:00:00 2001 From: Lais Andrade Date: Thu, 11 Jun 2020 10:33:19 +0000 Subject: [PATCH] Create ShutdownCheckPoints for shutdown call logging This class has a singleton that can be triggered from different places within the frameworks/base code to record information about calls to shutdown and reboot methods. The stacktrace, binder caller pid and intent are kept in memory and dumped in a file by the ShutdownThread. Follow up work: - Use the ShutdownCheckPoints record method in the framework. - Add a rotating file logic to ShutdownThread to store previous restarts, instead of rewriting the same file. Based on this cl: https://partner-android-review.googlesource.com/c/platform/frameworks/base/+/1197613 Bug: 113147108 Test: atest FrameworksServicesTests:ShutdownCheckPointsTest Change-Id: I08b1d8c990ea7d727988a2f711c66bd0c7d7ddb6 --- .../server/power/ShutdownCheckPoints.java | 299 ++++++++++++++++++ .../android/server/power/ShutdownThread.java | 45 ++- .../server/power/ShutdownCheckPointsTest.java | 256 +++++++++++++++ 3 files changed, 595 insertions(+), 5 deletions(-) create mode 100644 services/core/java/com/android/server/power/ShutdownCheckPoints.java create mode 100644 services/tests/servicestests/src/com/android/server/power/ShutdownCheckPointsTest.java diff --git a/services/core/java/com/android/server/power/ShutdownCheckPoints.java b/services/core/java/com/android/server/power/ShutdownCheckPoints.java new file mode 100644 index 0000000000000..c85a77ae46fb0 --- /dev/null +++ b/services/core/java/com/android/server/power/ShutdownCheckPoints.java @@ -0,0 +1,299 @@ +/* + * Copyright (C) 2020 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.power; + +import android.annotation.Nullable; +import android.app.ActivityManager; +import android.app.IActivityManager; +import android.os.Process; +import android.os.RemoteException; +import android.util.Slog; + +import com.android.internal.annotations.VisibleForTesting; + +import java.io.PrintWriter; +import java.text.SimpleDateFormat; +import java.util.ArrayList; +import java.util.Date; +import java.util.LinkedList; +import java.util.List; + +/** + * The shutdown check points are a recording of more detailed information of the origin of calls to + * system shutdown and reboot framework methods. + * + * @hide + */ +public final class ShutdownCheckPoints { + + private static final String TAG = "ShutdownCheckPoints"; + + private static final ShutdownCheckPoints INSTANCE = new ShutdownCheckPoints(); + + private static final int MAX_CHECK_POINTS = 100; + private static final SimpleDateFormat DATE_FORMAT = + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS z"); + + private final LinkedList mCheckPoints; + private final Injector mInjector; + + private ShutdownCheckPoints() { + this(new Injector() { + @Override + public long currentTimeMillis() { + return System.currentTimeMillis(); + } + + @Override + public int maxCheckPoints() { + return MAX_CHECK_POINTS; + } + + @Override + public IActivityManager activityManager() { + return ActivityManager.getService(); + } + }); + } + + @VisibleForTesting + ShutdownCheckPoints(Injector injector) { + mCheckPoints = new LinkedList<>(); + mInjector = injector; + } + + /** Records the stack trace of this {@link Thread} as a shutdown check point. */ + public static void recordCheckPoint() { + INSTANCE.recordCheckPointInternal(); + } + + /** Records the pid of the caller process as a shutdown check point. */ + public static void recordCheckPoint(int callerProcessId) { + INSTANCE.recordCheckPointInternal(callerProcessId); + } + + /** Records the {@link android.content.Intent} name and package as a shutdown check point. */ + public static void recordCheckPoint(String intentName, String packageName) { + INSTANCE.recordCheckPointInternal(intentName, packageName); + } + + /** Serializes the recorded check points and writes them to given {@code printWriter}. */ + public static void dump(PrintWriter printWriter) { + INSTANCE.dumpInternal(printWriter); + } + + @VisibleForTesting + void recordCheckPointInternal() { + recordCheckPointInternal(new SystemServerCheckPoint(mInjector)); + Slog.v(TAG, "System server shutdown checkpoint recorded"); + } + + @VisibleForTesting + void recordCheckPointInternal(int callerProcessId) { + recordCheckPointInternal(callerProcessId == Process.myPid() + ? new SystemServerCheckPoint(mInjector) + : new BinderCheckPoint(mInjector, callerProcessId)); + Slog.v(TAG, "Binder shutdown checkpoint recorded with pid=" + callerProcessId); + } + + @VisibleForTesting + void recordCheckPointInternal(String intentName, String packageName) { + recordCheckPointInternal("android".equals(packageName) + ? new SystemServerCheckPoint(mInjector) + : new IntentCheckPoint(mInjector, intentName, packageName)); + Slog.v(TAG, String.format("Shutdown intent checkpoint recorded intent=%s from package=%s", + intentName, packageName)); + } + + private void recordCheckPointInternal(CheckPoint checkPoint) { + synchronized (mCheckPoints) { + mCheckPoints.addLast(checkPoint); + if (mCheckPoints.size() > mInjector.maxCheckPoints()) mCheckPoints.removeFirst(); + } + } + + @VisibleForTesting + void dumpInternal(PrintWriter printWriter) { + final List records; + synchronized (mCheckPoints) { + records = new ArrayList<>(mCheckPoints); + } + for (CheckPoint record : records) { + record.dump(printWriter); + printWriter.println(); + } + } + + /** Injector used by {@link ShutdownCheckPoints} for testing purposes. */ + @VisibleForTesting + interface Injector { + long currentTimeMillis(); + + int maxCheckPoints(); + + IActivityManager activityManager(); + } + + /** Representation of a generic shutdown call, which can be serialized. */ + private abstract static class CheckPoint { + + private final long mTimestamp; + + CheckPoint(Injector injector) { + mTimestamp = injector.currentTimeMillis(); + } + + final void dump(PrintWriter printWriter) { + printWriter.print("Shutdown request from "); + printWriter.print(getOrigin()); + printWriter.print(" at "); + printWriter.print(DATE_FORMAT.format(new Date(mTimestamp))); + printWriter.println(" (epoch=" + mTimestamp + ")"); + dumpDetails(printWriter); + } + + abstract String getOrigin(); + + abstract void dumpDetails(PrintWriter printWriter); + } + + /** Representation of a shutdown call from the system server, with stack trace. */ + private static class SystemServerCheckPoint extends CheckPoint { + + private final StackTraceElement[] mStackTraceElements; + + SystemServerCheckPoint(Injector injector) { + super(injector); + mStackTraceElements = Thread.currentThread().getStackTrace(); + } + + @Override + String getOrigin() { + return "SYSTEM"; + } + + @Override + void dumpDetails(PrintWriter printWriter) { + String methodName = getMethodName(); + printWriter.println(methodName == null ? "Failed to get method name" : methodName); + printStackTrace(printWriter); + } + + @Nullable + String getMethodName() { + int idx = findCallSiteIndex(); + if (idx < mStackTraceElements.length) { + StackTraceElement element = mStackTraceElements[idx]; + return String.format("%s.%s", element.getClassName(), element.getMethodName()); + } + return null; + } + + void printStackTrace(PrintWriter printWriter) { + // Skip the call site line, as it's already considered with getMethodName. + for (int i = findCallSiteIndex() + 1; i < mStackTraceElements.length; i++) { + printWriter.print(" at "); + printWriter.println(mStackTraceElements[i]); + } + } + + private int findCallSiteIndex() { + String className = ShutdownCheckPoints.class.getCanonicalName(); + int idx = 0; + // Skip system trace lines until finding ShutdownCheckPoints call site. + while (idx < mStackTraceElements.length + && !mStackTraceElements[idx].getClassName().equals(className)) { + ++idx; + } + // Skip trace lines from ShutdownCheckPoints class. + while (idx < mStackTraceElements.length + && mStackTraceElements[idx].getClassName().equals(className)) { + ++idx; + } + return idx; + } + } + + /** Representation of a shutdown call to {@link android.os.Binder}, with caller process id. */ + private static class BinderCheckPoint extends SystemServerCheckPoint { + private final int mCallerProcessId; + private final IActivityManager mActivityManager; + + BinderCheckPoint(Injector injector, int callerProcessId) { + super(injector); + mCallerProcessId = callerProcessId; + mActivityManager = injector.activityManager(); + } + + @Override + String getOrigin() { + return "BINDER"; + } + + @Override + void dumpDetails(PrintWriter printWriter) { + String methodName = getMethodName(); + printWriter.println(methodName == null ? "Failed to get method name" : methodName); + + String processName = getProcessName(); + printWriter.print("From process "); + printWriter.print(processName == null ? "?" : processName); + printWriter.println(" (pid=" + mCallerProcessId + ")"); + } + + @Nullable + String getProcessName() { + try { + List runningProcesses = + mActivityManager.getRunningAppProcesses(); + for (ActivityManager.RunningAppProcessInfo processInfo : runningProcesses) { + if (processInfo.pid == mCallerProcessId) { + return processInfo.processName; + } + } + } catch (RemoteException e) { + Slog.e(TAG, "Failed to get running app processes from ActivityManager", e); + } + return null; + } + } + + /** Representation of a shutdown call with {@link android.content.Intent}. */ + private static class IntentCheckPoint extends CheckPoint { + private final String mIntentName; + private final String mPackageName; + + IntentCheckPoint(Injector injector, String intentName, String packageName) { + super(injector); + mIntentName = intentName; + mPackageName = packageName; + } + + @Override + String getOrigin() { + return "INTENT"; + } + + @Override + void dumpDetails(PrintWriter printWriter) { + printWriter.print("Intent: "); + printWriter.println(mIntentName); + printWriter.print("Package: "); + printWriter.println(mPackageName); + } + } +} diff --git a/services/core/java/com/android/server/power/ShutdownThread.java b/services/core/java/com/android/server/power/ShutdownThread.java index bc722f1816500..2c1fe58944d75 100644 --- a/services/core/java/com/android/server/power/ShutdownThread.java +++ b/services/core/java/com/android/server/power/ShutdownThread.java @@ -43,6 +43,7 @@ import android.os.UserManager; import android.os.Vibrator; import android.telephony.TelephonyManager; import android.util.ArrayMap; +import android.util.AtomicFile; import android.util.Log; import android.util.Slog; import android.util.TimingsTraceLog; @@ -56,6 +57,7 @@ import com.android.server.statusbar.StatusBarManagerInternal; import java.io.File; import java.io.FileOutputStream; import java.io.IOException; +import java.io.PrintWriter; import java.nio.charset.StandardCharsets; public final class ShutdownThread extends Thread { @@ -64,10 +66,10 @@ public final class ShutdownThread extends Thread { private static final int ACTION_DONE_POLL_WAIT_MS = 500; private static final int RADIOS_STATE_POLL_SLEEP_MS = 100; // maximum time we wait for the shutdown broadcast before going on. - private static final int MAX_BROADCAST_TIME = 10*1000; - private static final int MAX_SHUTDOWN_WAIT_TIME = 20*1000; - private static final int MAX_RADIO_WAIT_TIME = 12*1000; - private static final int MAX_UNCRYPT_WAIT_TIME = 15*60*1000; + private static final int MAX_BROADCAST_TIME = 10 * 1000; + private static final int MAX_CHECK_POINTS_DUMP_WAIT_TIME = 20 * 1000; + private static final int MAX_RADIO_WAIT_TIME = 12 * 1000; + private static final int MAX_UNCRYPT_WAIT_TIME = 15 * 60 * 1000; // constants for progress bar. the values are roughly estimated based on timeout. private static final int BROADCAST_STOP_PERCENT = 2; private static final int ACTIVITY_MANAGER_STOP_PERCENT = 4; @@ -105,8 +107,11 @@ public final class ShutdownThread extends Thread { // Metrics that will be reported to tron after reboot private static final ArrayMap TRON_METRICS = new ArrayMap<>(); - // File to use for save metrics + // File to use for saving shutdown metrics private static final String METRICS_FILE_BASENAME = "/data/system/shutdown-metrics"; + // File to use for saving shutdown check points + private static final String CHECK_POINTS_FILE_BASENAME = + "/data/system/shutdown-checkpoints/checkpoints"; // Metrics names to be persisted in shutdown-metrics file private static String METRIC_SYSTEM_SERVER = "shutdown_system_server"; @@ -422,6 +427,9 @@ public final class ShutdownThread extends Thread { metricShutdownStart(); metricStarted(METRIC_SYSTEM_SERVER); + // Start dumping check points for this shutdown in a separate thread. + Thread dumpCheckPointsThread = startCheckPointsDump(); + BroadcastReceiver br = new BroadcastReceiver() { @Override public void onReceive(Context context, Intent intent) { // We don't allow apps to cancel this, so ignore the result. @@ -542,6 +550,14 @@ public final class ShutdownThread extends Thread { uncrypt(); } + // Wait for the check points dump thread to finish, or kill it if not finished in time. + shutdownTimingLog.traceBegin("ShutdownCheckPointsDumpWait"); + try { + dumpCheckPointsThread.join(MAX_CHECK_POINTS_DUMP_WAIT_TIME); + } catch (InterruptedException ex) { + } + shutdownTimingLog.traceEnd(); // ShutdownCheckPointsDumpWait + shutdownTimingLog.traceEnd(); // SystemServerShutdown metricEnded(METRIC_SYSTEM_SERVER); saveMetrics(mReboot, mReason); @@ -712,6 +728,25 @@ public final class ShutdownThread extends Thread { } } + private Thread startCheckPointsDump() { + Thread thread = new Thread() { + public void run() { + // Writes to a file with .new suffix and then renames it to final file name. + // The final file won't be left with partial data if this thread is interrupted. + AtomicFile file = new AtomicFile(new File(CHECK_POINTS_FILE_BASENAME)); + try (FileOutputStream fos = file.startWrite()) { + PrintWriter pw = new PrintWriter(fos); + ShutdownCheckPoints.dump(pw); + file.finishWrite(fos); + } catch (IOException e) { + Log.e(TAG, "Cannot save shutdown checkpoints", e); + } + } + }; + thread.start(); + return thread; + } + private void uncrypt() { Log.i(TAG, "Calling uncrypt and monitoring the progress..."); diff --git a/services/tests/servicestests/src/com/android/server/power/ShutdownCheckPointsTest.java b/services/tests/servicestests/src/com/android/server/power/ShutdownCheckPointsTest.java new file mode 100644 index 0000000000000..7ffd0d0968860 --- /dev/null +++ b/services/tests/servicestests/src/com/android/server/power/ShutdownCheckPointsTest.java @@ -0,0 +1,256 @@ +/* + * Copyright (C) 2020 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.power; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; +import static org.mockito.Mockito.when; + +import android.app.ActivityManager; +import android.app.IActivityManager; +import android.os.Process; +import android.os.RemoteException; +import android.platform.test.annotations.Presubmit; + +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; +import org.mockito.Mock; +import org.mockito.junit.MockitoJUnit; +import org.mockito.junit.MockitoRule; + +import java.io.PrintWriter; +import java.io.StringWriter; +import java.util.ArrayList; +import java.util.List; +import java.util.Locale; +import java.util.TimeZone; + +/** + * Run: atest FrameworksServicesTests:ShutdownCheckPointsTest + */ +@Presubmit +public class ShutdownCheckPointsTest { + + @Rule + public MockitoRule rule = MockitoJUnit.rule(); + + @Mock + private IActivityManager mActivityManager; + + private TestInjector mTestInjector; + private ShutdownCheckPoints mInstance; + + @Before + public void setUp() { + Locale.setDefault(Locale.UK); + TimeZone.setDefault(TimeZone.getTimeZone("UTC")); + mTestInjector = new TestInjector(0, 100, mActivityManager); + mInstance = new ShutdownCheckPoints(mTestInjector); + } + + @Test + public void testSystemServerEntry() { + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal(); + + assertTrue(dumpToString().startsWith( + "Shutdown request from SYSTEM at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest" + + ".testSystemServerEntry\n at ")); + } + + @Test + public void testSystemServiceBinderEntry() { + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal(Process.myPid()); + + assertTrue(dumpToString().startsWith( + "Shutdown request from SYSTEM at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest" + + ".testSystemServiceBinderEntry\n at ")); + } + + @Test + public void testCallerProcessBinderEntry() throws RemoteException { + List runningAppProcessInfos = new ArrayList<>(); + runningAppProcessInfos.add( + new ActivityManager.RunningAppProcessInfo("process_name", 1, new String[0])); + when(mActivityManager.getRunningAppProcesses()).thenReturn(runningAppProcessInfos); + + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal(1); + + assertEquals( + "Shutdown request from BINDER at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest" + + ".testCallerProcessBinderEntry\n" + + "From process process_name (pid=1)\n\n", + dumpToString()); + } + + @Test + public void testRemoteExceptionOnBinderEntry() throws RemoteException { + when(mActivityManager.getRunningAppProcesses()).thenThrow(new RemoteException("Error")); + + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal(1); + + assertEquals( + "Shutdown request from BINDER at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest" + + ".testRemoteExceptionOnBinderEntry\n" + + "From process ? (pid=1)\n\n", + dumpToString()); + } + + @Test + public void testUnknownProcessBinderEntry() { + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal(1); + + assertEquals( + "Shutdown request from BINDER at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest" + + ".testUnknownProcessBinderEntry\n" + + "From process ? (pid=1)\n\n", + dumpToString()); + } + + @Test + public void testSystemServiceIntentEntry() { + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal("some.intent", "android"); + + assertTrue(dumpToString().startsWith( + "Shutdown request from SYSTEM at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest" + + ".testSystemServiceIntentEntry\n at ")); + } + + @Test + public void testIntentEntry() { + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal("some.intent", "some.app"); + + assertEquals( + "Shutdown request from INTENT at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "Intent: some.intent\n" + + "Package: some.app\n\n", + dumpToString()); + } + + @Test + public void testMultipleEntries() { + mTestInjector.setCurrentTime(1000); + mInstance.recordCheckPointInternal(1); + mTestInjector.setCurrentTime(2000); + mInstance.recordCheckPointInternal(2); + mTestInjector.setCurrentTime(3000); + mInstance.recordCheckPointInternal("intent", "app"); + + assertEquals( + "Shutdown request from BINDER at 1970-01-01 00:00:01.000 UTC (epoch=1000)\n" + + "com.android.server.power.ShutdownCheckPointsTest.testMultipleEntries\n" + + "From process ? (pid=1)\n" + + "\n" + + "Shutdown request from BINDER at 1970-01-01 00:00:02.000 UTC (epoch=2000)" + + "\n" + + "com.android.server.power.ShutdownCheckPointsTest.testMultipleEntries\n" + + "From process ? (pid=2)\n" + + "\n" + + "Shutdown request from INTENT at 1970-01-01 00:00:03.000 UTC (epoch=3000)" + + "\n" + + "Intent: intent\n" + + "Package: app\n" + + "\n", + dumpToString()); + } + + @Test + public void testTooManyEntriesDropsOlderOnes() { + mTestInjector.setCheckPointsLimit(2); + ShutdownCheckPoints limitedInstance = new ShutdownCheckPoints(mTestInjector); + + mTestInjector.setCurrentTime(1000); + limitedInstance.recordCheckPointInternal("intent.1", "app.1"); + mTestInjector.setCurrentTime(2000); + limitedInstance.recordCheckPointInternal("intent.2", "app.2"); + mTestInjector.setCurrentTime(3000); + limitedInstance.recordCheckPointInternal("intent.3", "app.3"); + + // Drops first intent. + assertEquals( + "Shutdown request from INTENT at 1970-01-01 00:00:02.000 UTC (epoch=2000)\n" + + "Intent: intent.2\n" + + "Package: app.2\n" + + "\n" + + "Shutdown request from INTENT at 1970-01-01 00:00:03.000 UTC (epoch=3000)" + + "\n" + + "Intent: intent.3\n" + + "Package: app.3\n" + + "\n", + dumpToString(limitedInstance)); + } + + private String dumpToString() { + return dumpToString(mInstance); + } + + private String dumpToString(ShutdownCheckPoints instance) { + StringWriter sw = new StringWriter(); + PrintWriter pw = new PrintWriter(sw); + instance.dumpInternal(pw); + return sw.toString(); + } + + /** Fake system dependencies for testing. */ + private final class TestInjector implements ShutdownCheckPoints.Injector { + private long mNow; + private int mLimit; + private IActivityManager mActivityManager; + + TestInjector(long now, int limit, IActivityManager activityManager) { + mNow = now; + mLimit = limit; + mActivityManager = activityManager; + } + + @Override + public long currentTimeMillis() { + return mNow; + } + + @Override + public int maxCheckPoints() { + return mLimit; + } + + @Override + public IActivityManager activityManager() { + return mActivityManager; + } + + void setCurrentTime(long time) { + mNow = time; + } + + void setCheckPointsLimit(int limit) { + mLimit = limit; + } + } +}