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