Merge "Add logging of dynamic loading of native code." (d7c5450f) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/pm/DynamicCodeLoggingService.java

+196 −23

Original line number	Diff line number	Diff line
		@@ -22,63 +22,117 @@ import android.app.job.JobScheduler;
		import android.app.job.JobService;
		import android.content.ComponentName;
		import android.content.Context;
		import android.os.Process;
		import android.os.ServiceManager;
		import android.util.ByteStringUtils;
		import android.util.EventLog;
		import android.util.Log;

		import com.android.server.pm.dex.DexLogger;

		import java.util.ArrayList;
		import java.util.List;
		import java.util.concurrent.TimeUnit;
		import java.util.regex.Matcher;
		import java.util.regex.Pattern;

		/**
		* 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}.
		* Scheduled jobs related to logging of app dynamic code loading. The idle logging job runs daily
		* while idle and charging and calls {@link DexLogger} to write dynamic code information to the
		* event log. The audit watching job scans the event log periodically while idle to find AVC audit
		* messages indicating use of dynamic native code and adds the information to {@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 static final boolean DEBUG = false;

		private volatile boolean mStopRequested = false;
		private static final int IDLE_LOGGING_JOB_ID = 2030028;
		private static final int AUDIT_WATCHING_JOB_ID = 203142925;

		private static final boolean DEBUG = false;
		private static final long IDLE_LOGGING_PERIOD_MILLIS = TimeUnit.DAYS.toMillis(1);
		private static final long AUDIT_WATCHING_PERIOD_MILLIS = TimeUnit.HOURS.toMillis(2);

		private static final int AUDIT_AVC = 1400; // Defined in linux/audit.h
		private static final String AVC_PREFIX = "type=" + AUDIT_AVC + " ";

		private static final Pattern EXECUTE_NATIVE_AUDIT_PATTERN =
		Pattern.compile(".\\bavc: granted \\{ execute(?:_no_trans\|) \\} ."
		+ "\\bpath=(?:\"([^\" ])\"\|([0-9A-F]+)) ."
		+ "\\bscontext=u:r:untrusted_app_2(?:5\|7):.*"
		+ "\\btcontext=u:object_r:app_data_file:.*"
		+ "\\btclass=file\\b.*");

		private volatile boolean mIdleLoggingStopRequested = false;
		private volatile boolean mAuditWatchingStopRequested = false;

		/**
		* Schedule our job with the {@link JobScheduler}.
		* Schedule our jobs 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)
		js.schedule(new JobInfo.Builder(IDLE_LOGGING_JOB_ID, serviceName)
		.setRequiresDeviceIdle(true)
		.setRequiresCharging(true)
		.setPeriodic(PERIOD_MILLIS)
		.setPeriodic(IDLE_LOGGING_PERIOD_MILLIS)
		.build());
		js.schedule(new JobInfo.Builder(AUDIT_WATCHING_JOB_ID, serviceName)
		.setRequiresDeviceIdle(true)
		.setRequiresBatteryNotLow(true)
		.setPeriodic(AUDIT_WATCHING_PERIOD_MILLIS)
		.build());

		if (DEBUG) {
		Log.d(TAG, "Job scheduled");
		Log.d(TAG, "Jobs scheduled");
		}
		}

		@Override
		public boolean onStartJob(JobParameters params) {
		int jobId = params.getJobId();
		if (DEBUG) {
		Log.d(TAG, "onStartJob");
		Log.d(TAG, "onStartJob " + jobId);
		}
		mStopRequested = false;
		switch (jobId) {
		case IDLE_LOGGING_JOB_ID:
		mIdleLoggingStopRequested = false;
		new IdleLoggingThread(params).start();
		return true; // Job is running on another thread
		case AUDIT_WATCHING_JOB_ID:
		mAuditWatchingStopRequested = false;
		new AuditWatchingThread(params).start();
		return true; // Job is running on another thread
		default:
		// Shouldn't happen, but indicate nothing is running.
		return false;
		}
		}

		@Override
		public boolean onStopJob(JobParameters params) {
		int jobId = params.getJobId();
		if (DEBUG) {
		Log.d(TAG, "onStopJob");
		Log.d(TAG, "onStopJob " + jobId);
		}
		mStopRequested = true;
		switch (jobId) {
		case IDLE_LOGGING_JOB_ID:
		mIdleLoggingStopRequested = true;
		return true; // Requests job be re-scheduled.
		case AUDIT_WATCHING_JOB_ID:
		mAuditWatchingStopRequested = true;
		return true; // Requests job be re-scheduled.
		default:
		return false;
		}
		}

		private static DexLogger getDexLogger() {
		PackageManagerService pm = (PackageManagerService) ServiceManager.getService("package");
		return pm.getDexManager().getDexLogger();
		}

		private class IdleLoggingThread extends Thread {
		@@ -92,14 +146,13 @@ public class DynamicCodeLoggingService extends JobService {
		@Override
		public void run() {
		if (DEBUG) {
		Log.d(TAG, "Starting logging run");
		Log.d(TAG, "Starting IdleLoggingJob run");
		}

		PackageManagerService pm = (PackageManagerService) ServiceManager.getService("package");
		DexLogger dexLogger = pm.getDexManager().getDexLogger();
		DexLogger dexLogger = getDexLogger();
		for (String packageName : dexLogger.getAllPackagesWithDynamicCodeLoading()) {
		if (mStopRequested) {
		Log.w(TAG, "Stopping logging run at scheduler request");
		if (mIdleLoggingStopRequested) {
		Log.w(TAG, "Stopping IdleLoggingJob run at scheduler request");
		return;
		}

		@@ -108,8 +161,128 @@ public class DynamicCodeLoggingService extends JobService {

		jobFinished(mParams, /* reschedule */ false);
		if (DEBUG) {
		Log.d(TAG, "Finished logging run");
		Log.d(TAG, "Finished IdleLoggingJob run");
		}
		}
		}

		private class AuditWatchingThread extends Thread {
		private final JobParameters mParams;

		AuditWatchingThread(JobParameters params) {
		super("DynamicCodeLoggingService_AuditWatchingJob");
		mParams = params;
		}

		@Override
		public void run() {
		if (DEBUG) {
		Log.d(TAG, "Starting AuditWatchingJob run");
		}

		if (processAuditEvents()) {
		jobFinished(mParams, /* reschedule */ false);
		if (DEBUG) {
		Log.d(TAG, "Finished AuditWatchingJob run");
		}
		}
		}

		private boolean processAuditEvents() {
		// Scan the event log for SELinux (avc) audit messages indicating when an
		// (untrusted) app has executed native code from an app data
		// file. Matches are recorded in DexLogger.
		//
		// These messages come from the kernel audit system via logd. (Note that
		// some devices may not generate these messages at all, or the format may
		// be different, in which case nothing will be recorded.)
		//
		// The messages use the auditd tag and the uid of the app that executed
		// the code.
		//
		// A typical message might look like this:
		// type=1400 audit(0.0:521): avc: granted { execute } for comm="executable"
		// path="/data/data/com.dummy.app/executable" dev="sda13" ino=1655302
		// scontext=u:r:untrusted_app_27:s0:c66,c257,c512,c768
		// tcontext=u:object_r:app_data_file:s0:c66,c257,c512,c768 tclass=file
		//
		// The information we want is the uid and the path. (Note this may be
		// either a quoted string, as shown above, or a sequence of hex-encoded
		// bytes.)
		//
		// On each run we process all the matching events in the log. This may
		// mean re-processing events we have already seen, and in any case there
		// may be duplicate events for the same app+file. These are de-duplicated
		// by DexLogger.
		//
		// Note that any app can write a message to the event log, including one
		// that looks exactly like an AVC audit message, so the information may
		// be spoofed by an app; in such a case the uid we see will be the app
		// that generated the spoof message.

		try {
		int[] tags = { EventLog.getTagCode("auditd") };
		if (tags[0] == -1) {
		// auditd is not a registered tag on this system, so there can't be any messages
		// of interest.
		return true;
		}

		DexLogger dexLogger = getDexLogger();

		List<EventLog.Event> events = new ArrayList<>();
		EventLog.readEvents(tags, events);

		for (int i = 0; i < events.size(); ++i) {
		if (mAuditWatchingStopRequested) {
		Log.w(TAG, "Stopping AuditWatchingJob run at scheduler request");
		return false;
		}

		EventLog.Event event = events.get(i);

		// Discard clearly unrelated messages as quickly as we can.
		int uid = event.getUid();
		if (!Process.isApplicationUid(uid)) {
		continue;
		}
		Object data = event.getData();
		if (!(data instanceof String)) {
		continue;
		}
		String message = (String) data;
		if (!message.startsWith(AVC_PREFIX)) {
		continue;
		}

		// And then use a regular expression to verify it's one of the messages we're
		// interested in and to extract the path of the file being loaded.
		Matcher matcher = EXECUTE_NATIVE_AUDIT_PATTERN.matcher(message);
		if (!matcher.matches()) {
		continue;
		}
		String path = matcher.group(1);
		if (path == null) {
		// If the path contains spaces or various weird characters the kernel
		// hex-encodes the bytes; we need to undo that.
		path = unhex(matcher.group(2));
		}
		dexLogger.recordNative(uid, path);
		}

		return true;
		} catch (Exception e) {
		Log.e(TAG, "AuditWatchingJob failed", e);
		return true;
		}
		}
		}

		private static String unhex(String hexEncodedPath) {
		byte[] bytes = ByteStringUtils.fromHexToByteArray(hexEncodedPath);
		if (bytes == null \|\| bytes.length == 0) {
		return "";
		}
		return new String(bytes);
		}
		}

services/core/java/com/android/server/pm/dex/DexLogger.java

+63 −17

Original line number	Diff line number	Diff line
		@@ -16,11 +16,15 @@

		package com.android.server.pm.dex;

		import static com.android.server.pm.dex.PackageDynamicCodeLoading.FILE_TYPE_DEX;
		import static com.android.server.pm.dex.PackageDynamicCodeLoading.FILE_TYPE_NATIVE;

		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.os.UserHandle;
		import android.os.storage.StorageManager;
		import android.util.ByteStringUtils;
		import android.util.EventLog;
		@@ -35,20 +39,23 @@ import com.android.server.pm.dex.PackageDynamicCodeLoading.DynamicCodeFile;
		import com.android.server.pm.dex.PackageDynamicCodeLoading.PackageDynamicCode;

		import java.io.File;
		import java.io.IOException;
		import java.util.Map;
		import java.util.Set;

		/**
		* This class is responsible for logging data about secondary dex files.
		* The data logged includes hashes of the name and content of each file.
		* This class is responsible for logging data about secondary dex files and, despite the name,
		* native code executed from an app's private directory. The data logged includes hashes of the
		* name and content of each file.
		*/
		public class DexLogger {
		private static final String TAG = "DexLogger";

		// Event log tag & subtag used for SafetyNet logging of dynamic
		// code loading (DCL) - see b/63927552.
		// Event log tag & subtags used for SafetyNet logging of dynamic code loading (DCL) -
		// see b/63927552.
		private static final int SNET_TAG = 0x534e4554;
		private static final String DCL_SUBTAG = "dcl";
		private static final String DCL_DEX_SUBTAG = "dcl";
		private static final String DCL_NATIVE_SUBTAG = "dcln";

		private final IPackageManager mPackageManager;
		private final PackageDynamicCodeLoading mPackageDynamicCodeLoading;
		@@ -114,12 +121,11 @@ public class DexLogger {
		}

		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)) {

		if (fileIsUnder(filePath, appInfo.credentialProtectedDataDir)) {
		storageFlags = StorageManager.FLAG_STORAGE_CE;
		} else if (fileIsUnder(filePath, appInfo.deviceProtectedDataDir)) {
		storageFlags = StorageManager.FLAG_STORAGE_DE;
		} else {
		Slog.e(TAG, "Could not infer CE/DE storage for path " + filePath);
		needWrite \|= mPackageDynamicCodeLoading.removeFile(packageName, filePath, userId);
		@@ -139,6 +145,9 @@ public class DexLogger {
		+ ": " + e.getMessage());
		}

		String subtag = fileInfo.mFileType == FILE_TYPE_DEX
		? DCL_DEX_SUBTAG
		: DCL_NATIVE_SUBTAG;
		String fileName = new File(filePath).getName();
		String message = PackageUtils.computeSha256Digest(fileName.getBytes());

		@@ -165,7 +174,7 @@ public class DexLogger {
		}

		if (loadingUid != -1) {
		writeDclEvent(loadingUid, message);
		writeDclEvent(subtag, loadingUid, message);
		}
		}
		}
		@@ -175,21 +184,58 @@ public class DexLogger {
		}
		}

		private boolean fileIsUnder(String filePath, String directoryPath) {
		if (directoryPath == null) {
		return false;
		}

		try {
		return FileUtils.contains(new File(directoryPath).getCanonicalPath(),
		new File(filePath).getCanonicalPath());
		} catch (IOException e) {
		return false;
		}
		}

		@VisibleForTesting
		PackageDynamicCode getPackageDynamicCodeInfo(String packageName) {
		return mPackageDynamicCodeLoading.getPackageDynamicCodeInfo(packageName);
		}

		@VisibleForTesting
		void writeDclEvent(int uid, String message) {
		EventLog.writeEvent(SNET_TAG, DCL_SUBTAG, uid, message);
		void writeDclEvent(String subtag, int uid, String message) {
		EventLog.writeEvent(SNET_TAG, subtag, uid, message);
		}

		void record(int loaderUserId, String dexPath,
		String owningPackageName, String loadingPackageName) {
		void recordDex(int loaderUserId, String dexPath, String owningPackageName,
		String loadingPackageName) {
		if (mPackageDynamicCodeLoading.record(owningPackageName, dexPath,
		PackageDynamicCodeLoading.FILE_TYPE_DEX, loaderUserId,
		loadingPackageName)) {
		FILE_TYPE_DEX, loaderUserId, loadingPackageName)) {
		mPackageDynamicCodeLoading.maybeWriteAsync();
		}
		}

		/**
		* Record that an app running in the specified uid has executed native code from the file at
		* {@link path}.
		*/
		public void recordNative(int loadingUid, String path) {
		String[] packages;
		try {
		packages = mPackageManager.getPackagesForUid(loadingUid);
		if (packages == null \|\| packages.length == 0) {
		return;
		}
		} catch (RemoteException e) {
		// Can't happen, we're local.
		return;
		}

		String loadingPackageName = packages[0];
		int loadingUserId = UserHandle.getUserId(loadingUid);

		if (mPackageDynamicCodeLoading.record(loadingPackageName, path,
		FILE_TYPE_NATIVE, loadingUserId, loadingPackageName)) {
		mPackageDynamicCodeLoading.maybeWriteAsync();
		}
		}

services/core/java/com/android/server/pm/dex/DexManager.java

+1 −1

Original line number	Diff line number	Diff line
		@@ -235,7 +235,7 @@ public class DexManager {
		continue;
		}

		mDexLogger.record(loaderUserId, dexPath, searchResult.mOwningPackageName,
		mDexLogger.recordDex(loaderUserId, dexPath, searchResult.mOwningPackageName,
		loadingAppInfo.packageName);

		if (classLoaderContexts != null) {

services/core/java/com/android/server/pm/dex/PackageDynamicCodeLoading.java

+9 −2

Original line number	Diff line number	Diff line
		@@ -53,6 +53,9 @@ class PackageDynamicCodeLoading extends AbstractStatsBase<Void> {
		// is represented in the text file format.)
		static final int FILE_TYPE_DEX = 'D';

		// Type code to indicate a secondary file containing native code.
		static final int FILE_TYPE_NATIVE = 'N';

		private static final String TAG = "PackageDynamicCodeLoading";

		private static final String FILE_VERSION_HEADER = "DCL1";
		@@ -107,7 +110,7 @@ class PackageDynamicCodeLoading extends AbstractStatsBase<Void> {
		*/
		boolean record(String owningPackageName, String filePath, int fileType, int ownerUserId,
		String loadingPackageName) {
		if (fileType != FILE_TYPE_DEX) {
		if (!isValidFileType(fileType)) {
		throw new IllegalArgumentException("Bad file type: " + fileType);
		}
		synchronized (mLock) {
		@@ -120,6 +123,10 @@ class PackageDynamicCodeLoading extends AbstractStatsBase<Void> {
		}
		}

		private static boolean isValidFileType(int fileType) {
		return fileType == FILE_TYPE_DEX \|\| fileType == FILE_TYPE_NATIVE;
		}

		/**
		* Return all packages that contain records of secondary dex files. (Note that data updates
		* asynchronously, so {@link #getPackageDynamicCodeInfo} may still return null if passed
		@@ -407,7 +414,7 @@ class PackageDynamicCodeLoading extends AbstractStatsBase<Void> {
		if (packages.length == 0) {
		throw new IOException("Malformed line: " + line);
		}
		if (type != FILE_TYPE_DEX) {
		if (!isValidFileType(type)) {
		throw new IOException("Unknown file type: " + line);
		}

services/tests/servicestests/src/com/android/server/pm/dex/DexLoggerTests.java

+81 −39

File changed.

Preview size limit exceeded, changes collapsed.