Fix vCard importer flow.

- call startService() before bindService() to suppress connection
  leakage
- make cancel operation work properly
- take care of cache files appropriately
- add useful logs
- show Toast every time when import started

Note: I still see some connection leakage in ImportVCardActivity.

Bug: 3150402
Bug: 3159855
Change-Id: Iaec6d4e5d8ebcda84e2df5571f87bd3c59e5b264
diff --git a/src/com/android/contacts/vcard/CancelImportActivity.java b/src/com/android/contacts/vcard/CancelImportActivity.java
index 50e6e99..b52ee98 100644
--- a/src/com/android/contacts/vcard/CancelImportActivity.java
+++ b/src/com/android/contacts/vcard/CancelImportActivity.java
@@ -39,7 +39,7 @@
  * with a same Uri in the queue.
  */
 public class CancelImportActivity extends Activity {
-    private final String LOG_TAG = "CancelImportActivity";
+    private final String LOG_TAG = "VCardImporter";
 
     /* package */ final String EXTRA_TARGET_URI = "extra_target_uri";
 
diff --git a/src/com/android/contacts/vcard/ImportProcessor.java b/src/com/android/contacts/vcard/ImportProcessor.java
index 89b6be6..0e6acee 100644
--- a/src/com/android/contacts/vcard/ImportProcessor.java
+++ b/src/com/android/contacts/vcard/ImportProcessor.java
@@ -60,13 +60,14 @@
  * recreate multiple instances, as this holds total count of vCard entries to be imported.
  */
 public class ImportProcessor {
-    private static final String LOG_TAG = ImportProcessor.class.getSimpleName();
+    private static final String LOG_TAG = "VCardImporter";
 
     private class ImportProcessorConnection implements ServiceConnection {
         private Messenger mMessenger;
         private boolean mBound;
 
         public synchronized void tryBind() {
+            mContext.startService(new Intent(mContext, VCardService.class));
             if (!mContext.bindService(new Intent(mContext, VCardService.class),
                     this, Context.BIND_AUTO_CREATE)) {
                 throw new RuntimeException("Failed to bind to VCardService.");
@@ -77,6 +78,9 @@
         public synchronized void tryUnbind() {
             if (mBound) {
                 mContext.unbindService(this);
+                // TODO: This is not appropriate. It would be better to send some "stop" request
+                // to service and let the service stop itself.
+                mContext.stopService(new Intent(mContext, VCardService.class));
             } else {
                 // TODO: Not graceful.
                 Log.w(LOG_TAG, "unbind() is tried while ServiceConnection is not bound yet");
@@ -230,8 +234,8 @@
             // Instead, we show one only when there's just one created uri.
             doFinishNotification(mCreatedUris.size() > 0 ? mCreatedUris.get(0) : null);
             connection.sendFinishNotification();
+            Log.i(LOG_TAG, "Finished successfully importing all vCard");
         } finally {
-            // TODO: verify this works fine.
             mReadyForRequest = false;  // Just in case.
             mNotifier.resetTotalCount();
             connection.tryUnbind();
@@ -278,6 +282,7 @@
             readOneVCard(uri, estimatedVCardType, estimatedCharset,
                     constructor, possibleVCardVersions);
         if (successful) {
+            Log.i(LOG_TAG, "Successfully finished reading one vCard file finished: " + uri);
             List<Uri> uris = committer.getCreatedUris();
             if (uris != null) {
                 mCreatedUris.addAll(uris);
@@ -287,6 +292,7 @@
                         "Created Uris is null while the creation itself is successful.");
             }
         } else {
+            Log.w(LOG_TAG, "Failed to read one vCard file: " + uri);
             mFailedUris.add(uri);
         }
 
@@ -339,6 +345,7 @@
     /* package */ boolean readOneVCard(Uri uri, int vcardType, String charset,
             final VCardInterpreter interpreter,
             final int[] possibleVCardVersions) {
+        Log.i(LOG_TAG, "start importing one vCard (Uri: " + uri + ")");
         boolean successful = false;
         final int length = possibleVCardVersions.length;
         for (int i = 0; i < length; i++) {
@@ -361,6 +368,8 @@
                             new VCardParser_V30(vcardType) :
                                 new VCardParser_V21(vcardType));
                     if (mCanceled) {
+                        Log.i(LOG_TAG, "ImportProcessor already recieves cancel request, so " +
+                                "send cancel request to vCard parser too.");
                         mVCardParser.cancel();
                     }
                 }
@@ -411,6 +420,7 @@
     }
 
     public void cancel() {
+        Log.i(LOG_TAG, "ImportProcessor received cancel request");
         mCanceled = true;
         synchronized (this) {
             if (mVCardParser != null) {
diff --git a/src/com/android/contacts/vcard/ImportVCardActivity.java b/src/com/android/contacts/vcard/ImportVCardActivity.java
index d66a09a..24df063 100644
--- a/src/com/android/contacts/vcard/ImportVCardActivity.java
+++ b/src/com/android/contacts/vcard/ImportVCardActivity.java
@@ -54,6 +54,7 @@
 import android.text.SpannableStringBuilder;
 import android.text.Spanned;
 import android.text.TextUtils;
+import android.text.format.DateUtils;
 import android.text.style.RelativeSizeSpan;
 import android.util.Log;
 
@@ -86,7 +87,7 @@
  * dialogs stuffs (like how onCreateDialog() is used).
  */
 public class ImportVCardActivity extends Activity {
-    private static final String LOG_TAG = "ImportVCardActivity";
+    private static final String LOG_TAG = "VCardImporter";
 
     private static final int SELECT_ACCOUNT = 0;
 
@@ -285,7 +286,6 @@
      */
     private class VCardCacheThread extends Thread
             implements DialogInterface.OnCancelListener {
-        private static final String CACHE_FILE_PREFIX = "import_tmp_";
         private boolean mCanceled;
         private PowerManager.WakeLock mWakeLock;
         private VCardParser mVCardParser;
@@ -316,26 +316,35 @@
             String errorMessage = null;
             mWakeLock.acquire();
             final CustomConnection connection = new CustomConnection();
+            startService(new Intent(ImportVCardActivity.this, VCardService.class));
             bindService(new Intent(ImportVCardActivity.this,
                     VCardService.class), connection, Context.BIND_AUTO_CREATE);
             try {
-                clearOldCache();
-
-                final int length = mSourceUris.length;
                 // Uris given from caller applications may not be opened twice: consider when
                 // it is not from local storage (e.g. "file:///...") but from some special
                 // provider (e.g. "content://...").
                 // Thus we have to once copy the content of Uri into local storage, and read
-                // it after it. This copy is also useful fro the view of stability of the import,
-                // as we are able to restore the procedure even when it is aborted during it.
-                // Imagine the case the importer encountered memory-low situation when
-                // reading 10th entry of a vCard file.
+                // it after it.
                 //
                 // We may be able to read content of each vCard file during copying them
                 // to local storage, but currently vCard code does not allow us to do so.
-                for (int i = 0; i < length; i++) {
-                    final Uri sourceUri = mSourceUris[i];
-                    final Uri localDataUri = copyToLocal(sourceUri, i);
+                int cache_index = 0;
+                for (Uri sourceUri : mSourceUris) {
+                    String filename = null;
+                    // Note: caches are removed by VCardService.
+                    while (true) {
+                        filename = VCardService.CACHE_FILE_PREFIX + cache_index + ".vcf";
+                        final File file = context.getFileStreamPath(filename);
+                        if (!file.exists()) {
+                            break;
+                        } else {
+                            if (cache_index == Integer.MAX_VALUE) {
+                                throw new RuntimeException("Exceeded cache limit");
+                            }
+                            cache_index++;
+                        }
+                    }
+                    final Uri localDataUri = copyTo(sourceUri, filename);
                     if (mCanceled) {
                         break;
                     }
@@ -351,8 +360,6 @@
                 }
             } catch (OutOfMemoryError e) {
                 Log.e(LOG_TAG, "OutOfMemoryError");
-                // We should take care of this case since Android devices may have
-                // smaller memory than we usually expect.
                 System.gc();
                 runOnUiThread(new DialogDisplayer(
                         getString(R.string.fail_reason_low_memory_during_import)));
@@ -368,36 +375,33 @@
         }
 
         /**
-         * Copy the content of sourceUri to local storage. 
+         * Copy the content of sourceUri to the destination.
          */
-        private Uri copyToLocal(final Uri sourceUri, int i) throws IOException {
+        private Uri copyTo(final Uri sourceUri, String filename) throws IOException {
+            Log.i(LOG_TAG, String.format("Copy a Uri to app local storage (%s -> %s)",
+                    sourceUri, filename));
             final Context context = ImportVCardActivity.this;
             final ContentResolver resolver = context.getContentResolver();
             ReadableByteChannel inputChannel = null;
             WritableByteChannel outputChannel = null;
-            Uri destUri;
+            Uri destUri = null;
             try {
-                // XXX: better way to copy stream?
-                {
-                    inputChannel = Channels.newChannel(resolver.openInputStream(mSourceUris[i]));
-                    final String filename = CACHE_FILE_PREFIX + i + ".vcf";
-                    destUri = Uri.parse(context.getFileStreamPath(filename).toURI().toString());
-                    outputChannel =
-                            context.openFileOutput(filename, Context.MODE_PRIVATE).getChannel();
-                    final ByteBuffer buffer = ByteBuffer.allocateDirect(8192);
-                    while (inputChannel.read(buffer) != -1) {
-                        if (mCanceled) {
-                            Log.d(LOG_TAG, "Canceled during caching " + mSourceUris[i]);
-                            return null;
-                        }
-                        buffer.flip();
-                        outputChannel.write(buffer);
-                        buffer.compact();
+                inputChannel = Channels.newChannel(resolver.openInputStream(sourceUri));
+                destUri = Uri.parse(context.getFileStreamPath(filename).toURI().toString());
+                outputChannel = context.openFileOutput(filename, Context.MODE_PRIVATE).getChannel();
+                final ByteBuffer buffer = ByteBuffer.allocateDirect(8192);
+                while (inputChannel.read(buffer) != -1) {
+                    if (mCanceled) {
+                        Log.d(LOG_TAG, "Canceled during caching " + sourceUri);
+                        return null;
                     }
                     buffer.flip();
-                    while (buffer.hasRemaining()) {
-                        outputChannel.write(buffer);
-                    }
+                    outputChannel.write(buffer);
+                    buffer.compact();
+                }
+                buffer.flip();
+                while (buffer.hasRemaining()) {
+                    outputChannel.write(buffer);
                 }
             } finally {
                 if (inputChannel != null) {
@@ -487,22 +491,6 @@
                     vcardVersion, counter.getCount());
         }
 
-        /**
-         * We (currently) don't have any way to clean up cache files used in the previous
-         * import process,
-         * TODO(dmiyakawa): Can we do it after Service being done?
-         */
-        private void clearOldCache() {
-            final Context context = ImportVCardActivity.this;
-            final String[] fileLists = context.fileList();
-            for (String fileName : fileLists) {
-                if (fileName.startsWith(CACHE_FILE_PREFIX)) {
-                    Log.d(LOG_TAG, "Remove temporary file: " + fileName);
-                    context.deleteFile(fileName);
-                }
-            }
-        }
-
         public Uri[] getSourceUris() {
             return mSourceUris;
         }
@@ -873,11 +861,11 @@
     }
 
     private void startImport(String action, Uri uri) {
-        Log.d(LOG_TAG, "action = " + action + " ; path = " + uri);
-
         if (uri != null) {
+            Log.i(LOG_TAG, "Starting vCard import using Uri " + uri);
             importVCard(uri);
         } else {
+            Log.i(LOG_TAG, "Start vCard without Uri. The user will select vCard manually.");
             doScanExternalStorageAndImportVCard();
         }
     }
diff --git a/src/com/android/contacts/vcard/VCardService.java b/src/com/android/contacts/vcard/VCardService.java
index 1e855ab..475d465 100644
--- a/src/com/android/contacts/vcard/VCardService.java
+++ b/src/com/android/contacts/vcard/VCardService.java
@@ -21,9 +21,15 @@
 import android.os.IBinder;
 import android.os.Message;
 import android.os.Messenger;
+import android.text.format.DateUtils;
 import android.util.Log;
 import android.widget.Toast;
 
+import java.io.File;
+import java.text.DateFormat;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+
 import com.android.contacts.R;
 
 /**
@@ -40,11 +46,7 @@
     /* package */ static final int IMPORT_NOTIFICATION_ID = 1000;
     /* package */ static final int EXPORT_NOTIFICATION_ID = 1001;
 
-    /**
-     * Small vCard file is imported soon, so any meassage saying "vCard import started" is
-     * not needed. We show the message when the size of vCard is larger than this constant. 
-     */
-    private static final int IMPORT_NOTIFICATION_THRESHOLD = 10;
+    /* package */ static final String CACHE_FILE_PREFIX = "import_tmp_";
 
     public class ImportRequestHandler extends Handler {
         private ImportProcessor mImportProcessor;
@@ -59,6 +61,7 @@
         public void handleMessage(Message msg) {
             switch (msg.what) {
                 case MSG_IMPORT_REQUEST: {
+                    Log.i(LOG_TAG, "Received vCard import request.");
                     if (mDoDelayedCancel) {
                         Log.i(LOG_TAG, "A cancel request came before import request. " +
                                 "Refrain current import once.");
@@ -75,15 +78,14 @@
                         }
 
                         mImportProcessor.pushRequest(parameter);
-                        if (parameter.entryCount > IMPORT_NOTIFICATION_THRESHOLD) {
-                            Toast.makeText(VCardService.this,
-                                    getString(R.string.vcard_importer_start_message),
-                                    Toast.LENGTH_LONG).show();
-                        }
+                        Toast.makeText(VCardService.this,
+                                getString(R.string.vcard_importer_start_message),
+                                Toast.LENGTH_LONG).show();
                     }
                     break;
                 }
                 case MSG_EXPORT_REQUEST: {
+                    Log.i(LOG_TAG, "Received vCard export request.");
                     final ExportRequest parameter = (ExportRequest)msg.obj;
                     mExportProcessor.pushRequest(parameter);
                     Toast.makeText(VCardService.this,
@@ -92,6 +94,7 @@
                     break;
                 }
                 case MSG_CANCEL_IMPORT_REQUEST: {
+                    Log.i(LOG_TAG, "Received cancel import request.");
                     if (mImportProcessor != null) {
                         mImportProcessor.cancel();
                     } else {
@@ -101,11 +104,11 @@
                     break;
                 }
                 case MSG_NOTIFY_IMPORT_FINISHED: {
-                    Log.d(LOG_TAG, "MSG_NOTIFY_IMPORT_FINISHED");
+                    Log.i(LOG_TAG, "Received vCard import finish notification.");
                     break;
                 }
                 default: {
-                    Log.e(LOG_TAG, "Unknown request type: " + msg.what);
+                    Log.w(LOG_TAG, "Received unknown request, ignoring it.");
                     super.hasMessages(msg.what);
                 }
             }
@@ -124,4 +127,26 @@
     public IBinder onBind(Intent intent) {
         return mMessenger.getBinder();
     }
+
+    @Override
+    public void onDestroy() {
+        clearCache();
+        super.onDestroy();
+    }
+
+    private void clearCache() {
+        Log.i(LOG_TAG, "start removing cache files if exist.");
+        final String[] fileLists = fileList();
+        for (String fileName : fileLists) {
+            if (fileName.startsWith(CACHE_FILE_PREFIX)) {
+                // We don't want to keep all the caches so we remove cache files old enough.
+                // TODO: Ideally we should ask VCardService whether the file is being used or
+                // going to be used.
+                final Date now = new Date();
+                final File file = getFileStreamPath(fileName);
+                Log.i(LOG_TAG, "Remove a temporary file: " + fileName);
+                deleteFile(fileName);
+            }
+        }
+    }
 }