server/devicepolicy/SecurityLogMonitor.java

/*
 * 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 static java.util.concurrent.TimeUnit.MILLISECONDS;
import static java.util.concurrent.TimeUnit.NANOSECONDS;

import android.app.admin.DeviceAdminReceiver;
import android.app.admin.SecurityLog;
import android.app.admin.SecurityLog.SecurityEvent;
import android.os.Process;
import android.os.SystemClock;
import android.util.Log;
import android.util.Slog;

import com.android.internal.annotations.GuardedBy;
import com.android.internal.annotations.VisibleForTesting;

import java.io.IOException;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.Semaphore;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;

/**
 * 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) {
        this(service, 0 /* id */);
    }

    @VisibleForTesting
    SecurityLogMonitor(DevicePolicyManagerService service, long id) {
        this.mService = service;
        this.mId = id;
        this.mLastForceNanos = System.nanoTime();
    }

    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.
     */
    @VisibleForTesting 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;
    /**
     * Critical log buffer level, 90% of capacity.
     */
    private static final int BUFFER_ENTRIES_CRITICAL_LEVEL = BUFFER_ENTRIES_MAXIMUM_LEVEL * 9 / 10;
    /**
     * How often should Device Owner be notified under normal circumstances.
     */
    private static final long RATE_LIMIT_INTERVAL_MS = 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_MS = TimeUnit.MINUTES.toMillis(30);
    /**
     * Internally how often should the monitor poll the security logs from logd.
     */
    private static final long POLLING_INTERVAL_MS = TimeUnit.MINUTES.toMillis(1);
    /**
     * Overlap between two subsequent log requests, required to avoid losing out of order events.
     */
    private static final long OVERLAP_NS = TimeUnit.SECONDS.toNanos(3);

    /** Minimum time between forced fetch attempts. */
    private static final long FORCE_FETCH_THROTTLE_NS = TimeUnit.SECONDS.toNanos(10);

    @GuardedBy("mLock")
    private Thread mMonitorThread = null;
    @GuardedBy("mLock")
    private ArrayList<SecurityEvent> mPendingLogs = new ArrayList<>();
    @GuardedBy("mLock")
    private long mId;
    @GuardedBy("mLock")
    private boolean mAllowedToRetrieve = false;

    // Whether we have already logged the fact that log buffer reached 90%, to avoid dupes.
    @GuardedBy("mLock")
    private boolean mCriticalLevelLogged = 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;

    /** Semaphore used to force log fetching on request from adb. */
    private final Semaphore mForceSemaphore = new Semaphore(0 /* permits */);

    /** The last timestamp when force fetch was used, to prevent abuse. */
    @GuardedBy("mForceSemaphore")
    private long mLastForceNanos = 0;

    void start() {
        Slog.i(TAG, "Starting security logging.");
        SecurityLog.writeEvent(SecurityLog.TAG_LOGGING_STARTED);
        mLock.lock();
        try {
            if (mMonitorThread == null) {
                mPendingLogs = new ArrayList<>();
                mCriticalLevelLogged = false;
                mId = 0;
                mAllowedToRetrieve = false;
                mNextAllowedRetrievalTimeMillis = -1;
                mPaused = false;

                mMonitorThread = new Thread(this);
                mMonitorThread.start();
            }
        } finally {
            mLock.unlock();
        }
    }

    void stop() {
        Slog.i(TAG, "Stopping security logging.");
        SecurityLog.writeEvent(SecurityLog.TAG_LOGGING_STOPPED);
        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<>();
                mId = 0;
                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(false /* force */);
        } catch (InterruptedException e) {
            Log.w(TAG, "Thread interrupted.", e);
        }
    }

    /**
     * Discard all collected logs.
     */
    void discardLogs() {
        mLock.lock();
        mAllowedToRetrieve = false;
        mPendingLogs = new ArrayList<>();
        mCriticalLevelLogged = false;
        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_MS;
                List<SecurityEvent> result = mPendingLogs;
                mPendingLogs = new ArrayList<>();
                mCriticalLevelLogged = false;
                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 {
        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_NS);
            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_NS) {
            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);
                assignLogId(curEvent);
                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.
                    assignLogId(curEvent);
                    mPendingLogs.add(curEvent);
                    if (DEBUG) Slog.d(TAG, "Event timestamp collision: " + lastNanos);
                }
                lastPos++;
                curPos++;
            }
        }
        // Assign an id to the new logs, after the overlap with mLastEvents.
        List<SecurityEvent> idLogs = newLogs.subList(curPos, newLogs.size());
        for (SecurityEvent event : idLogs) {
            assignLogId(event);
        }
        // Save the rest of the new batch.
        mPendingLogs.addAll(idLogs);

        checkCriticalLevel();

        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()));
            mCriticalLevelLogged = false;
            Slog.i(TAG, "Pending logs buffer full. Discarding old logs.");
        }
        if (DEBUG) Slog.d(TAG, mPendingLogs.size() + " pending events in the buffer after merging,"
                + " with ids " + mPendingLogs.get(0).getId()
                + " to " + mPendingLogs.get(mPendingLogs.size() - 1).getId());
    }

    @GuardedBy("mLock")
    private void checkCriticalLevel() {
        if (!SecurityLog.isLoggingEnabled()) {
            return;
        }

        if (mPendingLogs.size() >= BUFFER_ENTRIES_CRITICAL_LEVEL) {
            if (!mCriticalLevelLogged) {
                mCriticalLevelLogged = true;
                SecurityLog.writeEvent(SecurityLog.TAG_LOG_BUFFER_SIZE_CRITICAL);
            }
        }
    }

    @GuardedBy("mLock")
    private void assignLogId(SecurityEvent event) {
        event.setId(mId);
        if (mId == Long.MAX_VALUE) {
            Slog.i(TAG, "Reached maximum id value; wrapping around.");
            mId = 0;
        } else {
            mId++;
        }
    }

    @Override
    public void run() {
        Process.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND);

        final ArrayList<SecurityEvent> newLogs = new ArrayList<>();
        while (!Thread.currentThread().isInterrupted()) {
            try {
                final boolean force = mForceSemaphore.tryAcquire(POLLING_INTERVAL_MS, MILLISECONDS);

                getNextBatch(newLogs);

                mLock.lockInterruptibly();
                try {
                    mergeBatchLocked(newLogs);
                } finally {
                    mLock.unlock();
                }

                saveLastEvents(newLogs);
                newLogs.clear();
                notifyDeviceOwnerIfNeeded(force);
            } 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(boolean force) throws InterruptedException {
        boolean allowRetrievalAndNotifyDO = false;
        mLock.lockInterruptibly();
        try {
            if (mPaused) {
                return;
            }
            final int logSize = mPendingLogs.size();
            if (logSize >= BUFFER_ENTRIES_NOTIFICATION_LEVEL || (force && logSize > 0)) {
                // Allow DO to retrieve logs if too many pending logs or if forced.
                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_MS;
            }
        } finally {
            mLock.unlock();
        }
        if (allowRetrievalAndNotifyDO) {
            Slog.i(TAG, "notify DO");
            mService.sendDeviceOwnerCommand(DeviceAdminReceiver.ACTION_SECURITY_LOGS_AVAILABLE,
                    null);
        }
    }

    /**
     * Forces the logs to be fetched and made available. Returns 0 on success or timeout to wait
     * before attempting in milliseconds.
     */
    public long forceLogs() {
        final long nowNanos = System.nanoTime();
        // We only synchronize with another calls to this function, not with the fetching thread.
        synchronized (mForceSemaphore) {
            final long toWaitNanos = mLastForceNanos + FORCE_FETCH_THROTTLE_NS - nowNanos;
            if (toWaitNanos > 0) {
                return NANOSECONDS.toMillis(toWaitNanos) + 1; // Round up.
            }
            mLastForceNanos = nowNanos;
            // There is a race condition with the fetching thread below, but if the last permit is
            // acquired just after we do the check, logs are forced anyway and that's what we need.
            if (mForceSemaphore.availablePermits() == 0) {
                mForceSemaphore.release();
            }
            return 0;
        }
    }
}