blob: 5c3a37ae3c4e590a4a151f8a1f40f4e50d7b6c00 [file] [log] [blame]
/*
* Copyright (C) 2016 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.devicepolicy;
import android.app.admin.DeviceAdminReceiver;
import android.app.admin.SecurityLog;
import android.app.admin.SecurityLog.SecurityEvent;
import android.os.SystemClock;
import android.util.Log;
import android.util.Slog;
import com.android.internal.annotations.GuardedBy;
import java.io.IOException;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;
import android.os.Process;
/**
* A class managing access to the security logs. It maintains an internal buffer of pending
* logs to be retrieved by the device owner. The logs are retrieved from the logd daemon via
* JNI binding, and kept until device owner has retrieved to prevent loss of logs. Access to
* the logs from the device owner is rate-limited, and device owner is notified when the logs
* are ready to be retrieved. This happens every two hours, or when our internal buffer is
* larger than a certain threshold.
*/
class SecurityLogMonitor implements Runnable {
private final DevicePolicyManagerService mService;
private final Lock mLock = new ReentrantLock();
SecurityLogMonitor(DevicePolicyManagerService service) {
mService = service;
}
private static final boolean DEBUG = false; // STOPSHIP if true.
private static final String TAG = "SecurityLogMonitor";
/**
* Each log entry can hold up to 4K bytes (but as of {@link android.os.Build.VERSION_CODES#N}
* it should be less than 100 bytes), setting 1024 entries as the threshold to notify Device
* Owner.
*/
private static final int BUFFER_ENTRIES_NOTIFICATION_LEVEL = 1024;
/**
* The maximum number of entries we should store before dropping earlier logs, to limit the
* memory usage.
*/
private static final int BUFFER_ENTRIES_MAXIMUM_LEVEL = BUFFER_ENTRIES_NOTIFICATION_LEVEL * 10;
/**
* How often should Device Owner be notified under normal circumstances.
*/
private static final long RATE_LIMIT_INTERVAL_MILLISECONDS = TimeUnit.HOURS.toMillis(2);
/**
* How often to retry the notification about available logs if it is ignored or missed by DO.
*/
private static final long BROADCAST_RETRY_INTERVAL_MILLISECONDS = TimeUnit.MINUTES.toMillis(30);
/**
* Internally how often should the monitor poll the security logs from logd.
*/
private static final long POLLING_INTERVAL_MILLISECONDS = TimeUnit.MINUTES.toMillis(1);
/**
* Overlap between two subsequent log requests, required to avoid losing out of order events.
*/
private static final long OVERLAP_NANOS = TimeUnit.SECONDS.toNanos(3);
@GuardedBy("mLock")
private Thread mMonitorThread = null;
@GuardedBy("mLock")
private ArrayList<SecurityEvent> mPendingLogs = new ArrayList<>();
@GuardedBy("mLock")
private boolean mAllowedToRetrieve = false;
/**
* Last events fetched from log to check for overlap between batches. We can leave it empty if
* we are sure there will be no overlap anymore, e.g. when we get empty batch.
*/
private final ArrayList<SecurityEvent> mLastEvents = new ArrayList<>();
/** Timestamp of the very last event, -1 means request from the beginning of time. */
private long mLastEventNanos = -1;
/**
* When DO will be allowed to retrieve the log, in milliseconds since boot (as per
* {@link SystemClock#elapsedRealtime()}). After that it will mark the time to retry broadcast.
*/
@GuardedBy("mLock")
private long mNextAllowedRetrievalTimeMillis = -1;
@GuardedBy("mLock")
private boolean mPaused = false;
void start() {
Slog.i(TAG, "Starting security logging.");
mLock.lock();
try {
if (mMonitorThread == null) {
mPendingLogs = new ArrayList<>();
mAllowedToRetrieve = false;
mNextAllowedRetrievalTimeMillis = -1;
mPaused = false;
mMonitorThread = new Thread(this);
mMonitorThread.start();
}
} finally {
mLock.unlock();
}
}
void stop() {
Slog.i(TAG, "Stopping security logging.");
mLock.lock();
try {
if (mMonitorThread != null) {
mMonitorThread.interrupt();
try {
mMonitorThread.join(TimeUnit.SECONDS.toMillis(5));
} catch (InterruptedException e) {
Log.e(TAG, "Interrupted while waiting for thread to stop", e);
}
// Reset state and clear buffer
mPendingLogs = new ArrayList<>();
mAllowedToRetrieve = false;
mNextAllowedRetrievalTimeMillis = -1;
mPaused = false;
mMonitorThread = null;
}
} finally {
mLock.unlock();
}
}
/**
* If logs are being collected, keep collecting them but stop notifying the device owner that
* new logs are available (since they cannot be retrieved).
*/
void pause() {
Slog.i(TAG, "Paused.");
mLock.lock();
mPaused = true;
mAllowedToRetrieve = false;
mLock.unlock();
}
/**
* If logs are being collected, start notifying the device owner when logs are ready to be
* retrieved again (if it was paused).
* <p>If logging is enabled and there are logs ready to be retrieved, this method will attempt
* to notify the device owner. Therefore calling identity should be cleared before calling it
* (in case the method is called from a user other than the DO's user).
*/
void resume() {
mLock.lock();
try {
if (!mPaused) {
Log.d(TAG, "Attempted to resume, but logging is not paused.");
return;
}
mPaused = false;
mAllowedToRetrieve = false;
} finally {
mLock.unlock();
}
Slog.i(TAG, "Resumed.");
try {
notifyDeviceOwnerIfNeeded();
} catch (InterruptedException e) {
Log.w(TAG, "Thread interrupted.", e);
}
}
/**
* Discard all collected logs.
*/
void discardLogs() {
mLock.lock();
mAllowedToRetrieve = false;
mPendingLogs = new ArrayList<>();
mLock.unlock();
Slog.i(TAG, "Discarded all logs.");
}
/**
* Returns the new batch of logs since the last call to this method. Returns null if
* rate limit is exceeded.
*/
List<SecurityEvent> retrieveLogs() {
mLock.lock();
try {
if (mAllowedToRetrieve) {
mAllowedToRetrieve = false;
mNextAllowedRetrievalTimeMillis = SystemClock.elapsedRealtime()
+ RATE_LIMIT_INTERVAL_MILLISECONDS;
List<SecurityEvent> result = mPendingLogs;
mPendingLogs = new ArrayList<>();
return result;
} else {
return null;
}
} finally {
mLock.unlock();
}
}
/**
* Requests the next (or the first) batch of events from the log with appropriate timestamp.
*/
private void getNextBatch(ArrayList<SecurityEvent> newLogs)
throws IOException, InterruptedException {
if (mLastEventNanos < 0) {
// Non-blocking read that returns all logs immediately.
if (DEBUG) Slog.d(TAG, "SecurityLog.readEvents");
SecurityLog.readEvents(newLogs);
} else {
// If we have last events from the previous batch, request log events with time overlap
// with previously retrieved messages to avoid losing events due to reordering in logd.
final long startNanos = mLastEvents.isEmpty()
? mLastEventNanos : Math.max(0, mLastEventNanos - OVERLAP_NANOS);
if (DEBUG) Slog.d(TAG, "SecurityLog.readEventsSince: " + startNanos);
// Non-blocking read that returns all logs with timestamps >= startNanos immediately.
SecurityLog.readEventsSince(startNanos, newLogs);
}
// Sometimes events may be reordered in logd due to simultaneous readers and writers. In
// this case, we have to sort it to make overlap checking work. This is very unlikely.
for (int i = 0; i < newLogs.size() - 1; i++) {
if (newLogs.get(i).getTimeNanos() > newLogs.get(i+1).getTimeNanos()) {
if (DEBUG) Slog.d(TAG, "Got out of order events, sorting.");
// Sort using comparator that compares timestamps.
newLogs.sort((e1, e2) -> Long.signum(e1.getTimeNanos() - e2.getTimeNanos()));
break;
}
}
if (DEBUG) Slog.d(TAG, "Got " + newLogs.size() + " new events.");
}
/**
* Save the last events for overlap checking with the next batch.
*/
private void saveLastEvents(ArrayList<SecurityEvent> newLogs) {
mLastEvents.clear();
if (newLogs.isEmpty()) {
// This can happen if no events were logged yet or the buffer got cleared. In this case
// we aren't going to have any overlap next time, leave mLastEvents events empty.
return;
}
// Save the last timestamp.
mLastEventNanos = newLogs.get(newLogs.size() - 1).getTimeNanos();
// Position of the earliest event that has to be saved. Start from the penultimate event,
// going backward.
int pos = newLogs.size() - 2;
while (pos >= 0 && mLastEventNanos - newLogs.get(pos).getTimeNanos() < OVERLAP_NANOS) {
pos--;
}
// We either run past the start of the list or encountered an event that is too old to keep.
pos++;
mLastEvents.addAll(newLogs.subList(pos, newLogs.size()));
if (DEBUG) Slog.d(TAG, mLastEvents.size() + " events saved for overlap check");
}
/**
* Merges a new batch into already fetched logs and deals with overlapping and out of order
* events.
*/
@GuardedBy("mLock")
private void mergeBatchLocked(final ArrayList<SecurityEvent> newLogs) {
// Reserve capacity so that copying doesn't occur.
mPendingLogs.ensureCapacity(mPendingLogs.size() + newLogs.size());
// Run through the first events of the batch to check if there is an overlap with previous
// batch and if so, skip overlapping events. Events are sorted by timestamp, so we can
// compare it in linear time by advancing two pointers, one for each batch.
int curPos = 0;
int lastPos = 0;
// For the first batch mLastEvents will be empty, so no iterations will happen.
while (lastPos < mLastEvents.size() && curPos < newLogs.size()) {
final SecurityEvent curEvent = newLogs.get(curPos);
final long currentNanos = curEvent.getTimeNanos();
if (currentNanos > mLastEventNanos) {
// We got past the last event of the last batch, no overlap possible anymore.
break;
}
final SecurityEvent lastEvent = mLastEvents.get(lastPos);
final long lastNanos = lastEvent.getTimeNanos();
if (lastNanos > currentNanos) {
// New event older than the last we've seen so far, must be due to reordering.
if (DEBUG) Slog.d(TAG, "New event in the overlap: " + currentNanos);
mPendingLogs.add(curEvent);
curPos++;
} else if (lastNanos < currentNanos) {
if (DEBUG) Slog.d(TAG, "Event disappeared from the overlap: " + lastNanos);
lastPos++;
} else {
// Two events have the same timestamp, check if they are the same.
if (lastEvent.equals(curEvent)) {
// Actual overlap, just skip the event.
if (DEBUG) Slog.d(TAG, "Skipped dup event with timestamp: " + lastNanos);
} else {
// Wow, what a coincidence, or probably the clock is too coarse.
mPendingLogs.add(curEvent);
if (DEBUG) Slog.d(TAG, "Event timestamp collision: " + lastNanos);
}
lastPos++;
curPos++;
}
}
// Save the rest of the new batch.
mPendingLogs.addAll(newLogs.subList(curPos, newLogs.size()));
if (mPendingLogs.size() > BUFFER_ENTRIES_MAXIMUM_LEVEL) {
// Truncate buffer down to half of BUFFER_ENTRIES_MAXIMUM_LEVEL.
mPendingLogs = new ArrayList<>(mPendingLogs.subList(
mPendingLogs.size() - (BUFFER_ENTRIES_MAXIMUM_LEVEL / 2),
mPendingLogs.size()));
Slog.i(TAG, "Pending logs buffer full. Discarding old logs.");
}
if (DEBUG) Slog.d(TAG, mPendingLogs.size() + " pending events in the buffer after merging");
}
@Override
public void run() {
Process.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND);
ArrayList<SecurityEvent> newLogs = new ArrayList<>();
while (!Thread.currentThread().isInterrupted()) {
try {
Thread.sleep(POLLING_INTERVAL_MILLISECONDS);
getNextBatch(newLogs);
mLock.lockInterruptibly();
try {
mergeBatchLocked(newLogs);
} finally {
mLock.unlock();
}
saveLastEvents(newLogs);
newLogs.clear();
notifyDeviceOwnerIfNeeded();
} catch (IOException e) {
Log.e(TAG, "Failed to read security log", e);
} catch (InterruptedException e) {
Log.i(TAG, "Thread interrupted, exiting.", e);
// We are asked to stop.
break;
}
}
// Discard previous batch info.
mLastEvents.clear();
if (mLastEventNanos != -1) {
// Make sure we don't read old events if logging is re-enabled. Since mLastEvents is
// empty, the next request will be done without overlap, so it is enough to add 1 ns.
mLastEventNanos += 1;
}
Slog.i(TAG, "MonitorThread exit.");
}
private void notifyDeviceOwnerIfNeeded() throws InterruptedException {
boolean allowRetrievalAndNotifyDO = false;
mLock.lockInterruptibly();
try {
if (mPaused) {
return;
}
final int logSize = mPendingLogs.size();
if (logSize >= BUFFER_ENTRIES_NOTIFICATION_LEVEL) {
// Allow DO to retrieve logs if too many pending logs
if (!mAllowedToRetrieve) {
allowRetrievalAndNotifyDO = true;
}
if (DEBUG) Slog.d(TAG, "Number of log entries over threshold: " + logSize);
}
if (logSize > 0 && SystemClock.elapsedRealtime() >= mNextAllowedRetrievalTimeMillis) {
// Rate limit reset
allowRetrievalAndNotifyDO = true;
if (DEBUG) Slog.d(TAG, "Timeout reached");
}
if (allowRetrievalAndNotifyDO) {
mAllowedToRetrieve = true;
// Set the timeout to retry the notification if the DO misses it.
mNextAllowedRetrievalTimeMillis = SystemClock.elapsedRealtime()
+ BROADCAST_RETRY_INTERVAL_MILLISECONDS;
}
} finally {
mLock.unlock();
}
if (allowRetrievalAndNotifyDO) {
Slog.i(TAG, "notify DO");
mService.sendDeviceOwnerCommand(DeviceAdminReceiver.ACTION_SECURITY_LOGS_AVAILABLE,
null);
}
}
}