consolidate: a lot more log output, better recovery

4 files changed, 108 insertions, 35 deletions

diff --git a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/helper/Preferences.java b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/helper/Preferences.java
index 9a10148f2..5190a550e 100644
--- a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/helper/Preferences.java
+++ b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/helper/Preferences.java
@@ -146,7 +146,7 @@ public class Preferences {
     }
 
     public int getCachedConsolidateNumPublics() {
-        return mSharedPreferences.getInt(Pref.CACHED_CONSOLIDATE_PUBLICS, 100);
+        return mSharedPreferences.getInt(Pref.CACHED_CONSOLIDATE_PUBLICS, -1);
     }
 
     public void setCachedConsolidateNumPublics(int value) {
@@ -156,7 +156,7 @@ public class Preferences {
     }
 
     public int getCachedConsolidateNumSecrets() {
-        return mSharedPreferences.getInt(Pref.CACHED_CONSOLIDATE_SECRETS, 100);
+        return mSharedPreferences.getInt(Pref.CACHED_CONSOLIDATE_SECRETS, -1);
     }
 
     public void setCachedConsolidateNumSecrets(int value) {
diff --git a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/provider/ProviderHelper.java b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/provider/ProviderHelper.java
index 5f55eedd5..4f8b50a94 100644
--- a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/provider/ProviderHelper.java
+++ b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/provider/ProviderHelper.java
@@ -829,12 +829,12 @@ public class ProviderHelper {
     public ConsolidateResult consolidateDatabaseStep1(Progressable progress) {
 
         // 1a. fetch all secret keyrings into a cache file
-        log(LogLevel.START, LogType.MSG_CON, mIndent);
+        log(LogLevel.START, LogType.MSG_CON);
         mIndent += 1;
 
         try {
 
-            log(LogLevel.DEBUG, LogType.MSG_CON_SAVE_SECRET, mIndent);
+            log(LogLevel.DEBUG, LogType.MSG_CON_SAVE_SECRET);
             mIndent += 1;
 
             final Cursor cursor = mContentResolver.query(KeyRings.buildUnifiedKeyRingsUri(), new String[]{
@@ -842,6 +842,7 @@ public class ProviderHelper {
             }, KeyRings.HAS_ANY_SECRET + " = 1", null, null);
 
             if (cursor == null || !cursor.moveToFirst()) {
+                log(LogLevel.ERROR, LogType.MSG_CON_ERROR_DB);
                 return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
             }
 
@@ -883,7 +884,8 @@ public class ProviderHelper {
             });
 
         } catch (IOException e) {
-            Log.e(Constants.TAG, "error saving secret");
+            Log.e(Constants.TAG, "error saving secret", e);
+            log(LogLevel.ERROR, LogType.MSG_CON_ERROR_IO_SECRET);
             return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
         } finally {
             mIndent -= 1;
@@ -892,7 +894,7 @@ public class ProviderHelper {
         // 1b. fetch all public keyrings into a cache file
         try {
 
-            log(LogLevel.DEBUG, LogType.MSG_CON_SAVE_PUBLIC, mIndent);
+            log(LogLevel.DEBUG, LogType.MSG_CON_SAVE_PUBLIC);
             mIndent += 1;
 
             final Cursor cursor = mContentResolver.query(KeyRings.buildUnifiedKeyRingsUri(), new String[]{
@@ -900,10 +902,11 @@ public class ProviderHelper {
             }, null, null, null);
 
             if (cursor == null || !cursor.moveToFirst()) {
+                log(LogLevel.ERROR, LogType.MSG_CON_ERROR_DB);
                 return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
             }
 
-            Preferences.getPreferences(mContext).setCachedConsolidateNumSecrets(cursor.getCount());
+            Preferences.getPreferences(mContext).setCachedConsolidateNumPublics(cursor.getCount());
 
             FileImportCache<ParcelableKeyRing> cache =
                     new FileImportCache<ParcelableKeyRing>(mContext, "consolidate_public.pcl");
@@ -941,31 +944,48 @@ public class ProviderHelper {
             });
 
         } catch (IOException e) {
-            Log.e(Constants.TAG, "error saving public");
+            Log.e(Constants.TAG, "error saving public", e);
+            log(LogLevel.ERROR, LogType.MSG_CON_ERROR_IO_PUBLIC);
             return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
         } finally {
             mIndent -= 1;
         }
 
+        log(LogLevel.INFO, LogType.MSG_CON_CRITICAL_IN);
         Preferences.getPreferences(mContext).setCachedConsolidate(true);
 
-        return consolidateDatabaseStep2(progress);
+        return consolidateDatabaseStep2(progress, false);
     }
 
     public ConsolidateResult consolidateDatabaseStep2(Progressable progress) {
+        return consolidateDatabaseStep2(progress, true);
+    }
+
+    private ConsolidateResult consolidateDatabaseStep2(Progressable progress, boolean recovery) {
+
 
         Preferences prefs = Preferences.getPreferences(mContext);
-        if ( ! prefs.getCachedConsolidate()) {
-            log(LogLevel.ERROR, LogType.MSG_CON_ERROR_BAD_STATE);
-            return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
-        }
 
         // Set flag that we have a cached consolidation here
         int numSecrets = prefs.getCachedConsolidateNumSecrets();
         int numPublics = prefs.getCachedConsolidateNumPublics();
 
+        if (recovery) {
+            if (numSecrets >= 0 && numPublics >= 0) {
+                log(LogLevel.START, LogType.MSG_CON_RECOVER, numSecrets, Integer.toString(numPublics));
+            } else {
+                log(LogLevel.START, LogType.MSG_CON_RECOVER_UNKNOWN);
+            }
+            mIndent += 1;
+        }
+
+        if ( ! prefs.getCachedConsolidate()) {
+            log(LogLevel.ERROR, LogType.MSG_CON_ERROR_BAD_STATE);
+            return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
+        }
+
         // 2. wipe database (IT'S DANGEROUS)
-        log(LogLevel.DEBUG, LogType.MSG_CON_DB_CLEAR, mIndent);
+        log(LogLevel.DEBUG, LogType.MSG_CON_DB_CLEAR);
         new KeychainDatabase(mContext).clearDatabase();
 
         FileImportCache<ParcelableKeyRing> cacheSecret =
@@ -974,51 +994,71 @@ public class ProviderHelper {
                 new FileImportCache<ParcelableKeyRing>(mContext, "consolidate_public.pcl");
 
         // 3. Re-Import secret keyrings from cache
-        try {
-            log(LogLevel.DEBUG, LogType.MSG_CON_REIMPORT_SECRET, mIndent, numSecrets);
+        if (numSecrets > 0) try {
+            log(LogLevel.DEBUG, LogType.MSG_CON_REIMPORT_SECRET, numSecrets);
             mIndent += 1;
 
-            new PgpImportExport(mContext, this, new ProgressFixedScaler(progress, 10, 25, 100, R.string.progress_con_reimport))
+            new PgpImportExport(mContext, this,
+                new ProgressFixedScaler(progress, 10, 25, 100, R.string.progress_con_reimport))
                     .importKeyRings(cacheSecret.readCache(false), numSecrets);
         } catch (IOException e) {
-            Log.e(Constants.TAG, "error importing secret");
+            Log.e(Constants.TAG, "error importing secret", e);
+            log(LogLevel.ERROR, LogType.MSG_CON_ERROR_SECRET);
             return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
         } finally {
             mIndent -= 1;
+        } else {
+            log(LogLevel.DEBUG, LogType.MSG_CON_REIMPORT_SECRET_SKIP);
         }
 
         // 4. Re-Import public keyrings from cache
-        try {
-            log(LogLevel.DEBUG, LogType.MSG_CON_REIMPORT_PUBLIC, mIndent, numPublics);
+        if (numPublics > 0) try {
+            log(LogLevel.DEBUG, LogType.MSG_CON_REIMPORT_PUBLIC, numPublics);
             mIndent += 1;
 
-            new PgpImportExport(mContext, this, new ProgressScaler(progress, 25, 99, 100))
+            new PgpImportExport(mContext, this,
+                new ProgressFixedScaler(progress, 25, 99, 100, R.string.progress_con_reimport))
                     .importKeyRings(cachePublic.readCache(false), numPublics);
         } catch (IOException e) {
-            Log.e(Constants.TAG, "error importing public");
+            Log.e(Constants.TAG, "error importing public", e);
+            log(LogLevel.ERROR, LogType.MSG_CON_ERROR_PUBLIC);
             return new ConsolidateResult(ConsolidateResult.RESULT_ERROR, mLog);
         } finally {
             mIndent -= 1;
+        } else {
+            log(LogLevel.DEBUG, LogType.MSG_CON_REIMPORT_PUBLIC_SKIP);
         }
 
+        log(LogLevel.INFO, LogType.MSG_CON_CRITICAL_OUT);
         Preferences.getPreferences(mContext).setCachedConsolidate(false);
 
         // 5. Delete caches
         try {
+            log(LogLevel.DEBUG, LogType.MSG_CON_DELETE_SECRET);
+            mIndent += 1;
             cacheSecret.delete();
         } catch (IOException e) {
-            // doesn't really matter
+            // doesn't /really/ matter
             Log.e(Constants.TAG, "IOException during delete of secret cache", e);
+            log(LogLevel.WARN, LogType.MSG_CON_WARN_DELETE_SECRET);
+        } finally {
+            mIndent -= 1;
         }
+
         try {
+            log(LogLevel.DEBUG, LogType.MSG_CON_DELETE_PUBLIC);
+            mIndent += 1;
             cachePublic.delete();
         } catch (IOException e) {
-            // doesn't really matter
+            // doesn't /really/ matter
             Log.e(Constants.TAG, "IOException during deletion of public cache", e);
+            log(LogLevel.WARN, LogType.MSG_CON_WARN_DELETE_PUBLIC);
+        } finally {
+            mIndent -= 1;
         }
 
         progress.setProgress(100, 100);
-        log(LogLevel.OK, LogType.MSG_CON_SUCCESS, mIndent);
+        log(LogLevel.OK, LogType.MSG_CON_SUCCESS);
         mIndent -= 1;
 
         return new ConsolidateResult(ConsolidateResult.RESULT_OK, mLog);
diff --git a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/OperationResultParcel.java b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/OperationResultParcel.java
index 3f478cfed..cf9f69033 100644
--- a/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/OperationResultParcel.java
+++ b/OpenKeychain/src/main/java/org/sufficientlysecure/keychain/service/OperationResultParcel.java
@@ -390,14 +390,29 @@ public class OperationResultParcel implements Parcelable {
         MSG_MF_UNLOCK (R.string.msg_mf_unlock),
 
         // consolidate
-        MSG_CON (R.string.msg_con),
+        MSG_CON_CRITICAL_IN (R.string.msg_con_critical_in),
+        MSG_CON_CRITICAL_OUT (R.string.msg_con_critical_out),
+        MSG_CON_DB_CLEAR (R.string.msg_con_db_clear),
+        MSG_CON_DELETE_PUBLIC (R.string.msg_con_delete_public),
+        MSG_CON_DELETE_SECRET (R.string.msg_con_delete_secret),
         MSG_CON_ERROR_BAD_STATE (R.string.msg_con_error_bad_state),
-        MSG_CON_SAVE_SECRET (R.string.msg_con_save_secret),
+        MSG_CON_ERROR_DB (R.string.msg_con_error_db),
+        MSG_CON_ERROR_IO_PUBLIC (R.string.msg_con_error_io_public),
+        MSG_CON_ERROR_IO_SECRET (R.string.msg_con_error_io_secret),
+        MSG_CON_ERROR_PUBLIC (R.string.msg_con_error_public),
+        MSG_CON_ERROR_SECRET (R.string.msg_con_error_secret),
+        MSG_CON_RECOVER (R.plurals.msg_con_recover),
+        MSG_CON_RECOVER_UNKNOWN (R.string.msg_con_recover_unknown),
+        MSG_CON_REIMPORT_PUBLIC (R.string.msg_con_reimport_public),
+        MSG_CON_REIMPORT_PUBLIC_SKIP (R.string.msg_con_reimport_public_skip),
+        MSG_CON_REIMPORT_SECRET (R.string.msg_con_reimport_secret),
+        MSG_CON_REIMPORT_SECRET_SKIP (R.string.msg_con_reimport_secret_skip),
+        MSG_CON (R.string.msg_con),
         MSG_CON_SAVE_PUBLIC (R.string.msg_con_save_public),
-        MSG_CON_DB_CLEAR (R.string.msg_con_db_clear),
-        MSG_CON_REIMPORT_SECRET (R.plurals.msg_con_reimport_secret),
-        MSG_CON_REIMPORT_PUBLIC (R.plurals.msg_con_reimport_public),
+        MSG_CON_SAVE_SECRET (R.string.msg_con_save_secret),
         MSG_CON_SUCCESS (R.string.msg_con_success),
+        MSG_CON_WARN_DELETE_PUBLIC (R.string.msg_con_warn_delete_public),
+        MSG_CON_WARN_DELETE_SECRET (R.string.msg_con_warn_delete_secret),
         ;
 
         private final int mMsgId;
diff --git a/OpenKeychain/src/main/res/values/strings.xml b/OpenKeychain/src/main/res/values/strings.xml
index e506bf488..c00449f8e 100644
--- a/OpenKeychain/src/main/res/values/strings.xml
+++ b/OpenKeychain/src/main/res/values/strings.xml
@@ -677,15 +677,33 @@
     <string name="msg_con_save_secret">Saving secret keyrings</string>
     <string name="msg_con_save_public">Saving public keyrings</string>
     <string name="msg_con_db_clear">Clearing database</string>
-    <plurals name="msg_con_reimport_secret">
-        <item quantity="one">Reimporting one secret key</item>
-        <item quantity="other">Reimporting %d secret keys</item>
+    <string name="msg_con_success">Successfully consolidated database</string>
+    <string name="msg_con_critical_in">Entering critical phase</string>
+    <string name="msg_con_critical_out">Leaving critical phase</string>
+    <string name="msg_con_delete_public">Deleting public keyring cache file</string>
+    <string name="msg_con_delete_secret">Deleting secret keyring cache file</string>
+    <string name="msg_con_error_db">Error opening database!</string>
+    <string name="msg_con_error_io_public">IO error writing public keys to cache!</string>
+    <string name="msg_con_error_io_secret">IO error writing secret keys to cache!</string>
+    <string name="msg_con_error_public">Error reimporting public keys!</string>
+    <string name="msg_con_error_secret">Error reimporting secret keys!</string>
+    <plurals name="msg_con_recover">
+        <item quantity="one">Recovering consolidation with one secret and %s public keys</item>
+        <item quantity="many">Recovering consolidation with %d secret and %s public keys</item>
     </plurals>
+    <string name="msg_con_recover_unknown">Recovering from unknown state</string>
     <plurals name="msg_con_reimport_public">
         <item quantity="one">Reimporting one public key</item>
-        <item quantity="other">Reimporting %d public keys</item>
+        <item quantity="many">Reimporting %d public keys</item>
     </plurals>
-    <string name="msg_con_success">Successfully consolidated database</string>
+    <string name="msg_con_reimport_public_skip">No public keys to reimport, skipping…</string>
+    <plurals name="msg_con_reimport_secret">
+        <item quantity="one">Reimporting one secret key</item>
+        <item quantity="many">Reimporting %d secret keys</item>
+    </plurals>
+    <string name="msg_con_reimport_secret_skip">No secret keys to reimport, skipping…</string>
+    <string name="msg_con_warn_delete_public">Exception deleting public cache file</string>
+    <string name="msg_con_warn_delete_secret">Exception deleting public cache file</string>
 
     <!-- PassphraseCache -->
     <string name="passp_cache_notif_click_to_clear">Click to clear cached passphrases</string>