1/*
2 * Copyright (C) 2016 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 android.telecom.Logging;
18
19import android.content.Context;
20import android.os.Handler;
21import android.os.Looper;
22import android.os.Process;
23import android.provider.Settings;
24import android.telecom.Log;
25import android.util.Base64;
26
27import com.android.internal.annotations.VisibleForTesting;
28
29import java.nio.ByteBuffer;
30import java.util.ArrayList;
31import java.util.Arrays;
32import java.util.Iterator;
33import java.util.List;
34import java.util.concurrent.ConcurrentHashMap;
35
36/**
37 * TODO: Create better Sessions Documentation
38 * @hide
39 */
40
41public class SessionManager {
42
43    // Currently using 3 letters, So don't exceed 64^3
44    private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144;
45    // This parameter can be overridden in Telecom's Timeouts class.
46    private static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds
47    private static final String LOGGING_TAG = "Logging";
48    private static final String TIMEOUTS_PREFIX = "telecom.";
49
50    // Synchronized in all method calls
51    private int sCodeEntryCounter = 0;
52    private Context mContext;
53
54    @VisibleForTesting
55    public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100);
56    @VisibleForTesting
57    public java.lang.Runnable mCleanStaleSessions = () ->
58            cleanupStaleSessions(getSessionCleanupTimeoutMs());
59    private Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());
60
61    // Overridden in LogTest to skip query to ContentProvider
62    private interface ISessionCleanupTimeoutMs {
63        long get();
64    }
65
66    // Overridden in tests to provide test Thread IDs
67    public interface ICurrentThreadId {
68        int get();
69    }
70
71    @VisibleForTesting
72    public ICurrentThreadId mCurrentThreadId = Process::myTid;
73
74    private ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
75        // mContext may be null in some cases, such as testing. For these cases, use the
76        // default value.
77        if (mContext == null) {
78            return DEFAULT_SESSION_TIMEOUT_MS;
79        }
80        return getCleanupTimeout(mContext);
81    };
82
83    // Usage is synchronized on this class.
84    private List<ISessionListener> mSessionListeners = new ArrayList<>();
85
86    public interface ISessionListener {
87        /**
88         * This method is run when a full Session has completed.
89         * @param sessionName The name of the Session that has completed.
90         * @param timeMs The time it took to complete in ms.
91         */
92        void sessionComplete(String sessionName, long timeMs);
93    }
94
95    public interface ISessionIdQueryHandler {
96        String getSessionId();
97    }
98
99    public void setContext(Context context) {
100        mContext = context;
101    }
102
103    public SessionManager() {
104    }
105
106    private long getSessionCleanupTimeoutMs() {
107        return mSessionCleanupTimeoutMs.get();
108    }
109
110    private synchronized void resetStaleSessionTimer() {
111        mSessionCleanupHandler.removeCallbacksAndMessages(null);
112        // Will be null in Log Testing
113        if (mCleanStaleSessions != null) {
114            mSessionCleanupHandler.postDelayed(mCleanStaleSessions, getSessionCleanupTimeoutMs());
115        }
116    }
117
118    /**
119     * Determines whether or not to start a new session or continue an existing session based on
120     * the {@link Session.Info} info passed into startSession. If info is null, a new Session is
121     * created. This code must be accompanied by endSession() at the end of the Session.
122     */
123    public synchronized void startSession(Session.Info info, String shortMethodName,
124            String callerIdentification) {
125        // Start a new session normally if the
126        if(info == null) {
127            startSession(shortMethodName, callerIdentification);
128        } else {
129            startExternalSession(info, shortMethodName);
130        }
131    }
132
133    /**
134     * Call at an entry point to the Telecom code to track the session. This code must be
135     * accompanied by a Log.endSession().
136     */
137    public synchronized void startSession(String shortMethodName,
138            String callerIdentification) {
139        resetStaleSessionTimer();
140        int threadId = getCallingThreadId();
141        Session activeSession = mSessionMapper.get(threadId);
142        // We have called startSession within an active session that has not ended... Register this
143        // session as a subsession.
144        if (activeSession != null) {
145            Session childSession = createSubsession(true);
146            continueSession(childSession, shortMethodName);
147            return;
148        } else {
149            // Only Log that we are starting the parent session.
150            Log.d(LOGGING_TAG, Session.START_SESSION);
151        }
152        Session newSession = new Session(getNextSessionID(), shortMethodName,
153                System.currentTimeMillis(), false, callerIdentification);
154        mSessionMapper.put(threadId, newSession);
155    }
156
157    /**
158     * Registers an external Session with the Manager using that external Session's sessionInfo.
159     * Log.endSession will still need to be called at the end of the session.
160     * @param sessionInfo Describes the external Session's information.
161     * @param shortMethodName The method name of the new session that is being started.
162     */
163    public synchronized void startExternalSession(Session.Info sessionInfo,
164            String shortMethodName) {
165        if(sessionInfo == null) {
166            return;
167        }
168
169        int threadId = getCallingThreadId();
170        Session threadSession = mSessionMapper.get(threadId);
171        if (threadSession != null) {
172            // We should never get into a situation where there is already an active session AND
173            // an external session is added. We are just using that active session.
174            Log.w(LOGGING_TAG, "trying to start an external session with a session " +
175                    "already active.");
176            return;
177        }
178
179        // Create Session from Info and add to the sessionMapper under this ID.
180        Log.d(LOGGING_TAG, Session.START_EXTERNAL_SESSION);
181        Session externalSession = new Session(Session.EXTERNAL_INDICATOR + sessionInfo.sessionId,
182                sessionInfo.methodPath, System.currentTimeMillis(),
183                false /*isStartedFromActiveSession*/, null);
184        externalSession.setIsExternal(true);
185        // Mark the external session as already completed, since we have no way of knowing when
186        // the external session actually has completed.
187        externalSession.markSessionCompleted(Session.UNDEFINED);
188        // Track the external session with the SessionMapper so that we can create and continue
189        // an active subsession based on it.
190        mSessionMapper.put(threadId, externalSession);
191        // Create a subsession from this external Session parent node
192        Session childSession = createSubsession();
193        continueSession(childSession, shortMethodName);
194    }
195
196    /**
197     * Notifies the logging system that a subsession will be run at a later point and
198     * allocates the resources. Returns a session object that must be used in
199     * Log.continueSession(...) to start the subsession.
200     */
201    public Session createSubsession() {
202        return createSubsession(false);
203    }
204
205    private synchronized Session createSubsession(boolean isStartedFromActiveSession) {
206        int threadId = getCallingThreadId();
207        Session threadSession = mSessionMapper.get(threadId);
208        if (threadSession == null) {
209            Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
210                    "active.");
211            return null;
212        }
213        // Start execution time of the session will be overwritten in continueSession(...).
214        Session newSubsession = new Session(threadSession.getNextChildId(),
215                threadSession.getShortMethodName(), System.currentTimeMillis(),
216                isStartedFromActiveSession, null);
217        threadSession.addChild(newSubsession);
218        newSubsession.setParentSession(threadSession);
219
220        if (!isStartedFromActiveSession) {
221            Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
222                    newSubsession.toString());
223        } else {
224            Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
225                    " (Invisible subsession)");
226        }
227        return newSubsession;
228    }
229
230    /**
231     * Retrieve the information of the currently active Session. This information is parcelable and
232     * is used to create an external Session ({@link #startExternalSession(Session.Info, String)}).
233     * If there is no Session active, this method will return null.
234     */
235    public synchronized Session.Info getExternalSession() {
236        int threadId = getCallingThreadId();
237        Session threadSession = mSessionMapper.get(threadId);
238        if (threadSession == null) {
239            Log.d(LOGGING_TAG, "Log.getExternalSession was called with no session " +
240                    "active.");
241            return null;
242        }
243
244        return threadSession.getInfo();
245    }
246
247    /**
248     * Cancels a subsession that had Log.createSubsession() called on it, but will never have
249     * Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned
250     * gracefully instead of being removed by the mSessionCleanupHandler forcefully later.
251     */
252    public synchronized void cancelSubsession(Session subsession) {
253        if (subsession == null) {
254            return;
255        }
256
257        subsession.markSessionCompleted(Session.UNDEFINED);
258        endParentSessions(subsession);
259    }
260
261    /**
262     * Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method
263     * must be called at the end of this method. The full session will complete when all
264     * subsessions are completed.
265     */
266    public synchronized void continueSession(Session subsession, String shortMethodName) {
267        if (subsession == null) {
268            return;
269        }
270        resetStaleSessionTimer();
271        subsession.setShortMethodName(shortMethodName);
272        subsession.setExecutionStartTimeMs(System.currentTimeMillis());
273        Session parentSession = subsession.getParentSession();
274        if (parentSession == null) {
275            Log.i(LOGGING_TAG, "Log.continueSession was called with no session " +
276                    "active for method " + shortMethodName);
277            return;
278        }
279
280        mSessionMapper.put(getCallingThreadId(), subsession);
281        if (!subsession.isStartedFromActiveSession()) {
282            Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
283        } else {
284            Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
285                    " (Invisible Subsession) with Method " + shortMethodName);
286        }
287    }
288
289    /**
290     * Ends the current session/subsession. Must be called after a Log.startSession(...) and
291     * Log.continueSession(...) call.
292     */
293    public synchronized void endSession() {
294        int threadId = getCallingThreadId();
295        Session completedSession = mSessionMapper.get(threadId);
296        if (completedSession == null) {
297            Log.w(LOGGING_TAG, "Log.endSession was called with no session active.");
298            return;
299        }
300
301        completedSession.markSessionCompleted(System.currentTimeMillis());
302        if (!completedSession.isStartedFromActiveSession()) {
303            Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
304                    completedSession.getLocalExecutionTime() + " mS)");
305        } else {
306            Log.v(LOGGING_TAG, Session.END_SUBSESSION +
307                    " (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() +
308                    " ms)");
309        }
310        // Remove after completed so that reference still exists for logging the end events
311        Session parentSession = completedSession.getParentSession();
312        mSessionMapper.remove(threadId);
313        endParentSessions(completedSession);
314        // If this subsession was started from a parent session using Log.startSession, return the
315        // ThreadID back to the parent after completion.
316        if (parentSession != null && !parentSession.isSessionCompleted() &&
317                completedSession.isStartedFromActiveSession()) {
318            mSessionMapper.put(threadId, parentSession);
319        }
320    }
321
322    // Recursively deletes all complete parent sessions of the current subsession if it is a leaf.
323    private void endParentSessions(Session subsession) {
324        // Session is not completed or not currently a leaf, so we can not remove because a child is
325        // still running
326        if (!subsession.isSessionCompleted() || subsession.getChildSessions().size() != 0) {
327            return;
328        }
329        Session parentSession = subsession.getParentSession();
330        if (parentSession != null) {
331            subsession.setParentSession(null);
332            parentSession.removeChild(subsession);
333            // Report the child session of the external session as being complete to the listeners,
334            // not the external session itself.
335            if (parentSession.isExternal()) {
336                long fullSessionTimeMs =
337                        System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
338                notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs);
339            }
340            endParentSessions(parentSession);
341        } else {
342            // All of the subsessions have been completed and it is time to report on the full
343            // running time of the session.
344            long fullSessionTimeMs =
345                    System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
346            Log.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
347                    + " ms): " + subsession.toString());
348            if (!subsession.isExternal()) {
349                notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs);
350            }
351        }
352    }
353
354    private void notifySessionCompleteListeners(String methodName, long sessionTimeMs) {
355        for (ISessionListener l : mSessionListeners) {
356            l.sessionComplete(methodName, sessionTimeMs);
357        }
358    }
359
360    public String getSessionId() {
361        Session currentSession = mSessionMapper.get(getCallingThreadId());
362        return currentSession != null ? currentSession.toString() : "";
363    }
364
365    public synchronized void registerSessionListener(ISessionListener l) {
366        if (l != null) {
367            mSessionListeners.add(l);
368        }
369    }
370
371    private synchronized String getNextSessionID() {
372        Integer nextId = sCodeEntryCounter++;
373        if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) {
374            restartSessionCounter();
375            nextId = sCodeEntryCounter++;
376        }
377        return getBase64Encoding(nextId);
378    }
379
380    private synchronized void restartSessionCounter() {
381        sCodeEntryCounter = 0;
382    }
383
384    private String getBase64Encoding(int number) {
385        byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array();
386        idByteArray = Arrays.copyOfRange(idByteArray, 2, 4);
387        return Base64.encodeToString(idByteArray, Base64.NO_WRAP | Base64.NO_PADDING);
388    }
389
390    private int getCallingThreadId() {
391        return mCurrentThreadId.get();
392    }
393
394    @VisibleForTesting
395    public synchronized void cleanupStaleSessions(long timeoutMs) {
396        String logMessage = "Stale Sessions Cleaned:\n";
397        boolean isSessionsStale = false;
398        long currentTimeMs = System.currentTimeMillis();
399        // Remove references that are in the Session Mapper (causing GC to occur) on
400        // sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS.
401        // If this occurs, then there is most likely a Session active that never had
402        // Log.endSession called on it.
403        for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it =
404             mSessionMapper.entrySet().iterator(); it.hasNext(); ) {
405            ConcurrentHashMap.Entry<Integer, Session> entry = it.next();
406            Session session = entry.getValue();
407            if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) {
408                it.remove();
409                logMessage += session.printFullSessionTree() + "\n";
410                isSessionsStale = true;
411            }
412        }
413        if (isSessionsStale) {
414            Log.w(LOGGING_TAG, logMessage);
415        } else {
416            Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
417        }
418    }
419
420    /**
421     * Returns the amount of time after a Logging session has been started that Telecom is set to
422     * perform a sweep to check and make sure that the session is still not incomplete (stale).
423     */
424    private long getCleanupTimeout(Context context) {
425        return Settings.Secure.getLong(context.getContentResolver(), TIMEOUTS_PREFIX +
426                "stale_session_cleanup_timeout_millis", DEFAULT_SESSION_TIMEOUT_MS);
427    }
428}
429