/* * Copyright 2014, The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package com.android.server.telecom; import android.net.Uri; import android.telecom.PhoneAccount; import android.telephony.PhoneNumberUtils; import android.text.TextUtils; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.util.IndentingPrintWriter; import java.security.MessageDigest; import java.security.NoSuchAlgorithmException; import java.text.DateFormat; import java.text.SimpleDateFormat; import java.util.Date; import java.util.HashMap; import java.util.IllegalFormatException; import java.util.LinkedList; import java.util.List; import java.util.Locale; import java.util.Map; import java.util.concurrent.LinkedBlockingQueue; /** * Manages logging for the entire module. */ @VisibleForTesting public class Log { /** * Stores the various events associated with {@link Call}s. Also stores all request-response * pairs amongst the events. */ public final static class Events { public static final String CREATED = "CREATED"; public static final String DESTROYED = "DESTROYED"; public static final String SET_NEW = "SET_NEW"; public static final String SET_CONNECTING = "SET_CONNECTING"; public static final String SET_DIALING = "SET_DIALING"; public static final String SET_ACTIVE = "SET_ACTIVE"; public static final String SET_HOLD = "SET_HOLD"; public static final String SET_RINGING = "SET_RINGING"; public static final String SET_DISCONNECTED = "SET_DISCONNECTED"; public static final String SET_DISCONNECTING = "SET_DISCONNECTING"; public static final String SET_SELECT_PHONE_ACCOUNT = "SET_SELECT_PHONE_ACCOUNT"; public static final String REQUEST_HOLD = "REQUEST_HOLD"; public static final String REQUEST_UNHOLD = "REQUEST_UNHOLD"; public static final String REQUEST_DISCONNECT = "REQUEST_DISCONNECT"; public static final String REQUEST_ACCEPT = "REQUEST_ACCEPT"; public static final String REQUEST_REJECT = "REQUEST_REJECT"; public static final String REQUEST_TRANSFER = "REQUEST_TRANSFER"; public static final String START_DTMF = "START_DTMF"; public static final String STOP_DTMF = "STOP_DTMF"; public static final String START_RINGER = "START_RINGER"; public static final String STOP_RINGER = "STOP_RINGER"; public static final String START_CALL_WAITING_TONE = "START_CALL_WAITING_TONE"; public static final String STOP_CALL_WAITING_TONE = "STOP_CALL_WAITING_TONE"; public static final String START_CONNECTION = "START_CONNECTION"; public static final String BIND_CS = "BIND_CS"; public static final String CS_BOUND = "CS_BOUND"; public static final String CONFERENCE_WITH = "CONF_WITH"; public static final String SPLIT_CONFERENCE = "CONF_SPLIT"; public static final String SWAP = "SWAP"; public static final String ADD_CHILD = "ADD_CHILD"; public static final String REMOVE_CHILD = "REMOVE_CHILD"; public static final String SET_PARENT = "SET_PARENT"; public static final String MUTE = "MUTE"; public static final String AUDIO_ROUTE = "AUDIO_ROUTE"; public static final String ERROR_LOG = "ERROR"; public static final String SILENCE = "SILENCE"; /** * Maps from a request to a response. The same event could be listed as the * response for multiple requests (e.g. REQUEST_ACCEPT and REQUEST_UNHOLD both map to the * SET_ACTIVE response). This map is used to print out the amount of time it takes between * a request and a response. */ public static final Map requestResponsePairs = new HashMap() {{ put(REQUEST_ACCEPT, SET_ACTIVE); put(REQUEST_REJECT, SET_DISCONNECTED); put(REQUEST_DISCONNECT, SET_DISCONNECTED); put(REQUEST_HOLD, SET_HOLD); put(REQUEST_UNHOLD, SET_ACTIVE); put(START_CONNECTION, SET_DIALING); put(BIND_CS, CS_BOUND); }}; } public static class CallEvent { public String eventId; public long time; public Object data; public CallEvent(String eventId, long time, Object data) { this.eventId = eventId; this.time = time; this.data = data; } } public static class CallEventRecord { private static final DateFormat sDateFormat = new SimpleDateFormat("HH:mm:ss.SSS"); private static int sNextId = 1; private final List mEvents = new LinkedList<>(); private final Call mCall; private final int mId; public CallEventRecord(Call call) { mCall = call; mId = ++sNextId; } public Call getCall() { return mCall; } public void addEvent(String event, Object data) { mEvents.add(new CallEvent(event, System.currentTimeMillis(), data)); Log.i("Event", "Call %d: %s, %s", mId, event, data); } public void dump(IndentingPrintWriter pw) { Map pendingResponses = new HashMap<>(); pw.print("Call "); pw.print(mId); pw.print(" ["); pw.print(sDateFormat.format(new Date(mCall.getCreationTimeMillis()))); pw.print("]"); pw.println(mCall.isIncoming() ? "(MT - incoming)" : "(MO - outgoing)"); pw.increaseIndent(); pw.println("To address: " + piiHandle(mCall.getHandle())); for (CallEvent event : mEvents) { // We print out events in chronological order. During that process we look at each // event and see if it maps to a request on the Request-Response pairs map. If it // does, then we effectively start 'listening' for the response. We do that by // storing the response event ID in {@code pendingResponses}. When we find the // response in a later iteration of the loop, we grab the original request and // calculate the time it took to get a response. if (Events.requestResponsePairs.containsKey(event.eventId)) { // This event expects a response, so add that response to the maps // of pending events. String pendingResponse = Events.requestResponsePairs.get(event.eventId); pendingResponses.put(pendingResponse, event); } pw.print(sDateFormat.format(new Date(event.time))); pw.print(" - "); pw.print(event.eventId); if (event.data != null) { pw.print(" ("); Object data = event.data; if (data instanceof Call) { // If the data is another call, then change the data to the call's CallEvent // ID instead. CallEventRecord record = mCallEventRecordMap.get(data); if (record != null) { data = "Call " + record.mId; } } pw.print(data); pw.print(")"); } // If this event is a response event that we've been waiting for, calculate the time // it took for the response to complete and print that out as well. CallEvent requestEvent = pendingResponses.remove(event.eventId); if (requestEvent != null) { pw.print(", time since "); pw.print(requestEvent.eventId); pw.print(": "); pw.print(event.time - requestEvent.time); pw.print(" ms"); } pw.println(); } pw.decreaseIndent(); } } public static final int MAX_CALLS_TO_CACHE = 5; // Arbitrarily chosen. // Generic tag for all In Call logging @VisibleForTesting public static String TAG = "Telecom"; public static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */ public static final boolean SYSTRACE_DEBUG = false; /* STOP SHIP if true */ public static final boolean DEBUG = isLoggable(android.util.Log.DEBUG); public static final boolean INFO = isLoggable(android.util.Log.INFO); public static final boolean VERBOSE = isLoggable(android.util.Log.VERBOSE); public static final boolean WARN = isLoggable(android.util.Log.WARN); public static final boolean ERROR = isLoggable(android.util.Log.ERROR); private static final Map mCallEventRecordMap = new HashMap<>(); private static final LinkedBlockingQueue mCallEventRecords = new LinkedBlockingQueue(MAX_CALLS_TO_CACHE); private Log() {} @VisibleForTesting public static void setTag(String tag) { TAG = tag; } public static void event(Call call, String event) { event(call, event, null); } public static void event(Call call, String event, Object data) { if (call == null) { Log.i(TAG, "Non-call EVENT: %s, %s", event, data); return; } synchronized (mCallEventRecords) { if (!mCallEventRecordMap.containsKey(call)) { // First remove the oldest entry if no new ones exist. if (mCallEventRecords.remainingCapacity() == 0) { CallEventRecord record = mCallEventRecords.poll(); if (record != null) { mCallEventRecordMap.remove(record.getCall()); } } // Now add a new entry CallEventRecord newRecord = new CallEventRecord(call); mCallEventRecords.add(newRecord); mCallEventRecordMap.put(call, newRecord); } CallEventRecord record = mCallEventRecordMap.get(call); record.addEvent(event, data); } } public static boolean isLoggable(int level) { return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level); } public static void d(String prefix, String format, Object... args) { if (DEBUG) { android.util.Slog.d(TAG, buildMessage(prefix, format, args)); } } public static void d(Object objectPrefix, String format, Object... args) { if (DEBUG) { android.util.Slog.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void i(String prefix, String format, Object... args) { if (INFO) { android.util.Slog.i(TAG, buildMessage(prefix, format, args)); } } public static void i(Object objectPrefix, String format, Object... args) { if (INFO) { android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void v(String prefix, String format, Object... args) { if (VERBOSE) { android.util.Slog.v(TAG, buildMessage(prefix, format, args)); } } public static void v(Object objectPrefix, String format, Object... args) { if (VERBOSE) { android.util.Slog.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void w(String prefix, String format, Object... args) { if (WARN) { android.util.Slog.w(TAG, buildMessage(prefix, format, args)); } } public static void w(Object objectPrefix, String format, Object... args) { if (WARN) { android.util.Slog.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void e(String prefix, Throwable tr, String format, Object... args) { if (ERROR) { android.util.Slog.e(TAG, buildMessage(prefix, format, args), tr); } } public static void e(Object objectPrefix, Throwable tr, String format, Object... args) { if (ERROR) { android.util.Slog.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), tr); } } public static void wtf(String prefix, Throwable tr, String format, Object... args) { android.util.Slog.wtf(TAG, buildMessage(prefix, format, args), tr); } public static void wtf(Object objectPrefix, Throwable tr, String format, Object... args) { android.util.Slog.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), tr); } public static void wtf(String prefix, String format, Object... args) { String msg = buildMessage(prefix, format, args); android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg)); } public static void wtf(Object objectPrefix, String format, Object... args) { String msg = buildMessage(getPrefixFromObject(objectPrefix), format, args); android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg)); } public static String piiHandle(Object pii) { if (pii == null || VERBOSE) { return String.valueOf(pii); } StringBuilder sb = new StringBuilder(); if (pii instanceof Uri) { Uri uri = (Uri) pii; String scheme = uri.getScheme(); if (!TextUtils.isEmpty(scheme)) { sb.append(scheme).append(":"); } String textToObfuscate = uri.getSchemeSpecificPart(); if (PhoneAccount.SCHEME_TEL.equals(scheme)) { for (int i = 0; i < textToObfuscate.length(); i++) { char c = textToObfuscate.charAt(i); sb.append(PhoneNumberUtils.isDialable(c) ? "*" : c); } } else if (PhoneAccount.SCHEME_SIP.equals(scheme)) { for (int i = 0; i < textToObfuscate.length(); i++) { char c = textToObfuscate.charAt(i); if (c != '@' && c != '.') { c = '*'; } sb.append(c); } } else { sb.append(pii(pii)); } } return sb.toString(); } /** * Redact personally identifiable information for production users. * If we are running in verbose mode, return the original string, otherwise * return a SHA-1 hash of the input string. */ public static String pii(Object pii) { if (pii == null || VERBOSE) { return String.valueOf(pii); } return "[" + secureHash(String.valueOf(pii).getBytes()) + "]"; } public static void dumpCallEvents(IndentingPrintWriter pw) { pw.println("Historical Calls:"); pw.increaseIndent(); for (CallEventRecord callEventRecord : mCallEventRecords) { callEventRecord.dump(pw); } pw.decreaseIndent(); } private static String secureHash(byte[] input) { MessageDigest messageDigest; try { messageDigest = MessageDigest.getInstance("SHA-1"); } catch (NoSuchAlgorithmException e) { return null; } messageDigest.update(input); byte[] result = messageDigest.digest(); return encodeHex(result); } private static String encodeHex(byte[] bytes) { StringBuffer hex = new StringBuffer(bytes.length * 2); for (int i = 0; i < bytes.length; i++) { int byteIntValue = bytes[i] & 0xff; if (byteIntValue < 0x10) { hex.append("0"); } hex.append(Integer.toString(byteIntValue, 16)); } return hex.toString(); } private static String getPrefixFromObject(Object obj) { return obj == null ? "" : obj.getClass().getSimpleName(); } private static String buildMessage(String prefix, String format, Object... args) { String msg; try { msg = (args == null || args.length == 0) ? format : String.format(Locale.US, format, args); } catch (IllegalFormatException ife) { e("Log", ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, args.length); msg = format + " (An error occurred while formatting the message.)"; } return String.format(Locale.US, "%s: %s", prefix, msg); } }