From 0ab53dcb31e7ae52cc265c8020df538df90ed2d7 Mon Sep 17 00:00:00 2001 From: Felipe Leme Date: Thu, 23 Feb 2017 08:33:18 -0800 Subject: [PATCH] Auto-fill logging improvements: - Shorten history line by removing less relevant items. - Decrease number of history items (from 100 to 20). - Removed redundant logs from service (and kept them on manager) - Use {} on all log statements. - Remove DEBUG guard on some important messages. - Remove DEBUG guard from service-side toString() implementations. - Don't log FLAG_FOCUS_LOST actions. BUG: 33197203 Test: manual verification Change-Id: I30466ab3c0d12cfa2ad68b2b2a107d5890256845 --- .../view/autofill/AutoFillManager.java | 10 ++- .../autofill/AutoFillManagerService.java | 23 ++--- .../autofill/AutoFillManagerServiceImpl.java | 90 +++++++++++-------- 3 files changed, 68 insertions(+), 55 deletions(-) diff --git a/core/java/android/view/autofill/AutoFillManager.java b/core/java/android/view/autofill/AutoFillManager.java index 2168444b9b58f..4cc73d08dd474 100644 --- a/core/java/android/view/autofill/AutoFillManager.java +++ b/core/java/android/view/autofill/AutoFillManager.java @@ -17,6 +17,7 @@ package android.view.autofill; import static android.view.autofill.Helper.DEBUG; +import static android.view.autofill.Helper.VERBOSE; import android.content.Context; import android.content.Intent; @@ -273,7 +274,7 @@ public final class AutoFillManager { private void startSession(AutoFillId id, Rect bounds, AutoFillValue value) { if (DEBUG) { - Log.v(TAG, "startSession(): id=" + id + ", bounds=" + bounds + ", value=" + value); + Log.d(TAG, "startSession(): id=" + id + ", bounds=" + bounds + ", value=" + value); } try { mService.startSession(mContext.getActivityToken(), mServiceClient.asBinder(), @@ -287,7 +288,7 @@ public final class AutoFillManager { private void finishSession() { if (DEBUG) { - Log.v(TAG, "finishSession()"); + Log.d(TAG, "finishSession()"); } mHasSession = false; try { @@ -299,9 +300,12 @@ public final class AutoFillManager { private void updateSession(AutoFillId id, Rect bounds, AutoFillValue value, int flags) { if (DEBUG) { - Log.v(TAG, "updateSession(): id=" + id + ", bounds=" + bounds + ", value=" + value + if (VERBOSE || (flags & FLAG_FOCUS_LOST) != 0) { + Log.d(TAG, "updateSession(): id=" + id + ", bounds=" + bounds + ", value=" + value + ", flags=" + flags); + } } + try { mService.updateSession(mContext.getActivityToken(), id, bounds, value, flags, mContext.getUserId()); diff --git a/services/autofill/java/com/android/server/autofill/AutoFillManagerService.java b/services/autofill/java/com/android/server/autofill/AutoFillManagerService.java index 3257812d6054b..e01fee28ffe56 100644 --- a/services/autofill/java/com/android/server/autofill/AutoFillManagerService.java +++ b/services/autofill/java/com/android/server/autofill/AutoFillManagerService.java @@ -18,7 +18,6 @@ package com.android.server.autofill; import static android.Manifest.permission.MANAGE_AUTO_FILL; import static android.content.Context.AUTO_FILL_MANAGER_SERVICE; -import static com.android.server.autofill.Helper.DEBUG; import static com.android.server.autofill.Helper.VERBOSE; import android.Manifest; @@ -100,14 +99,16 @@ public final class AutoFillManagerService extends SystemService { private SparseArray mServicesCache = new SparseArray<>(); // TODO(b/33197203): set a different max (or disable it) on low-memory devices. - private final LocalLog mRequestsHistory = new LocalLog(100); + private final LocalLog mRequestsHistory = new LocalLog(20); private final BroadcastReceiver mBroadcastReceiver = new BroadcastReceiver() { @Override public void onReceive(Context context, Intent intent) { if (Intent.ACTION_CLOSE_SYSTEM_DIALOGS.equals(intent.getAction())) { final String reason = intent.getStringExtra("reason"); - if (DEBUG) Slog.d(TAG, "close system dialogs: " + reason); + if (VERBOSE) { + Slog.v(TAG, "close system dialogs: " + reason); + } mUi.hideAll(); } } @@ -246,7 +247,9 @@ public final class AutoFillManagerService extends SystemService { private IBinder getTopActivityForUser() { final List topActivities = LocalServices .getService(ActivityManagerInternal.class).getTopVisibleActivities(); - if (DEBUG) Slog.d(TAG, "Top activities (" + topActivities.size() + "): " + topActivities); + if (VERBOSE) { + Slog.v(TAG, "Top activities (" + topActivities.size() + "): " + topActivities); + } if (topActivities.isEmpty()) { Slog.w(TAG, "Could not get top activity"); return null; @@ -275,11 +278,6 @@ public final class AutoFillManagerService extends SystemService { Rect bounds, AutoFillValue value, int userId) { // TODO(b/33197203): make sure it's called by resumed / focused activity - if (VERBOSE) { - Slog.v(TAG, "startSession: autoFillId=" + autoFillId + ", bounds=" + bounds - + ", value=" + value); - } - synchronized (mLock) { final AutoFillManagerServiceImpl service = getServiceForUserLocked(userId); service.startSessionLocked(activityToken, appCallback, autoFillId, bounds, value); @@ -289,11 +287,6 @@ public final class AutoFillManagerService extends SystemService { @Override public void updateSession(IBinder activityToken, AutoFillId id, Rect bounds, AutoFillValue value, int flags, int userId) { - if (DEBUG) { - Slog.d(TAG, "updateSession: flags=" + flags + ", autoFillId=" + id - + ", bounds=" + bounds + ", value=" + value); - } - synchronized (mLock) { final AutoFillManagerServiceImpl service = mServicesCache.get( UserHandle.getCallingUserId()); @@ -305,8 +298,6 @@ public final class AutoFillManagerService extends SystemService { @Override public void finishSession(IBinder activityToken, int userId) { - if (VERBOSE) Slog.v(TAG, "finishSession(): " + activityToken); - synchronized (mLock) { final AutoFillManagerServiceImpl service = mServicesCache.get( UserHandle.getCallingUserId()); diff --git a/services/autofill/java/com/android/server/autofill/AutoFillManagerServiceImpl.java b/services/autofill/java/com/android/server/autofill/AutoFillManagerServiceImpl.java index ec3d35629bef3..988df69bf9fb0 100644 --- a/services/autofill/java/com/android/server/autofill/AutoFillManagerServiceImpl.java +++ b/services/autofill/java/com/android/server/autofill/AutoFillManagerServiceImpl.java @@ -103,7 +103,7 @@ final class AutoFillManagerServiceImpl { handleSessionSave((IBinder) msg.obj); break; default: - Slog.d(TAG, "invalid msg: " + msg); + Slog.w(TAG, "invalid msg on handler: " + msg); } }; @@ -127,17 +127,18 @@ final class AutoFillManagerServiceImpl { private final IResultReceiver mAssistReceiver = new IResultReceiver.Stub() { @Override public void send(int resultCode, Bundle resultData) throws RemoteException { - if (DEBUG) Slog.d(TAG, "resultCode on mAssistReceiver: " + resultCode); + if (VERBOSE) { + Slog.v(TAG, "resultCode on mAssistReceiver: " + resultCode); + } final AssistStructure structure = resultData.getParcelable(KEY_STRUCTURE); if (structure == null) { - Slog.w(TAG, "no assist structure for id " + resultCode); + Slog.wtf(TAG, "no assist structure for id " + resultCode); return; } final Bundle receiverExtras = resultData.getBundle(KEY_RECEIVER_EXTRAS); if (receiverExtras == null) { - // Should not happen Slog.wtf(TAG, "No " + KEY_RECEIVER_EXTRAS + " on receiver"); return; } @@ -194,7 +195,7 @@ final class AutoFillManagerServiceImpl { final ApplicationInfo info = pm.getApplicationInfo(packageName, 0); return pm.getApplicationLabel(info); } catch (Exception e) { - Slog.w(TAG, "Could not get label for " + packageName + ": " + e); + Slog.e(TAG, "Could not get label for " + packageName + ": " + e); return packageName; } } @@ -210,7 +211,7 @@ final class AutoFillManagerServiceImpl { serviceInfo = AppGlobals.getPackageManager().getServiceInfo(serviceComponent, 0, mUserId); } catch (RuntimeException | RemoteException e) { - Slog.e(TAG, "Bad auto-fill service name " + componentName, e); + Slog.e(TAG, "Bad auto-fill service name " + componentName + ": " + e); return; } } @@ -234,7 +235,7 @@ final class AutoFillManagerServiceImpl { sendStateToClients(); } } catch (PackageManager.NameNotFoundException e) { - Slog.e(TAG, "Bad auto-fill service name " + componentName, e); + Slog.e(TAG, "Bad auto-fill service name " + componentName + ": " + e); } } @@ -278,9 +279,9 @@ final class AutoFillManagerServiceImpl { return; } - final String historyItem = "s=" + new ComponentName(mInfo.getServiceInfo().packageName, - mInfo.getServiceInfo().name) + " u=" + mUserId + " a=" + activityToken - + " i=" + autoFillId + " b=" + bounds + " v=" + value; + final String historyItem = "s=" + mInfo.getServiceInfo().packageName + + " u=" + mUserId + " a=" + activityToken + + " i=" + autoFillId + " b=" + bounds; mRequestsHistory.log(historyItem); // TODO(b/33197203): Handle partitioning @@ -327,8 +328,6 @@ final class AutoFillManagerServiceImpl { try { if (!ActivityManager.getService().requestAutoFillData(mAssistReceiver, receiverExtras, activityToken)) { - // TODO(b/33197203): might need a way to warn user (perhaps a new method on - // AutoFillService). Slog.w(TAG, "failed to request auto-fill data for " + activityToken); } } finally { @@ -345,7 +344,9 @@ final class AutoFillManagerServiceImpl { // TODO(b/33197203): add MetricsLogger call final Session session = mSessions.get(activityToken); if (session == null) { - Slog.w(TAG, "updateSessionLocked(): session gone for " + activityToken); + if (VERBOSE) { + Slog.v(TAG, "updateSessionLocked(): session gone for " + activityToken); + } return; } @@ -365,7 +366,9 @@ final class AutoFillManagerServiceImpl { } void destroyLocked() { - if (VERBOSE) Slog.v(TAG, "destroyLocked()"); + if (VERBOSE) { + Slog.v(TAG, "destroyLocked()"); + } for (Session session : mSessions.values()) { session.destroyLocked(); @@ -376,7 +379,7 @@ final class AutoFillManagerServiceImpl { void dumpLocked(String prefix, PrintWriter pw) { final String prefix2 = prefix + " "; - pw.print(prefix); pw.println("Component:"); pw.println(mInfo != null + pw.print(prefix); pw.print("Component:"); pw.println(mInfo != null ? mInfo.getServiceInfo().getComponentName() : null); if (VERBOSE) { @@ -522,8 +525,6 @@ final class AutoFillManagerServiceImpl { @Override public String toString() { - if (!DEBUG) return super.toString(); - return "ViewState: [id=" + mId + ", value=" + mAutoFillValue + ", bounds=" + mBounds + ", updated = " + mValueUpdated + "]"; } @@ -595,7 +596,9 @@ final class AutoFillManagerServiceImpl { mClient = IAutoFillManagerClient.Stub.asInterface(client); try { client.linkToDeath(() -> { - if (DEBUG) Slog.d(TAG, "app binder died"); + if (DEBUG) { + Slog.d(TAG, "app binder died"); + } removeSelf(); }, 0); @@ -696,20 +699,23 @@ final class AutoFillManagerServiceImpl { */ public void showSaveLocked() { if (mStructure == null) { - // Sanity check; should not happen... Slog.wtf(TAG, "showSaveLocked(): no mStructure"); return; } if (mCurrentResponse == null) { - // Happens when the activity / session was finished before the service replied. - Slog.d(TAG, "showSaveLocked(): no mCurrentResponse yet"); + // Happens when the activity / session was finished before the service replied, or + // when the service cannot auto-fill it (and returned a null response). + if (DEBUG) { + Slog.d(TAG, "showSaveLocked(): no mCurrentResponse"); + } return; } final ArraySet savableIds = mCurrentResponse.getSavableIds(); - if (VERBOSE) Slog.v(TAG, "showSaveLocked(): savableIds=" + savableIds); + if (DEBUG) { + Slog.d(TAG, "showSaveLocked(): savableIds=" + savableIds); + } - if (savableIds.isEmpty()) { - if (DEBUG) Slog.d(TAG, "showSaveLocked(): service doesn't want to save"); + if (savableIds == null || savableIds.isEmpty()) { return; } @@ -732,21 +738,27 @@ final class AutoFillManagerServiceImpl { } // Nothing changed... - if (DEBUG) Slog.d(TAG, "showSaveLocked(): with no changes, comes no responsibilities"); + if (DEBUG) { + Slog.d(TAG, "showSaveLocked(): with no changes, comes no responsibilities"); + } } /** * Calls service when user requested save. */ private void callSaveLocked() { - if (DEBUG) Slog.d(TAG, "callSaveLocked(): mViewStates=" + mViewStates); + if (DEBUG) { + Slog.d(TAG, "callSaveLocked(): mViewStates=" + mViewStates); + } final Bundle extras = this.mCurrentResponse.getExtras(); for (Entry entry : mViewStates.entrySet()) { final AutoFillValue value = entry.getValue().mAutoFillValue; if (value == null) { - if (VERBOSE) Slog.v(TAG, "callSaveLocked(): skipping " + entry.getKey()); + if (VERBOSE) { + Slog.v(TAG, "callSaveLocked(): skipping " + entry.getKey()); + } continue; } final AutoFillId id = entry.getKey(); @@ -755,7 +767,9 @@ final class AutoFillManagerServiceImpl { Slog.w(TAG, "callSaveLocked(): did not find node with id " + id); continue; } - if (DEBUG) Slog.d(TAG, "callSaveLocked(): updating " + id + " to " + value); + if (VERBOSE) { + Slog.v(TAG, "callSaveLocked(): updating " + id + " to " + value); + } node.updateAutoFillValue(value); } @@ -771,11 +785,9 @@ final class AutoFillManagerServiceImpl { } void updateLocked(AutoFillId id, Rect bounds, AutoFillValue value, int flags) { - if (DEBUG) Slog.d(TAG, "updateLocked(): id=" + id + ", flags=" + flags); - if (mAutoFilledDataset != null && (flags & FLAG_VALUE_CHANGED) == 0) { // TODO(b/33197203): ignoring because we don't support partitions yet - if (DEBUG) Slog.d(TAG, "updateLocked(): ignoring " + flags + " after auto-filled"); + Slog.d(TAG, "updateLocked(): ignoring " + flags + " after app was auto-filled"); return; } @@ -841,7 +853,7 @@ final class AutoFillManagerServiceImpl { return; } - Slog.w(TAG, "unknown flags " + flags); + Slog.w(TAG, "updateLocked(): unknown flags " + flags); } @Override @@ -860,8 +872,10 @@ final class AutoFillManagerServiceImpl { } private void processResponseLocked(FillResponse response) { - if (DEBUG) Slog.d(TAG, "processResponseLocked(authRequired=" - + response.getAuthentication() + "):" + response); + if (DEBUG) { + Slog.d(TAG, "processResponseLocked(auth=" + response.getAuthentication() + + "):" + response); + } // TODO(b/33197203): add MetricsLogger calls @@ -945,7 +959,9 @@ final class AutoFillManagerServiceImpl { void autoFillApp(Dataset dataset) { synchronized (mLock) { try { - if (DEBUG) Slog.d(TAG, "autoFillApp(): the buck is on the app: " + dataset); + if (DEBUG) { + Slog.d(TAG, "autoFillApp(): the buck is on the app: " + dataset); + } mClient.autoFill(dataset.getFieldIds(), dataset.getFieldValues()); } catch (RemoteException e) { Slog.w(TAG, "Error auto-filling activity: " + e); @@ -999,7 +1015,9 @@ final class AutoFillManagerServiceImpl { } private void removeSelf() { - if (VERBOSE) Slog.v(TAG, "removeSelf()"); + if (VERBOSE) { + Slog.v(TAG, "removeSelf()"); + } synchronized (mLock) { destroyLocked();