1 /* 2 * Copyright 2014, 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.telecom; 18 19 import android.content.Context; 20 import android.net.Uri; 21 import android.os.Handler; 22 import android.os.Looper; 23 import android.os.AsyncTask; 24 import android.telecom.PhoneAccount; 25 import android.telephony.PhoneNumberUtils; 26 import android.text.TextUtils; 27 import android.util.Base64; 28 29 import com.android.internal.annotations.VisibleForTesting; 30 import com.android.internal.util.IndentingPrintWriter; 31 32 import java.nio.ByteBuffer; 33 import java.security.MessageDigest; 34 import java.security.NoSuchAlgorithmException; 35 import java.text.DateFormat; 36 import java.text.SimpleDateFormat; 37 import java.util.Arrays; 38 import java.util.Date; 39 import java.util.HashMap; 40 import java.util.IllegalFormatException; 41 import java.util.Iterator; 42 import java.util.LinkedList; 43 import java.util.List; 44 import java.util.Locale; 45 import java.util.Map; 46 import java.util.concurrent.ConcurrentHashMap; 47 import java.util.concurrent.LinkedBlockingQueue; 48 49 /** 50 * Manages logging for the entire module. 51 */ 52 @VisibleForTesting 53 public class Log { 54 55 /** 56 * Stores the various events associated with {@link Call}s. Also stores all request-response 57 * pairs amongst the events. 58 */ 59 public final static class Events { 60 public static final String CREATED = "CREATED"; 61 public static final String DESTROYED = "DESTROYED"; 62 public static final String SET_NEW = "SET_NEW"; 63 public static final String SET_CONNECTING = "SET_CONNECTING"; 64 public static final String SET_DIALING = "SET_DIALING"; 65 public static final String SET_ACTIVE = "SET_ACTIVE"; 66 public static final String SET_HOLD = "SET_HOLD"; 67 public static final String SET_RINGING = "SET_RINGING"; 68 public static final String SET_DISCONNECTED = "SET_DISCONNECTED"; 69 public static final String SET_DISCONNECTING = "SET_DISCONNECTING"; 70 public static final String SET_SELECT_PHONE_ACCOUNT = "SET_SELECT_PHONE_ACCOUNT"; 71 public static final String REQUEST_HOLD = "REQUEST_HOLD"; 72 public static final String REQUEST_UNHOLD = "REQUEST_UNHOLD"; 73 public static final String REQUEST_DISCONNECT = "REQUEST_DISCONNECT"; 74 public static final String REQUEST_ACCEPT = "REQUEST_ACCEPT"; 75 public static final String REQUEST_REJECT = "REQUEST_REJECT"; 76 public static final String START_DTMF = "START_DTMF"; 77 public static final String STOP_DTMF = "STOP_DTMF"; 78 public static final String START_RINGER = "START_RINGER"; 79 public static final String STOP_RINGER = "STOP_RINGER"; 80 public static final String SKIP_RINGING = "SKIP_RINGING"; 81 public static final String START_CALL_WAITING_TONE = "START_CALL_WAITING_TONE"; 82 public static final String STOP_CALL_WAITING_TONE = "STOP_CALL_WAITING_TONE"; 83 public static final String START_CONNECTION = "START_CONNECTION"; 84 public static final String BIND_CS = "BIND_CS"; 85 public static final String CS_BOUND = "CS_BOUND"; 86 public static final String CONFERENCE_WITH = "CONF_WITH"; 87 public static final String SPLIT_CONFERENCE = "CONF_SPLIT"; 88 public static final String SWAP = "SWAP"; 89 public static final String ADD_CHILD = "ADD_CHILD"; 90 public static final String REMOVE_CHILD = "REMOVE_CHILD"; 91 public static final String SET_PARENT = "SET_PARENT"; 92 public static final String MUTE = "MUTE"; 93 public static final String AUDIO_ROUTE = "AUDIO_ROUTE"; 94 public static final String ERROR_LOG = "ERROR"; 95 public static final String USER_LOG_MARK = "USER_LOG_MARK"; 96 public static final String SILENCE = "SILENCE"; 97 public static final String BIND_SCREENING = "BIND_SCREENING"; 98 public static final String SCREENING_BOUND = "SCREENING_BOUND"; 99 public static final String SCREENING_SENT = "SCREENING_SENT"; 100 public static final String SCREENING_COMPLETED = "SCREENING_COMPLETED"; 101 public static final String BLOCK_CHECK_INITIATED = "BLOCK_CHECK_INITIATED"; 102 public static final String BLOCK_CHECK_FINISHED = "BLOCK_CHECK_FINISHED"; 103 public static final String DIRECT_TO_VM_INITIATED = "DIRECT_TO_VM_INITIATED"; 104 public static final String DIRECT_TO_VM_FINISHED = "DIRECT_TO_VM_FINISHED"; 105 public static final String FILTERING_INITIATED = "FILTERING_INITIATED"; 106 public static final String FILTERING_COMPLETED = "FILTERING_COMPLETED"; 107 public static final String FILTERING_TIMED_OUT = "FILTERING_TIMED_OUT"; 108 public static final String REMOTELY_HELD = "REMOTELY_HELD"; 109 public static final String REMOTELY_UNHELD = "REMOTELY_UNHELD"; 110 public static final String PULL = "PULL"; 111 public static final String INFO = "INFO"; 112 113 /** 114 * Maps from a request to a response. The same event could be listed as the 115 * response for multiple requests (e.g. REQUEST_ACCEPT and REQUEST_UNHOLD both map to the 116 * SET_ACTIVE response). This map is used to print out the amount of time it takes between 117 * a request and a response. 118 */ 119 public static final Map<String, String> requestResponsePairs = 120 new HashMap<String, String>() {{ 121 put(REQUEST_ACCEPT, SET_ACTIVE); 122 put(REQUEST_REJECT, SET_DISCONNECTED); 123 put(REQUEST_DISCONNECT, SET_DISCONNECTED); 124 put(REQUEST_HOLD, SET_HOLD); 125 put(REQUEST_UNHOLD, SET_ACTIVE); 126 put(START_CONNECTION, SET_DIALING); 127 put(BIND_CS, CS_BOUND); 128 put(SCREENING_SENT, SCREENING_COMPLETED); 129 put(BLOCK_CHECK_INITIATED, BLOCK_CHECK_FINISHED); 130 put(DIRECT_TO_VM_INITIATED, DIRECT_TO_VM_FINISHED); 131 put(FILTERING_INITIATED, FILTERING_COMPLETED); 132 }}; 133 } 134 135 public static class CallEvent { 136 public String eventId; 137 public String sessionId; 138 public long time; 139 public Object data; 140 141 public CallEvent(String eventId, String sessionId, long time, Object data) { 142 this.eventId = eventId; 143 this.sessionId = sessionId; 144 this.time = time; 145 this.data = data; 146 } 147 } 148 149 public static class CallEventRecord { 150 private static final DateFormat sLongDateFormat = new SimpleDateFormat( 151 "yyyy-MM-dd HH:mm:ss.SSS"); 152 private static final DateFormat sDateFormat = new SimpleDateFormat("HH:mm:ss.SSS"); 153 private static int sNextId = 1; 154 private final List<CallEvent> mEvents = new LinkedList<>(); 155 private final Call mCall; 156 157 public CallEventRecord(Call call) { 158 mCall = call; 159 } 160 161 public Call getCall() { 162 return mCall; 163 } 164 165 public void addEvent(String event, String sessionId, Object data) { 166 mEvents.add(new CallEvent(event, sessionId, System.currentTimeMillis(), data)); 167 Log.i("Event", "Call %s: %s, %s", mCall.getId(), event, data); 168 } 169 170 public void dump(IndentingPrintWriter pw) { 171 Map<String, CallEvent> pendingResponses = new HashMap<>(); 172 173 pw.print("Call "); 174 pw.print(mCall.getId()); 175 pw.print(" ["); 176 pw.print(sLongDateFormat.format(new Date(mCall.getCreationTimeMillis()))); 177 pw.print("]"); 178 pw.println(mCall.isIncoming() ? "(MT - incoming)" : "(MO - outgoing)"); 179 180 pw.increaseIndent(); 181 pw.println("To address: " + piiHandle(mCall.getHandle())); 182 183 for (CallEvent event : mEvents) { 184 185 // We print out events in chronological order. During that process we look at each 186 // event and see if it maps to a request on the Request-Response pairs map. If it 187 // does, then we effectively start 'listening' for the response. We do that by 188 // storing the response event ID in {@code pendingResponses}. When we find the 189 // response in a later iteration of the loop, we grab the original request and 190 // calculate the time it took to get a response. 191 if (Events.requestResponsePairs.containsKey(event.eventId)) { 192 // This event expects a response, so add that response to the maps 193 // of pending events. 194 String pendingResponse = Events.requestResponsePairs.get(event.eventId); 195 pendingResponses.put(pendingResponse, event); 196 } 197 198 pw.print(sDateFormat.format(new Date(event.time))); 199 pw.print(" - "); 200 pw.print(event.eventId); 201 if (event.data != null) { 202 pw.print(" ("); 203 Object data = event.data; 204 205 if (data instanceof Call) { 206 // If the data is another call, then change the data to the call's CallEvent 207 // ID instead. 208 CallEventRecord record = mCallEventRecordMap.get(data); 209 if (record != null) { 210 data = "Call " + record.mCall.getId(); 211 } 212 } 213 214 pw.print(data); 215 pw.print(")"); 216 } 217 218 // If this event is a response event that we've been waiting for, calculate the time 219 // it took for the response to complete and print that out as well. 220 CallEvent requestEvent = pendingResponses.remove(event.eventId); 221 if (requestEvent != null) { 222 pw.print(", time since "); 223 pw.print(requestEvent.eventId); 224 pw.print(": "); 225 pw.print(event.time - requestEvent.time); 226 pw.print(" ms"); 227 } 228 pw.print(":"); 229 pw.print(event.sessionId); 230 pw.println(); 231 } 232 pw.decreaseIndent(); 233 } 234 } 235 236 public static final int MAX_CALLS_TO_CACHE = 5; // Arbitrarily chosen. 237 public static final int MAX_CALLS_TO_CACHE_DEBUG = 20; // Arbitrarily chosen. 238 private static final long EXTENDED_LOGGING_DURATION_MILLIS = 60000 * 30; // 30 minutes 239 240 // Don't check in with this true! 241 private static final boolean LOG_DBG = false; 242 243 // Currently using 3 letters, So don't exceed 64^3 244 private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144; 245 246 // Generic tag for all In Call logging 247 @VisibleForTesting 248 public static String TAG = "Telecom"; 249 public static String LOGGING_TAG = "Logging"; 250 251 public static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */ 252 public static final boolean SYSTRACE_DEBUG = false; /* STOP SHIP if true */ 253 public static final boolean DEBUG = isLoggable(android.util.Log.DEBUG); 254 public static final boolean INFO = isLoggable(android.util.Log.INFO); 255 public static final boolean VERBOSE = isLoggable(android.util.Log.VERBOSE); 256 public static final boolean WARN = isLoggable(android.util.Log.WARN); 257 public static final boolean ERROR = isLoggable(android.util.Log.ERROR); 258 259 private static final Map<Call, CallEventRecord> mCallEventRecordMap = new HashMap<>(); 260 private static LinkedBlockingQueue<CallEventRecord> mCallEventRecords = 261 new LinkedBlockingQueue<CallEventRecord>(MAX_CALLS_TO_CACHE); 262 263 private static Context mContext = null; 264 // Synchronized in all method calls 265 private static int sCodeEntryCounter = 0; 266 @VisibleForTesting 267 public static ConcurrentHashMap<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100); 268 @VisibleForTesting 269 public static Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper()); 270 @VisibleForTesting 271 public static java.lang.Runnable sCleanStaleSessions = new java.lang.Runnable() { 272 @Override 273 public void run() { 274 cleanupStaleSessions(getSessionCleanupTimeoutMs()); 275 } 276 }; 277 278 // Set the logging container to be the system's. This will only change when being mocked 279 // during testing. 280 private static SystemLoggingContainer systemLogger = new SystemLoggingContainer(); 281 282 /** 283 * Tracks whether user-activated extended logging is enabled. 284 */ 285 private static boolean mIsUserExtendedLoggingEnabled = false; 286 287 /** 288 * The time when user-activated extended logging should be ended. Used to determine when 289 * extended logging should automatically be disabled. 290 */ 291 private static long mUserExtendedLoggingStopTime = 0; 292 293 private Log() { 294 } 295 296 public static void setContext(Context context) { 297 mContext = context; 298 } 299 300 /** 301 * Enable or disable extended telecom logging. 302 * 303 * @param isExtendedLoggingEnabled {@code true} if extended logging should be enabled, 304 * {@code false} if it should be disabled. 305 */ 306 public static void setIsExtendedLoggingEnabled(boolean isExtendedLoggingEnabled) { 307 // If the state hasn't changed, bail early. 308 if (mIsUserExtendedLoggingEnabled == isExtendedLoggingEnabled) { 309 return; 310 } 311 312 // Resize the event queue. 313 int newSize = isExtendedLoggingEnabled ? MAX_CALLS_TO_CACHE_DEBUG : MAX_CALLS_TO_CACHE; 314 LinkedBlockingQueue<CallEventRecord> oldEventLog = mCallEventRecords; 315 mCallEventRecords = new LinkedBlockingQueue<CallEventRecord>(newSize); 316 mCallEventRecordMap.clear(); 317 318 // Copy the existing queue into the new one. 319 for (CallEventRecord event : oldEventLog) { 320 addCallEventRecord(event); 321 } 322 323 mIsUserExtendedLoggingEnabled = isExtendedLoggingEnabled; 324 if (mIsUserExtendedLoggingEnabled) { 325 mUserExtendedLoggingStopTime = System.currentTimeMillis() 326 + EXTENDED_LOGGING_DURATION_MILLIS; 327 } else { 328 mUserExtendedLoggingStopTime = 0; 329 } 330 } 331 332 public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds 333 private static MessageDigest sMessageDigest; 334 335 public static void initMd5Sum() { 336 new AsyncTask<Void, Void, Void>() { 337 @Override 338 public Void doInBackground(Void... args) { 339 MessageDigest md; 340 try { 341 md = MessageDigest.getInstance("SHA-1"); 342 } catch (NoSuchAlgorithmException e) { 343 md = null; 344 } 345 sMessageDigest = md; 346 return null; 347 } 348 }.execute(); 349 } 350 351 @VisibleForTesting 352 public static void setTag(String tag) { 353 TAG = tag; 354 } 355 356 @VisibleForTesting 357 public static void setLoggingContainer(SystemLoggingContainer logger) { 358 systemLogger = logger; 359 } 360 361 // Overridden in LogTest to skip query to ContentProvider 362 public interface ISessionCleanupTimeoutMs { 363 long get(); 364 } 365 @VisibleForTesting 366 public static ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = 367 new ISessionCleanupTimeoutMs() { 368 @Override 369 public long get() { 370 // mContext will be null if Log is called from another process 371 // (UserCallActivity, for example). For these cases, use the default value. 372 if(mContext == null) { 373 return DEFAULT_SESSION_TIMEOUT_MS; 374 } 375 return Timeouts.getStaleSessionCleanupTimeoutMillis( 376 mContext.getContentResolver()); 377 } 378 }; 379 380 private static long getSessionCleanupTimeoutMs() { 381 return sSessionCleanupTimeoutMs.get(); 382 } 383 384 private static synchronized void resetStaleSessionTimer() { 385 sSessionCleanupHandler.removeCallbacksAndMessages(null); 386 // Will be null in Log Testing 387 if (sCleanStaleSessions != null) { 388 sSessionCleanupHandler.postDelayed(sCleanStaleSessions, getSessionCleanupTimeoutMs()); 389 } 390 } 391 392 /** 393 * Call at an entry point to the Telecom code to track the session. This code must be 394 * accompanied by a Log.endSession(). 395 */ 396 public static synchronized void startSession(String shortMethodName) { 397 startSession(shortMethodName, null); 398 } 399 public static synchronized void startSession(String shortMethodName, 400 String callerIdentification) { 401 resetStaleSessionTimer(); 402 int threadId = getCallingThreadId(); 403 Session activeSession = sSessionMapper.get(threadId); 404 // We have called startSession within an active session that has not ended... Register this 405 // session as a subsession. 406 if (activeSession != null) { 407 Session childSession = createSubsession(true); 408 continueSession(childSession, shortMethodName); 409 return; 410 } 411 Session newSession = new Session(getNextSessionID(), shortMethodName, 412 System.currentTimeMillis(), threadId, false, callerIdentification); 413 sSessionMapper.put(threadId, newSession); 414 415 Log.v(LOGGING_TAG, Session.START_SESSION); 416 } 417 418 419 /** 420 * Notifies the logging system that a subsession will be run at a later point and 421 * allocates the resources. Returns a session object that must be used in 422 * Log.continueSession(...) to start the subsession. 423 */ 424 public static Session createSubsession() { 425 return createSubsession(false); 426 } 427 428 private static synchronized Session createSubsession(boolean isStartedFromActiveSession) { 429 int threadId = getCallingThreadId(); 430 Session threadSession = sSessionMapper.get(threadId); 431 if (threadSession == null) { 432 Log.d(LOGGING_TAG, "Log.createSubsession was called with no session active."); 433 return null; 434 } 435 // Start execution time of the session will be overwritten in continueSession(...). 436 Session newSubsession = new Session(threadSession.getNextChildId(), 437 threadSession.getShortMethodName(), System.currentTimeMillis(), threadId, 438 isStartedFromActiveSession, null); 439 threadSession.addChild(newSubsession); 440 newSubsession.setParentSession(threadSession); 441 442 if(!isStartedFromActiveSession) { 443 Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " + newSubsession.toString()); 444 } else { 445 Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " (Invisible subsession)"); 446 } 447 return newSubsession; 448 } 449 450 /** 451 * Cancels a subsession that had Log.createSubsession() called on it, but will never have 452 * Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned 453 * gracefully instead of being removed by the sSessionCleanupHandler forcefully later. 454 */ 455 public static synchronized void cancelSubsession(Session subsession) { 456 if (subsession == null) { 457 return; 458 } 459 460 subsession.markSessionCompleted(0); 461 endParentSessions(subsession); 462 } 463 464 /** 465 * Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method 466 * must be called at the end of this method. The full session will complete when all 467 * subsessions are completed. 468 */ 469 public static synchronized void continueSession(Session subsession, String shortMethodName) { 470 if (subsession == null) { 471 return; 472 } 473 resetStaleSessionTimer(); 474 String callingMethodName = subsession.getShortMethodName(); 475 subsession.setShortMethodName(callingMethodName + "->" + shortMethodName); 476 subsession.setExecutionStartTimeMs(System.currentTimeMillis()); 477 Session parentSession = subsession.getParentSession(); 478 if (parentSession == null) { 479 Log.d(LOGGING_TAG, "Log.continueSession was called with no session active for " + 480 "method %s.", shortMethodName); 481 return; 482 } 483 484 sSessionMapper.put(getCallingThreadId(), subsession); 485 if(!subsession.isStartedFromActiveSession()) { 486 Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION); 487 } else { 488 Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION + " (Invisible Subsession) with " + 489 "Method " + shortMethodName); 490 } 491 } 492 493 public static void checkIsThreadLogged() { 494 int threadId = getCallingThreadId(); 495 Session threadSession = sSessionMapper.get(threadId); 496 if (threadSession == null) { 497 android.util.Log.e(LOGGING_TAG, "Logging Thread Check Failed!", new Exception()); 498 } 499 } 500 501 /** 502 * Ends the current session/subsession. Must be called after a Log.startSession(...) and 503 * Log.continueSession(...) call. 504 */ 505 public static synchronized void endSession() { 506 int threadId = getCallingThreadId(); 507 Session completedSession = sSessionMapper.get(threadId); 508 if (completedSession == null) { 509 Log.w(LOGGING_TAG, "Log.endSession was called with no session active."); 510 return; 511 } 512 513 completedSession.markSessionCompleted(System.currentTimeMillis()); 514 if(!completedSession.isStartedFromActiveSession()) { 515 Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " + 516 completedSession.getLocalExecutionTime() + " mS)"); 517 } else { 518 Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (Invisible Subsession) (dur: " + 519 completedSession.getLocalExecutionTime() + " mS)"); 520 } 521 // Remove after completed so that reference still exists for logging the end events 522 Session parentSession = completedSession.getParentSession(); 523 sSessionMapper.remove(threadId); 524 endParentSessions(completedSession); 525 // If this subsession was started from a parent session using Log.startSession, return the 526 // ThreadID back to the parent after completion. 527 if (parentSession != null && !parentSession.isSessionCompleted() && 528 completedSession.isStartedFromActiveSession()) { 529 sSessionMapper.put(threadId, parentSession); 530 } 531 } 532 533 // Recursively deletes all complete parent sessions of the current subsession if it is a leaf. 534 private static void endParentSessions(Session subsession) { 535 // Session is not completed or not currently a leaf, so we can not remove because a child is 536 // still running 537 if (!subsession.isSessionCompleted() || subsession.getChildSessions().size() != 0) { 538 return; 539 } 540 541 Session parentSession = subsession.getParentSession(); 542 if (parentSession != null) { 543 subsession.setParentSession(null); 544 parentSession.removeChild(subsession); 545 endParentSessions(parentSession); 546 } else { 547 // All of the subsessions have been completed and it is time to report on the full 548 // running time of the session. 549 long fullSessionTimeMs = 550 System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds(); 551 Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs + " ms): " + 552 subsession.toString()); 553 } 554 } 555 556 private synchronized static String getNextSessionID() { 557 Integer nextId = sCodeEntryCounter++; 558 if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) { 559 restartSessionCounter(); 560 nextId = sCodeEntryCounter++; 561 } 562 return getBase64Encoding(nextId); 563 } 564 565 @VisibleForTesting 566 public synchronized static void restartSessionCounter() { 567 sCodeEntryCounter = 0; 568 } 569 570 @VisibleForTesting 571 public static String getBase64Encoding(int number) { 572 byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array(); 573 idByteArray = Arrays.copyOfRange(idByteArray, 2, 4); 574 return Base64.encodeToString(idByteArray, Base64.NO_WRAP | Base64.NO_PADDING); 575 } 576 577 public static int getCallingThreadId() { 578 return android.os.Process.myTid(); 579 } 580 581 public static void event(Call call, String event) { 582 event(call, event, null); 583 } 584 585 public static void event(Call call, String event, Object data) { 586 Session currentSession = sSessionMapper.get(getCallingThreadId()); 587 String currentSessionID = currentSession != null ? currentSession.toString() : ""; 588 589 if (call == null) { 590 Log.i(TAG, "Non-call EVENT: %s, %s", event, data); 591 return; 592 } 593 synchronized (mCallEventRecords) { 594 if (!mCallEventRecordMap.containsKey(call)) { 595 CallEventRecord newRecord = new CallEventRecord(call); 596 addCallEventRecord(newRecord); 597 } 598 599 CallEventRecord record = mCallEventRecordMap.get(call); 600 record.addEvent(event, currentSessionID, data); 601 } 602 } 603 604 @VisibleForTesting 605 public static synchronized void cleanupStaleSessions(long timeoutMs) { 606 String logMessage = "Stale Sessions Cleaned:\n"; 607 boolean isSessionsStale = false; 608 long currentTimeMs = System.currentTimeMillis(); 609 // Remove references that are in the Session Mapper (causing GC to occur) on 610 // sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS. 611 // If this occurs, then there is most likely a Session active that never had 612 // Log.endSession called on it. 613 for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it = 614 sSessionMapper.entrySet().iterator(); it.hasNext(); ) { 615 ConcurrentHashMap.Entry<Integer, Session> entry = it.next(); 616 Session session = entry.getValue(); 617 if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) { 618 it.remove(); 619 logMessage += session.printFullSessionTree() + "\n"; 620 isSessionsStale = true; 621 } 622 } 623 if (isSessionsStale) { 624 Log.w(LOGGING_TAG, logMessage); 625 } else { 626 Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned..."); 627 } 628 } 629 630 private static void addCallEventRecord(CallEventRecord newRecord) { 631 Call call = newRecord.getCall(); 632 633 // First remove the oldest entry if no new ones exist. 634 if (mCallEventRecords.remainingCapacity() == 0) { 635 CallEventRecord record = mCallEventRecords.poll(); 636 if (record != null) { 637 mCallEventRecordMap.remove(record.getCall()); 638 } 639 } 640 641 // Now add a new entry 642 mCallEventRecords.add(newRecord); 643 mCallEventRecordMap.put(call, newRecord); 644 } 645 646 /** 647 * If user enabled extended logging is enabled and the time limit has passed, disables the 648 * extended logging. 649 */ 650 private static void maybeDisableLogging() { 651 if (!mIsUserExtendedLoggingEnabled) { 652 return; 653 } 654 655 if (mUserExtendedLoggingStopTime < System.currentTimeMillis()) { 656 mUserExtendedLoggingStopTime = 0; 657 mIsUserExtendedLoggingEnabled = false; 658 } 659 } 660 661 public static boolean isLoggable(int level) { 662 return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level); 663 } 664 665 public static void d(String prefix, String format, Object... args) { 666 if (mIsUserExtendedLoggingEnabled) { 667 maybeDisableLogging(); 668 systemLogger.i(TAG, buildMessage(prefix, format, args)); 669 } else if (DEBUG) { 670 systemLogger.d(TAG, buildMessage(prefix, format, args)); 671 } 672 } 673 674 public static void d(Object objectPrefix, String format, Object... args) { 675 if (mIsUserExtendedLoggingEnabled) { 676 maybeDisableLogging(); 677 systemLogger.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 678 } else if (DEBUG) { 679 systemLogger.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 680 } 681 } 682 683 public static void i(String prefix, String format, Object... args) { 684 if (INFO) { 685 systemLogger.i(TAG, buildMessage(prefix, format, args)); 686 } 687 } 688 689 public static void i(Object objectPrefix, String format, Object... args) { 690 if (INFO) { 691 systemLogger.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 692 } 693 } 694 695 public static void v(String prefix, String format, Object... args) { 696 if (mIsUserExtendedLoggingEnabled) { 697 maybeDisableLogging(); 698 systemLogger.i(TAG, buildMessage(prefix, format, args)); 699 } else if (VERBOSE) { 700 systemLogger.v(TAG, buildMessage(prefix, format, args)); 701 } 702 } 703 704 public static void v(Object objectPrefix, String format, Object... args) { 705 if (mIsUserExtendedLoggingEnabled) { 706 maybeDisableLogging(); 707 systemLogger.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 708 } else if (VERBOSE) { 709 systemLogger.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 710 } 711 } 712 713 public static void w(String prefix, String format, Object... args) { 714 if (WARN) { 715 systemLogger.w(TAG, buildMessage(prefix, format, args)); 716 } 717 } 718 719 public static void w(Object objectPrefix, String format, Object... args) { 720 if (WARN) { 721 systemLogger.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 722 } 723 } 724 725 public static void e(String prefix, Throwable tr, String format, Object... args) { 726 if (ERROR) { 727 systemLogger.e(TAG, buildMessage(prefix, format, args), tr); 728 } 729 } 730 731 public static void e(Object objectPrefix, Throwable tr, String format, Object... args) { 732 if (ERROR) { 733 systemLogger.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), 734 tr); 735 } 736 } 737 738 public static void wtf(String prefix, Throwable tr, String format, Object... args) { 739 systemLogger.wtf(TAG, buildMessage(prefix, format, args), tr); 740 } 741 742 public static void wtf(Object objectPrefix, Throwable tr, String format, Object... args) { 743 systemLogger.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), 744 tr); 745 } 746 747 public static void wtf(String prefix, String format, Object... args) { 748 String msg = buildMessage(prefix, format, args); 749 systemLogger.wtf(TAG, msg, new IllegalStateException(msg)); 750 } 751 752 public static void wtf(Object objectPrefix, String format, Object... args) { 753 String msg = buildMessage(getPrefixFromObject(objectPrefix), format, args); 754 systemLogger.wtf(TAG, msg, new IllegalStateException(msg)); 755 } 756 757 public static String piiHandle(Object pii) { 758 if (pii == null || VERBOSE) { 759 return String.valueOf(pii); 760 } 761 762 StringBuilder sb = new StringBuilder(); 763 if (pii instanceof Uri) { 764 Uri uri = (Uri) pii; 765 String scheme = uri.getScheme(); 766 767 if (!TextUtils.isEmpty(scheme)) { 768 sb.append(scheme).append(":"); 769 } 770 771 String textToObfuscate = uri.getSchemeSpecificPart(); 772 if (PhoneAccount.SCHEME_TEL.equals(scheme)) { 773 for (int i = 0; i < textToObfuscate.length(); i++) { 774 char c = textToObfuscate.charAt(i); 775 sb.append(PhoneNumberUtils.isDialable(c) ? "*" : c); 776 } 777 } else if (PhoneAccount.SCHEME_SIP.equals(scheme)) { 778 for (int i = 0; i < textToObfuscate.length(); i++) { 779 char c = textToObfuscate.charAt(i); 780 if (c != '@' && c != '.') { 781 c = '*'; 782 } 783 sb.append(c); 784 } 785 } else { 786 sb.append(pii(pii)); 787 } 788 } 789 790 return sb.toString(); 791 } 792 793 /** 794 * Redact personally identifiable information for production users. 795 * If we are running in verbose mode, return the original string, otherwise 796 * return a SHA-1 hash of the input string. 797 */ 798 public static String pii(Object pii) { 799 if (pii == null || VERBOSE) { 800 return String.valueOf(pii); 801 } 802 return "[" + secureHash(String.valueOf(pii).getBytes()) + "]"; 803 } 804 805 public static void dumpCallEvents(IndentingPrintWriter pw) { 806 pw.println("Historical Calls:"); 807 pw.increaseIndent(); 808 for (CallEventRecord callEventRecord : mCallEventRecords) { 809 callEventRecord.dump(pw); 810 } 811 pw.decreaseIndent(); 812 } 813 814 private static String secureHash(byte[] input) { 815 if (sMessageDigest != null) { 816 sMessageDigest.reset(); 817 sMessageDigest.update(input); 818 byte[] result = sMessageDigest.digest(); 819 return encodeHex(result); 820 } else { 821 return "Uninitialized SHA1"; 822 } 823 } 824 825 private static String encodeHex(byte[] bytes) { 826 StringBuffer hex = new StringBuffer(bytes.length * 2); 827 828 for (int i = 0; i < bytes.length; i++) { 829 int byteIntValue = bytes[i] & 0xff; 830 if (byteIntValue < 0x10) { 831 hex.append("0"); 832 } 833 hex.append(Integer.toString(byteIntValue, 16)); 834 } 835 836 return hex.toString(); 837 } 838 839 private static String getPrefixFromObject(Object obj) { 840 return obj == null ? "<null>" : obj.getClass().getSimpleName(); 841 } 842 843 private static String buildMessage(String prefix, String format, Object... args) { 844 if (LOG_DBG) { 845 checkIsThreadLogged(); 846 } 847 // Incorporate thread ID and calling method into prefix 848 String sessionPostfix = ""; 849 Session currentSession = sSessionMapper.get(getCallingThreadId()); 850 if (currentSession != null) { 851 sessionPostfix = ": " + currentSession.toString(); 852 } 853 854 String msg; 855 try { 856 msg = (args == null || args.length == 0) ? format 857 : String.format(Locale.US, format, args); 858 } catch (IllegalFormatException ife) { 859 e("Log", ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, 860 args.length); 861 msg = format + " (An error occurred while formatting the message.)"; 862 } 863 return String.format(Locale.US, "%s: %s%s", prefix, msg, sessionPostfix); 864 } 865 } 866
