No warning/info log for expected/normal situations
This CL hides warning and info log messages from
InputMethodManagerService (IMMS) and InputMethodService (IMS) behind
DEBUG flag like other logs unless the state is certainly unusual.
Of course the definition of "unusual" is still an open question, but
basically that we should not see any suspicious message from IMMS/IMS
just by turning on a new phone, launching some applications, typing
something, and turning off the device. IMMS and IMS should expect all
events that can (easily) occur in that scenario, and no log is
necessary for such things.
Note that warnings suppressed with TODO comments will be tracked
under Bug 34851776 (and Bug 34886274).
Test: adb logcat -s InputMethodManagerService:* InputMethodService:*
to monitor log in the following scenario:
1. Boot the device.
2. Complete the setup wizard.
3. Launch Dialer and type something on it.
4. Launch Contacts app and type something on it.
5. Try some special modes:
- Turn on/off display
- Recents screen
- Split-window mode
- Guest user
- Multi user
- Direct-boot (setup a device password and reboot)
except for logs about actual IPC calls from a background user.
Bug: 34838583
Bug: 34851776
Bug: 34886274
Change-Id: I3fcdeb919bb2f2940da9ff45e17ac00baa1253f4
diff --git a/services/core/java/com/android/server/InputMethodManagerService.java b/services/core/java/com/android/server/InputMethodManagerService.java
index 8020f0e..3e711ec 100644
--- a/services/core/java/com/android/server/InputMethodManagerService.java
+++ b/services/core/java/com/android/server/InputMethodManagerService.java
@@ -932,7 +932,9 @@
return;
}
final InputMethodInfo defIm = suitableImes.get(0);
- Slog.i(TAG, "Default found, using " + defIm.getId());
+ if (DEBUG) {
+ Slog.i(TAG, "Default found, using " + defIm.getId());
+ }
setSelectedInputMethodAndSubtypeLocked(defIm, NOT_A_SUBTYPE_ID, false);
}
@@ -1123,6 +1125,7 @@
}
return true;
}
+ // TODO(b/34886274): The semantics of this verification is actually not well-defined.
Slog.w(TAG, "--- IPC called from background users. Ignore. callers="
+ Debug.getCallers(10));
return false;
@@ -1134,8 +1137,18 @@
* @param token The window token given to the input method when it was started.
* @return true if and only if non-null valid token is specified.
*/
- private boolean calledWithValidToken(IBinder token) {
- if (token == null || mCurToken != token) {
+ private boolean calledWithValidToken(@Nullable IBinder token) {
+ if (token == null && Binder.getCallingPid() == Process.myPid()) {
+ if (DEBUG) {
+ // TODO(b/34851776): Basically it's the caller's fault if we reach here.
+ Slog.d(TAG, "Bug 34851776 is detected callers=" + Debug.getCallers(10));
+ }
+ return false;
+ }
+ if (token == null || token != mCurToken) {
+ // TODO(b/34886274): The semantics of this verification is actually not well-defined.
+ Slog.e(TAG, "Ignoring " + Debug.getCaller() + " due to an invalid token."
+ + " uid:" + Binder.getCallingUid() + " token:" + token);
return false;
}
return true;
@@ -1338,8 +1351,10 @@
// because if the focus changes some time before or after, the
// next client receiving focus that has any interest in input will
// be calling through here after that change happens.
- Slog.w(TAG, "Starting input on non-focused client " + cs.client
- + " (uid=" + cs.uid + " pid=" + cs.pid + ")");
+ if (DEBUG) {
+ Slog.w(TAG, "Starting input on non-focused client " + cs.client
+ + " (uid=" + cs.uid + " pid=" + cs.pid + ")");
+ }
return null;
}
} catch (RemoteException e) {
@@ -1457,7 +1472,7 @@
mCurId = info.getId();
mCurToken = new Binder();
try {
- if (true || DEBUG) Slog.v(TAG, "Adding window token: " + mCurToken);
+ if (DEBUG) Slog.v(TAG, "Adding window token: " + mCurToken);
mIWindowManager.addWindowToken(mCurToken, TYPE_INPUT_METHOD, DEFAULT_DISPLAY);
} catch (RemoteException e) {
}
@@ -1662,9 +1677,6 @@
public void updateStatusIcon(IBinder token, String packageName, int iconId) {
synchronized (mMethodMap) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring updateStatusIcon due to an invalid token. uid:" + uid
- + " token:" + token);
return;
}
final long ident = Binder.clearCallingIdentity();
@@ -1767,9 +1779,6 @@
@Override
public void setImeWindowStatus(IBinder token, int vis, int backDisposition) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring setImeWindowStatus due to an invalid token. uid:" + uid
- + " token:" + token);
return;
}
@@ -1789,9 +1798,6 @@
// Caution! This method is called in this class. Handle multi-user carefully
private void updateSystemUiLocked(IBinder token, int vis, int backDisposition) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring updateSystemUiLocked due to an invalid token. uid:" + uid
- + " token:" + token);
return;
}
@@ -2259,8 +2265,10 @@
// because if the focus changes some time before or after, the
// next client receiving focus that has any interest in input will
// be calling through here after that change happens.
- Slog.w(TAG, "Focus gain on non-focused client " + cs.client
- + " (uid=" + cs.uid + " pid=" + cs.pid + ")");
+ if (DEBUG) {
+ Slog.w(TAG, "Focus gain on non-focused client " + cs.client
+ + " (uid=" + cs.uid + " pid=" + cs.pid + ")");
+ }
return null;
}
} catch (RemoteException e) {
@@ -2275,8 +2283,10 @@
}
if (mCurFocusedWindow == windowToken) {
- Slog.w(TAG, "Window already focused, ignoring focus gain of: " + client
- + " attribute=" + attribute + ", token = " + windowToken);
+ if (DEBUG) {
+ Slog.w(TAG, "Window already focused, ignoring focus gain of: " + client
+ + " attribute=" + attribute + ", token = " + windowToken);
+ }
if (attribute != null) {
return startInputUncheckedLocked(cs, inputContext, missingMethods,
attribute, controlFlags);
@@ -2519,9 +2529,6 @@
}
synchronized (mMethodMap) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring switchToNextInputMethod due to an invalid token. uid:" + uid
- + " token:" + token);
return false;
}
final ImeSubtypeListItem nextSubtype = mSwitchingController.getNextInputMethodLocked(
@@ -2543,9 +2550,6 @@
}
synchronized (mMethodMap) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring shouldOfferSwitchingToNextInputMethod due to an invalid "
- + "token. uid:" + uid + " token:" + token);
return false;
}
final ImeSubtypeListItem nextSubtype = mSwitchingController.getNextInputMethodLocked(
@@ -2636,9 +2640,6 @@
}
synchronized (mMethodMap) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring clearLastInputMethodWindowForTransition due to an "
- + "invalid token. uid:" + uid + " token:" + token);
return;
}
}
@@ -2702,9 +2703,6 @@
}
synchronized (mMethodMap) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring hideInputMethod due to an invalid token. uid:"
- + uid + " token:" + token);
return;
}
long ident = Binder.clearCallingIdentity();
@@ -2723,9 +2721,6 @@
}
synchronized (mMethodMap) {
if (!calledWithValidToken(token)) {
- final int uid = Binder.getCallingUid();
- Slog.e(TAG, "Ignoring showMySoftInput due to an invalid token. uid:"
- + uid + " token:" + token);
return;
}
long ident = Binder.clearCallingIdentity();
@@ -3076,7 +3071,9 @@
}
}
if (!enabledImeFound) {
- Slog.i(TAG, "All the enabled IMEs are gone. Reset default enabled IMEs.");
+ if (DEBUG) {
+ Slog.i(TAG, "All the enabled IMEs are gone. Reset default enabled IMEs.");
+ }
resetDefaultEnabledIme = true;
resetSelectedInputMethodAndSubtypeLocked("");
}