Separate job service for dynamic code logging.

Decouple logging of dynamic code loading from background DEX
optimisation/reconciliation (BackgroundDexOptService).

Add DynamicCodeLoggingService to run DCL logging daily while idle and
charging.

Update DexLoggerIntegrationTests to use the new job, and to verify
that we now handle unknown class loaders.

Bug: 111336847
Test: atest -p services/core/java/com/android/server/pm/dex
Change-Id: Id688a7eef5976120be12606e726830ce32451a1e
diff --git a/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java b/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java
new file mode 100644
index 0000000..2ae424d
--- /dev/null
+++ b/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java
@@ -0,0 +1,115 @@
+/*
+ * Copyright 2018 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.pm;
+
+import android.app.job.JobInfo;
+import android.app.job.JobParameters;
+import android.app.job.JobScheduler;
+import android.app.job.JobService;
+import android.content.ComponentName;
+import android.content.Context;
+import android.os.ServiceManager;
+import android.util.Log;
+
+import com.android.server.pm.dex.DexLogger;
+
+import java.util.concurrent.TimeUnit;
+
+/**
+ * Scheduled job to trigger logging of app dynamic code loading. This runs daily while idle and
+ * charging. The actual logging is performed by {@link DexLogger}.
+ * {@hide}
+ */
+public class DynamicCodeLoggingService extends JobService {
+    private static final String TAG = DynamicCodeLoggingService.class.getName();
+
+    private static final int JOB_ID = 2030028;
+    private static final long PERIOD_MILLIS = TimeUnit.DAYS.toMillis(1);
+
+    private volatile boolean mStopRequested = false;
+
+    private static final boolean DEBUG = false;
+
+    /**
+     * Schedule our job with the {@link JobScheduler}.
+     */
+    public static void schedule(Context context) {
+        ComponentName serviceName = new ComponentName(
+                "android", DynamicCodeLoggingService.class.getName());
+
+        JobScheduler js = (JobScheduler) context.getSystemService(Context.JOB_SCHEDULER_SERVICE);
+        js.schedule(new JobInfo.Builder(JOB_ID, serviceName)
+                .setRequiresDeviceIdle(true)
+                .setRequiresCharging(true)
+                .setPeriodic(PERIOD_MILLIS)
+                .build());
+        if (DEBUG) {
+            Log.d(TAG, "Job scheduled");
+        }
+    }
+
+    @Override
+    public boolean onStartJob(JobParameters params) {
+        if (DEBUG) {
+            Log.d(TAG, "onStartJob");
+        }
+        mStopRequested = false;
+        new IdleLoggingThread(params).start();
+        return true;  // Job is running on another thread
+    }
+
+    @Override
+    public boolean onStopJob(JobParameters params) {
+        if (DEBUG) {
+            Log.d(TAG, "onStopJob");
+        }
+        mStopRequested = true;
+        return true;  // Requests job be re-scheduled.
+    }
+
+    private class IdleLoggingThread extends Thread {
+        private final JobParameters mParams;
+
+        IdleLoggingThread(JobParameters params) {
+            super("DynamicCodeLoggingService_IdleLoggingJob");
+            mParams = params;
+        }
+
+        @Override
+        public void run() {
+            if (DEBUG) {
+                Log.d(TAG, "Starting logging run");
+            }
+
+            PackageManagerService pm = (PackageManagerService) ServiceManager.getService("package");
+            DexLogger dexLogger = pm.getDexManager().getDexLogger();
+            for (String packageName : dexLogger.getAllPackagesWithDynamicCodeLoading()) {
+                if (mStopRequested) {
+                    Log.w(TAG, "Stopping logging run at scheduler request");
+                    return;
+                }
+
+                dexLogger.logDynamicCodeLoading(packageName);
+            }
+
+            jobFinished(mParams, /* reschedule */ false);
+            if (DEBUG) {
+                Log.d(TAG, "Finished logging run");
+            }
+        }
+    }
+}
diff --git a/services/core/java/com/android/server/pm/PackageManagerService.java b/services/core/java/com/android/server/pm/PackageManagerService.java
index edab94c..9aebee0 100644
--- a/services/core/java/com/android/server/pm/PackageManagerService.java
+++ b/services/core/java/com/android/server/pm/PackageManagerService.java
@@ -304,7 +304,6 @@
 import com.android.server.pm.Settings.DatabaseVersion;
 import com.android.server.pm.Settings.VersionInfo;
 import com.android.server.pm.dex.ArtManagerService;
-import com.android.server.pm.dex.DexLogger;
 import com.android.server.pm.dex.DexManager;
 import com.android.server.pm.dex.DexoptOptions;
 import com.android.server.pm.dex.PackageDexUsage;
@@ -2168,10 +2167,7 @@
 
         mPackageDexOptimizer = new PackageDexOptimizer(installer, mInstallLock, context,
                 "*dexopt*");
-        DexManager.Listener dexManagerListener = DexLogger.getListener(this,
-                installer, mInstallLock);
-        mDexManager = new DexManager(mContext, this, mPackageDexOptimizer, installer, mInstallLock,
-                dexManagerListener);
+        mDexManager = new DexManager(mContext, this, mPackageDexOptimizer, installer, mInstallLock);
         mArtManagerService = new ArtManagerService(mContext, this, installer, mInstallLock);
         mMoveCallbacks = new MoveCallbacks(FgThread.get().getLooper());
 
@@ -9215,7 +9211,7 @@
 
     /**
      * Reconcile the information we have about the secondary dex files belonging to
-     * {@code packagName} and the actual dex files. For all dex files that were
+     * {@code packageName} and the actual dex files. For all dex files that were
      * deleted, update the internal records and delete the generated oat files.
      */
     @Override
diff --git a/services/core/java/com/android/server/pm/dex/DexLogger.java b/services/core/java/com/android/server/pm/dex/DexLogger.java
index 88d9e52..68a755b 100644
--- a/services/core/java/com/android/server/pm/dex/DexLogger.java
+++ b/services/core/java/com/android/server/pm/dex/DexLogger.java
@@ -18,29 +18,32 @@
 
 import android.content.pm.ApplicationInfo;
 import android.content.pm.IPackageManager;
+import android.content.pm.PackageInfo;
+import android.os.FileUtils;
 import android.os.RemoteException;
-
-import android.util.ArraySet;
+import android.os.storage.StorageManager;
 import android.util.ByteStringUtils;
 import android.util.EventLog;
 import android.util.PackageUtils;
 import android.util.Slog;
+import android.util.SparseArray;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.annotations.VisibleForTesting;
 import com.android.server.pm.Installer;
 import com.android.server.pm.Installer.InstallerException;
+import com.android.server.pm.dex.PackageDynamicCodeLoading.DynamicCodeFile;
+import com.android.server.pm.dex.PackageDynamicCodeLoading.PackageDynamicCode;
 
 import java.io.File;
+import java.util.Map;
 import java.util.Set;
 
-import static com.android.server.pm.dex.PackageDexUsage.DexUseInfo;
-
 /**
  * This class is responsible for logging data about secondary dex files.
  * The data logged includes hashes of the name and content of each file.
  */
-public class DexLogger implements DexManager.Listener {
+public class DexLogger {
     private static final String TAG = "DexLogger";
 
     // Event log tag & subtag used for SafetyNet logging of dynamic
@@ -49,75 +52,172 @@
     private static final String DCL_SUBTAG = "dcl";
 
     private final IPackageManager mPackageManager;
+    private final PackageDynamicCodeLoading mPackageDynamicCodeLoading;
     private final Object mInstallLock;
     @GuardedBy("mInstallLock")
     private final Installer mInstaller;
 
-    public static DexManager.Listener getListener(IPackageManager pms,
-            Installer installer, Object installLock) {
-        return new DexLogger(pms, installer, installLock);
+    public DexLogger(IPackageManager pms, Installer installer, Object installLock) {
+        this(pms, installer, installLock, new PackageDynamicCodeLoading());
     }
 
     @VisibleForTesting
-    /*package*/ DexLogger(IPackageManager pms, Installer installer, Object installLock) {
+    DexLogger(IPackageManager pms, Installer installer, Object installLock,
+            PackageDynamicCodeLoading packageDynamicCodeLoading) {
         mPackageManager = pms;
+        mPackageDynamicCodeLoading = packageDynamicCodeLoading;
         mInstaller = installer;
         mInstallLock = installLock;
     }
 
-    /**
-     * Compute and log hashes of the name and content of a secondary dex file.
-     */
-    @Override
-    public void onReconcileSecondaryDexFile(ApplicationInfo appInfo, DexUseInfo dexUseInfo,
-            String dexPath, int storageFlags) {
-        int ownerUid = appInfo.uid;
+    public Set<String> getAllPackagesWithDynamicCodeLoading() {
+        return mPackageDynamicCodeLoading.getAllPackagesWithDynamicCodeLoading();
+    }
 
-        byte[] hash = null;
-        synchronized(mInstallLock) {
-            try {
-                hash = mInstaller.hashSecondaryDexFile(dexPath, appInfo.packageName,
-                        ownerUid, appInfo.volumeUuid, storageFlags);
-            } catch (InstallerException e) {
-                Slog.e(TAG, "Got InstallerException when hashing dex " + dexPath +
-                        " : " + e.getMessage());
-            }
-        }
-        if (hash == null) {
+    /**
+     * Write information about code dynamically loaded by {@code packageName} to the event log.
+     */
+    public void logDynamicCodeLoading(String packageName) {
+        PackageDynamicCode info = getPackageDynamicCodeInfo(packageName);
+        if (info == null) {
             return;
         }
 
-        String dexFileName = new File(dexPath).getName();
-        String message = PackageUtils.computeSha256Digest(dexFileName.getBytes());
-        // Valid SHA256 will be 256 bits, 32 bytes.
-        if (hash.length == 32) {
-            message = message + ' ' + ByteStringUtils.toHexString(hash);
-        }
+        SparseArray<ApplicationInfo> appInfoByUser = new SparseArray<>();
+        boolean needWrite = false;
 
-        writeDclEvent(ownerUid, message);
+        for (Map.Entry<String, DynamicCodeFile> fileEntry : info.mFileUsageMap.entrySet()) {
+            String filePath = fileEntry.getKey();
+            DynamicCodeFile fileInfo = fileEntry.getValue();
+            int userId = fileInfo.mUserId;
 
-        if (dexUseInfo.isUsedByOtherApps()) {
-            Set<String> otherPackages = dexUseInfo.getLoadingPackages();
-            Set<Integer> otherUids = new ArraySet<>(otherPackages.size());
-            for (String otherPackageName : otherPackages) {
+            int index = appInfoByUser.indexOfKey(userId);
+            ApplicationInfo appInfo;
+            if (index >= 0) {
+                appInfo = appInfoByUser.get(userId);
+            } else {
+                appInfo = null;
+
                 try {
-                    int otherUid = mPackageManager.getPackageUid(
-                        otherPackageName, /*flags*/0, dexUseInfo.getOwnerUserId());
-                    if (otherUid != -1 && otherUid != ownerUid) {
-                        otherUids.add(otherUid);
-                    }
-                } catch (RemoteException ignore) {
+                    PackageInfo ownerInfo =
+                            mPackageManager.getPackageInfo(packageName, /*flags*/ 0, userId);
+                    appInfo = ownerInfo == null ? null : ownerInfo.applicationInfo;
+                } catch (RemoteException ignored) {
                     // Can't happen, we're local.
                 }
+                appInfoByUser.put(userId, appInfo);
+                if (appInfo == null) {
+                    Slog.d(TAG, "Could not find package " + packageName + " for user " + userId);
+                    // Package has probably been uninstalled for user.
+                    needWrite |= mPackageDynamicCodeLoading.removeUserPackage(packageName, userId);
+                }
             }
-            for (int otherUid : otherUids) {
-                writeDclEvent(otherUid, message);
+
+            if (appInfo == null) {
+                continue;
             }
+
+            int storageFlags;
+            if (appInfo.deviceProtectedDataDir != null
+                    && FileUtils.contains(appInfo.deviceProtectedDataDir, filePath)) {
+                storageFlags = StorageManager.FLAG_STORAGE_DE;
+            } else if (appInfo.credentialProtectedDataDir != null
+                    && FileUtils.contains(appInfo.credentialProtectedDataDir, filePath)) {
+                storageFlags = StorageManager.FLAG_STORAGE_CE;
+            } else {
+                Slog.e(TAG, "Could not infer CE/DE storage for path " + filePath);
+                needWrite |= mPackageDynamicCodeLoading.removeFile(packageName, filePath, userId);
+                continue;
+            }
+
+            byte[] hash = null;
+            synchronized (mInstallLock) {
+                try {
+                    hash = mInstaller.hashSecondaryDexFile(filePath, packageName, appInfo.uid,
+                            appInfo.volumeUuid, storageFlags);
+                } catch (InstallerException e) {
+                    Slog.e(TAG, "Got InstallerException when hashing file " + filePath
+                            + ": " + e.getMessage());
+                }
+            }
+
+            String fileName = new File(filePath).getName();
+            String message = PackageUtils.computeSha256Digest(fileName.getBytes());
+
+            // Valid SHA256 will be 256 bits, 32 bytes.
+            if (hash != null && hash.length == 32) {
+                message = message + ' ' + ByteStringUtils.toHexString(hash);
+            } else {
+                Slog.d(TAG, "Got no hash for " + filePath);
+                // File has probably been deleted.
+                needWrite |= mPackageDynamicCodeLoading.removeFile(packageName, filePath, userId);
+            }
+
+            for (String loadingPackageName : fileInfo.mLoadingPackages) {
+                int loadingUid = -1;
+                if (loadingPackageName.equals(packageName)) {
+                    loadingUid = appInfo.uid;
+                } else {
+                    try {
+                        loadingUid = mPackageManager.getPackageUid(loadingPackageName, /*flags*/ 0,
+                                userId);
+                    } catch (RemoteException ignored) {
+                        // Can't happen, we're local.
+                    }
+                }
+
+                if (loadingUid != -1) {
+                    writeDclEvent(loadingUid, message);
+                }
+            }
+        }
+
+        if (needWrite) {
+            mPackageDynamicCodeLoading.maybeWriteAsync();
         }
     }
 
     @VisibleForTesting
-    /*package*/ void writeDclEvent(int uid, String message) {
+    PackageDynamicCode getPackageDynamicCodeInfo(String packageName) {
+        return mPackageDynamicCodeLoading.getPackageDynamicCodeInfo(packageName);
+    }
+
+    @VisibleForTesting
+    void writeDclEvent(int uid, String message) {
         EventLog.writeEvent(SNET_TAG, DCL_SUBTAG, uid, message);
     }
+
+    void record(int loaderUserId, String dexPath,
+            String owningPackageName, String loadingPackageName) {
+        if (mPackageDynamicCodeLoading.record(owningPackageName, dexPath,
+                PackageDynamicCodeLoading.FILE_TYPE_DEX, loaderUserId,
+                loadingPackageName)) {
+            mPackageDynamicCodeLoading.maybeWriteAsync();
+        }
+    }
+
+    void clear() {
+        mPackageDynamicCodeLoading.clear();
+    }
+
+    void removePackage(String packageName) {
+        if (mPackageDynamicCodeLoading.removePackage(packageName)) {
+            mPackageDynamicCodeLoading.maybeWriteAsync();
+        }
+    }
+
+    void removeUserPackage(String packageName, int userId) {
+        if (mPackageDynamicCodeLoading.removeUserPackage(packageName, userId)) {
+            mPackageDynamicCodeLoading.maybeWriteAsync();
+        }
+    }
+
+    void readAndSync(Map<String, Set<Integer>> packageToUsersMap) {
+        mPackageDynamicCodeLoading.read();
+        mPackageDynamicCodeLoading.syncData(packageToUsersMap);
+    }
+
+    void writeNow() {
+        mPackageDynamicCodeLoading.writeNow();
+    }
 }
diff --git a/services/core/java/com/android/server/pm/dex/DexManager.java b/services/core/java/com/android/server/pm/dex/DexManager.java
index 36b7269..25ef767 100644
--- a/services/core/java/com/android/server/pm/dex/DexManager.java
+++ b/services/core/java/com/android/server/pm/dex/DexManager.java
@@ -19,7 +19,6 @@
 import static com.android.server.pm.InstructionSets.getAppDexInstructionSets;
 import static com.android.server.pm.dex.PackageDexUsage.DexUseInfo;
 import static com.android.server.pm.dex.PackageDexUsage.PackageUseInfo;
-import static com.android.server.pm.dex.PackageDynamicCodeLoading.PackageDynamicCode;
 
 import android.content.ContentResolver;
 import android.content.Context;
@@ -90,18 +89,17 @@
     // encode and save the dex usage data.
     private final PackageDexUsage mPackageDexUsage;
 
-    // PackageDynamicCodeLoading handles recording of dynamic code loading -
-    // which is similar to PackageDexUsage but records a different aspect of the data.
+    // DexLogger handles recording of dynamic code loading - which is similar to PackageDexUsage
+    // but records a different aspect of the data.
     // (It additionally includes DEX files loaded with unsupported class loaders, and doesn't
     // record class loaders or ISAs.)
-    private final PackageDynamicCodeLoading mPackageDynamicCodeLoading;
+    private final DexLogger mDexLogger;
 
     private final IPackageManager mPackageManager;
     private final PackageDexOptimizer mPackageDexOptimizer;
     private final Object mInstallLock;
     @GuardedBy("mInstallLock")
     private final Installer mInstaller;
-    private final Listener mListener;
 
     // Possible outcomes of a dex search.
     private static int DEX_SEARCH_NOT_FOUND = 0;  // dex file not found
@@ -122,26 +120,20 @@
      */
     private final static PackageUseInfo DEFAULT_USE_INFO = new PackageUseInfo();
 
-    public interface Listener {
-        /**
-         * Invoked just before the secondary dex file {@code dexPath} for the specified application
-         * is reconciled.
-         */
-        void onReconcileSecondaryDexFile(ApplicationInfo appInfo, DexUseInfo dexUseInfo,
-                String dexPath, int storageFlags);
-    }
-
     public DexManager(Context context, IPackageManager pms, PackageDexOptimizer pdo,
-            Installer installer, Object installLock, Listener listener) {
+            Installer installer, Object installLock) {
         mContext = context;
         mPackageCodeLocationsCache = new HashMap<>();
         mPackageDexUsage = new PackageDexUsage();
-        mPackageDynamicCodeLoading = new PackageDynamicCodeLoading();
         mPackageManager = pms;
         mPackageDexOptimizer = pdo;
         mInstaller = installer;
         mInstallLock = installLock;
-        mListener = listener;
+        mDexLogger = new DexLogger(pms, installer, installLock);
+    }
+
+    public DexLogger getDexLogger() {
+        return mDexLogger;
     }
 
     public void systemReady() {
@@ -243,11 +235,8 @@
                     continue;
                 }
 
-                if (mPackageDynamicCodeLoading.record(searchResult.mOwningPackageName, dexPath,
-                        PackageDynamicCodeLoading.FILE_TYPE_DEX, loaderUserId,
-                        loadingAppInfo.packageName)) {
-                    mPackageDynamicCodeLoading.maybeWriteAsync();
-                }
+                mDexLogger.record(loaderUserId, dexPath, searchResult.mOwningPackageName,
+                        loadingAppInfo.packageName);
 
                 if (classLoaderContexts != null) {
 
@@ -284,7 +273,7 @@
             loadInternal(existingPackages);
         } catch (Exception e) {
             mPackageDexUsage.clear();
-            mPackageDynamicCodeLoading.clear();
+            mDexLogger.clear();
             Slog.w(TAG, "Exception while loading. Starting with a fresh state.", e);
         }
     }
@@ -335,16 +324,12 @@
             if (mPackageDexUsage.removePackage(packageName)) {
                 mPackageDexUsage.maybeWriteAsync();
             }
-            if (mPackageDynamicCodeLoading.removePackage(packageName)) {
-                mPackageDynamicCodeLoading.maybeWriteAsync();
-            }
+            mDexLogger.removePackage(packageName);
         } else {
             if (mPackageDexUsage.removeUserPackage(packageName, userId)) {
                 mPackageDexUsage.maybeWriteAsync();
             }
-            if (mPackageDynamicCodeLoading.removeUserPackage(packageName, userId)) {
-                mPackageDynamicCodeLoading.maybeWriteAsync();
-            }
+            mDexLogger.removeUserPackage(packageName, userId);
         }
     }
 
@@ -423,10 +408,9 @@
         }
 
         try {
-            mPackageDynamicCodeLoading.read();
-            mPackageDynamicCodeLoading.syncData(packageToUsersMap);
+            mDexLogger.readAndSync(packageToUsersMap);
         } catch (Exception e) {
-            mPackageDynamicCodeLoading.clear();
+            mDexLogger.clear();
             Slog.w(TAG, "Exception while loading package dynamic code usage. "
                     + "Starting with a fresh state.", e);
         }
@@ -460,11 +444,6 @@
         return mPackageDexUsage.getPackageUseInfo(packageName) != null;
     }
 
-    @VisibleForTesting
-    /*package*/ PackageDynamicCode getPackageDynamicCodeInfo(String packageName) {
-        return mPackageDynamicCodeLoading.getPackageDynamicCodeInfo(packageName);
-    }
-
     /**
      * Perform dexopt on with the given {@code options} on the secondary dex files.
      * @return true if all secondary dex files were processed successfully (compiled or skipped
@@ -574,10 +553,6 @@
                 continue;
             }
 
-            if (mListener != null) {
-                mListener.onReconcileSecondaryDexFile(info, dexUseInfo, dexPath, flags);
-            }
-
             boolean dexStillExists = true;
             synchronized(mInstallLock) {
                 try {
@@ -721,7 +696,7 @@
      */
     public void writePackageDexUsageNow() {
         mPackageDexUsage.writeNow();
-        mPackageDynamicCodeLoading.writeNow();
+        mDexLogger.writeNow();
     }
 
     private void registerSettingObserver() {