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.net.Uri; 20 import android.telecom.PhoneAccount; 21 import android.telephony.PhoneNumberUtils; 22 import android.text.TextUtils; 23 24 import com.android.internal.annotations.VisibleForTesting; 25 import com.android.internal.util.IndentingPrintWriter; 26 27 import java.security.MessageDigest; 28 import java.security.NoSuchAlgorithmException; 29 import java.text.DateFormat; 30 import java.text.SimpleDateFormat; 31 import java.util.Date; 32 import java.util.HashMap; 33 import java.util.IllegalFormatException; 34 import java.util.LinkedList; 35 import java.util.List; 36 import java.util.Locale; 37 import java.util.Map; 38 import java.util.concurrent.LinkedBlockingQueue; 39 40 /** 41 * Manages logging for the entire module. 42 */ 43 @VisibleForTesting 44 public class Log { 45 46 /** 47 * Stores the various events associated with {@link Call}s. Also stores all request-response 48 * pairs amongst the events. 49 */ 50 public final static class Events { 51 public static final String CREATED = "CREATED"; 52 public static final String DESTROYED = "DESTROYED"; 53 public static final String SET_NEW = "SET_NEW"; 54 public static final String SET_CONNECTING = "SET_CONNECTING"; 55 public static final String SET_DIALING = "SET_DIALING"; 56 public static final String SET_ACTIVE = "SET_ACTIVE"; 57 public static final String SET_HOLD = "SET_HOLD"; 58 public static final String SET_RINGING = "SET_RINGING"; 59 public static final String SET_DISCONNECTED = "SET_DISCONNECTED"; 60 public static final String SET_DISCONNECTING = "SET_DISCONNECTING"; 61 public static final String SET_SELECT_PHONE_ACCOUNT = "SET_SELECT_PHONE_ACCOUNT"; 62 public static final String REQUEST_HOLD = "REQUEST_HOLD"; 63 public static final String REQUEST_UNHOLD = "REQUEST_UNHOLD"; 64 public static final String REQUEST_DISCONNECT = "REQUEST_DISCONNECT"; 65 public static final String REQUEST_ACCEPT = "REQUEST_ACCEPT"; 66 public static final String REQUEST_REJECT = "REQUEST_REJECT"; 67 public static final String START_DTMF = "START_DTMF"; 68 public static final String STOP_DTMF = "STOP_DTMF"; 69 public static final String START_RINGER = "START_RINGER"; 70 public static final String STOP_RINGER = "STOP_RINGER"; 71 public static final String START_CALL_WAITING_TONE = "START_CALL_WAITING_TONE"; 72 public static final String STOP_CALL_WAITING_TONE = "STOP_CALL_WAITING_TONE"; 73 public static final String START_CONNECTION = "START_CONNECTION"; 74 public static final String BIND_CS = "BIND_CS"; 75 public static final String CS_BOUND = "CS_BOUND"; 76 public static final String CONFERENCE_WITH = "CONF_WITH"; 77 public static final String SPLIT_CONFERENCE = "CONF_SPLIT"; 78 public static final String SWAP = "SWAP"; 79 public static final String ADD_CHILD = "ADD_CHILD"; 80 public static final String REMOVE_CHILD = "REMOVE_CHILD"; 81 public static final String SET_PARENT = "SET_PARENT"; 82 public static final String MUTE = "MUTE"; 83 public static final String AUDIO_ROUTE = "AUDIO_ROUTE"; 84 public static final String ERROR_LOG = "ERROR"; 85 86 /** 87 * Maps from a request to a response. The same event could be listed as the 88 * response for multiple requests (e.g. REQUEST_ACCEPT and REQUEST_UNHOLD both map to the 89 * SET_ACTIVE response). This map is used to print out the amount of time it takes between 90 * a request and a response. 91 */ 92 public static final Map<String, String> requestResponsePairs = 93 new HashMap<String, String>() {{ 94 put(REQUEST_ACCEPT, SET_ACTIVE); 95 put(REQUEST_REJECT, SET_DISCONNECTED); 96 put(REQUEST_DISCONNECT, SET_DISCONNECTED); 97 put(REQUEST_HOLD, SET_HOLD); 98 put(REQUEST_UNHOLD, SET_ACTIVE); 99 put(START_CONNECTION, SET_DIALING); 100 put(BIND_CS, CS_BOUND); 101 }}; 102 } 103 104 public static class CallEvent { 105 public String eventId; 106 public long time; 107 public Object data; 108 CallEvent(String eventId, long time, Object data)109 public CallEvent(String eventId, long time, Object data) { 110 this.eventId = eventId; 111 this.time = time; 112 this.data = data; 113 } 114 } 115 116 public static class CallEventRecord { 117 private static final DateFormat sDateFormat = new SimpleDateFormat("HH:mm:ss.SSS"); 118 private static int sNextId = 1; 119 private final List<CallEvent> mEvents = new LinkedList<>(); 120 private final Call mCall; 121 private final int mId; 122 CallEventRecord(Call call)123 public CallEventRecord(Call call) { 124 mCall = call; 125 mId = ++sNextId; 126 } 127 getCall()128 public Call getCall() { 129 return mCall; 130 } 131 addEvent(String event, Object data)132 public void addEvent(String event, Object data) { 133 mEvents.add(new CallEvent(event, System.currentTimeMillis(), data)); 134 Log.i("Event", "Call %d: %s, %s", mId, event, data); 135 } 136 dump(IndentingPrintWriter pw)137 public void dump(IndentingPrintWriter pw) { 138 Map<String, CallEvent> pendingResponses = new HashMap<>(); 139 140 pw.print("Call "); 141 pw.print(mId); 142 pw.print(" ["); 143 pw.print(sDateFormat.format(new Date(mCall.getCreationTimeMillis()))); 144 pw.print("]"); 145 pw.println(mCall.isIncoming() ? "(MT - incoming)" : "(MO - outgoing)"); 146 147 pw.increaseIndent(); 148 pw.println("To address: " + piiHandle(mCall.getHandle())); 149 150 for (CallEvent event : mEvents) { 151 152 // We print out events in chronological order. During that process we look at each 153 // event and see if it maps to a request on the Request-Response pairs map. If it 154 // does, then we effectively start 'listening' for the response. We do that by 155 // storing the response event ID in {@code pendingResponses}. When we find the 156 // response in a later iteration of the loop, we grab the original request and 157 // calculate the time it took to get a response. 158 if (Events.requestResponsePairs.containsKey(event.eventId)) { 159 // This event expects a response, so add that response to the maps 160 // of pending events. 161 String pendingResponse = Events.requestResponsePairs.get(event.eventId); 162 pendingResponses.put(pendingResponse, event); 163 } 164 165 pw.print(sDateFormat.format(new Date(event.time))); 166 pw.print(" - "); 167 pw.print(event.eventId); 168 if (event.data != null) { 169 pw.print(" ("); 170 Object data = event.data; 171 172 if (data instanceof Call) { 173 // If the data is another call, then change the data to the call's CallEvent 174 // ID instead. 175 CallEventRecord record = mCallEventRecordMap.get(data); 176 if (record != null) { 177 data = "Call " + record.mId; 178 } 179 } 180 181 pw.print(data); 182 pw.print(")"); 183 } 184 185 // If this event is a response event that we've been waiting for, calculate the time 186 // it took for the response to complete and print that out as well. 187 CallEvent requestEvent = pendingResponses.remove(event.eventId); 188 if (requestEvent != null) { 189 pw.print(", time since "); 190 pw.print(requestEvent.eventId); 191 pw.print(": "); 192 pw.print(event.time - requestEvent.time); 193 pw.print(" ms"); 194 } 195 pw.println(); 196 } 197 pw.decreaseIndent(); 198 } 199 } 200 201 public static final int MAX_CALLS_TO_CACHE = 5; // Arbitrarily chosen. 202 203 // Generic tag for all In Call logging 204 @VisibleForTesting 205 public static String TAG = "Telecom"; 206 207 public static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */ 208 public static final boolean SYSTRACE_DEBUG = false; /* STOP SHIP if true */ 209 public static final boolean DEBUG = isLoggable(android.util.Log.DEBUG); 210 public static final boolean INFO = isLoggable(android.util.Log.INFO); 211 public static final boolean VERBOSE = isLoggable(android.util.Log.VERBOSE); 212 public static final boolean WARN = isLoggable(android.util.Log.WARN); 213 public static final boolean ERROR = isLoggable(android.util.Log.ERROR); 214 215 private static final Map<Call, CallEventRecord> mCallEventRecordMap = new HashMap<>(); 216 private static final LinkedBlockingQueue<CallEventRecord> mCallEventRecords = 217 new LinkedBlockingQueue<CallEventRecord>(MAX_CALLS_TO_CACHE); 218 Log()219 private Log() {} 220 221 @VisibleForTesting setTag(String tag)222 public static void setTag(String tag) { 223 TAG = tag; 224 } 225 event(Call call, String event)226 public static void event(Call call, String event) { 227 event(call, event, null); 228 } 229 event(Call call, String event, Object data)230 public static void event(Call call, String event, Object data) { 231 if (call == null) { 232 Log.i(TAG, "Non-call EVENT: %s, %s", event, data); 233 return; 234 } 235 synchronized (mCallEventRecords) { 236 if (!mCallEventRecordMap.containsKey(call)) { 237 // First remove the oldest entry if no new ones exist. 238 if (mCallEventRecords.remainingCapacity() == 0) { 239 CallEventRecord record = mCallEventRecords.poll(); 240 if (record != null) { 241 mCallEventRecordMap.remove(record.getCall()); 242 } 243 } 244 245 // Now add a new entry 246 CallEventRecord newRecord = new CallEventRecord(call); 247 mCallEventRecords.add(newRecord); 248 mCallEventRecordMap.put(call, newRecord); 249 } 250 251 CallEventRecord record = mCallEventRecordMap.get(call); 252 record.addEvent(event, data); 253 } 254 } 255 isLoggable(int level)256 public static boolean isLoggable(int level) { 257 return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level); 258 } 259 d(String prefix, String format, Object... args)260 public static void d(String prefix, String format, Object... args) { 261 if (DEBUG) { 262 android.util.Slog.d(TAG, buildMessage(prefix, format, args)); 263 } 264 } 265 d(Object objectPrefix, String format, Object... args)266 public static void d(Object objectPrefix, String format, Object... args) { 267 if (DEBUG) { 268 android.util.Slog.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 269 } 270 } 271 i(String prefix, String format, Object... args)272 public static void i(String prefix, String format, Object... args) { 273 if (INFO) { 274 android.util.Slog.i(TAG, buildMessage(prefix, format, args)); 275 } 276 } 277 i(Object objectPrefix, String format, Object... args)278 public static void i(Object objectPrefix, String format, Object... args) { 279 if (INFO) { 280 android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 281 } 282 } 283 v(String prefix, String format, Object... args)284 public static void v(String prefix, String format, Object... args) { 285 if (VERBOSE) { 286 android.util.Slog.v(TAG, buildMessage(prefix, format, args)); 287 } 288 } 289 v(Object objectPrefix, String format, Object... args)290 public static void v(Object objectPrefix, String format, Object... args) { 291 if (VERBOSE) { 292 android.util.Slog.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 293 } 294 } 295 w(String prefix, String format, Object... args)296 public static void w(String prefix, String format, Object... args) { 297 if (WARN) { 298 android.util.Slog.w(TAG, buildMessage(prefix, format, args)); 299 } 300 } 301 w(Object objectPrefix, String format, Object... args)302 public static void w(Object objectPrefix, String format, Object... args) { 303 if (WARN) { 304 android.util.Slog.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); 305 } 306 } 307 e(String prefix, Throwable tr, String format, Object... args)308 public static void e(String prefix, Throwable tr, String format, Object... args) { 309 if (ERROR) { 310 android.util.Slog.e(TAG, buildMessage(prefix, format, args), tr); 311 } 312 } 313 e(Object objectPrefix, Throwable tr, String format, Object... args)314 public static void e(Object objectPrefix, Throwable tr, String format, Object... args) { 315 if (ERROR) { 316 android.util.Slog.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), 317 tr); 318 } 319 } 320 wtf(String prefix, Throwable tr, String format, Object... args)321 public static void wtf(String prefix, Throwable tr, String format, Object... args) { 322 android.util.Slog.wtf(TAG, buildMessage(prefix, format, args), tr); 323 } 324 wtf(Object objectPrefix, Throwable tr, String format, Object... args)325 public static void wtf(Object objectPrefix, Throwable tr, String format, Object... args) { 326 android.util.Slog.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), 327 tr); 328 } 329 wtf(String prefix, String format, Object... args)330 public static void wtf(String prefix, String format, Object... args) { 331 String msg = buildMessage(prefix, format, args); 332 android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg)); 333 } 334 wtf(Object objectPrefix, String format, Object... args)335 public static void wtf(Object objectPrefix, String format, Object... args) { 336 String msg = buildMessage(getPrefixFromObject(objectPrefix), format, args); 337 android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg)); 338 } 339 piiHandle(Object pii)340 public static String piiHandle(Object pii) { 341 if (pii == null || VERBOSE) { 342 return String.valueOf(pii); 343 } 344 345 StringBuilder sb = new StringBuilder(); 346 if (pii instanceof Uri) { 347 Uri uri = (Uri) pii; 348 String scheme = uri.getScheme(); 349 350 if (!TextUtils.isEmpty(scheme)) { 351 sb.append(scheme).append(":"); 352 } 353 354 String textToObfuscate = uri.getSchemeSpecificPart(); 355 if (PhoneAccount.SCHEME_TEL.equals(scheme)) { 356 for (int i = 0; i < textToObfuscate.length(); i++) { 357 char c = textToObfuscate.charAt(i); 358 sb.append(PhoneNumberUtils.isDialable(c) ? "*" : c); 359 } 360 } else if (PhoneAccount.SCHEME_SIP.equals(scheme)) { 361 for (int i = 0; i < textToObfuscate.length(); i++) { 362 char c = textToObfuscate.charAt(i); 363 if (c != '@' && c != '.') { 364 c = '*'; 365 } 366 sb.append(c); 367 } 368 } else { 369 sb.append(pii(pii)); 370 } 371 } 372 373 return sb.toString(); 374 } 375 376 /** 377 * Redact personally identifiable information for production users. 378 * If we are running in verbose mode, return the original string, otherwise 379 * return a SHA-1 hash of the input string. 380 */ pii(Object pii)381 public static String pii(Object pii) { 382 if (pii == null || VERBOSE) { 383 return String.valueOf(pii); 384 } 385 return "[" + secureHash(String.valueOf(pii).getBytes()) + "]"; 386 } 387 dumpCallEvents(IndentingPrintWriter pw)388 public static void dumpCallEvents(IndentingPrintWriter pw) { 389 pw.println("Historical Calls:"); 390 pw.increaseIndent(); 391 for (CallEventRecord callEventRecord : mCallEventRecords) { 392 callEventRecord.dump(pw); 393 } 394 pw.decreaseIndent(); 395 } 396 secureHash(byte[] input)397 private static String secureHash(byte[] input) { 398 MessageDigest messageDigest; 399 try { 400 messageDigest = MessageDigest.getInstance("SHA-1"); 401 } catch (NoSuchAlgorithmException e) { 402 return null; 403 } 404 messageDigest.update(input); 405 byte[] result = messageDigest.digest(); 406 return encodeHex(result); 407 } 408 encodeHex(byte[] bytes)409 private static String encodeHex(byte[] bytes) { 410 StringBuffer hex = new StringBuffer(bytes.length * 2); 411 412 for (int i = 0; i < bytes.length; i++) { 413 int byteIntValue = bytes[i] & 0xff; 414 if (byteIntValue < 0x10) { 415 hex.append("0"); 416 } 417 hex.append(Integer.toString(byteIntValue, 16)); 418 } 419 420 return hex.toString(); 421 } 422 getPrefixFromObject(Object obj)423 private static String getPrefixFromObject(Object obj) { 424 return obj == null ? "<null>" : obj.getClass().getSimpleName(); 425 } 426 buildMessage(String prefix, String format, Object... args)427 private static String buildMessage(String prefix, String format, Object... args) { 428 String msg; 429 try { 430 msg = (args == null || args.length == 0) ? format 431 : String.format(Locale.US, format, args); 432 } catch (IllegalFormatException ife) { 433 e("Log", ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, 434 args.length); 435 msg = format + " (An error occurred while formatting the message.)"; 436 } 437 return String.format(Locale.US, "%s: %s", prefix, msg); 438 } 439 } 440