Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Create ShutdownCheckPoints for shutdown call logging

Browse Source 
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
This commit is contained in:
Lais Andrade
2020-06-11 10:33:19 +00:00
parent 625770f7fd
commit ea76d7e31c
3 changed files with 595 additions and 5 deletions
Download Patch File Download Diff File Expand all files Collapse all files

299
services/core/java/com/android/server/power/ShutdownCheckPoints.java Normal file
View File

@@ -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<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);
}
}
}

45
services/core/java/com/android/server/power/ShutdownThread.java
View File

@@ -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<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...");

256
services/tests/servicestests/src/com/android/server/power/ShutdownCheckPointsTest.java Normal file
View File

@@ -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<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;
}
}
}