Add logging of dynamic loading of native code.
This uses the SELinux audit messages generated when an untrusted app,
targeting SDK 28 or lower, executes native code from an app data
directory. "Executes" here covers memory mapping a file with execute
permission (including using dl_open) or calling execve.
As with dynamic loading of DEX code we write a hash of the contents of
the file executed to the event log.
The existing unit and integration tests are extended to verify the new
behaviour.
Bug: 111338677
Test: atest -p services/core/java/com/android/server/pm/dex
Change-Id: Ifbb3b338135db413be2cd83b1a8e7499d61d88dd
diff --git a/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java b/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java
index 2ae424d..5b765df 100644
--- a/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java
+++ b/services/core/java/com/android/server/pm/DynamicCodeLoggingService.java
@@ -22,63 +22,117 @@
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 volatile boolean mStopRequested = false;
-
private static final boolean DEBUG = false;
+ private static final int IDLE_LOGGING_JOB_ID = 2030028;
+ private static final int AUDIT_WATCHING_JOB_ID = 203142925;
+
+ 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;
- new IdleLoggingThread(params).start();
- return true; // Job is running on another thread
+ 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;
- return true; // Requests job be re-scheduled.
+ 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 @@
@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 @@
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);
+ }
}