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
17package com.android.server.telecom;
18
19import android.net.Uri;
20import android.telecom.PhoneAccount;
21import android.telephony.PhoneNumberUtils;
22import android.text.TextUtils;
23
24import com.android.internal.annotations.VisibleForTesting;
25import com.android.internal.util.IndentingPrintWriter;
26
27import java.security.MessageDigest;
28import java.security.NoSuchAlgorithmException;
29import java.text.DateFormat;
30import java.text.SimpleDateFormat;
31import java.util.Date;
32import java.util.HashMap;
33import java.util.IllegalFormatException;
34import java.util.LinkedList;
35import java.util.List;
36import java.util.Locale;
37import java.util.Map;
38import java.util.concurrent.LinkedBlockingQueue;
39
40/**
41 * Manages logging for the entire module.
42 */
43@VisibleForTesting
44public 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
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
123        public CallEventRecord(Call call) {
124            mCall = call;
125            mId = ++sNextId;
126        }
127
128        public Call getCall() {
129            return mCall;
130        }
131
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
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
219    private Log() {}
220
221    @VisibleForTesting
222    public static void setTag(String tag) {
223        TAG = tag;
224    }
225
226    public static void event(Call call, String event) {
227        event(call, event, null);
228    }
229
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
256    public static boolean isLoggable(int level) {
257        return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level);
258    }
259
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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     */
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
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
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
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
423    private static String getPrefixFromObject(Object obj) {
424        return obj == null ? "<null>" : obj.getClass().getSimpleName();
425    }
426
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