Merge "Create ShutdownCheckPoints for shutdown call logging" (07e99730) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/power/ShutdownCheckPoints.java

0 → 100644

+299 −0

Original line number	Diff line number	Diff line
		/*
		* 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<CheckPoint> 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<CheckPoint> 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<ActivityManager.RunningAppProcessInfo> 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);
		}
		}
		}

services/core/java/com/android/server/power/ShutdownThread.java

+40 −5

Original line number	Diff line number	Diff line
		@@ -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 {
		@@ -65,7 +67,7 @@ public final class ShutdownThread extends Thread {
		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_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.
		@@ -105,8 +107,11 @@ public final class ShutdownThread extends Thread {
		// Metrics that will be reported to tron after reboot
		private static final ArrayMap<String, Long> 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...");

services/tests/servicestests/src/com/android/server/power/ShutdownCheckPointsTest.java

0 → 100644

+256 −0

Original line number	Diff line number	Diff line
		/*
		* 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<ActivityManager.RunningAppProcessInfo> 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;
		}
		}
		}