consolidate: a lot more log output, better recovery

1 files changed, 63 insertions, 23 deletions

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);