1 /*
2  * Copyright (C) 2024 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package android.os.profiling;
18 
19 import android.annotation.NonNull;
20 import android.annotation.Nullable;
21 import android.content.Context;
22 import android.icu.text.SimpleDateFormat;
23 import android.icu.util.Calendar;
24 import android.icu.util.TimeZone;
25 import android.os.Binder;
26 import android.os.Bundle;
27 import android.os.FileUtils;
28 import android.os.Handler;
29 import android.os.HandlerThread;
30 import android.os.IBinder;
31 import android.os.IProfilingResultCallback;
32 import android.os.IProfilingService;
33 import android.os.ParcelFileDescriptor;
34 import android.os.ProfilingManager;
35 import android.os.ProfilingResult;
36 import android.os.RemoteException;
37 import android.provider.DeviceConfig;
38 import android.text.TextUtils;
39 import android.util.ArrayMap;
40 import android.util.Log;
41 import android.util.SparseArray;
42 
43 import com.android.internal.annotations.GuardedBy;
44 import com.android.internal.annotations.VisibleForTesting;
45 import com.android.server.SystemService;
46 
47 import java.io.File;
48 import java.io.FileInputStream;
49 import java.io.FileOutputStream;
50 import java.io.FilenameFilter;
51 import java.io.IOException;
52 import java.nio.file.Files;
53 import java.nio.file.Path;
54 import java.util.ArrayList;
55 import java.util.List;
56 import java.util.Locale;
57 import java.util.UUID;
58 import java.util.concurrent.TimeUnit;
59 
60 public class ProfilingService extends IProfilingService.Stub {
61     private static final String TAG = ProfilingService.class.getSimpleName();
62     private static final boolean DEBUG = false;
63 
64     private static final String TEMP_TRACE_PATH = "/data/misc/perfetto-traces/profiling/";
65     private static final String OUTPUT_FILE_RELATIVE_PATH = "/profiling/";
66     private static final String OUTPUT_FILE_SECTION_SEPARATOR = "_";
67     private static final String OUTPUT_FILE_PREFIX = "profile";
68     // Keep in sync with {@link ProfilingFrameworkTests}.
69     private static final String OUTPUT_FILE_JAVA_HEAP_DUMP_SUFFIX = ".perfetto-java-heap-dump";
70     private static final String OUTPUT_FILE_HEAP_PROFILE_SUFFIX = ".perfetto-heap-profile";
71     private static final String OUTPUT_FILE_STACK_SAMPLING_SUFFIX = ".perfetto-stack-sample";
72     private static final String OUTPUT_FILE_TRACE_SUFFIX = ".perfetto-trace";
73     private static final String OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX = ".perfetto-trace-unredacted";
74 
75     private static final int TAG_MAX_CHARS_FOR_FILENAME = 20;
76 
77     private static final int PERFETTO_DESTROY_DEFAULT_TIMEOUT_MS = 10 * 1000;
78 
79     private static final int DEFAULT_MAX_RESULT_REDELIVERY_COUNT = 3;
80 
81     private static final int REDACTION_DEFAULT_MAX_RUNTIME_ALLOTTED_MS = 20  * 1000;
82 
83     private static final int REDACTION_DEFAULT_CHECK_FREQUENCY_MS = 2 * 1000;
84 
85     // The cadence at which the profiling process will be checked after the initial delay
86     // has elapsed.
87     private static final int PROFILING_DEFAULT_RECHECK_DELAY_MS = 5 * 1000;
88 
89     private static final int CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_DEFAULT_MS = 24 * 60 * 60 * 1000;
90     private static final int CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_DEFAULT_MS = 5 * 60 * 1000;
91 
92     // The longest amount of time that we will retain a queued result and continue retrying to
93     // deliver it. After this amount of time the result will be discarded.
94     @VisibleForTesting
95     public static final int QUEUED_RESULT_MAX_RETAINED_DURATION_MS = 7 * 24 * 60 * 60 * 1000;
96 
97     private final Context mContext;
98     private final Object mLock = new Object();
99     private final HandlerThread mHandlerThread = new HandlerThread("ProfilingService");
100 
101     @VisibleForTesting public RateLimiter mRateLimiter = null;
102 
103     // Timeout for Perfetto process to successfully stop after we try to stop it.
104     private int mPerfettoDestroyTimeoutMs;
105     private int mMaxResultRedeliveryCount;
106     private int mProfilingRecheckDelayMs;
107 
108     @GuardedBy("mLock")
109     private long mLastClearTemporaryDirectoryTimeMs = 0;
110     private int mClearTemporaryDirectoryFrequencyMs;
111     private final int mClearTemporaryDirectoryBootDelayMs;
112 
113     private int mRedactionCheckFrequencyMs;
114     private int mRedactionMaxRuntimeAllottedMs;
115 
116     private Handler mHandler;
117 
118     private Calendar mCalendar = null;
119     private SimpleDateFormat mDateFormat = null;
120 
121     // uid indexed collection of lists of callbacks for results.
122     @VisibleForTesting
123     public SparseArray<List<IProfilingResultCallback>> mResultCallbacks = new SparseArray<>();
124 
125     // Request UUID key indexed storage of active tracing sessions. Currently only 1 active session
126     // is supported at a time, but this will be used in future to support multiple.
127     @VisibleForTesting
128     public ArrayMap<String, TracingSession> mTracingSessions = new ArrayMap<>();
129 
130     // uid indexed storage of completed tracing sessions that have not yet successfully handled the
131     // result.
132     @VisibleForTesting
133     public SparseArray<List<TracingSession>> mQueuedTracingResults = new SparseArray<>();
134 
135     /** To be disabled for testing only. */
136     @GuardedBy("mLock")
137     private boolean mKeepUnredactedTrace = false;
138 
139     @VisibleForTesting
ProfilingService(Context context)140     public ProfilingService(Context context) {
141         mContext = context;
142 
143         mPerfettoDestroyTimeoutMs = DeviceConfigHelper.getInt(
144                 DeviceConfigHelper.PERFETTO_DESTROY_TIMEOUT_MS,
145                 PERFETTO_DESTROY_DEFAULT_TIMEOUT_MS);
146 
147         mMaxResultRedeliveryCount = DeviceConfigHelper.getInt(
148                 DeviceConfigHelper.MAX_RESULT_REDELIVERY_COUNT,
149                 DEFAULT_MAX_RESULT_REDELIVERY_COUNT);
150 
151         mProfilingRecheckDelayMs = DeviceConfigHelper.getInt(
152                 DeviceConfigHelper.PROFILING_RECHECK_DELAY_MS,
153                 PROFILING_DEFAULT_RECHECK_DELAY_MS);
154 
155         mClearTemporaryDirectoryFrequencyMs = DeviceConfigHelper.getInt(
156                 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_MS,
157                 CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_DEFAULT_MS);
158 
159         mClearTemporaryDirectoryBootDelayMs = DeviceConfigHelper.getInt(
160                 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_MS,
161             CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_DEFAULT_MS);
162 
163         mRedactionCheckFrequencyMs = DeviceConfigHelper.getInt(
164                 DeviceConfigHelper.REDACTION_CHECK_FREQUENCY_MS,
165                 REDACTION_DEFAULT_CHECK_FREQUENCY_MS);
166 
167         mRedactionMaxRuntimeAllottedMs = DeviceConfigHelper.getInt(
168                 DeviceConfigHelper.REDACTION_MAX_RUNTIME_ALLOTTED_MS,
169                 REDACTION_DEFAULT_MAX_RUNTIME_ALLOTTED_MS);
170 
171 
172         mHandlerThread.start();
173 
174         // Get initial value for whether unredacted trace should be retained.
175         // This is used for (automated and manual) testing only.
176         synchronized (mLock) {
177             mKeepUnredactedTrace = DeviceConfigHelper.getTestBoolean(
178                     DeviceConfigHelper.DISABLE_DELETE_UNREDACTED_TRACE, false);
179         }
180         // Now subscribe to updates on test config.
181         DeviceConfig.addOnPropertiesChangedListener(DeviceConfigHelper.NAMESPACE_TESTING,
182                 mContext.getMainExecutor(), new DeviceConfig.OnPropertiesChangedListener() {
183                     @Override
184                     public void onPropertiesChanged(@NonNull DeviceConfig.Properties properties) {
185                         synchronized (mLock) {
186                             mKeepUnredactedTrace = properties.getBoolean(
187                                     DeviceConfigHelper.DISABLE_DELETE_UNREDACTED_TRACE, false);
188                             getRateLimiter().maybeUpdateRateLimiterDisabled(properties);
189                         }
190                     }
191                 });
192 
193         // Subscribe to updates on the main config.
194         DeviceConfig.addOnPropertiesChangedListener(DeviceConfigHelper.NAMESPACE,
195                 mContext.getMainExecutor(), new DeviceConfig.OnPropertiesChangedListener() {
196                     @Override
197                     public void onPropertiesChanged(@NonNull DeviceConfig.Properties properties) {
198                         synchronized (mLock) {
199                             getRateLimiter().maybeUpdateConfigs(properties);
200                             Configs.maybeUpdateConfigs(properties);
201 
202                             mPerfettoDestroyTimeoutMs = properties.getInt(
203                                     DeviceConfigHelper.PERFETTO_DESTROY_TIMEOUT_MS,
204                                     mPerfettoDestroyTimeoutMs);
205 
206                             mMaxResultRedeliveryCount = properties.getInt(
207                                     DeviceConfigHelper.MAX_RESULT_REDELIVERY_COUNT,
208                                     mMaxResultRedeliveryCount);
209 
210                             mProfilingRecheckDelayMs = properties.getInt(
211                                     DeviceConfigHelper.PROFILING_RECHECK_DELAY_MS,
212                                     mProfilingRecheckDelayMs);
213 
214                             mClearTemporaryDirectoryFrequencyMs = properties.getInt(
215                                     DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_MS,
216                                     mClearTemporaryDirectoryFrequencyMs);
217 
218                             // No need to handle updates for
219                             // {@link mClearTemporaryDirectoryBootDelayMs} as it's only used on
220                             // initialization of this class so by the time this occurs it will never
221                             // be used again.
222 
223                             mRedactionCheckFrequencyMs = properties.getInt(
224                                     DeviceConfigHelper.REDACTION_CHECK_FREQUENCY_MS,
225                                     mRedactionCheckFrequencyMs);
226 
227                             mRedactionMaxRuntimeAllottedMs = properties.getInt(
228                                     DeviceConfigHelper.REDACTION_MAX_RUNTIME_ALLOTTED_MS,
229                                     mRedactionMaxRuntimeAllottedMs);
230                         }
231                     }
232                 });
233 
234         // Schedule initial storage cleanup after delay so as not to increase non-critical work
235         // during boot.
236         getHandler().postDelayed(new Runnable() {
237             @Override
238             public void run() {
239                 maybeCleanupTemporaryDirectory();
240             }
241         }, mClearTemporaryDirectoryBootDelayMs);
242     }
243 
244     /** Perform a temporary directory cleanup if it has been long enough to warrant one. */
maybeCleanupTemporaryDirectory()245     private void maybeCleanupTemporaryDirectory() {
246         synchronized (mLock) {
247             if (mLastClearTemporaryDirectoryTimeMs + mClearTemporaryDirectoryFrequencyMs
248                     < System.currentTimeMillis()) {
249                 cleanupTemporaryDirectoryLocked(TEMP_TRACE_PATH);
250             }
251         }
252     }
253 
254 
255     /** Cleanup untracked data stored in provided directory. */
256     @GuardedBy("mLock")
257     @VisibleForTesting
cleanupTemporaryDirectoryLocked(String temporaryDirectoryPath)258     public void cleanupTemporaryDirectoryLocked(String temporaryDirectoryPath) {
259         // Obtain a list of all currently tracked files and create a filter with it. Filter is set
260         // to null if the list is empty as that will efficiently accept all files.
261         final List<String> trackedFilenames = getTrackedFilenames();
262         FilenameFilter filenameFilter = trackedFilenames.isEmpty() ? null : new FilenameFilter() {
263             @Override
264             public boolean accept(File dir, String name) {
265                 // We only want to accept files which are not in the tracked files list.
266                 return !trackedFilenames.contains(name);
267             }
268         };
269 
270         // Now obtain a list of files in the provided directory that are not tracked.
271         File directory = new File(temporaryDirectoryPath);
272         File[] files = null;
273         try {
274             files = directory.listFiles(filenameFilter);
275         } catch (SecurityException e) {
276             // Couldn't get a list of files, can't cleanup anything.
277             if (DEBUG) {
278                 Log.d(TAG, "Failed to get file list from temporary directory. Cleanup aborted.", e);
279             }
280             return;
281         }
282 
283         if (files == null) {
284             // The path doesn't exist or an I/O error occurred.
285             if (DEBUG) {
286                 Log.d(TAG, "Temporary directory doesn't exist or i/o error occurred. "
287                         + "Cleanup aborted.");
288             }
289             return;
290         }
291 
292         // Set time here as we'll either return due to no files or attempt to delete files, after
293         // either of which we should wait before checking again.
294         mLastClearTemporaryDirectoryTimeMs = System.currentTimeMillis();
295 
296         if (files.length == 0) {
297             // No files, nothing to cleanup.
298             if (DEBUG) Log.d(TAG, "No files in temporary directory to cleanup.");
299             return;
300         }
301 
302         // Iterate through and delete them.
303         for (int i = 0; i < files.length; i++) {
304             try {
305                 files[i].delete();
306             } catch (SecurityException e) {
307                 // Exception deleting file, keep trying for the others.
308                 if (DEBUG) Log.d(TAG, "Exception deleting file from temp directory.", e);
309             }
310         }
311     }
312 
313     /**
314      * Return a list of all filenames that are currently tracked in either the in progress
315      * collections or the queued results, including both redacted and unredacted.
316      */
getTrackedFilenames()317     private List<String> getTrackedFilenames() {
318         List<String> filenames = new ArrayList<String>();
319 
320         // If active sessions is not empty, iterate through and add the filenames from each.
321         if (!mTracingSessions.isEmpty()) {
322             for (int i = 0; i < mTracingSessions.size(); i++) {
323                 TracingSession session = mTracingSessions.valueAt(i);
324                 String filename = session.getFileName();
325                 if (filename != null) {
326                     filenames.add(filename);
327                 }
328                 String redactedFilename = session.getRedactedFileName();
329                 if (redactedFilename != null) {
330                     filenames.add(redactedFilename);
331                 }
332             }
333         }
334 
335         // If queued sessions is not empty, iterate through and add the filenames from each.
336         if (mQueuedTracingResults.size() != 0) {
337             for (int i = 0; i < mQueuedTracingResults.size(); i++) {
338                 List<TracingSession> perUidSessions = mQueuedTracingResults.valueAt(i);
339                 if (!perUidSessions.isEmpty()) {
340                     for (int j = 0; j < perUidSessions.size(); j++) {
341                         TracingSession session = perUidSessions.get(j);
342                         String filename = session.getFileName();
343                         if (filename != null) {
344                             filenames.add(filename);
345                         }
346                         String redactedFilename = session.getRedactedFileName();
347                         if (redactedFilename != null) {
348                             filenames.add(redactedFilename);
349                         }
350                     }
351                 }
352             }
353         }
354 
355         return filenames;
356     }
357 
358     /**
359      * This method validates the request, arguments, whether the app is allowed to profile now,
360      * and if so, starts the profiling.
361      */
requestProfiling(int profilingType, Bundle params, String filePath, String tag, long keyMostSigBits, long keyLeastSigBits, String packageName)362     public void requestProfiling(int profilingType, Bundle params, String filePath, String tag,
363             long keyMostSigBits, long keyLeastSigBits, String packageName) {
364         int uid = Binder.getCallingUid();
365 
366         if (profilingType != ProfilingManager.PROFILING_TYPE_JAVA_HEAP_DUMP
367                 && profilingType != ProfilingManager.PROFILING_TYPE_HEAP_PROFILE
368                 && profilingType != ProfilingManager.PROFILING_TYPE_STACK_SAMPLING
369                 && profilingType != ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) {
370             if (DEBUG) Log.d(TAG, "Invalid request profiling type: " + profilingType);
371             processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
372                     ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag,
373                     "Invalid request profiling type");
374             return;
375         }
376 
377         cleanupActiveTracingSessions();
378 
379         // Check if we're running another trace so we don't run multiple at once.
380         try {
381             if (areAnyTracesRunning()) {
382                 processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
383                         ProfilingResult.ERROR_FAILED_PROFILING_IN_PROGRESS, null, tag, null);
384                 return;
385             }
386         } catch (RuntimeException e) {
387             if (DEBUG) Log.d(TAG, "Error communicating with perfetto", e);
388             processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
389                     ProfilingResult.ERROR_UNKNOWN, null, tag, "Error communicating with perfetto");
390             return;
391         }
392 
393         if (packageName == null) {
394             // This shouldn't happen as it should be checked on the app side.
395             if (DEBUG) Log.d(TAG, "PackageName is null");
396             processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
397                     ProfilingResult.ERROR_UNKNOWN, null, tag, "Couldn't determine package name");
398             return;
399         }
400 
401         String[] uidPackages = mContext.getPackageManager().getPackagesForUid(uid);
402         if (uidPackages == null || uidPackages.length == 0) {
403             // Failed to get uids for this package, can't validate package name.
404             if (DEBUG) Log.d(TAG, "Failed to resolve package name");
405             processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
406                     ProfilingResult.ERROR_UNKNOWN, null, tag, "Couldn't determine package name");
407             return;
408         }
409 
410         boolean packageNameInUidList = false;
411         for (int i = 0; i < uidPackages.length; i++) {
412             if (packageName.equals(uidPackages[i])) {
413                 packageNameInUidList = true;
414                 break;
415             }
416         }
417         if (!packageNameInUidList) {
418             // Package name is not associated with calling uid, reject request.
419             if (DEBUG) Log.d(TAG, "Package name not associated with calling uid");
420             processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
421                     ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag,
422                     "Package name not associated with calling uid.");
423             return;
424         }
425 
426         // Check with rate limiter if this request is allowed.
427         final int status = getRateLimiter().isProfilingRequestAllowed(Binder.getCallingUid(),
428                 profilingType, params);
429         if (DEBUG) Log.d(TAG, "Rate limiter status: " + status);
430         if (status == RateLimiter.RATE_LIMIT_RESULT_ALLOWED) {
431             // Rate limiter approved, try to start the request.
432             try {
433                 TracingSession session = new TracingSession(profilingType, params, filePath, uid,
434                         packageName, tag, keyMostSigBits, keyLeastSigBits);
435                 startProfiling(session);
436             } catch (IllegalArgumentException e) {
437                 // This should not happen, it should have been caught when checking rate limiter.
438                 // Issue with the request. Apps fault.
439                 if (DEBUG) {
440                     Log.d(TAG,
441                             "Invalid request at config generation. This should not have happened.",
442                             e);
443                 }
444                 processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
445                         ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, e.getMessage());
446                 return;
447             } catch (RuntimeException e) {
448                 // Perfetto error. Systems fault.
449                 if (DEBUG) Log.d(TAG, "Perfetto error", e);
450                 processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
451                         ProfilingResult.ERROR_UNKNOWN, null, tag, "Perfetto error");
452                 return;
453             }
454         } else {
455             // Rate limiter denied, notify caller.
456             if (DEBUG) Log.d(TAG, "Request denied with status: " + status);
457             processResultCallback(uid, keyMostSigBits, keyLeastSigBits,
458                     RateLimiter.statusToResult(status), null, tag, null);
459         }
460     }
461 
462     /** Call from application to register a callback object. */
registerResultsCallback(boolean isGeneralCallback, IProfilingResultCallback callback)463     public void registerResultsCallback(boolean isGeneralCallback,
464             IProfilingResultCallback callback) {
465         maybeCleanupResultsCallbacks();
466 
467         int callingUid = Binder.getCallingUid();
468         List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(callingUid);
469         if (perUidCallbacks == null) {
470             perUidCallbacks = new ArrayList<IProfilingResultCallback>();
471             mResultCallbacks.put(callingUid, perUidCallbacks);
472         }
473         perUidCallbacks.add(callback);
474 
475         ProfilingDeathRecipient deathRecipient = new ProfilingDeathRecipient(callingUid);
476         try {
477             callback.asBinder().linkToDeath(deathRecipient, 0);
478         } catch (RemoteException e) {
479             // Failed to link death recipient. Ignore.
480             if (DEBUG) Log.d(TAG, "Exception linking death recipient", e);
481         }
482 
483         // Only handle queued results when a new general listener has been added.
484         if (isGeneralCallback) {
485             handleQueuedResults(callingUid);
486         }
487     }
488 
489     /**
490      * Iterate through and delete any callbacks for which binder is not alive.
491      *
492      * Each binder object has a registered linkToDeath which also handles removal. This mechanism
493      * serves as a backup to guarantee that the list stays in check.
494      */
maybeCleanupResultsCallbacks()495     private void maybeCleanupResultsCallbacks() {
496         // Create a temporary list to hold callbacks to be removed.
497         ArrayList<IProfilingResultCallback> callbacksToRemove =
498                 new ArrayList<IProfilingResultCallback>();
499 
500         // Iterate through the results callback, each iteration is for a uid which has registered
501         // callbacks.
502         for (int i = 0; i < mResultCallbacks.size(); i++) {
503             // Ensure the temporary list is empty
504             callbacksToRemove.clear();
505 
506             // Grab the current list of callbacks.
507             List<IProfilingResultCallback> callbacks = mResultCallbacks.valueAt(i);
508 
509             if (callbacks != null && !callbacks.isEmpty()) {
510                 // Now iterate through each of the callbacks for this uid.
511                 for (int j = 0; j < callbacks.size(); j++) {
512                     IProfilingResultCallback callback = callbacks.get(j);
513                     // If the callback is no longer alive, add it to the list for removal.
514                     if (callback == null || !callback.asBinder().isBinderAlive()) {
515                         callbacksToRemove.add(callback);
516                     }
517                 }
518 
519                 // Now remove all the callbacks that were added to the list for removal.
520                 callbacks.removeAll(callbacksToRemove);
521             }
522         }
523     }
524 
525     /**
526      * Call from application to notify that a new global listener was added and can be accessed
527      * through the existing callback object.
528      */
generalListenerAdded()529     public void generalListenerAdded() {
530         handleQueuedResults(Binder.getCallingUid());
531     }
532 
requestCancel(long keyMostSigBits, long keyLeastSigBits)533     public void requestCancel(long keyMostSigBits, long keyLeastSigBits) {
534         String key = (new UUID(keyMostSigBits, keyLeastSigBits)).toString();
535         if (!isTraceRunning(key)) {
536             // No trace running, nothing to cancel.
537             if (DEBUG) {
538                 Log.d(TAG, "Exited requestCancel without stopping trace key:" + key
539                         + " due to no trace running.");
540             }
541             return;
542         }
543         stopProfiling(key);
544     }
545 
546     /**
547      * Method called by manager, after creating a file from within application context, to send a
548      * file descriptor for service to write the result of the profiling session to.
549      *
550      * Note: only expected to be called in response to a generateFile request sent to manager.
551      */
receiveFileDescriptor(ParcelFileDescriptor fileDescriptor, long keyMostSigBits, long keyLeastSigBits)552     public void receiveFileDescriptor(ParcelFileDescriptor fileDescriptor, long keyMostSigBits,
553             long keyLeastSigBits) {
554         List<TracingSession> sessions = mQueuedTracingResults.get(Binder.getCallingUid());
555         if (sessions == null) {
556             // No sessions for this uid, so no profiling result to write to this file descriptor.
557             // Attempt to cleanup.
558             finishReceiveFileDescriptor(null, fileDescriptor, null, null, false);
559             return;
560         }
561 
562         TracingSession session = null;
563         // Iterate through and try to find the session this file is associated with using the
564         // key values. Key values were provided from the session to the generate file call that
565         // triggered this.
566         String key = (new UUID(keyMostSigBits, keyLeastSigBits)).toString();
567         for (int i = 0; i < sessions.size(); i++) {
568             TracingSession tempSession = sessions.get(i);
569             if (tempSession.getKey().equals(key)) {
570                 session = tempSession;
571                 break;
572             }
573         }
574         if (session == null) {
575             // No session for the provided key, nothing to do with this file descriptor. Attempt
576             // to cleanup.
577             finishReceiveFileDescriptor(session, fileDescriptor, null, null, false);
578             return;
579         }
580 
581         // At this point we've identified the session that has sent us this file descriptor.
582         // Now, we'll create a temporary file pointing to the profiling output for that session.
583         // If that file looks good, we'll copy it to the app's local file descriptor.
584         File tempResultFile = new File(TEMP_TRACE_PATH
585                 + (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE
586                 ? session.getRedactedFileName() : session.getFileName()));
587         FileInputStream tempPerfettoFileInStream = null;
588         FileOutputStream appFileOutStream = null;
589 
590         try {
591             if (!tempResultFile.exists() || tempResultFile.length() == 0L) {
592                 // The profiling process output file does not exist or is empty, nothing to copy.
593                 if (DEBUG) {
594                     Log.d(TAG, "Temporary profiling output file is missing or empty, nothing to"
595                             + " copy.");
596                 }
597                 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream,
598                         appFileOutStream, false);
599                 return;
600             }
601         } catch (SecurityException e) {
602             // If we hit a security exception checking file exists or size then we won't be able to
603             // copy it, attempt to cleanup and return.
604             if (DEBUG) {
605                 Log.d(TAG, "Exception checking if temporary file exists and is non-empty", e);
606             }
607             finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream,
608                     appFileOutStream, false);
609             return;
610         }
611 
612         // Only copy the file if we haven't previously.
613         if (session.getState().getValue() < TracingSession.TracingState.COPIED_FILE.getValue()) {
614             // Setup file streams.
615             try {
616                 tempPerfettoFileInStream = new FileInputStream(tempResultFile);
617             } catch (IOException e) {
618                 // IO Exception opening temp perfetto file. No result.
619                 if (DEBUG) Log.d(TAG, "Exception opening temp perfetto file.", e);
620                 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream,
621                         appFileOutStream, false);
622                 return;
623             }
624 
625             // Obtain a file descriptor for the result file in app storage from
626             // {@link ProfilingManager}
627             if (fileDescriptor != null) {
628                 appFileOutStream = new FileOutputStream(fileDescriptor.getFileDescriptor());
629             }
630 
631             if (appFileOutStream == null) {
632                 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream,
633                         appFileOutStream, false);
634                 return;
635             }
636 
637             // Now copy the file over.
638             try {
639                 FileUtils.copy(tempPerfettoFileInStream, appFileOutStream);
640                 session.setState(TracingSession.TracingState.COPIED_FILE);
641             } catch (IOException e) {
642                 // Exception writing to local app file. Attempt to delete the bad copy.
643                 deleteBadCopiedFile(session);
644                 if (DEBUG) Log.d(TAG, "Exception writing to local app file.", e);
645                 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream,
646                         appFileOutStream, false);
647                 return;
648             }
649         }
650 
651         finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream,
652                 appFileOutStream, true);
653     }
654 
finishReceiveFileDescriptor(TracingSession session, ParcelFileDescriptor fileDescriptor, FileInputStream tempPerfettoFileInStream, FileOutputStream appFileOutStream, boolean succeeded)655     private void finishReceiveFileDescriptor(TracingSession session,
656             ParcelFileDescriptor fileDescriptor, FileInputStream tempPerfettoFileInStream,
657             FileOutputStream appFileOutStream, boolean succeeded) {
658         // Cleanup.
659         if (tempPerfettoFileInStream != null) {
660             try {
661                 tempPerfettoFileInStream.close();
662             } catch (IOException e) {
663                 if (DEBUG) Log.d(TAG, "Failed to close temp perfetto input stream.", e);
664             }
665         }
666         if (fileDescriptor != null) {
667             try {
668                 fileDescriptor.close();
669             } catch (IOException e) {
670                 if (DEBUG) Log.d(TAG, "Failed to close app file output file FileDescriptor.", e);
671             }
672         }
673         if (appFileOutStream != null) {
674             try {
675                 appFileOutStream.close();
676             } catch (IOException e) {
677                 if (DEBUG) Log.d(TAG, "Failed to close app file output file stream.", e);
678             }
679         }
680 
681         if (session != null) {
682             finishProcessingResult(session, succeeded);
683         }
684     }
685 
processResultCallback(TracingSession session, int status, @Nullable String error)686     private void processResultCallback(TracingSession session, int status, @Nullable String error) {
687         processResultCallback(session.getUid(), session.getKeyMostSigBits(),
688                 session.getKeyLeastSigBits(), status,
689                 session.getDestinationFileName(OUTPUT_FILE_RELATIVE_PATH),
690                 session.getTag(), error);
691     }
692 
693     /**
694      * An app can register multiple callbacks between this service and {@link ProfilingManager}, one
695      * per context that the app created a manager instance with. As we do not know on this service
696      * side which callbacks need to be triggered with this result, trigger all of them and let them
697      * decide whether to finish delivering it.
698      */
processResultCallback(int uid, long keyMostSigBits, long keyLeastSigBits, int status, @Nullable String filePath, @Nullable String tag, @Nullable String error)699     private void processResultCallback(int uid, long keyMostSigBits, long keyLeastSigBits,
700             int status, @Nullable String filePath, @Nullable String tag, @Nullable String error) {
701         List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(uid);
702         if (perUidCallbacks == null || perUidCallbacks.isEmpty()) {
703             // No callbacks, nowhere to notify with result or failure.
704             if (DEBUG) Log.d(TAG, "No callback to ProfilingManager, callback dropped.");
705             return;
706         }
707 
708         for (int i = 0; i < perUidCallbacks.size(); i++) {
709             try {
710                 perUidCallbacks.get(i).sendResult(filePath, keyMostSigBits, keyLeastSigBits, status,
711                         tag, error);
712             } catch (RemoteException e) {
713                 // Failed to send result. Ignore.
714                 if (DEBUG) Log.d(TAG, "Exception processing result callback", e);
715             }
716         }
717     }
718 
startProfiling(final TracingSession session)719     private void startProfiling(final TracingSession session)
720             throws RuntimeException {
721         // Parse config and post processing delay out of request first, if we can't get these
722         // we can't start the trace.
723         int postProcessingInitialDelayMs;
724         byte[] config;
725         String suffix;
726         String tag;
727         try {
728             postProcessingInitialDelayMs = session.getPostProcessingScheduleDelayMs();
729             config = session.getConfigBytes();
730             suffix = getFileSuffixForRequest(session.getProfilingType());
731 
732             // Create a version of tag that is non null, containing only valid filename chars,
733             // and shortened to class defined max size.
734             tag = session.getTag() == null
735                     ? "" : removeInvalidFilenameChars(session.getTag());
736             if (tag.length() > TAG_MAX_CHARS_FOR_FILENAME) {
737                 tag = tag.substring(0, TAG_MAX_CHARS_FOR_FILENAME);
738             }
739         } catch (IllegalArgumentException e) {
740             // Request couldn't be processed. This shouldn't happen.
741             if (DEBUG) Log.d(TAG, "Request couldn't be processed", e);
742             processResultCallback(session, ProfilingResult.ERROR_FAILED_INVALID_REQUEST,
743                     e.getMessage());
744             return;
745 
746         }
747 
748         String baseFileName = OUTPUT_FILE_PREFIX
749                 + (tag.isEmpty() ? "" : OUTPUT_FILE_SECTION_SEPARATOR + tag)
750                 + OUTPUT_FILE_SECTION_SEPARATOR + getFormattedDate();
751 
752         // Only trace files will go through the redaction process, set the name here for the file
753         // that will be created later when results are processed.
754         if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) {
755             session.setRedactedFileName(baseFileName + OUTPUT_FILE_TRACE_SUFFIX);
756         }
757 
758         session.setFileName(baseFileName + suffix);
759 
760         try {
761             ProcessBuilder pb = new ProcessBuilder("/system/bin/perfetto", "-o",
762                     TEMP_TRACE_PATH + session.getFileName(), "-c", "-");
763             Process activeTrace = pb.start();
764             activeTrace.getOutputStream().write(config);
765             activeTrace.getOutputStream().close();
766             // If we made it this far the trace is running, save the session.
767             session.setActiveTrace(activeTrace);
768             session.setProfilingStartTimeMs(System.currentTimeMillis());
769             mTracingSessions.put(session.getKey(), session);
770         } catch (Exception e) {
771             // Catch all exceptions related to starting process as they'll all be handled similarly.
772             if (DEBUG) Log.d(TAG, "Trace couldn't be started", e);
773             processResultCallback(session, ProfilingResult.ERROR_FAILED_EXECUTING, null);
774             return;
775         }
776 
777         session.setState(TracingSession.TracingState.PROFILING_STARTED);
778 
779         // Create post process runnable, store it, and schedule it.
780         session.setProcessResultRunnable(new Runnable() {
781             @Override
782             public void run() {
783                 // Check if the profiling process is complete or reschedule the check.
784                 checkProfilingCompleteRescheduleIfNeeded(session);
785             }
786         });
787         getHandler().postDelayed(session.getProcessResultRunnable(), postProcessingInitialDelayMs);
788     }
789 
790     /**
791         This method will check if the profiling subprocess is still alive. If it's still alive and
792         there is still time permitted to run, another check will be scheduled. If the process is
793         still alive but max allotted processing time has been exceeded, the profiling process will
794         be stopped and results processed and returned to client. If the profiling process is
795         complete results will be processed and returned to the client.
796      */
checkProfilingCompleteRescheduleIfNeeded(TracingSession session)797     private void checkProfilingCompleteRescheduleIfNeeded(TracingSession session) {
798 
799         long processingTimeRemaining = session.getMaxProfilingTimeAllowedMs()
800                 - (System.currentTimeMillis() - session.getProfilingStartTimeMs());
801 
802         if (session.getActiveTrace().isAlive()
803                 && processingTimeRemaining >= 0) {
804             // still running and under max allotted processing time, reschedule the check.
805             getHandler().postDelayed(session.getProcessResultRunnable(),
806                     Math.min(mProfilingRecheckDelayMs, processingTimeRemaining));
807         } else if (session.getActiveTrace().isAlive()
808                 && processingTimeRemaining < 0) {
809             // still running but exceeded max allotted processing time, stop profiling and deliver
810             // what results are available.
811             stopProfiling(session.getKey());
812         } else {
813             // complete, process results and deliver.
814             session.setProcessResultRunnable(null);
815             processResult(session);
816         }
817     }
818 
819     /** Stop any active profiling sessions belonging to the provided uid. */
stopAllProfilingForUid(int uid)820     private void stopAllProfilingForUid(int uid) {
821         if (mTracingSessions.isEmpty()) {
822             // If there are no active traces, then there are none for this uid.
823             return;
824         }
825 
826         // Iterate through active sessions and stop profiling if they belong to the provided uid.
827         // Note: Currently, this will only ever have 1 session.
828         for (int i = 0; i < mTracingSessions.size(); i++) {
829             TracingSession session = mTracingSessions.valueAt(i);
830             if (session.getUid() == uid) {
831                 stopProfiling(session);
832             }
833         }
834     }
835 
stopProfiling(String key)836     private void stopProfiling(String key) throws RuntimeException {
837         TracingSession session = mTracingSessions.get(key);
838         stopProfiling(session);
839     }
840 
stopProfiling(TracingSession session)841     private void stopProfiling(TracingSession session) throws RuntimeException {
842         if (session == null || session.getActiveTrace() == null) {
843             if (DEBUG) Log.d(TAG, "No active trace, nothing to stop.");
844             return;
845         }
846 
847         if (session.getProcessResultRunnable() == null) {
848             if (DEBUG) {
849                 Log.d(TAG,
850                         "No runnable, it either stopped already or is in the process of stopping.");
851             }
852             return;
853         }
854 
855         // Remove the post processing runnable set with the default timeout. After stopping use the
856         // same runnable to process immediately.
857         getHandler().removeCallbacks(session.getProcessResultRunnable());
858 
859         // End the tracing session.
860         session.getActiveTrace().destroyForcibly();
861         try {
862             if (!session.getActiveTrace().waitFor(mPerfettoDestroyTimeoutMs,
863                     TimeUnit.MILLISECONDS)) {
864                 if (DEBUG) Log.d(TAG, "Stopping of running trace process timed out.");
865                 throw new RuntimeException("Stopping of running trace process timed out.");
866             }
867         } catch (InterruptedException e) {
868             throw new RuntimeException(e);
869         }
870 
871         // If we made it here the result is ready, now run the post processing runnable.
872         getHandler().post(session.getProcessResultRunnable());
873     }
874 
areAnyTracesRunning()875     public boolean areAnyTracesRunning() throws RuntimeException {
876         for (int i = 0; i < mTracingSessions.size(); i++) {
877             if (isTraceRunning(mTracingSessions.keyAt(i))) {
878                 return true;
879             }
880         }
881         return false;
882     }
883 
884     /**
885      * Cleanup the data structure of active sessions. Non active sessions are never expected to be
886      * present in {@link mTracingSessions} as they would be moved to {@link mQueuedTracingResults}
887      * when profiling completes. If a session is present but not running, remove it. If a session
888      * has a not alive process, try to stop it.
889      */
cleanupActiveTracingSessions()890     public void cleanupActiveTracingSessions() throws RuntimeException {
891         // Create a temporary list to store the keys of sessions to be stopped.
892         ArrayList<String> sessionsToStop = new ArrayList<String>();
893 
894         // Iterate through in reverse order so we can immediately remove the non running sessions
895         // that don't have to be stopped.
896         for (int i = mTracingSessions.size() - 1; i >= 0; i--) {
897             String key = mTracingSessions.keyAt(i);
898             TracingSession session = mTracingSessions.get(key);
899 
900             if (session == null || session.getActiveTrace() == null) {
901                 // Profiling isn't running, remove from list.
902                 mTracingSessions.removeAt(i);
903             } else if (!session.getActiveTrace().isAlive()) {
904                 // Profiling process exists but isn't alive, add to list of sessions to stop. Do not
905                 // stop here due to potential unanticipated modification of list being iterated
906                 // through.
907                 sessionsToStop.add(key);
908             }
909         }
910 
911         // If we have any sessions to stop, now is the time.
912         if (!sessionsToStop.isEmpty()) {
913             for (int i = 0; i < sessionsToStop.size(); i++) {
914                 stopProfiling(sessionsToStop.get(i));
915             }
916         }
917     }
918 
isTraceRunning(String key)919     public boolean isTraceRunning(String key) throws RuntimeException {
920         TracingSession session = mTracingSessions.get(key);
921         if (session == null || session.getActiveTrace() == null) {
922             // No subprocess, nothing running.
923             if (DEBUG) Log.d(TAG, "No subprocess, nothing running.");
924             return false;
925         } else if (session.getActiveTrace().isAlive()) {
926             // Subprocess exists and is alive.
927             if (DEBUG) Log.d(TAG, "Subprocess exists and is alive, trace is running.");
928             return true;
929         } else {
930             // Subprocess exists but is not alive, nothing running.
931             if (DEBUG) Log.d(TAG, "Subprocess exists but is not alive, nothing running.");
932             return false;
933         }
934     }
935 
936     /**
937      * Begin moving result to storage by validating and then sending a request to
938      * {@link ProfilingManager} for a file to write to. File will be returned as a
939      * {@link ParcelFileDescriptor} via {@link sendFileDescriptor}.
940      */
941     @VisibleForTesting
beginMoveFileToAppStorage(TracingSession session)942     public void beginMoveFileToAppStorage(TracingSession session) {
943         if (session.getState() == TracingSession.TracingState.DISCARDED) {
944             // This should not have happened, if the session was discarded why are we trying to
945             // continue processing it? Remove from all data stores just in case.
946             if (DEBUG) {
947                 Log.d(TAG, "Attempted beginMoveFileToAppStorage on a session with status discarded"
948                         + " or an invalid status.");
949             }
950             mTracingSessions.remove(session.getKey());
951             cleanupTracingSession(session);
952             return;
953         }
954 
955         List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(session.getUid());
956         if (perUidCallbacks == null || perUidCallbacks.isEmpty()) {
957             // No callback so no way to obtain a file to populate with result.
958             if (DEBUG) Log.d(TAG, "No callback to ProfilingManager, callback dropped.");
959             // TODO: b/333456916 run a cleanup of old results based on a max size and time.
960             return;
961         }
962 
963         requestFileForResult(perUidCallbacks, session);
964     }
965 
966     /**
967      * Finish processing profiling result by sending the appropriate callback and cleaning up
968      * temporary directory.
969      */
970     @VisibleForTesting
finishProcessingResult(TracingSession session, boolean success)971     public void finishProcessingResult(TracingSession session, boolean success) {
972         if (success) {
973             processResultCallback(session, ProfilingResult.ERROR_NONE, null);
974             cleanupTracingSession(session);
975         } else {
976             // Couldn't move file. File is still in temp directory and will be tried later.
977             if (DEBUG) Log.d(TAG, "Couldn't move file to app storage.");
978             processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null);
979         }
980 
981         // Clean up temporary directory if it has been long enough to warrant it.
982         maybeCleanupTemporaryDirectory();
983     }
984 
985     /**
986      * Delete a file which failed to copy via ProfilingManager.
987      */
deleteBadCopiedFile(TracingSession session)988     private void deleteBadCopiedFile(TracingSession session) {
989         List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(session.getUid());
990         for (int i = 0; i < perUidCallbacks.size(); i++) {
991             try {
992                 String fileName =
993                         session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE
994                         ? session.getRedactedFileName() : session.getFileName();
995                 IProfilingResultCallback callback = perUidCallbacks.get(i);
996                 if (callback.asBinder().isBinderAlive()) {
997                     callback.deleteFile(
998                             session.getAppFilePath() + OUTPUT_FILE_RELATIVE_PATH + fileName);
999                     // Only need one delete call, return.
1000                     return;
1001                 }
1002             } catch (RemoteException e) {
1003                 // Binder exception deleting file. Continue trying other callbacks for this process.
1004                 if (DEBUG) Log.d(TAG, "Binder exception deleting file. Trying next callback", e);
1005             }
1006         }
1007     }
1008 
1009     /**
1010      * Request a {@link ParcelFileDescriptor} to a new file in app storage from the first live
1011      * callback for this uid.
1012      *
1013      * The new file is created by {@link ProfilingManager} from within app context. We only need a
1014      * single file, which can be created from any of the contexts belonging to the app that
1015      * requested this profiling, so it does not matter which of the requesting app's callbacks we
1016      * use.
1017      */
1018     @Nullable
requestFileForResult( @onNull List<IProfilingResultCallback> perUidCallbacks, TracingSession session)1019     private void requestFileForResult(
1020             @NonNull List<IProfilingResultCallback> perUidCallbacks, TracingSession session) {
1021         String filePath = session.getAppFilePath() + OUTPUT_FILE_RELATIVE_PATH;
1022         String fileName = session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE
1023                 ? session.getRedactedFileName()
1024                 : session.getFileName();
1025         for (int i = 0; i < perUidCallbacks.size(); i++) {
1026             try {
1027                 IProfilingResultCallback callback = perUidCallbacks.get(i);
1028                 if (callback.asBinder().isBinderAlive()) {
1029                     // Great, this one works! Call it and exit if we don't hit an exception.
1030                     perUidCallbacks.get(i).generateFile(filePath, fileName,
1031                             session.getKeyMostSigBits(), session.getKeyLeastSigBits());
1032                     return;
1033                 }
1034             } catch (RemoteException e) {
1035                 // Binder exception getting file. Continue trying other callbacks for this process.
1036                 if (DEBUG) Log.d(TAG, "Binder exception getting file. Trying next callback", e);
1037             }
1038         }
1039         if (DEBUG) Log.d(TAG, "Failed to obtain file descriptor from callbacks.");
1040     }
1041 
1042 
1043     // processResult will be called after every profiling type is collected, traces will go
1044     // through a redaction process before being returned to the client.  All other profiling types
1045     // can be returned as is.
processResult(TracingSession session)1046     private void processResult(TracingSession session) {
1047         // Move this session from active to queued results.
1048         List<TracingSession> queuedResults = mQueuedTracingResults.get(session.getUid());
1049         if (queuedResults == null) {
1050             queuedResults = new ArrayList<TracingSession>();
1051             mQueuedTracingResults.put(session.getUid(), queuedResults);
1052         }
1053         queuedResults.add(session);
1054         mTracingSessions.remove(session.getKey());
1055 
1056         session.setState(TracingSession.TracingState.PROFILING_FINISHED);
1057 
1058         if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) {
1059             handleTraceResult(session);
1060         } else {
1061             beginMoveFileToAppStorage(session);
1062         }
1063     }
1064 
1065     /** Handle a trace result by attempting to kick off redaction process. */
1066     @VisibleForTesting
handleTraceResult(TracingSession session)1067     public void handleTraceResult(TracingSession session) {
1068         try {
1069             // We need to create an empty file for the redaction process to write the output into.
1070             File emptyRedactedTraceFile = new File(TEMP_TRACE_PATH
1071                     + session.getRedactedFileName());
1072             emptyRedactedTraceFile.createNewFile();
1073         } catch (Exception exception) {
1074             if (DEBUG) Log.e(TAG, "Creating empty redacted file failed.", exception);
1075             processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null);
1076             return;
1077         }
1078 
1079         try {
1080             // Start the redaction process and log the time of start.  Redaction has
1081             // mRedactionMaxRuntimeAllottedMs to complete. Redaction status will be checked every
1082             // mRedactionCheckFrequencyMs.
1083             ProcessBuilder redactionProcess = new ProcessBuilder("/system/bin/trace_redactor",
1084                     TEMP_TRACE_PATH + session.getFileName(),
1085                     TEMP_TRACE_PATH + session.getRedactedFileName(),
1086                     session.getPackageName());
1087             session.setActiveRedaction(redactionProcess.start());
1088             session.setRedactionStartTimeMs(System.currentTimeMillis());
1089         } catch (Exception exception) {
1090             if (DEBUG) Log.e(TAG, "Redaction failed to run completely.", exception);
1091             processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null);
1092             return;
1093         }
1094         session.setProcessResultRunnable(new Runnable() {
1095 
1096             @Override
1097             public void run() {
1098                 checkRedactionStatus(session);
1099             }
1100         });
1101 
1102         getHandler().postDelayed(session.getProcessResultRunnable(),
1103                 mRedactionCheckFrequencyMs);
1104     }
1105 
checkRedactionStatus(TracingSession session)1106     private void checkRedactionStatus(TracingSession session) {
1107         // Check if redaction is complete.
1108         if (!session.getActiveRedaction().isAlive()) {
1109             handleRedactionComplete(session);
1110             session.setProcessResultRunnable(null);
1111             return;
1112         }
1113 
1114         // Check if we are over the mRedactionMaxRuntimeAllottedMs threshold.
1115         if ((System.currentTimeMillis() - session.getRedactionStartTimeMs())
1116                 > mRedactionMaxRuntimeAllottedMs) {
1117             if (DEBUG) Log.d(TAG, "Redaction process has timed out");
1118 
1119             session.getActiveRedaction().destroyForcibly();
1120             session.setProcessResultRunnable(null);
1121             processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING,
1122                     null);
1123 
1124             return;
1125         }
1126         getHandler().postDelayed(session.getProcessResultRunnable(),
1127                 Math.min(mRedactionCheckFrequencyMs, mRedactionMaxRuntimeAllottedMs
1128                         - (System.currentTimeMillis() - session.getRedactionStartTimeMs())));
1129 
1130     }
1131 
handleRedactionComplete(TracingSession session)1132     private void handleRedactionComplete(TracingSession session) {
1133         int redactionErrorCode = session.getActiveRedaction().exitValue();
1134         if (redactionErrorCode != 0) {
1135             // Redaction process failed. This failure cannot be recovered.
1136             if (DEBUG) {
1137                 Log.d(TAG, String.format("Redaction processed failed with error code: %s",
1138                         redactionErrorCode));
1139             }
1140             cleanupTracingSession(session);
1141             processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null);
1142             return;
1143         }
1144 
1145         // At this point redaction has completed successfully it is safe to delete the
1146         // unredacted trace file unless {@link mKeepUnredactedTrace} has been enabled.
1147         synchronized (mLock) {
1148             if (mKeepUnredactedTrace) {
1149                 Log.i(TAG, "Unredacted trace file retained at: "
1150                         + TEMP_TRACE_PATH + session.getFileName());
1151             } else {
1152                 // TODO b/331988161 Delete after file is delivered to app.
1153                 maybeDeleteUnredactedTrace(session);
1154             }
1155         }
1156 
1157         session.setState(TracingSession.TracingState.REDACTED);
1158 
1159         beginMoveFileToAppStorage(session);
1160     }
1161 
1162     /**
1163      * Called whenever a new global listener has been added to the specified uid.
1164      * Attempts to process queued results if present.
1165      */
1166     @VisibleForTesting
handleQueuedResults(int uid)1167     public void handleQueuedResults(int uid) {
1168         List<TracingSession> queuedSessions = mQueuedTracingResults.get(uid);
1169         if (queuedSessions == null || queuedSessions.isEmpty()) {
1170             // No queued results for this uid, nothing to handle. Attempt to cleanup the queue for
1171             // all other uids before exiting.
1172             maybeCleanupQueue();
1173             return;
1174         }
1175 
1176         // Triggering the callbacks may result in the object being removed from the class level
1177         // queue list, ensure this remains safe by using a unmodifiable shallow copy of the list.
1178         List<TracingSession> unmodifiableQueuedSessions = List.copyOf(queuedSessions);
1179         for (int i = 0; i < unmodifiableQueuedSessions.size(); i++) {
1180             TracingSession session = unmodifiableQueuedSessions.get(i);
1181 
1182             // Check if we already retried too many times and discard the result if we have.
1183             if (session.getRetryCount() >= mMaxResultRedeliveryCount) {
1184                 cleanupTracingSession(session, queuedSessions);
1185                 continue;
1186             }
1187             session.incrementRetryCount();
1188 
1189             switch (session.getState()) {
1190                 case NOT_STARTED:
1191                 case PROFILING_STARTED:
1192                     // This should never happen as the session should not be in queuedSessions until
1193                     // past this state, but run stop and cleanup just in case.
1194                     stopProfiling(session);
1195                     cleanupTracingSession(session);
1196                     break;
1197                 case PROFILING_FINISHED:
1198                     if (session.getProfilingType()
1199                             == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) {
1200                         handleTraceResult(session);
1201                     } else {
1202                         beginMoveFileToAppStorage(session);
1203                     }
1204                     break;
1205                 case REDACTED:
1206                     beginMoveFileToAppStorage(session);
1207                     break;
1208                 case COPIED_FILE:
1209                     finishProcessingResult(session, true);
1210                     break;
1211                 case DISCARDED:
1212                     // This should never happen as this state should only occur after cleanup of
1213                     // this file.
1214                     cleanupTracingSession(session, queuedSessions);
1215                     break;
1216             }
1217         }
1218 
1219         // Now attempt to cleanup the queue.
1220         maybeCleanupQueue();
1221     }
1222 
1223     /** Run through all queued sessions and clean up the ones that are too old. */
maybeCleanupQueue()1224     private void maybeCleanupQueue() {
1225         List<TracingSession> sessionsToRemove = new ArrayList();
1226         // Iterate in reverse so we can remove the index if empty.
1227         for (int i = mQueuedTracingResults.size() - 1; i >= 0; i--) {
1228             List<TracingSession> sessions = mQueuedTracingResults.valueAt(i);
1229             if (sessions != null && !sessions.isEmpty()) {
1230                 sessionsToRemove.clear();
1231                 for (int j = 0; j < sessions.size(); j++) {
1232                     TracingSession session = sessions.get(j);
1233                     if (session.getProfilingStartTimeMs() + QUEUED_RESULT_MAX_RETAINED_DURATION_MS
1234                             < System.currentTimeMillis()) {
1235                         cleanupTracingSession(session);
1236                         sessionsToRemove.add(session);
1237                     }
1238                 }
1239                 sessions.removeAll(sessionsToRemove);
1240                 if (sessions.isEmpty()) {
1241                     mQueuedTracingResults.removeAt(i);
1242                 }
1243             } else {
1244                 mQueuedTracingResults.removeAt(i);
1245             }
1246         }
1247     }
1248 
1249     /**
1250      * Cleanup is intended for when we're done with a queued trace session, whether successful or
1251      * not.
1252      *
1253      * Cleanup will attempt to delete the temporary file(s) and then remove it from the queue.
1254      */
cleanupTracingSession(TracingSession session)1255     private void cleanupTracingSession(TracingSession session) {
1256         List<TracingSession> queuedSessions = mQueuedTracingResults.get(session.getUid());
1257         cleanupTracingSession(session, queuedSessions);
1258     }
1259 
1260     /**
1261      * Cleanup is intended for when we're done with a queued trace session, whether successful or
1262      * not.
1263      *
1264      * Cleanup will attempt to delete the temporary file(s) and then remove it from the queue.
1265      */
cleanupTracingSession(TracingSession session, List<TracingSession> queuedSessions)1266     private void cleanupTracingSession(TracingSession session,
1267             List<TracingSession> queuedSessions) {
1268         // Delete all files
1269         if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) {
1270             // If type is trace, try to delete the temp file only if {@link mKeepUnredactedTrace} is
1271             // false, and always try to delete redacted file.
1272             maybeDeleteUnredactedTrace(session);
1273             try {
1274                 Files.delete(Path.of(TEMP_TRACE_PATH + session.getRedactedFileName()));
1275             } catch (Exception exception) {
1276                 if (DEBUG) Log.e(TAG, "Failed to delete file for discarded record.", exception);
1277             }
1278         } else {
1279             // If type is not trace, try to delete the temp file. There is no redacted file.
1280             try {
1281                 Files.delete(Path.of(TEMP_TRACE_PATH + session.getFileName()));
1282             } catch (Exception exception) {
1283                 if (DEBUG) Log.e(TAG, "Failed to delete file for discarded record.", exception);
1284             }
1285 
1286         }
1287 
1288         session.setState(TracingSession.TracingState.DISCARDED);
1289         queuedSessions.remove(session);
1290 
1291         if (queuedSessions.isEmpty()) {
1292             mQueuedTracingResults.remove(session.getUid());
1293         }
1294     }
1295 
1296     /**
1297      * Attempt to delete unredacted trace unless mKeepUnredactedTrace is enabled.
1298      *
1299      * Note: only to be called for types that support redaction.
1300      */
maybeDeleteUnredactedTrace(TracingSession session)1301     private void maybeDeleteUnredactedTrace(TracingSession session) {
1302         synchronized (mLock) {
1303             if (mKeepUnredactedTrace) {
1304                 return;
1305             }
1306             try {
1307                 Files.delete(Path.of(TEMP_TRACE_PATH + session.getFileName()));
1308             } catch (Exception exception) {
1309                 if (DEBUG) Log.e(TAG, "Failed to delete file.", exception);
1310             }
1311         }
1312     }
1313 
getHandler()1314     private Handler getHandler() {
1315         if (mHandler == null) {
1316             mHandler = new Handler(mHandlerThread.getLooper());
1317         }
1318         return mHandler;
1319     }
1320 
getRateLimiter()1321     private RateLimiter getRateLimiter() {
1322         if (mRateLimiter == null) {
1323             mRateLimiter = new RateLimiter(new RateLimiter.HandlerCallback() {
1324                 @Override
1325                 public Handler obtainHandler() {
1326                     return getHandler();
1327                 }
1328             });
1329         }
1330         return mRateLimiter;
1331     }
1332 
getFormattedDate()1333     private String getFormattedDate() {
1334         if (mCalendar == null) {
1335             mCalendar = Calendar.getInstance(TimeZone.getTimeZone("GMT"));
1336         }
1337         if (mDateFormat == null) {
1338             mDateFormat = new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss", Locale.US);
1339         }
1340         mCalendar.setTimeInMillis(System.currentTimeMillis());
1341         return mDateFormat.format(mCalendar.getTime());
1342     }
1343 
getFileSuffixForRequest(int profilingType)1344     private static String getFileSuffixForRequest(int profilingType) {
1345         switch (profilingType) {
1346             case ProfilingManager.PROFILING_TYPE_JAVA_HEAP_DUMP:
1347                 return OUTPUT_FILE_JAVA_HEAP_DUMP_SUFFIX;
1348             case ProfilingManager.PROFILING_TYPE_HEAP_PROFILE:
1349                 return OUTPUT_FILE_HEAP_PROFILE_SUFFIX;
1350             case ProfilingManager.PROFILING_TYPE_STACK_SAMPLING:
1351                 return OUTPUT_FILE_STACK_SAMPLING_SUFFIX;
1352             case ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE:
1353                 return OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX;
1354             default:
1355                 throw new IllegalArgumentException("Invalid profiling type");
1356         }
1357     }
1358 
removeInvalidFilenameChars(String original)1359     private static String removeInvalidFilenameChars(String original) {
1360         if (TextUtils.isEmpty(original)) {
1361             return "";
1362         }
1363         final StringBuilder sb = new StringBuilder(original.length());
1364         for (int i = 0; i < original.length(); i++) {
1365             final char c = Character.toLowerCase(original.charAt(i));
1366             if (isValidFilenameChar(c)) {
1367                 sb.append(c);
1368             }
1369         }
1370         return sb.toString();
1371     }
1372 
isValidFilenameChar(char c)1373     private static boolean isValidFilenameChar(char c) {
1374         if (c >= 'a' && c <= 'z') {
1375             return true;
1376         }
1377         if (c >= '0' && c <= '9') {
1378             return true;
1379         }
1380         if (c == '-') {
1381             return true;
1382         }
1383         return false;
1384     }
1385 
1386     private class ProfilingDeathRecipient implements IBinder.DeathRecipient {
1387         private final int mUid;
1388 
ProfilingDeathRecipient(int uid)1389         ProfilingDeathRecipient(int uid) {
1390             mUid = uid;
1391         }
1392 
1393         @Override
binderDied()1394         public void binderDied() {
1395             if (DEBUG) Log.d(TAG, "binderDied without who should not have been called");
1396         }
1397 
1398         @Override
binderDied(IBinder who)1399         public void binderDied(IBinder who) {
1400             // Synchronize because multiple binder died callbacks may occur simultaneously
1401             // on different threads and we want to ensure that when an app dies (i.e. all
1402             // binder objects die) we attempt to stop profiling exactly once.
1403             synchronized (mLock) {
1404                 List<IProfilingResultCallback> callbacks = mResultCallbacks.get(mUid);
1405 
1406                 if (callbacks == null) {
1407                     // No callbacks list for this uid, this likely means profiling was already
1408                     // stopped (i.e. this is not the first binderDied call for this death).
1409                     return;
1410                 }
1411 
1412                 // Callbacks aren't valid anymore, remove the list.
1413                 mResultCallbacks.remove(mUid);
1414 
1415                 // Finally, attempt to stop profiling. Once the profiling is stopped, processing
1416                 // will continue as usual and will fail at copy to app storage which is the next
1417                 // step that requires the now dead binder objects. The failure will result in the
1418                 // session being added to {@link mQueueTracingResults} and being delivered to the
1419                 // app the next time it registers a general listener.
1420                 stopAllProfilingForUid(mUid);
1421             }
1422         }
1423     }
1424 
1425     public static final class Lifecycle extends SystemService {
1426         final ProfilingService mService;
1427 
Lifecycle(Context context)1428         public Lifecycle(Context context) {
1429             this(context, new ProfilingService(context));
1430         }
1431 
1432         @VisibleForTesting
Lifecycle(Context context, ProfilingService service)1433         public Lifecycle(Context context, ProfilingService service) {
1434             super(context);
1435             mService = service;
1436         }
1437 
1438         @Override
onStart()1439         public void onStart() {
1440             try {
1441                 publishBinderService("profiling_service", mService);
1442             } catch (Exception e) {
1443                 if (DEBUG) Log.d(TAG, "Failed to publish service", e);
1444             }
1445         }
1446 
1447         @Override
onBootPhase(int phase)1448         public void onBootPhase(int phase) {
1449             super.onBootPhase(phase);
1450         }
1451     }
1452 }
1453