import-log: add log statements in import routine

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/pgp/OperationResultParcel.java

@@ -88,9 +88,43 @@ public class OperationResultParcel implements Parcelable {
     }
 
     public static enum LogType {
-        // TODO add actual log entry types here
+        MSG_IP_APPLY_BATCH (R.string.msg_ip_apply_batch),
-        MSG_IMPORT_OK (R.string.copy),
+        MSG_IP_BAD_TYPE_SECRET (R.string.msg_ip_bad_type_secret),
-        MSG_IMPORT_FAILED (R.string.cancel);
+        MSG_IP_DELETE_OLD_FAIL (R.string.msg_ip_delete_old_fail),
+        MSG_IP_DELETE_OLD_OK (R.string.msg_ip_delete_old_ok),
+        MSG_IP_ENCODE_FAIL (R.string.msg_ip_encode_fail),
+        MSG_IP_FAIL_IO_EXC (R.string.msg_ip_fail_io_exc),
+        MSG_IP_FAIL_OP_EX (R.string.msg_ip_fail_op_ex),
+        MSG_IP_FAIL_REMOTE_EX (R.string.msg_ip_fail_remote_ex),
+        MSG_IP_IMPORTING (R.string.msg_ip_importing),
+        MSG_IP_INSERT_KEYRING (R.string.msg_ip_insert_keyring),
+        MSG_IP_INSERT_SUBKEY (R.string.msg_ip_insert_subkey),
+        MSG_IP_INSERT_SUBKEYS (R.string.msg_ip_insert_subkeys),
+        MSG_IP_PRESERVING_SECRET (R.string.msg_ip_preserving_secret),
+        MSG_IP_REINSERT_SECRET (R.string.msg_ip_reinsert_secret),
+        MSG_IP_SUCCESS (R.string.msg_ip_success),
+        MSG_IP_TRUST_RETRIEVE (R.string.msg_ip_trust_retrieve),
+        MSG_IP_TRUST_USING (R.string.msg_ip_trust_using),
+        MSG_IP_TRUST_USING_SEC (R.string.msg_ip_trust_using_sec),
+        MSG_IP_UID_CERT_BAD (R.string.msg_ip_uid_cert_bad),
+        MSG_IP_UID_CERT_ERROR (R.string.msg_ip_uid_cert_error),
+        MSG_IP_UID_CERT_GOOD (R.string.msg_ip_uid_cert_good),
+        MSG_IP_UID_CERTS_UNKNOWN (R.string.msg_ip_uid_certs_unknown),
+        MSG_IP_UID_CLASSIFYING (R.string.msg_ip_uid_classifying),
+        MSG_IP_UID_INSERT (R.string.msg_ip_uid_insert),
+        MSG_IP_UID_PROCESSING (R.string.msg_ip_uid_processing),
+        MSG_IP_UID_SELF_BAD (R.string.msg_ip_uid_self_bad),
+        MSG_IP_UID_SELF_GOOD (R.string.msg_ip_uid_self_good),
+        MSG_IP_UID_SELF_IGNORING_OLD (R.string.msg_ip_uid_self_ignoring_old),
+        MSG_IP_UID_SELF_NEWER (R.string.msg_ip_uid_self_newer),
+        MSG_IS_BAD_TYPE_PUBLIC (R.string.msg_is_bad_type_public),
+        MSG_IS_IMPORTING (R.string.msg_is_importing),
+        MSG_IS_IMPORTING_SUBKEYS (R.string.msg_is_importing_subkeys),
+        MSG_IS_IO_EXCPTION (R.string.msg_is_io_excption),
+        MSG_IS_SUBKEY_NONEXISTENT (R.string.msg_is_subkey_nonexistent),
+        MSG_IS_SUBKEY_OK (R.string.msg_is_subkey_ok),
+        MSG_IS_SUCCESS (R.string.msg_is_success),
+        ;
 
         private int mMsgId;
         LogType(int msgId) {

OpenKeychain/src/main/java/org/sufficientlysecure/keychain/provider/ProviderHelper.java

@@ -241,64 +241,97 @@ public class ProviderHelper {
      * Saves PGPPublicKeyRing with its keys and userIds in DB
      */
     @SuppressWarnings("unchecked")
-    public void savePublicKeyRing(UncachedKeyRing keyRing) throws IOException {
+    public OperationResultParcel savePublicKeyRing(UncachedKeyRing keyRing) {
         if (keyRing.isSecret()) {
-            throw new RuntimeException("Tried to save secret keyring as public! " +
+            log(LogLevel.ERROR, LogType.MSG_IP_BAD_TYPE_SECRET);
-                    "This is a bug, please file a bug report.");
+            return new OperationResultParcel(1, mLog);
         }
 
         UncachedPublicKey masterKey = keyRing.getPublicKey();
         long masterKeyId = masterKey.getKeyId();
+        log(LogLevel.INFO, LogType.MSG_IP_IMPORTING,
+                new String[]{Long.toString(masterKeyId)});
 
         // IF there is a secret key, preserve it!
-        UncachedKeyRing secretRing = null;
+        UncachedKeyRing secretRing;
         try {
             secretRing = getWrappedSecretKeyRing(masterKeyId).getUncached();
+            log(LogLevel.DEBUG, LogType.MSG_IP_PRESERVING_SECRET);
         } catch (NotFoundException e) {
-            Log.e(Constants.TAG, "key not found!");
+            secretRing = null;
         }
 
         // delete old version of this keyRing, which also deletes all keys and userIds on cascade
         try {
             mContentResolver.delete(KeyRingData.buildPublicKeyRingUri(Long.toString(masterKeyId)), null, null);
+            log(LogLevel.DEBUG, LogType.MSG_IP_DELETE_OLD_OK);
         } catch (UnsupportedOperationException e) {
             Log.e(Constants.TAG, "Key could not be deleted! Maybe we are creating a new one!", e);
+            log(LogLevel.DEBUG, LogType.MSG_IP_DELETE_OLD_FAIL);
         }
 
         // insert new version of this keyRing
         ContentValues values = new ContentValues();
         values.put(KeyRingData.MASTER_KEY_ID, masterKeyId);
+        try {
             values.put(KeyRingData.KEY_RING_DATA, keyRing.getEncoded());
-        Uri uri = KeyRingData.buildPublicKeyRingUri(Long.toString(masterKeyId));
+        } catch (IOException e) {
-        mContentResolver.insert(uri, values);
+            log(LogLevel.ERROR, LogType.MSG_IP_ENCODE_FAIL);
+            return new OperationResultParcel(1, mLog);
+        }
 
         // save all keys and userIds included in keyRing object in database
         ArrayList<ContentProviderOperation> operations = new ArrayList<ContentProviderOperation>();
 
+        try {
+
+            log(LogLevel.INFO, LogType.MSG_IP_INSERT_KEYRING);
+            Uri uri = KeyRingData.buildPublicKeyRingUri(Long.toString(masterKeyId));
+            operations.add(ContentProviderOperation.newInsert(uri).withValues(values).build());
+
+            log(LogLevel.INFO, LogType.MSG_IP_INSERT_SUBKEYS);
+            mIndent += 1;
             int rank = 0;
             for (UncachedPublicKey key : new IterableIterator<UncachedPublicKey>(keyRing.getPublicKeys())) {
+                log(LogLevel.DEBUG, LogType.MSG_IP_INSERT_SUBKEY, new String[] {
+                    PgpKeyHelper.convertKeyIdToHex(masterKeyId)
+                });
                 operations.add(buildPublicKeyOperations(masterKeyId, key, rank));
                 ++rank;
             }
+            mIndent -= 1;
 
+            log(LogLevel.DEBUG, LogType.MSG_IP_TRUST_RETRIEVE);
             // get a list of owned secret keys, for verification filtering
-        LongSparseArray<UncachedPublicKey> allKeyRings =
+            LongSparseArray<UncachedPublicKey> trustedKeys =
                     getUncachedMasterKeys(KeyRingData.buildSecretKeyRingUri());
             // special case: available secret keys verify themselves!
             if (secretRing != null) {
-            allKeyRings.put(secretRing.getMasterKeyId(), secretRing.getPublicKey());
+                trustedKeys.put(secretRing.getMasterKeyId(), secretRing.getPublicKey());
+                log(LogLevel.INFO, LogType.MSG_IP_TRUST_USING_SEC, new String[]{
+                        Integer.toString(trustedKeys.size())
+                });
+            } else {
+                log(LogLevel.INFO, LogType.MSG_IP_TRUST_USING, new String[] {
+                    Integer.toString(trustedKeys.size())
+                });
             }
 
             // classify and order user ids. primary are moved to the front, revoked to the back,
             // otherwise the order in the keyfile is preserved.
+            log(LogLevel.DEBUG, LogType.MSG_IP_UID_CLASSIFYING);
+            mIndent += 1;
             List<UserIdItem> uids = new ArrayList<UserIdItem>();
-
             for (String userId : new IterableIterator<String>(
                     masterKey.getUnorderedUserIds().iterator())) {
                 UserIdItem item = new UserIdItem();
                 uids.add(item);
                 item.userId = userId;
 
+                int unknownCerts = 0;
+
+                log(LogLevel.INFO, LogType.MSG_IP_UID_PROCESSING, new String[] { userId });
+                mIndent += 1;
                 // look through signatures for this specific key
                 for (WrappedSignature cert : new IterableIterator<WrappedSignature>(
                         masterKey.getSignaturesForId(userId))) {
@@ -308,34 +341,65 @@ public class ProviderHelper {
                         if (certId == masterKeyId) {
                             cert.init(masterKey);
                             if (!cert.verifySignature(masterKey, userId)) {
-                            // not verified?! dang! TODO notify user? this is kinda serious...
+                                // Bad self certification? That's kinda bad...
-                            Log.e(Constants.TAG, "Could not verify self signature for " + userId + "!");
+                                log(LogLevel.ERROR, LogType.MSG_IP_UID_SELF_BAD);
+                                return new OperationResultParcel(1, mLog);
+                            }
+
+                            // if we already have a cert..
+                            if (item.selfCert != null) {
+                                // ..is this perchance a more recent one?
+                                if (item.selfCert.getCreationTime().before(cert.getCreationTime())) {
+                                    log(LogLevel.DEBUG, LogType.MSG_IP_UID_SELF_NEWER);
+                                } else {
+                                    log(LogLevel.DEBUG, LogType.MSG_IP_UID_SELF_IGNORING_OLD);
                                     continue;
                                 }
-                        // is this the first, or a more recent certificate?
+                            } else {
-                        if (item.selfCert == null ||
+                                log(LogLevel.DEBUG, LogType.MSG_IP_UID_SELF_GOOD);
-                                item.selfCert.getCreationTime().before(cert.getCreationTime())) {
+                            }
+
+                            // save certificate as primary self-cert
                             item.selfCert = cert;
                             item.isPrimary = cert.isPrimaryUserId();
                             item.isRevoked = cert.isRevocation();
+
                         }
-                    }
+
                         // verify signatures from known private keys
-                    if (allKeyRings.indexOfKey(certId) >= 0) {
+                        if (trustedKeys.indexOfKey(certId) >= 0) {
-                        cert.init(allKeyRings.get(certId));
+                            UncachedPublicKey trustedKey = trustedKeys.get(certId);
+                            cert.init(trustedKey);
                             if (cert.verifySignature(masterKey, userId)) {
                                 item.trustedCerts.add(cert);
-                        }
+                                log(LogLevel.INFO, LogType.MSG_IP_UID_CERT_GOOD, new String[] {
-                    }
+                                    PgpKeyHelper.convertKeyIdToHex(trustedKey.getKeyId())
-                } catch (PgpGeneralException e) {
+                                });
-                    Log.e(Constants.TAG, "Signature verification failed! "
+                            } else {
-                            + PgpKeyHelper.convertKeyIdToHex(masterKey.getKeyId())
+                                log(LogLevel.WARN, LogType.MSG_IP_UID_CERT_BAD);
-                            + " from "
-                            + PgpKeyHelper.convertKeyIdToHex(cert.getKeyId()), e);
-                }
                             }
                         }
 
+                        unknownCerts += 1;
+
+                    } catch (PgpGeneralException e) {
+                        log(LogLevel.WARN, LogType.MSG_IP_UID_CERT_ERROR, new String[]{
+                                PgpKeyHelper.convertKeyIdToHex(cert.getKeyId())
+                        });
+                    }
+                }
+                mIndent -= 1;
+
+                if (unknownCerts > 0) {
+                    log(LogLevel.DEBUG, LogType.MSG_IP_UID_CERTS_UNKNOWN, new String[] {
+                            Integer.toString(unknownCerts)
+                    });
+                }
+
+            }
+            mIndent -= 1;
+
+            log(LogLevel.INFO, LogType.MSG_IP_UID_INSERT);
             // primary before regular before revoked (see UserIdItem.compareTo)
             // this is a stable sort, so the order of keys is otherwise preserved.
             Collections.sort(uids);
@@ -358,19 +422,27 @@ public class ProviderHelper {
                 }
             }
 
-        try {
+            log(LogLevel.DEBUG, LogType.MSG_IP_APPLY_BATCH);
             mContentResolver.applyBatch(KeychainContract.CONTENT_AUTHORITY, operations);
+        } catch (IOException e) {
+            log(LogLevel.ERROR, LogType.MSG_IP_FAIL_IO_EXC);
         } catch (RemoteException e) {
-            Log.e(Constants.TAG, "applyBatch failed!", e);
+            log(LogLevel.ERROR, LogType.MSG_IP_FAIL_REMOTE_EX);
         } catch (OperationApplicationException e) {
-            Log.e(Constants.TAG, "applyBatch failed!", e);
+            log(LogLevel.ERROR, LogType.MSG_IP_FAIL_OP_EX);
         }
 
         // Save the saved keyring (if any)
         if (secretRing != null) {
+            log(LogLevel.DEBUG, LogType.MSG_IP_REINSERT_SECRET);
+            mIndent += 1;
             saveSecretKeyRing(secretRing);
+            mIndent -= 1;
         }
 
+        log(LogLevel.INFO, LogType.MSG_IP_SUCCESS);
+        return new OperationResultParcel(0, mLog);
+
     }
 
     private static class UserIdItem implements Comparable<UserIdItem> {
@@ -398,13 +470,29 @@ public class ProviderHelper {
      * Saves a PGPSecretKeyRing in the DB. This will only work if a corresponding public keyring
      * is already in the database!
      */
-    public void saveSecretKeyRing(UncachedKeyRing keyRing) throws IOException {
+    public OperationResultParcel saveSecretKeyRing(UncachedKeyRing keyRing) {
         if (!keyRing.isSecret()) {
-            throw new RuntimeException("Tried to save publkc keyring as secret! " +
+            log(LogLevel.ERROR, LogType.MSG_IS_BAD_TYPE_PUBLIC);
-                    "This is a bug, please file a bug report.");
+            return new OperationResultParcel(1, mLog);
         }
 
         long masterKeyId = keyRing.getMasterKeyId();
+        log(LogLevel.INFO, LogType.MSG_IS_IMPORTING,
+                new String[]{ Long.toString(masterKeyId) });
+
+        // save secret keyring
+        try {
+            ContentValues values = new ContentValues();
+            values.put(KeyRingData.MASTER_KEY_ID, masterKeyId);
+            values.put(KeyRingData.KEY_RING_DATA, keyRing.getEncoded());
+            // insert new version of this keyRing
+            Uri uri = KeyRingData.buildSecretKeyRingUri(Long.toString(masterKeyId));
+            mContentResolver.insert(uri, values);
+        } catch (IOException e) {
+            Log.e(Constants.TAG, "Failed to encode key!", e);
+            log(LogLevel.ERROR, LogType.MSG_IS_IO_EXCPTION);
+            return new OperationResultParcel(1, mLog);
+        }
 
         {
             Uri uri = Keys.buildKeysUri(Long.toString(masterKeyId));
@@ -416,24 +504,30 @@ public class ProviderHelper {
 
             values.put(Keys.HAS_SECRET, 1);
             // then, mark exactly the keys we have available
+            log(LogLevel.INFO, LogType.MSG_IS_IMPORTING_SUBKEYS);
+            mIndent += 1;
             for (Long sub : new IterableIterator<Long>(keyRing.getAvailableSubkeys().iterator())) {
-                mContentResolver.update(uri, values, Keys.KEY_ID + " = ?", new String[] {
+                int upd = mContentResolver.update(uri, values, Keys.KEY_ID + " = ?", new String[] {
                     Long.toString(sub)
                 });
+                if(upd == 0) {
+                    log(LogLevel.DEBUG, LogType.MSG_IS_SUBKEY_OK, new String[] {
+                            PgpKeyHelper.convertKeyIdToHex(sub)
+                    });
+                } else {
+                    log(LogLevel.WARN, LogType.MSG_IS_SUBKEY_NONEXISTENT, new String[] {
+                        PgpKeyHelper.convertKeyIdToHex(sub)
+                    });
                 }
+            }
+            mIndent -= 1;
+
             // this implicitly leaves all keys which were not in the secret key ring
             // with has_secret = 0
         }
 
-        // save secret keyring
+        log(LogLevel.INFO, LogType.MSG_IS_SUCCESS);
-        {
+        return new OperationResultParcel(0, mLog);
-            ContentValues values = new ContentValues();
-            values.put(KeyRingData.MASTER_KEY_ID, masterKeyId);
-            values.put(KeyRingData.KEY_RING_DATA, keyRing.getEncoded());
-            // insert new version of this keyRing
-            Uri uri = KeyRingData.buildSecretKeyRingUri(Long.toString(masterKeyId));
-            mContentResolver.insert(uri, values);
-        }
 
     }