TrustAgents: Improve debug logging

Bug: 30037948
Change-Id: If374c6d4b4fb6e5341986dc42a2f7debb60a4955
diff --git a/services/core/java/com/android/server/trust/TrustAgentWrapper.java b/services/core/java/com/android/server/trust/TrustAgentWrapper.java
index 9c2c6bf..e7c5384 100644
--- a/services/core/java/com/android/server/trust/TrustAgentWrapper.java
+++ b/services/core/java/com/android/server/trust/TrustAgentWrapper.java
@@ -51,7 +51,7 @@
     private static final String EXTRA_COMPONENT_NAME = "componentName";
     private static final String TRUST_EXPIRED_ACTION = "android.server.trust.TRUST_EXPIRED_ACTION";
     private static final String PERMISSION = android.Manifest.permission.PROVIDE_TRUST_AGENT;
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = TrustManagerService.DEBUG;
     private static final String TAG = "TrustAgentWrapper";
 
     private static final int MSG_GRANT_TRUST = 1;
@@ -128,7 +128,7 @@
                             // DevicePolicyManager#KEYGUARD_DISABLE_TRUST_AGENTS.
                             duration = Math.min(durationMs, mMaximumTimeToLock);
                             if (DEBUG) {
-                                Log.v(TAG, "DPM lock timeout in effect. Timeout adjusted from "
+                                Slog.d(TAG, "DPM lock timeout in effect. Timeout adjusted from "
                                     + durationMs + " to " + duration);
                             }
                         } else {
@@ -146,7 +146,7 @@
                     mTrustManagerService.updateTrust(mUserId, flags);
                     break;
                 case MSG_TRUST_TIMEOUT:
-                    if (DEBUG) Slog.v(TAG, "Trust timed out : " + mName.flattenToShortString());
+                    if (DEBUG) Slog.d(TAG, "Trust timed out : " + mName.flattenToShortString());
                     mTrustManagerService.mArchive.logTrustTimeout(mUserId, mName);
                     onTrustTimeout();
                     // Fall through.
@@ -160,6 +160,8 @@
                     mTrustManagerService.updateTrust(mUserId, 0);
                     break;
                 case MSG_RESTART_TIMEOUT:
+                    Slog.w(TAG, "Connection attempt to agent " + mName.flattenToShortString()
+                            + " timed out, rebinding");
                     destroy();
                     mTrustManagerService.resetAgent(mName, mUserId);
                     break;
@@ -169,14 +171,14 @@
                     if (mSetTrustAgentFeaturesToken == token) {
                         mSetTrustAgentFeaturesToken = null;
                         if (mTrustDisabledByDpm && result) {
-                            if (DEBUG) Log.v(TAG, "Re-enabling agent because it acknowledged "
-                                    + "enabled features: " + mName);
+                            if (DEBUG) Slog.d(TAG, "Re-enabling agent because it acknowledged "
+                                    + "enabled features: " + mName.flattenToShortString());
                             mTrustDisabledByDpm = false;
                             mTrustManagerService.updateTrust(mUserId, 0);
                         }
                     } else {
-                        if (DEBUG) Log.w(TAG, "Ignoring MSG_SET_TRUST_AGENT_FEATURES_COMPLETED "
-                                + "with obsolete token: " + mName);
+                        if (DEBUG) Slog.w(TAG, "Ignoring MSG_SET_TRUST_AGENT_FEATURES_COMPLETED "
+                                + "with obsolete token: " + mName.flattenToShortString());
                     }
                     break;
                 case MSG_MANAGING_TRUST:
@@ -196,7 +198,7 @@
 
         @Override
         public void grantTrust(CharSequence userMessage, long durationMs, int flags) {
-            if (DEBUG) Slog.v(TAG, "enableTrust(" + userMessage + ", durationMs = " + durationMs
+            if (DEBUG) Slog.d(TAG, "enableTrust(" + userMessage + ", durationMs = " + durationMs
                         + ", flags = " + flags + ")");
 
             Message msg = mHandler.obtainMessage(
@@ -207,19 +209,19 @@
 
         @Override
         public void revokeTrust() {
-            if (DEBUG) Slog.v(TAG, "revokeTrust()");
+            if (DEBUG) Slog.d(TAG, "revokeTrust()");
             mHandler.sendEmptyMessage(MSG_REVOKE_TRUST);
         }
 
         @Override
         public void setManagingTrust(boolean managingTrust) {
-            if (DEBUG) Slog.v(TAG, "managingTrust()");
+            if (DEBUG) Slog.d(TAG, "managingTrust()");
             mHandler.obtainMessage(MSG_MANAGING_TRUST, managingTrust ? 1 : 0, 0).sendToTarget();
         }
 
         @Override
         public void onConfigureCompleted(boolean result, IBinder token) {
-            if (DEBUG) Slog.v(TAG, "onSetTrustAgentFeaturesEnabledCompleted(result=" + result);
+            if (DEBUG) Slog.d(TAG, "onSetTrustAgentFeaturesEnabledCompleted(result=" + result);
             mHandler.obtainMessage(MSG_SET_TRUST_AGENT_FEATURES_COMPLETED,
                     result ? 1 : 0, 0, token).sendToTarget();
         }
@@ -228,7 +230,7 @@
     private final ServiceConnection mConnection = new ServiceConnection() {
         @Override
         public void onServiceConnected(ComponentName name, IBinder service) {
-            if (DEBUG) Log.v(TAG, "TrustAgent started : " + name.flattenToString());
+            if (DEBUG) Slog.d(TAG, "TrustAgent started : " + name.flattenToString());
             mHandler.removeMessages(MSG_RESTART_TIMEOUT);
             mTrustAgentService = ITrustAgentService.Stub.asInterface(service);
             mTrustManagerService.mArchive.logAgentConnected(mUserId, name);
@@ -249,7 +251,7 @@
 
         @Override
         public void onServiceDisconnected(ComponentName name) {
-            if (DEBUG) Log.v(TAG, "TrustAgent disconnected : " + name.flattenToShortString());
+            if (DEBUG) Slog.d(TAG, "TrustAgent disconnected : " + name.flattenToShortString());
             mTrustAgentService = null;
             mManagingTrust = false;
             mSetTrustAgentFeaturesToken = null;
@@ -352,7 +354,7 @@
 
     boolean updateDevicePolicyFeatures() {
         boolean trustDisabled = false;
-        if (DEBUG) Slog.v(TAG, "updateDevicePolicyFeatures(" + mName + ")");
+        if (DEBUG) Slog.d(TAG, "updateDevicePolicyFeatures(" + mName + ")");
         try {
             if (mTrustAgentService != null) {
                 DevicePolicyManager dpm =
@@ -363,10 +365,10 @@
                     List<PersistableBundle> config = dpm.getTrustAgentConfiguration(
                             null, mName, mUserId);
                     trustDisabled = true;
-                    if (DEBUG) Slog.v(TAG, "Detected trust agents disabled. Config = " + config);
+                    if (DEBUG) Slog.d(TAG, "Detected trust agents disabled. Config = " + config);
                     if (config != null && config.size() > 0) {
                         if (DEBUG) {
-                            Slog.v(TAG, "TrustAgent " + mName.flattenToShortString()
+                            Slog.d(TAG, "TrustAgent " + mName.flattenToShortString()
                                     + " disabled until it acknowledges "+ config);
                         }
                         mSetTrustAgentFeaturesToken = new Binder();
@@ -415,7 +417,7 @@
         if (!mBound) {
             return;
         }
-        if (DEBUG) Log.v(TAG, "TrustAgent unbound : " + mName.flattenToShortString());
+        if (DEBUG) Slog.d(TAG, "TrustAgent unbound : " + mName.flattenToShortString());
         mTrustManagerService.mArchive.logAgentStopped(mUserId, mName);
         mContext.unbindService(mConnection);
         mBound = false;
diff --git a/services/core/java/com/android/server/trust/TrustManagerService.java b/services/core/java/com/android/server/trust/TrustManagerService.java
index 95550aa..e60488a 100644
--- a/services/core/java/com/android/server/trust/TrustManagerService.java
+++ b/services/core/java/com/android/server/trust/TrustManagerService.java
@@ -44,6 +44,7 @@
 import android.content.res.XmlResourceParser;
 import android.graphics.drawable.Drawable;
 import android.os.Binder;
+import android.os.Build;
 import android.os.DeadObjectException;
 import android.os.Handler;
 import android.os.IBinder;
@@ -86,9 +87,8 @@
  * instance of a {@link android.service.trust.TrustAgentService}.
  */
 public class TrustManagerService extends SystemService {
-
-    private static final boolean DEBUG = false;
     private static final String TAG = "TrustManagerService";
+    static final boolean DEBUG = Build.IS_DEBUGGABLE && Log.isLoggable(TAG, Log.VERBOSE);
 
     private static final Intent TRUST_AGENT_INTENT =
             new Intent(TrustAgentService.SERVICE_INTERFACE);
@@ -255,11 +255,33 @@
         for (UserInfo userInfo : userInfos) {
             if (userInfo == null || userInfo.partial || !userInfo.isEnabled()
                     || userInfo.guestToRemove) continue;
-            if (!userInfo.supportsSwitchToByUser()) continue;
-            if (!StorageManager.isUserKeyUnlocked(userInfo.id)) continue;
-            if (!mActivityManager.isUserRunning(userInfo.id)) continue;
-            if (!lockPatternUtils.isSecure(userInfo.id)) continue;
-            if (!mStrongAuthTracker.canAgentsRunForUser(userInfo.id)) continue;
+            if (!userInfo.supportsSwitchToByUser()) {
+                if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping user " + userInfo.id
+                        + ": switchToByUser=false");
+                continue;
+            }
+            if (!StorageManager.isUserKeyUnlocked(userInfo.id)) {
+                if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping user " + userInfo.id
+                        + ": FDE still locked");
+                continue;
+            }
+            if (!mActivityManager.isUserRunning(userInfo.id)) {
+                if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping user " + userInfo.id
+                        + ": user not started");
+                continue;
+            }
+            if (!lockPatternUtils.isSecure(userInfo.id)) {
+                if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping user " + userInfo.id
+                        + ": no secure credential");
+                continue;
+            }
+            if (!mStrongAuthTracker.canAgentsRunForUser(userInfo.id)) {
+                if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping user " + userInfo.id
+                        + ": prevented by StrongAuthTracker = 0x"
+                        + Integer.toHexString(mStrongAuthTracker.getStrongAuthForUser(
+                        userInfo.id)));
+                continue;
+            }
             DevicePolicyManager dpm = lockPatternUtils.getDevicePolicyManager();
             int disabledFeatures = dpm.getKeyguardDisabledFeatures(null, userInfo.id);
             final boolean disableTrustAgents =
@@ -267,18 +289,30 @@
 
             List<ComponentName> enabledAgents = lockPatternUtils.getEnabledTrustAgents(userInfo.id);
             if (enabledAgents == null) {
+                if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping user " + userInfo.id
+                        + ": no agents enabled by user");
                 continue;
             }
             List<ResolveInfo> resolveInfos = resolveAllowedTrustAgents(pm, userInfo.id);
             for (ResolveInfo resolveInfo : resolveInfos) {
                 ComponentName name = getComponentName(resolveInfo);
 
-                if (!enabledAgents.contains(name)) continue;
+                if (!enabledAgents.contains(name)) {
+                    if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping "
+                            + name.flattenToShortString() + " u"+ userInfo.id
+                            + ": not enabled by user");
+                    continue;
+                }
                 if (disableTrustAgents) {
                     List<PersistableBundle> config =
                             dpm.getTrustAgentConfiguration(null /* admin */, name, userInfo.id);
                     // Disable agent if no features are enabled.
-                    if (config == null || config.isEmpty()) continue;
+                    if (config == null || config.isEmpty()) {
+                        if (DEBUG) Slog.d(TAG, "refreshAgentList: skipping "
+                                + name.flattenToShortString() + " u"+ userInfo.id
+                                + ": not allowed by DPM");
+                        continue;
+                    }
                 }
 
                 AgentInfo agentInfo = new AgentInfo();