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