Adding additional logging. am: 92f07de365

Original change: https://android-review.googlesource.com/c/platform/packages/apps/RemoteProvisioner/+/1913629

Change-Id: I8214899f36f368c2870d9ba22bf2b72c019507f3
diff --git a/src/com/android/remoteprovisioner/PeriodicProvisioner.java b/src/com/android/remoteprovisioner/PeriodicProvisioner.java
index fd5e69c..1c2bc88 100644
--- a/src/com/android/remoteprovisioner/PeriodicProvisioner.java
+++ b/src/com/android/remoteprovisioner/PeriodicProvisioner.java
@@ -91,6 +91,7 @@
                 ConnectivityManager cm = (ConnectivityManager) mContext.getSystemService(
                         Context.CONNECTIVITY_SERVICE);
                 boolean isMetered = cm.isActiveNetworkMetered();
+                Log.i(TAG, "Connection is metered: " + isMetered);
                 long expiringBy;
                 if (isMetered) {
                     // Check a shortened duration to attempt to avoid metered connection
@@ -156,6 +157,7 @@
                     int keysToCertify = keysNeededForSecLevel[i];
                     while (keysToCertify != 0) {
                         int batchSize = min(keysToCertify, SAFE_CSR_BATCH_SIZE);
+                        Log.i(TAG, "Requesting " + batchSize + " keys to be provisioned.");
                         Provisioner.provisionCerts(batchSize,
                                                    implInfos[i].secLevel,
                                                    resp.getGeekChain(implInfos[i].supportedCurve),
@@ -223,7 +225,16 @@
          */
         private int generateNumKeysNeeded(IRemoteProvisioning binder, long expiringBy, int secLevel)
                 throws InterruptedException, RemoteException {
-            AttestationPoolStatus pool = binder.getPoolStatus(expiringBy, secLevel);
+            AttestationPoolStatus pool =
+                    SystemInterface.getPoolStatus(expiringBy, secLevel, binder);
+            if (pool == null) {
+                Log.e(TAG, "Failed to fetch pool status.");
+                return 0;
+            }
+            Log.i(TAG, "Pool status.\nTotal: " + pool.total
+                       + "\nAttested: " + pool.attested
+                       + "\nUnassigned: " + pool.unassigned
+                       + "\nExpiring: " + pool.expiring);
             int unattestedKeys = pool.total - pool.attested;
             int keysInUse = pool.attested - pool.unassigned;
             int totalSignedKeys = keysInUse + SettingsManager.getExtraSignedKeysAvailable(mContext);
@@ -233,12 +244,14 @@
             // reduce network usage if the app just provisions an entire new batch in one go, rather
             // than consistently grabbing just a few at a time as the expiration dates become
             // misaligned.
-            if (pool.expiring > pool.unassigned && pool.attested == totalSignedKeys) {
+            if (pool.expiring < pool.unassigned && pool.attested >= totalSignedKeys) {
+                Log.i(TAG,
+                        "No keys expiring and the expected number of attested keys are available");
                 return 0;
             }
             for (generated = 0;
                     generated + unattestedKeys < totalSignedKeys; generated++) {
-                binder.generateKeyPair(false /* isTestMode */, secLevel);
+                SystemInterface.generateKeyPair(false /* isTestMode */, secLevel, binder);
                 // Prioritize provisioning if there are no keys available. No keys being available
                 // indicates that this is the first time a device is being brought online.
                 if (pool.total != 0) {
@@ -246,8 +259,11 @@
                 }
             }
             if (totalSignedKeys > 0) {
+                Log.i(TAG, "Generated " + generated + " keys. "
+                        + (generated + unattestedKeys) + " keys are now available for signing.");
                 return generated + unattestedKeys;
             }
+            Log.i(TAG, "No keys generated.");
             return 0;
         }
     }
diff --git a/src/com/android/remoteprovisioner/Provisioner.java b/src/com/android/remoteprovisioner/Provisioner.java
index 06a7f4d..e7d591d 100644
--- a/src/com/android/remoteprovisioner/Provisioner.java
+++ b/src/com/android/remoteprovisioner/Provisioner.java
@@ -62,6 +62,7 @@
      */
     public static int provisionCerts(int numKeys, int secLevel, byte[] geekChain, byte[] challenge,
             @NonNull IRemoteProvisioning binder, Context context) {
+        Log.i(TAG, "Request for " + numKeys + " keys to be provisioned.");
         if (numKeys < 1) {
             Log.e(TAG, "Request at least 1 key to be signed. Num requested: " + numKeys);
             return 0;
@@ -91,6 +92,7 @@
             Log.e(TAG, "Server response failed on provisioning attempt.");
             return 0;
         }
+        Log.i(TAG, "Received " + certChains.size() + " certificate chains from the server.");
         int provisioned = 0;
         for (byte[] certChain : certChains) {
             // DER encoding specifies leaf to root ordering. Pull the public key and expiration
@@ -119,6 +121,8 @@
                 return provisioned;
             }
         }
+        Log.i(TAG, "In provisionCerts: Requested " + numKeys + " keys. "
+                   + provisioned + " were provisioned.");
         return provisioned;
     }
 }
diff --git a/src/com/android/remoteprovisioner/SystemInterface.java b/src/com/android/remoteprovisioner/SystemInterface.java
index 67ab028..d04beec 100644
--- a/src/com/android/remoteprovisioner/SystemInterface.java
+++ b/src/com/android/remoteprovisioner/SystemInterface.java
@@ -20,6 +20,8 @@
 import android.hardware.security.keymint.DeviceInfo;
 import android.hardware.security.keymint.ProtectedData;
 import android.os.RemoteException;
+import android.os.ServiceSpecificException;
+import android.security.remoteprovisioning.AttestationPoolStatus;
 import android.security.remoteprovisioning.IRemoteProvisioning;
 import android.util.Log;
 
@@ -42,7 +44,7 @@
  */
 public class SystemInterface {
 
-    private static final String TAG = "SystemInterface";
+    private static final String TAG = "RemoteProvisioner";
 
     private static byte[] makeProtectedHeaders() throws CborException {
         ByteArrayOutputStream baos = new ByteArrayOutputStream();
@@ -72,6 +74,7 @@
             byte[] geekChain, byte[] challenge, ProtectedData protectedData, DeviceInfo deviceInfo,
             @NonNull IRemoteProvisioning binder) {
         try {
+            Log.i(TAG, "Packaging " + numKeys + " keys into a CSR. Test: " + testMode);
             ProtectedData dataBundle = new ProtectedData();
             byte[] macedPublicKeys = binder.generateCsr(testMode,
                                                         numKeys,
@@ -101,6 +104,9 @@
         } catch (RemoteException e) {
             Log.e(TAG, "Failed to generate CSR blob", e);
             return null;
+        } catch (ServiceSpecificException e) {
+            Log.e(TAG, "Failure in Keystore or Keymint to facilitate blob generation.", e);
+            return null;
         } catch (CborException e) {
             Log.e(TAG, "Failed to parse/build CBOR", e);
             return null;
@@ -122,6 +128,41 @@
             Log.e(TAG, "Error on the binder side when attempting to provision the signed chain",
                     e);
             return false;
+        } catch (ServiceSpecificException e) {
+            Log.e(TAG, "Error on the Keystore side", e);
+            return false;
+        }
+    }
+
+    /**
+     * Returns the pool status for a given {@code secLevel}, with the expiration date configured to
+     * the value passed in as {@code expiringBy}.
+     */
+    public static AttestationPoolStatus getPoolStatus(long expiringBy,
+                                                      int secLevel,
+                                                      IRemoteProvisioning binder)
+            throws RemoteException {
+        try {
+            return binder.getPoolStatus(expiringBy, secLevel);
+        } catch (ServiceSpecificException e) {
+            Log.e(TAG, "Failure in Keystore", e);
+            throw new RemoteException(e);
+        }
+    }
+
+    /**
+     * Generates an attestation key pair.
+     *
+     * @param isTestMode Whether or not to generate a test key, which would accept any EEK later.
+     * @param secLevel Which security level to generate the key for.
+     */
+    public static void generateKeyPair(boolean isTestMode, int secLevel, IRemoteProvisioning binder)
+            throws RemoteException {
+        try {
+            binder.generateKeyPair(isTestMode, secLevel);
+        } catch (ServiceSpecificException e) {
+            Log.e(TAG, "Failure in Keystore or KeyMint.", e);
+            throw new RemoteException(e);
         }
     }
 }
diff --git a/src/com/android/remoteprovisioner/service/GenerateRkpKeyService.java b/src/com/android/remoteprovisioner/service/GenerateRkpKeyService.java
index 73c83b1..ab2ec8d 100644
--- a/src/com/android/remoteprovisioner/service/GenerateRkpKeyService.java
+++ b/src/com/android/remoteprovisioner/service/GenerateRkpKeyService.java
@@ -55,6 +55,7 @@
         @Override
         public void generateKey(int securityLevel) {
             try {
+                Log.i(TAG, "generateKey ping for secLevel: " + securityLevel);
                 IRemoteProvisioning binder =
                         IRemoteProvisioning.Stub.asInterface(ServiceManager.getService(SERVICE));
                 checkAndFillPool(binder, securityLevel);
@@ -66,6 +67,7 @@
         @Override
         public void notifyKeyGenerated(int securityLevel) {
             try {
+                Log.i(TAG, "Notify key generated ping for secLevel: " + securityLevel);
                 IRemoteProvisioning binder =
                         IRemoteProvisioning.Stub.asInterface(ServiceManager.getService(SERVICE));
                 checkAndFillPool(binder, securityLevel);