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