• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /*
2  * Copyright (C) 2016 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.server.devicepolicy;
18 
19 import static java.util.concurrent.TimeUnit.MILLISECONDS;
20 import static java.util.concurrent.TimeUnit.NANOSECONDS;
21 
22 import android.annotation.Nullable;
23 import android.app.admin.DeviceAdminReceiver;
24 import android.app.admin.IAuditLogEventsCallback;
25 import android.app.admin.SecurityLog;
26 import android.app.admin.SecurityLog.SecurityEvent;
27 import android.app.admin.flags.Flags;
28 import android.os.Handler;
29 import android.os.IBinder;
30 import android.os.Process;
31 import android.os.RemoteException;
32 import android.os.SystemClock;
33 import android.util.Log;
34 import android.util.Slog;
35 import android.util.SparseArray;
36 
37 import com.android.internal.annotations.GuardedBy;
38 import com.android.internal.annotations.VisibleForTesting;
39 import com.android.server.utils.Slogf;
40 
41 import java.io.IOException;
42 import java.util.ArrayDeque;
43 import java.util.ArrayList;
44 import java.util.Iterator;
45 import java.util.List;
46 import java.util.concurrent.Semaphore;
47 import java.util.concurrent.TimeUnit;
48 import java.util.concurrent.locks.Lock;
49 import java.util.concurrent.locks.ReentrantLock;
50 import java.util.function.Consumer;
51 
52 /**
53  * A class managing access to the security logs. It maintains an internal buffer of pending
54  * logs to be retrieved by the device owner. The logs are retrieved from the logd daemon via
55  * JNI binding, and kept until device owner has retrieved to prevent loss of logs. Access to
56  * the logs from the device owner is rate-limited, and device owner is notified when the logs
57  * are ready to be retrieved. This happens every two hours, or when our internal buffer is
58  * larger than a certain threshold.
59  */
60 class SecurityLogMonitor implements Runnable {
61     private final DevicePolicyManagerService mService;
62 
63     private final Lock mLock = new ReentrantLock();
64 
65     private int mEnabledUser;
66 
SecurityLogMonitor(DevicePolicyManagerService service, Handler handler)67     SecurityLogMonitor(DevicePolicyManagerService service, Handler handler) {
68         mService = service;
69         mId = 0;
70         mLastForceNanos = System.nanoTime();
71         mHandler = handler;
72     }
73 
74     private static final boolean DEBUG = false;  // STOPSHIP if true.
75     private static final String TAG = "SecurityLogMonitor";
76     /**
77      * Each log entry can hold up to 4K bytes (but as of {@link android.os.Build.VERSION_CODES#N}
78      * it should be less than 100 bytes), setting 1024 entries as the threshold to notify Device
79      * Owner.
80      */
81     @VisibleForTesting static final int BUFFER_ENTRIES_NOTIFICATION_LEVEL = 1024;
82     /**
83      * The maximum number of entries we should store before dropping earlier logs, to limit the
84      * memory usage.
85      */
86     private static final int BUFFER_ENTRIES_MAXIMUM_LEVEL = BUFFER_ENTRIES_NOTIFICATION_LEVEL * 10;
87     /**
88      * Critical log buffer level, 90% of capacity.
89      */
90     private static final int BUFFER_ENTRIES_CRITICAL_LEVEL = BUFFER_ENTRIES_MAXIMUM_LEVEL * 9 / 10;
91     /**
92      * How often should Device Owner be notified under normal circumstances.
93      */
94     private static final long RATE_LIMIT_INTERVAL_MS = TimeUnit.HOURS.toMillis(2);
95     /**
96      * How often to retry the notification about available logs if it is ignored or missed by DO.
97      */
98     private static final long BROADCAST_RETRY_INTERVAL_MS = TimeUnit.MINUTES.toMillis(30);
99     /**
100      * Internally how often should the monitor poll the security logs from logd.
101      */
102     private static final long POLLING_INTERVAL_MS = TimeUnit.MINUTES.toMillis(1);
103     /**
104      * Overlap between two subsequent log requests, required to avoid losing out of order events.
105      */
106     private static final long OVERLAP_NS = TimeUnit.SECONDS.toNanos(3);
107 
108     /** Minimum time between forced fetch attempts. */
109     private static final long FORCE_FETCH_THROTTLE_NS = TimeUnit.SECONDS.toNanos(10);
110 
111     /**
112      * Monitor thread is not null iff SecurityLogMonitor is running, i.e. started and not stopped.
113      * Pausing doesn't change it.
114      */
115     @GuardedBy("mLock")
116     private Thread mMonitorThread = null;
117     @GuardedBy("mLock")
118     private ArrayList<SecurityEvent> mPendingLogs = new ArrayList<>();
119     @GuardedBy("mLock")
120     private long mId;
121     @GuardedBy("mLock")
122     private boolean mAllowedToRetrieve = false;
123 
124     // Whether we have already logged the fact that log buffer reached 90%, to avoid dupes.
125     @GuardedBy("mLock")
126     private boolean mCriticalLevelLogged = false;
127 
128     private boolean mLegacyLogEnabled;
129     private boolean mAuditLogEnabled;
130 
131     /**
132      * Last events fetched from log to check for overlap between batches. We can leave it empty if
133      * we are sure there will be no overlap anymore, e.g. when we get empty batch.
134      */
135     private final ArrayList<SecurityEvent> mLastEvents = new ArrayList<>();
136     /** Timestamp of the very last event, -1 means request from the beginning of time. */
137     private long mLastEventNanos = -1;
138 
139     /**
140      * When DO will be allowed to retrieve the log, in milliseconds since boot (as per
141      * {@link SystemClock#elapsedRealtime()}). After that it will mark the time to retry broadcast.
142      */
143     @GuardedBy("mLock")
144     private long mNextAllowedRetrievalTimeMillis = -1;
145     @GuardedBy("mLock")
146     private boolean mPaused = false;
147 
148     /** Semaphore used to force log fetching on request from adb. */
149     private final Semaphore mForceSemaphore = new Semaphore(0 /* permits */);
150 
151     /** The last timestamp when force fetch was used, to prevent abuse. */
152     @GuardedBy("mForceSemaphore")
153     private long mLastForceNanos = 0;
154 
155     /**
156      * Handler shared with DPMS.
157      */
158     private final Handler mHandler;
159 
160     /**
161      * Oldest events get purged from audit log buffer if total number exceeds this value.
162      */
163     private static final int MAX_AUDIT_LOG_EVENTS = 10000;
164     /**
165      * Events older than this get purged from audit log buffer.
166      */
167     private static final long MAX_AUDIT_LOG_EVENT_AGE_NS = TimeUnit.HOURS.toNanos(8);
168 
169     /**
170      * Audit log callbacks keyed by UID. The code should maintain the following invariant: all
171      * callbacks in this map have received (or are scheduled to receive) all events in
172      * mAuditLogEventsBuffer. To ensure this, before a callback is put into this map, it must be
173      * scheduled to receive all the events in the buffer, and conversely, before a new chunk of
174      * events is added to the buffer, it must be scheduled to be sent to all callbacks already in
175      * this list. All scheduling should happen on mHandler, so that they aren't reordered, and
176      * while holding the lock. This ensures that no callback misses an event or receives a duplicate
177      * or out of order events.
178      */
179     @GuardedBy("mLock")
180     private final SparseArray<IAuditLogEventsCallback> mAuditLogCallbacks = new SparseArray<>();
181 
182     /**
183      * Audit log event buffer. It is shrunk automatically whenever either there are too many events
184      * or the oldest one is too old.
185      */
186     @GuardedBy("mLock")
187     private final ArrayDeque<SecurityEvent> mAuditLogEventBuffer = new ArrayDeque<>();
188 
189     @GuardedBy("mLock")
190     @Nullable
191     private Consumer<List<SecurityEvent>> mInternalEventsCallback;
192 
stop()193     void stop() {
194         Slog.i(TAG, "Stopping security logging.");
195         mLock.lock();
196         try {
197             if (mMonitorThread != null) {
198                 stopMonitorThreadLocked();
199                 resetLegacyBufferLocked();
200             }
201         } finally {
202             mLock.unlock();
203         }
204     }
205 
setLoggingParams(int enabledUser, boolean legacyLogEnabled, boolean auditLogEnabled)206     void setLoggingParams(int enabledUser, boolean legacyLogEnabled, boolean auditLogEnabled) {
207         Slogf.i(TAG, "Setting logging params, user = %d -> %d, legacy: %b -> %b, audit %b -> %b",
208                 mEnabledUser, enabledUser, mLegacyLogEnabled, legacyLogEnabled, mAuditLogEnabled,
209                 auditLogEnabled);
210         mLock.lock();
211         try {
212             mEnabledUser = enabledUser;
213             if (mMonitorThread == null && (legacyLogEnabled || auditLogEnabled)) {
214                 startMonitorThreadLocked();
215             } else if (mMonitorThread != null && !legacyLogEnabled && !auditLogEnabled) {
216                 stopMonitorThreadLocked();
217             }
218 
219             if (mLegacyLogEnabled != legacyLogEnabled) {
220                 resetLegacyBufferLocked();
221                 mLegacyLogEnabled = legacyLogEnabled;
222             }
223 
224             if (mAuditLogEnabled != auditLogEnabled) {
225                 resetAuditBufferLocked();
226                 mAuditLogEnabled = auditLogEnabled;
227             }
228         } finally {
229             mLock.unlock();
230         }
231     }
232 
233     @GuardedBy("mLock")
startMonitorThreadLocked()234     private void startMonitorThreadLocked() {
235         mId = 0;
236         mPaused = false;
237         mMonitorThread = new Thread(this);
238         mMonitorThread.start();
239         SecurityLog.writeEvent(SecurityLog.TAG_LOGGING_STARTED);
240         Slog.i(TAG, "Security log monitor thread started");
241     }
242 
243     @GuardedBy("mLock")
stopMonitorThreadLocked()244     private void stopMonitorThreadLocked() {
245         mMonitorThread.interrupt();
246         try {
247             mMonitorThread.join(TimeUnit.SECONDS.toMillis(5));
248         } catch (InterruptedException e) {
249             Log.e(TAG, "Interrupted while waiting for thread to stop", e);
250         }
251         mMonitorThread = null;
252         SecurityLog.writeEvent(SecurityLog.TAG_LOGGING_STOPPED);
253     }
254 
255     @GuardedBy("mLock")
resetLegacyBufferLocked()256     private void resetLegacyBufferLocked() {
257         mPendingLogs = new ArrayList<>();
258         mCriticalLevelLogged = false;
259         mAllowedToRetrieve = false;
260         mNextAllowedRetrievalTimeMillis = -1;
261         Slog.i(TAG, "Legacy buffer reset.");
262     }
263 
264     @GuardedBy("mLock")
resetAuditBufferLocked()265     private void resetAuditBufferLocked() {
266         mAuditLogEventBuffer.clear();
267         mAuditLogCallbacks.clear();
268     }
269 
270     /**
271      * If logs are being collected, keep collecting them but stop notifying the device owner that
272      * new logs are available (since they cannot be retrieved).
273      */
pause()274     void pause() {
275         Slog.i(TAG, "Paused.");
276 
277         mLock.lock();
278         mPaused = true;
279         mAllowedToRetrieve = false;
280         mLock.unlock();
281     }
282 
283     /**
284      * If logs are being collected, start notifying the device owner when logs are ready to be
285      * retrieved again (if it was paused).
286      * <p>If logging is enabled and there are logs ready to be retrieved, this method will attempt
287      * to notify the device owner. Therefore calling identity should be cleared before calling it
288      * (in case the method is called from a user other than the DO's user).
289      */
resume()290     void resume() {
291         mLock.lock();
292         try {
293             if (!mPaused) {
294                 Log.d(TAG, "Attempted to resume, but logging is not paused.");
295                 return;
296             }
297             mPaused = false;
298             mAllowedToRetrieve = false;
299         } finally {
300             mLock.unlock();
301         }
302 
303         Slog.i(TAG, "Resumed.");
304         try {
305             notifyDeviceOwnerOrProfileOwnerIfNeeded(false /* force */);
306         } catch (InterruptedException e) {
307             Log.w(TAG, "Thread interrupted.", e);
308         }
309     }
310 
311     /**
312      * Discard all collected logs.
313      */
discardLogs()314     void discardLogs() {
315         mLock.lock();
316         mAllowedToRetrieve = false;
317         mPendingLogs = new ArrayList<>();
318         mCriticalLevelLogged = false;
319         mLock.unlock();
320         Slog.i(TAG, "Discarded all logs.");
321     }
322 
323     /**
324      * Returns the new batch of logs since the last call to this method. Returns null if
325      * rate limit is exceeded.
326      */
retrieveLogs()327     List<SecurityEvent> retrieveLogs() {
328         mLock.lock();
329         try {
330             if (mAllowedToRetrieve) {
331                 mAllowedToRetrieve = false;
332                 mNextAllowedRetrievalTimeMillis = SystemClock.elapsedRealtime()
333                         + RATE_LIMIT_INTERVAL_MS;
334                 List<SecurityEvent> result = mPendingLogs;
335                 mPendingLogs = new ArrayList<>();
336                 mCriticalLevelLogged = false;
337                 return result;
338             } else {
339                 return null;
340             }
341         } finally {
342             mLock.unlock();
343         }
344     }
345 
346     /**
347      * Requests the next (or the first) batch of events from the log with appropriate timestamp.
348      */
getNextBatch(ArrayList<SecurityEvent> newLogs)349     private void getNextBatch(ArrayList<SecurityEvent> newLogs) throws IOException {
350         if (mLastEventNanos < 0) {
351             // Non-blocking read that returns all logs immediately.
352             if (DEBUG) Slog.d(TAG, "SecurityLog.readEvents");
353             SecurityLog.readEvents(newLogs);
354         } else {
355             // If we have last events from the previous batch, request log events with time overlap
356             // with previously retrieved messages to avoid losing events due to reordering in logd.
357             final long startNanos = mLastEvents.isEmpty()
358                     ? mLastEventNanos : Math.max(0, mLastEventNanos - OVERLAP_NS);
359             if (DEBUG) Slog.d(TAG, "SecurityLog.readEventsSince: " + startNanos);
360             // Non-blocking read that returns all logs with timestamps >= startNanos immediately.
361             SecurityLog.readEventsSince(startNanos, newLogs);
362         }
363 
364         // Sometimes events may be reordered in logd due to simultaneous readers and writers. In
365         // this case, we have to sort it to make overlap checking work. This is very unlikely.
366         for (int i = 0; i < newLogs.size() - 1; i++) {
367             if (newLogs.get(i).getTimeNanos() > newLogs.get(i+1).getTimeNanos()) {
368                 if (DEBUG) Slog.d(TAG, "Got out of order events, sorting.");
369                 // Sort using comparator that compares timestamps.
370                 newLogs.sort((e1, e2) -> Long.signum(e1.getTimeNanos() - e2.getTimeNanos()));
371                 break;
372             }
373         }
374         if (!Flags.internalLogEventListener()) {
375             SecurityLog.redactEvents(newLogs, mEnabledUser);
376         }
377         if (DEBUG) Slog.d(TAG, "Got " + newLogs.size() + " new events.");
378     }
379 
380     /**
381      * Save the last events for overlap checking with the next batch.
382      */
saveLastEvents(ArrayList<SecurityEvent> newLogs)383     private void saveLastEvents(ArrayList<SecurityEvent> newLogs) {
384         mLastEvents.clear();
385         if (newLogs.isEmpty()) {
386             // This can happen if no events were logged yet or the buffer got cleared. In this case
387             // we aren't going to have any overlap next time, leave mLastEvents events empty.
388             return;
389         }
390 
391         // Save the last timestamp.
392         mLastEventNanos = newLogs.get(newLogs.size() - 1).getTimeNanos();
393         // Position of the earliest event that has to be saved. Start from the penultimate event,
394         // going backward.
395         int pos = newLogs.size() - 2;
396         while (pos >= 0 && mLastEventNanos - newLogs.get(pos).getTimeNanos() < OVERLAP_NS) {
397             pos--;
398         }
399         // We either run past the start of the list or encountered an event that is too old to keep.
400         pos++;
401         mLastEvents.addAll(newLogs.subList(pos, newLogs.size()));
402         if (DEBUG) Slog.d(TAG, mLastEvents.size() + " events saved for overlap check");
403     }
404 
405     /**
406      * Merges a new batch into already fetched logs and deals with overlapping and out of order
407      * events.
408      */
409     @GuardedBy("mLock")
mergeBatchLocked(final ArrayList<SecurityEvent> newLogs)410     private void mergeBatchLocked(final ArrayList<SecurityEvent> newLogs) {
411         ArrayList<SecurityEvent> dedupedLogs = new ArrayList<>();
412         // Run through the first events of the batch to check if there is an overlap with previous
413         // batch and if so, skip overlapping events. Events are sorted by timestamp, so we can
414         // compare it in linear time by advancing two pointers, one for each batch.
415         int curPos = 0;
416         int lastPos = 0;
417         // For the first batch mLastEvents will be empty, so no iterations will happen.
418         while (lastPos < mLastEvents.size() && curPos < newLogs.size()) {
419             final SecurityEvent curEvent = newLogs.get(curPos);
420             final long currentNanos = curEvent.getTimeNanos();
421             if (currentNanos > mLastEventNanos) {
422                 // We got past the last event of the last batch, no overlap possible anymore.
423                 break;
424             }
425             final SecurityEvent lastEvent = mLastEvents.get(lastPos);
426             final long lastNanos = lastEvent.getTimeNanos();
427             if (lastNanos > currentNanos) {
428                 // New event older than the last we've seen so far, must be due to reordering.
429                 if (DEBUG) Slog.d(TAG, "New event in the overlap: " + currentNanos);
430                 dedupedLogs.add(curEvent);
431                 curPos++;
432             } else if (lastNanos < currentNanos) {
433                 if (DEBUG) Slog.d(TAG, "Event disappeared from the overlap: " + lastNanos);
434                 lastPos++;
435             } else {
436                 // Two events have the same timestamp, check if they are the same.
437                 if (lastEvent.eventEquals(curEvent)) {
438                     // Actual overlap, just skip the event.
439                     if (DEBUG) Slog.d(TAG, "Skipped dup event with timestamp: " + lastNanos);
440                 } else {
441                     // Wow, what a coincidence, or probably the clock is too coarse.
442                     dedupedLogs.add(curEvent);
443                     if (DEBUG) Slog.d(TAG, "Event timestamp collision: " + lastNanos);
444                 }
445                 lastPos++;
446                 curPos++;
447             }
448         }
449 
450         dedupedLogs.addAll(newLogs.subList(curPos, newLogs.size()));
451 
452         if (Flags.internalLogEventListener() && !dedupedLogs.isEmpty()) {
453             if (mInternalEventsCallback != null) {
454                 final ArrayList<SecurityEvent> events = new ArrayList<>(dedupedLogs);
455                 final Consumer<List<SecurityEvent>> callback = mInternalEventsCallback;
456                 mHandler.post(() -> callback.accept(events));
457             }
458             SecurityLog.redactEvents(dedupedLogs, mEnabledUser);
459         }
460 
461         // Assign an id to the new logs, after the overlap with mLastEvents.
462         for (SecurityEvent event : dedupedLogs) {
463             assignLogId(event);
464         }
465 
466         if (mLegacyLogEnabled) {
467             addToLegacyBufferLocked(dedupedLogs);
468         }
469 
470         if (mAuditLogEnabled) {
471             addAuditLogEventsLocked(dedupedLogs);
472         }
473     }
474 
475     @GuardedBy("mLock")
addToLegacyBufferLocked(List<SecurityEvent> dedupedLogs)476     private void addToLegacyBufferLocked(List<SecurityEvent> dedupedLogs) {
477         // Save the rest of the new batch.
478         mPendingLogs.addAll(dedupedLogs);
479 
480         checkCriticalLevel();
481 
482         if (mPendingLogs.size() > BUFFER_ENTRIES_MAXIMUM_LEVEL) {
483             // Truncate buffer down to half of BUFFER_ENTRIES_MAXIMUM_LEVEL.
484             mPendingLogs = new ArrayList<>(mPendingLogs.subList(
485                     mPendingLogs.size() - (BUFFER_ENTRIES_MAXIMUM_LEVEL / 2),
486                     mPendingLogs.size()));
487             mCriticalLevelLogged = false;
488             Slog.i(TAG, "Pending logs buffer full. Discarding old logs.");
489         }
490         if (DEBUG) {
491             if (mPendingLogs.size() > 0) {
492                 Slog.d(TAG, mPendingLogs.size() + " pending events in the buffer after merging,"
493                         + " with ids " + mPendingLogs.get(0).getId()
494                         + " to " + mPendingLogs.get(mPendingLogs.size() - 1).getId());
495             } else {
496                 Slog.d(TAG, "0 pending events in the buffer after merging");
497             }
498         }
499     }
500 
501     @GuardedBy("mLock")
checkCriticalLevel()502     private void checkCriticalLevel() {
503         if (!SecurityLog.isLoggingEnabled()) {
504             return;
505         }
506 
507         if (mPendingLogs.size() >= BUFFER_ENTRIES_CRITICAL_LEVEL) {
508             if (!mCriticalLevelLogged) {
509                 mCriticalLevelLogged = true;
510                 SecurityLog.writeEvent(SecurityLog.TAG_LOG_BUFFER_SIZE_CRITICAL);
511             }
512         }
513     }
514 
515     @GuardedBy("mLock")
assignLogId(SecurityEvent event)516     private void assignLogId(SecurityEvent event) {
517         event.setId(mId);
518         if (mId == Long.MAX_VALUE) {
519             Slog.i(TAG, "Reached maximum id value; wrapping around.");
520             mId = 0;
521         } else {
522             mId++;
523         }
524     }
525 
526     @Override
run()527     public void run() {
528         Process.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND);
529 
530         final ArrayList<SecurityEvent> newLogs = new ArrayList<>();
531         while (!Thread.currentThread().isInterrupted()) {
532             try {
533                 final boolean force = mForceSemaphore.tryAcquire(POLLING_INTERVAL_MS, MILLISECONDS);
534 
535                 getNextBatch(newLogs);
536 
537                 mLock.lockInterruptibly();
538                 try {
539                     mergeBatchLocked(newLogs);
540                 } finally {
541                     mLock.unlock();
542                 }
543 
544                 saveLastEvents(newLogs);
545                 newLogs.clear();
546 
547                 if (mLegacyLogEnabled) {
548                     notifyDeviceOwnerOrProfileOwnerIfNeeded(force);
549                 }
550             } catch (IOException e) {
551                 Log.e(TAG, "Failed to read security log", e);
552             } catch (InterruptedException e) {
553                 Log.i(TAG, "Thread interrupted, exiting.", e);
554                 // We are asked to stop.
555                 break;
556             }
557         }
558 
559         // Discard previous batch info.
560         mLastEvents.clear();
561         if (mLastEventNanos != -1) {
562             // Make sure we don't read old events if logging is re-enabled. Since mLastEvents is
563             // empty, the next request will be done without overlap, so it is enough to add 1 ns.
564             mLastEventNanos += 1;
565         }
566 
567         Slog.i(TAG, "MonitorThread exit.");
568     }
569 
notifyDeviceOwnerOrProfileOwnerIfNeeded(boolean force)570     private void notifyDeviceOwnerOrProfileOwnerIfNeeded(boolean force)
571             throws InterruptedException {
572         boolean allowRetrievalAndNotifyDOOrPO = false;
573         mLock.lockInterruptibly();
574         try {
575             if (mPaused) {
576                 return;
577             }
578             final int logSize = mPendingLogs.size();
579             if (logSize >= BUFFER_ENTRIES_NOTIFICATION_LEVEL || (force && logSize > 0)) {
580                 // Allow DO to retrieve logs if too many pending logs or if forced.
581                 if (!mAllowedToRetrieve) {
582                     allowRetrievalAndNotifyDOOrPO = true;
583                 }
584                 if (DEBUG) Slog.d(TAG, "Number of log entries over threshold: " + logSize);
585             }
586             if (logSize > 0 && SystemClock.elapsedRealtime() >= mNextAllowedRetrievalTimeMillis) {
587                 // Rate limit reset
588                 allowRetrievalAndNotifyDOOrPO = true;
589                 if (DEBUG) Slog.d(TAG, "Timeout reached");
590             }
591             if (allowRetrievalAndNotifyDOOrPO) {
592                 mAllowedToRetrieve = true;
593                 // Set the timeout to retry the notification if the DO misses it.
594                 mNextAllowedRetrievalTimeMillis = SystemClock.elapsedRealtime()
595                         + BROADCAST_RETRY_INTERVAL_MS;
596             }
597         } finally {
598             mLock.unlock();
599         }
600         if (allowRetrievalAndNotifyDOOrPO) {
601             Slog.i(TAG, "notify DO or PO");
602             mService.sendDeviceOwnerOrProfileOwnerCommand(
603                     DeviceAdminReceiver.ACTION_SECURITY_LOGS_AVAILABLE, null, mEnabledUser);
604         }
605     }
606 
607     /**
608      * Forces the logs to be fetched and made available. Returns 0 on success or timeout to wait
609      * before attempting in milliseconds.
610      */
forceLogs()611     public long forceLogs() {
612         final long nowNanos = System.nanoTime();
613         // We only synchronize with another calls to this function, not with the fetching thread.
614         synchronized (mForceSemaphore) {
615             final long toWaitNanos = mLastForceNanos + FORCE_FETCH_THROTTLE_NS - nowNanos;
616             if (toWaitNanos > 0) {
617                 return NANOSECONDS.toMillis(toWaitNanos) + 1; // Round up.
618             }
619             mLastForceNanos = nowNanos;
620             // There is a race condition with the fetching thread below, but if the last permit is
621             // acquired just after we do the check, logs are forced anyway and that's what we need.
622             if (mForceSemaphore.availablePermits() == 0) {
623                 mForceSemaphore.release();
624             }
625             return 0;
626         }
627     }
628 
setAuditLogEventsCallback(int uid, IAuditLogEventsCallback callback)629     public void setAuditLogEventsCallback(int uid, IAuditLogEventsCallback callback) {
630         mLock.lock();
631         try {
632             if (callback == null) {
633                 mAuditLogCallbacks.remove(uid);
634                 Slogf.i(TAG, "Cleared audit log callback for UID %d", uid);
635                 return;
636             }
637             // Create a copy while holding the lock, so that that new events are not added
638             // resulting in duplicates.
639             final List<SecurityEvent> events = new ArrayList<>(mAuditLogEventBuffer);
640             scheduleSendAuditLogs(uid, callback, events);
641             mAuditLogCallbacks.append(uid, callback);
642         } finally {
643             mLock.unlock();
644         }
645         Slogf.i(TAG, "Set audit log callback for UID %d", uid);
646     }
647 
648     @GuardedBy("mLock")
addAuditLogEventsLocked(List<SecurityEvent> events)649     private void addAuditLogEventsLocked(List<SecurityEvent> events) {
650         if (mPaused) {
651             // TODO: maybe we need to stash the logs in some temp buffer wile paused so that
652             // they can be accessed after affiliation is fixed.
653             return;
654         }
655         if (!events.isEmpty()) {
656             for (int i = 0; i < mAuditLogCallbacks.size(); i++) {
657                 final int uid = mAuditLogCallbacks.keyAt(i);
658                 scheduleSendAuditLogs(uid, mAuditLogCallbacks.valueAt(i), events);
659             }
660         }
661         if (DEBUG) {
662             Slogf.d(TAG, "Adding audit %d events to %d already present in the buffer",
663                     events.size(), mAuditLogEventBuffer.size());
664         }
665         mAuditLogEventBuffer.addAll(events);
666         trimAuditLogBufferLocked();
667         if (DEBUG) {
668             Slogf.d(TAG, "Audit event buffer size after trimming: %d",
669                     mAuditLogEventBuffer.size());
670         }
671     }
672 
673     @GuardedBy("mLock")
trimAuditLogBufferLocked()674     private void trimAuditLogBufferLocked() {
675         long nowNanos = TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis());
676 
677         final Iterator<SecurityEvent> iterator = mAuditLogEventBuffer.iterator();
678         while (iterator.hasNext()) {
679             final SecurityEvent event = iterator.next();
680             if (mAuditLogEventBuffer.size() <= MAX_AUDIT_LOG_EVENTS
681                     && nowNanos - event.getTimeNanos() <= MAX_AUDIT_LOG_EVENT_AGE_NS) {
682                 break;
683             }
684 
685             iterator.remove();
686         }
687     }
688 
scheduleSendAuditLogs( int uid, IAuditLogEventsCallback callback, List<SecurityEvent> events)689     private void scheduleSendAuditLogs(
690             int uid, IAuditLogEventsCallback callback, List<SecurityEvent> events) {
691         if (DEBUG) {
692             Slogf.d(TAG, "Scheduling to send %d audit log events to UID %d", events.size(), uid);
693         }
694         mHandler.post(() -> sendAuditLogs(uid, callback, events));
695     }
696 
sendAuditLogs( int uid, IAuditLogEventsCallback callback, List<SecurityEvent> events)697     private void sendAuditLogs(
698             int uid, IAuditLogEventsCallback callback, List<SecurityEvent> events) {
699         try {
700             final int size = events.size();
701             if (DEBUG) {
702                 Slogf.d(TAG, "Sending %d audit log events to UID %d", size, uid);
703             }
704             callback.onNewAuditLogEvents(events);
705             if (DEBUG) {
706                 Slogf.d(TAG, "Sent %d audit log events to UID %d", size, uid);
707             }
708         } catch (RemoteException e) {
709             Slogf.e(TAG, e, "Failed to invoke audit log callback for UID %d", uid);
710             removeAuditLogEventsCallbackIfDead(uid, callback);
711         }
712     }
713 
removeAuditLogEventsCallbackIfDead(int uid, IAuditLogEventsCallback callback)714     private void removeAuditLogEventsCallbackIfDead(int uid, IAuditLogEventsCallback callback) {
715         final IBinder binder = callback.asBinder();
716         if (binder.isBinderAlive()) {
717             Slog.i(TAG, "Callback binder is still alive, not removing.");
718             return;
719         }
720 
721         mLock.lock();
722         try {
723             int index = mAuditLogCallbacks.indexOfKey(uid);
724             if (index < 0) {
725                 Slogf.i(TAG, "Callback not registered for UID %d, nothing to remove", uid);
726                 return;
727             }
728 
729             final IBinder storedBinder = mAuditLogCallbacks.valueAt(index).asBinder();
730             if (!storedBinder.equals(binder)) {
731                 Slogf.i(TAG, "Callback is already replaced for UID %d, not removing", uid);
732                 return;
733             }
734 
735             Slogf.i(TAG, "Removing callback for UID %d", uid);
736             mAuditLogCallbacks.removeAt(index);
737         } finally {
738             mLock.unlock();
739         }
740     }
741 
setInternalEventsCallback(@ullable Consumer<List<SecurityEvent>> callback)742     public void setInternalEventsCallback(@Nullable Consumer<List<SecurityEvent>> callback) {
743         if (!Flags.internalLogEventListener()) {
744             Slog.wtf(TAG, "Internal callbacks not enabled");
745             return;
746         }
747         mLock.lock();
748         try {
749             this.mInternalEventsCallback = callback;
750         } finally {
751             mLock.unlock();
752         }
753     }
754 }
755