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