1 /*
2  * Copyright (C) 2022 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.inputmethod;
18 
19 import android.Manifest;
20 import android.annotation.EnforcePermission;
21 import android.annotation.NonNull;
22 import android.annotation.Nullable;
23 import android.os.Binder;
24 import android.os.Handler;
25 import android.os.IBinder;
26 import android.os.Looper;
27 import android.util.Log;
28 import android.view.inputmethod.ImeTracker;
29 
30 import com.android.internal.annotations.GuardedBy;
31 import com.android.internal.infra.AndroidFuture;
32 import com.android.internal.inputmethod.IImeTracker;
33 import com.android.internal.inputmethod.InputMethodDebug;
34 import com.android.internal.inputmethod.SoftInputShowHideReason;
35 import com.android.internal.util.FrameworkStatsLog;
36 
37 import java.io.PrintWriter;
38 import java.time.Instant;
39 import java.time.ZoneId;
40 import java.time.format.DateTimeFormatter;
41 import java.util.ArrayDeque;
42 import java.util.Locale;
43 import java.util.WeakHashMap;
44 import java.util.concurrent.atomic.AtomicInteger;
45 
46 /**
47  * Service for managing and logging {@link ImeTracker.Token} instances.
48  *
49  * @implNote Suppresses {@link GuardedBy} warnings, as linter reports that {@link #mHistory}
50  * interactions are guarded by {@code this} instead of {@code ImeTrackerService.this}, which should
51  * be identical.
52  *
53  * @hide
54  */
55 @SuppressWarnings("GuardedBy")
56 public final class ImeTrackerService extends IImeTracker.Stub {
57 
58     private static final String TAG = ImeTracker.TAG;
59 
60     /** The threshold in milliseconds after which a history entry is considered timed out. */
61     private static final long TIMEOUT_MS = 10_000;
62 
63     /** Handler for registering timeouts for live entries. */
64     @GuardedBy("mLock")
65     private final Handler mHandler;
66 
67     /** Singleton instance of the History. */
68     @GuardedBy("mLock")
69     private final History mHistory = new History();
70 
71     private final Object mLock = new Object();
72 
ImeTrackerService(@onNull Looper looper)73     ImeTrackerService(@NonNull Looper looper) {
74         mHandler = new Handler(looper, null /* callback */, true /* async */);
75     }
76 
77     @NonNull
78     @Override
onStart(@onNull String tag, int uid, @ImeTracker.Type int type, @ImeTracker.Origin int origin, @SoftInputShowHideReason int reason, boolean fromUser)79     public ImeTracker.Token onStart(@NonNull String tag, int uid, @ImeTracker.Type int type,
80             @ImeTracker.Origin int origin, @SoftInputShowHideReason int reason, boolean fromUser) {
81         final var binder = new Binder();
82         final var token = new ImeTracker.Token(binder, tag);
83         final var entry = new History.Entry(tag, uid, type, ImeTracker.STATUS_RUN, origin, reason,
84                 fromUser);
85         synchronized (mLock) {
86             mHistory.addEntry(binder, entry);
87 
88             // Register a delayed task to handle the case where the new entry times out.
89             mHandler.postDelayed(() -> {
90                 synchronized (mLock) {
91                     mHistory.setFinished(token, ImeTracker.STATUS_TIMEOUT,
92                             ImeTracker.PHASE_NOT_SET);
93                 }
94             }, TIMEOUT_MS);
95         }
96         return token;
97     }
98 
99     @Override
onProgress(@onNull IBinder binder, @ImeTracker.Phase int phase)100     public void onProgress(@NonNull IBinder binder, @ImeTracker.Phase int phase) {
101         synchronized (mLock) {
102             final var entry = mHistory.getEntry(binder);
103             if (entry == null) return;
104 
105             entry.mPhase = phase;
106         }
107     }
108 
109     @Override
onFailed(@onNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase)110     public void onFailed(@NonNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase) {
111         synchronized (mLock) {
112             mHistory.setFinished(statsToken, ImeTracker.STATUS_FAIL, phase);
113         }
114     }
115 
116     @Override
onCancelled(@onNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase)117     public void onCancelled(@NonNull ImeTracker.Token statsToken, @ImeTracker.Phase int phase) {
118         synchronized (mLock) {
119             mHistory.setFinished(statsToken, ImeTracker.STATUS_CANCEL, phase);
120         }
121     }
122 
123     @Override
onShown(@onNull ImeTracker.Token statsToken)124     public void onShown(@NonNull ImeTracker.Token statsToken) {
125         synchronized (mLock) {
126             mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET);
127         }
128     }
129 
130     @Override
onHidden(@onNull ImeTracker.Token statsToken)131     public void onHidden(@NonNull ImeTracker.Token statsToken) {
132         synchronized (mLock) {
133             mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET);
134         }
135     }
136 
137     @Override
onDispatched(@onNull ImeTracker.Token statsToken)138     public void onDispatched(@NonNull ImeTracker.Token statsToken) {
139         synchronized (mLock) {
140             mHistory.setFinished(statsToken, ImeTracker.STATUS_SUCCESS, ImeTracker.PHASE_NOT_SET);
141         }
142     }
143 
144     /**
145      * Updates the IME request tracking token with new information available in IMMS.
146      *
147      * @param statsToken the token tracking the current IME request.
148      * @param requestWindowName the name of the window that created the IME request.
149      */
onImmsUpdate(@onNull ImeTracker.Token statsToken, @NonNull String requestWindowName)150     public void onImmsUpdate(@NonNull ImeTracker.Token statsToken,
151             @NonNull String requestWindowName) {
152         synchronized (mLock) {
153             final var entry = mHistory.getEntry(statsToken.getBinder());
154             if (entry == null) return;
155 
156             entry.mRequestWindowName = requestWindowName;
157         }
158     }
159 
160     /** Dumps the contents of the history. */
dump(@onNull PrintWriter pw, @NonNull String prefix)161     public void dump(@NonNull PrintWriter pw, @NonNull String prefix) {
162         synchronized (mLock) {
163             mHistory.dump(pw, prefix);
164         }
165     }
166 
167     @EnforcePermission(Manifest.permission.TEST_INPUT_METHOD)
168     @Override
hasPendingImeVisibilityRequests()169     public boolean hasPendingImeVisibilityRequests() {
170         super.hasPendingImeVisibilityRequests_enforcePermission();
171         synchronized (mLock) {
172             return !mHistory.mLiveEntries.isEmpty();
173         }
174     }
175 
176     @EnforcePermission(Manifest.permission.TEST_INPUT_METHOD)
177     @Override
finishTrackingPendingImeVisibilityRequests( @onNull AndroidFuture completionSignal )178     public void finishTrackingPendingImeVisibilityRequests(
179             @NonNull AndroidFuture completionSignal /* T=Void */) {
180         super.finishTrackingPendingImeVisibilityRequests_enforcePermission();
181         @SuppressWarnings("unchecked")
182         final AndroidFuture<Void> typedCompletionSignal = completionSignal;
183         try {
184             synchronized (mLock) {
185                 mHistory.mLiveEntries.clear();
186             }
187             typedCompletionSignal.complete(null);
188         } catch (Throwable e) {
189             typedCompletionSignal.completeExceptionally(e);
190         }
191     }
192 
193     /**
194      * A circular buffer storing the most recent few {@link ImeTracker.Token} entries information.
195      */
196     private static final class History {
197 
198         /** The circular buffer's capacity. */
199         private static final int CAPACITY = 100;
200 
201         /** Backing store for the circular buffer. */
202         @GuardedBy("ImeTrackerService.this")
203         private final ArrayDeque<Entry> mEntries = new ArrayDeque<>(CAPACITY);
204 
205         /** Backing store for the live entries (i.e. entries that are not finished yet). */
206         @GuardedBy("ImeTrackerService.this")
207         private final WeakHashMap<IBinder, Entry> mLiveEntries = new WeakHashMap<>();
208 
209         /** Latest entry sequence number. */
210         private static final AtomicInteger sSequenceNumber = new AtomicInteger(0);
211 
212         /** Adds a live entry corresponding to the given IME tracking token's binder. */
213         @GuardedBy("ImeTrackerService.this")
addEntry(@onNull IBinder binder, @NonNull Entry entry)214         private void addEntry(@NonNull IBinder binder, @NonNull Entry entry) {
215             mLiveEntries.put(binder, entry);
216         }
217 
218         /** Gets the entry corresponding to the given IME tracking token's binder, if it exists. */
219         @Nullable
220         @GuardedBy("ImeTrackerService.this")
getEntry(@onNull IBinder binder)221         private Entry getEntry(@NonNull IBinder binder) {
222             return mLiveEntries.get(binder);
223         }
224 
225         /**
226          * Sets the live entry corresponding to the tracking token, if it exists, as finished,
227          * and uploads the data for metrics.
228          *
229          * @param statsToken the token tracking the current IME request.
230          * @param status the finish status of the IME request.
231          * @param phase the phase the IME request finished at, if it exists
232          *              (or {@link ImeTracker#PHASE_NOT_SET} otherwise).
233          */
234         @GuardedBy("ImeTrackerService.this")
setFinished(@onNull ImeTracker.Token statsToken, @ImeTracker.Status int status, @ImeTracker.Phase int phase)235         private void setFinished(@NonNull ImeTracker.Token statsToken,
236                 @ImeTracker.Status int status, @ImeTracker.Phase int phase) {
237             final var entry = mLiveEntries.remove(statsToken.getBinder());
238             if (entry == null) {
239                 // This will be unconditionally called through the postDelayed above to handle
240                 // potential timeouts, and is thus intentionally dropped to avoid having to manually
241                 // save and remove the registered callback. Only timeout calls are expected.
242                 if (status != ImeTracker.STATUS_TIMEOUT) {
243                     Log.i(TAG, statsToken.getTag()
244                             + ": setFinished on previously finished token at "
245                             + ImeTracker.Debug.phaseToString(phase) + " with "
246                             + ImeTracker.Debug.statusToString(status));
247                 }
248                 return;
249             }
250 
251             entry.mDuration = System.currentTimeMillis() - entry.mStartTime;
252             entry.mStatus = status;
253 
254             if (phase != ImeTracker.PHASE_NOT_SET) {
255                 entry.mPhase = phase;
256             }
257 
258             if (status == ImeTracker.STATUS_TIMEOUT) {
259                 // All events other than timeouts are already logged in the client-side ImeTracker.
260                 Log.i(TAG, statsToken.getTag() + ": setFinished at "
261                         + ImeTracker.Debug.phaseToString(entry.mPhase) + " with "
262                         + ImeTracker.Debug.statusToString(status));
263             }
264 
265             // Remove excess entries overflowing capacity (plus one for the new entry).
266             while (mEntries.size() >= CAPACITY) {
267                 mEntries.remove();
268             }
269 
270             mEntries.offer(entry);
271 
272             // Log newly finished entry.
273             FrameworkStatsLog.write(FrameworkStatsLog.IME_REQUEST_FINISHED, entry.mUid,
274                     entry.mDuration, entry.mType, entry.mStatus, entry.mReason,
275                     entry.mOrigin, entry.mPhase, entry.mFromUser);
276         }
277 
278         /** Dumps the contents of the circular buffer. */
279         @GuardedBy("ImeTrackerService.this")
dump(@onNull PrintWriter pw, @NonNull String prefix)280         private void dump(@NonNull PrintWriter pw, @NonNull String prefix) {
281             final var formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS", Locale.US)
282                     .withZone(ZoneId.systemDefault());
283 
284             pw.print(prefix);
285             pw.println("mLiveEntries: " + mLiveEntries.size() + " elements");
286 
287             for (final var entry: mLiveEntries.values()) {
288                 dumpEntry(entry, pw, prefix + "  ", formatter);
289             }
290             pw.print(prefix);
291             pw.println("mEntries: " + mEntries.size() + " elements");
292 
293             for (final var entry: mEntries) {
294                 dumpEntry(entry, pw, prefix + "  ", formatter);
295             }
296         }
297 
298         @GuardedBy("ImeTrackerService.this")
dumpEntry(@onNull Entry entry, @NonNull PrintWriter pw, @NonNull String prefix, @NonNull DateTimeFormatter formatter)299         private void dumpEntry(@NonNull Entry entry, @NonNull PrintWriter pw,
300                 @NonNull String prefix, @NonNull DateTimeFormatter formatter) {
301             pw.print(prefix);
302             pw.print("#" + entry.mSequenceNumber);
303             pw.print(" " + ImeTracker.Debug.typeToString(entry.mType));
304             pw.print(" - " + ImeTracker.Debug.statusToString(entry.mStatus));
305             pw.print(" - " + entry.mTag);
306             pw.println(" (" + entry.mDuration + "ms):");
307 
308             pw.print(prefix);
309             pw.print("  startTime=" + formatter.format(Instant.ofEpochMilli(entry.mStartTime)));
310             pw.println(" " + ImeTracker.Debug.originToString(entry.mOrigin));
311 
312             pw.print(prefix);
313             pw.print("  reason=" + InputMethodDebug.softInputDisplayReasonToString(entry.mReason));
314             pw.println(" " + ImeTracker.Debug.phaseToString(entry.mPhase));
315 
316             pw.print(prefix);
317             pw.println("  requestWindowName=" + entry.mRequestWindowName);
318         }
319 
320         /** A history entry. */
321         private static final class Entry {
322 
323             /** The entry's sequence number in the history. */
324             private final int mSequenceNumber = sSequenceNumber.getAndIncrement();
325 
326             /** Logging tag, of the shape "component:random_hexadecimal". */
327             @NonNull
328             private final String mTag;
329 
330             /** Uid of the client that requested the IME. */
331             private final int mUid;
332 
333             /** Clock time in milliseconds when the IME request was created. */
334             private final long mStartTime = System.currentTimeMillis();
335 
336             /** Duration in milliseconds of the IME request from start to end. */
337             private long mDuration = 0;
338 
339             /** Type of the IME request. */
340             @ImeTracker.Type
341             private final int mType;
342 
343             /** Status of the IME request. */
344             @ImeTracker.Status
345             private int mStatus;
346 
347             /** Origin of the IME request. */
348             @ImeTracker.Origin
349             private final int mOrigin;
350 
351             /** Reason for creating the IME request. */
352             @SoftInputShowHideReason
353             private final int mReason;
354 
355             /** Latest phase of the IME request. */
356             @ImeTracker.Phase
357             private int mPhase = ImeTracker.PHASE_NOT_SET;
358 
359             /** Whether this request was created directly from a user interaction. */
360             private final boolean mFromUser;
361 
362             /**
363              * Name of the window that created the IME request.
364              *
365              * Note: This is later set through {@link #onImmsUpdate}.
366              */
367             @NonNull
368             private String mRequestWindowName = "not set";
369 
Entry(@onNull String tag, int uid, @ImeTracker.Type int type, @ImeTracker.Status int status, @ImeTracker.Origin int origin, @SoftInputShowHideReason int reason, boolean fromUser)370             private Entry(@NonNull String tag, int uid, @ImeTracker.Type int type,
371                     @ImeTracker.Status int status, @ImeTracker.Origin int origin,
372                     @SoftInputShowHideReason int reason, boolean fromUser) {
373                 mTag = tag;
374                 mUid = uid;
375                 mType = type;
376                 mStatus = status;
377                 mOrigin = origin;
378                 mReason = reason;
379                 mFromUser = fromUser;
380             }
381         }
382     }
383 }
384