From ff52eef8e691645e657f02a21c9d51968c2bdcfd Mon Sep 17 00:00:00 2001 From: Anthony Lee Date: Tue, 24 Jun 2014 15:14:06 -0700 Subject: [PATCH] Revamp logging & remove the threading around downloads. There is no need to launch a new AsyncTask around adding an attachment to the queue of downloads. We can restore the attachment in the worker thread of AttachmentService instead. Also reworked the logging so we can trace the flow of the AttachmentService if we need to debug again in the future. Change-Id: I368ebb4322bc0af0f4cadedf102959d621e5ee80 --- .../email/service/AttachmentService.java | 369 +++++++++++------- .../email/service/AttachmentServiceTests.java | 2 +- 2 files changed, 229 insertions(+), 142 deletions(-) diff --git a/src/com/android/email/service/AttachmentService.java b/src/com/android/email/service/AttachmentService.java index 4329fac38..f4f6d0bc0 100644 --- a/src/com/android/email/service/AttachmentService.java +++ b/src/com/android/email/service/AttachmentService.java @@ -27,7 +27,6 @@ import android.content.Intent; import android.database.Cursor; import android.net.ConnectivityManager; import android.net.Uri; -import android.os.AsyncTask; import android.os.IBinder; import android.os.RemoteException; import android.os.SystemClock; @@ -65,6 +64,9 @@ public class AttachmentService extends Service implements Runnable { // For logging. public static final String LOG_TAG = "AttachmentService"; + // STOPSHIP Set this to 0 before shipping. + private static final int ENABLE_ATTACHMENT_SERVICE_DEBUG = 0; + // Minimum wait time before retrying a download that failed due to connection error private static final long CONNECTION_ERROR_RETRY_MILLIS = 10 * DateUtils.SECOND_IN_MILLIS; // Number of retries before we start delaying between @@ -102,7 +104,10 @@ public class AttachmentService extends Service implements Runnable { // Limit on the number of attachments we'll check for background download private static final int MAX_ATTACHMENTS_TO_CHECK = 25; - private static final String EXTRA_ATTACHMENT = "com.android.email.AttachmentService.attachment"; + private static final String EXTRA_ATTACHMENT_ID = + "com.android.email.AttachmentService.attachment_id"; + private static final String EXTRA_ATTACHMENT_FLAGS = + "com.android.email.AttachmentService.attachment_flags"; // This callback is invoked by the various service implementations to give us download progress // since those modules are responsible for the actual download. @@ -141,14 +146,17 @@ public class AttachmentService extends Service implements Runnable { final DownloadQueue mDownloadQueue = new DownloadQueue(); // The queue entries here are entries of the form {id, flags}, with the values passed in to - // attachmentChanged(). Entries in the queue are picked off by calls to attachmentChanged - // and processed in an async task in parallel. + // attachmentChanged(). Entries in the queue are picked off in processQueue(). private static final Queue sAttachmentChangedQueue = new ConcurrentLinkedQueue(); - // The task that pulls requests off of the queue of changed attachment and launches - // the AttachmentService as needed. Access to this task is guarded by sAttachmentService. - private static AsyncTask sAttachmentChangedTask; + // Extra layer of control over debug logging that should only be enabled when + // we need to take an extra deep dive at debugging the workflow in this class. + static private void debugTrace(final String format, final Object... args) { + if (ENABLE_ATTACHMENT_SERVICE_DEBUG > 0) { + LogUtils.d(LOG_TAG, String.format(format, args)); + } + } /** * This class is used to contain the details and state of a particular request to download @@ -159,7 +167,7 @@ public class AttachmentService extends Service implements Runnable { static class DownloadRequest { // Details of the request. final int mPriority; - final long mTime; + final long mCreatedTime; final long mAttachmentId; final long mMessageId; final long mAccountId; @@ -181,7 +189,7 @@ public class AttachmentService extends Service implements Runnable { @VisibleForTesting DownloadRequest(final int attPriority, final long attId) { // This constructor should only be used for unit tests. - mTime = SystemClock.elapsedRealtime(); + mCreatedTime = SystemClock.elapsedRealtime(); mPriority = attPriority; mAttachmentId = attId; mAccountId = -1; @@ -198,7 +206,7 @@ public class AttachmentService extends Service implements Runnable { mAccountId = mMessageId = -1; } mPriority = getAttachmentPriority(attachment); - mTime = SystemClock.elapsedRealtime(); + mCreatedTime = SystemClock.elapsedRealtime(); } private DownloadRequest(final DownloadRequest orig, final long newTime) { @@ -206,7 +214,7 @@ public class AttachmentService extends Service implements Runnable { mAttachmentId = orig.mAttachmentId; mMessageId = orig.mMessageId; mAccountId = orig.mAccountId; - mTime = newTime; + mCreatedTime = newTime; mInProgress = orig.mInProgress; mLastStatusCode = orig.mLastStatusCode; mLastProgress = orig.mLastProgress; @@ -258,10 +266,10 @@ public class AttachmentService extends Service implements Runnable { if (req1.mPriority != req2.mPriority) { res = (req1.mPriority < req2.mPriority) ? -1 : 1; } else { - if (req1.mTime == req2.mTime) { + if (req1.mCreatedTime == req2.mCreatedTime) { res = 0; } else { - res = (req1.mTime < req2.mTime) ? -1 : 1; + res = (req1.mCreatedTime < req2.mCreatedTime) ? -1 : 1; } } return res; @@ -274,7 +282,8 @@ public class AttachmentService extends Service implements Runnable { // Secondary collection to quickly find objects w/o the help of an iterator. // This class should be kept in lock step with the priority queue. - final ConcurrentHashMap mRequestMap = new ConcurrentHashMap(); + final ConcurrentHashMap mRequestMap = + new ConcurrentHashMap(); /** * This function will add the request to our collections if it does not already @@ -293,16 +302,18 @@ public class AttachmentService extends Service implements Runnable { final long requestId = request.mAttachmentId; if (requestId < 0) { // Invalid request - LogUtils.wtf(AttachmentService.LOG_TAG, - "Adding a DownloadRequest with an invalid id"); + LogUtils.d(LOG_TAG, "Not adding a DownloadRequest with an invalid attachment id"); return false; } + debugTrace("Queuing DownloadRequest #%d", requestId); synchronized (mLock) { // Check to see if this request is is already in the queue final boolean exists = mRequestMap.containsKey(requestId); if (!exists) { mRequestQueue.offer(request); mRequestMap.put(requestId, request); + } else { + debugTrace("DownloadRequest #%d was already in the queue"); } } return true; @@ -319,6 +330,7 @@ public class AttachmentService extends Service implements Runnable { // If it is invalid, its not in the queue. return true; } + debugTrace("Removing DownloadRequest #%d", request.mAttachmentId); final boolean result; synchronized (mLock) { // It is key to keep the map and queue in lock step @@ -344,6 +356,9 @@ public class AttachmentService extends Service implements Runnable { mRequestMap.remove(requestId); } } + if (returnRequest != null) { + debugTrace("Retrieved DownloadRequest #%d", returnRequest.mAttachmentId); + } return returnRequest; } @@ -397,6 +412,7 @@ public class AttachmentService extends Service implements Runnable { final AlarmManager am = (AlarmManager)context.getSystemService(Context.ALARM_SERVICE); am.set(AlarmManager.RTC_WAKEUP, System.currentTimeMillis() + delay, mWatchdogPendingIntent); + debugTrace("Set up a watchdog for %d millis in the future", delay); } public void setWatchdogAlarm(final Context context) { @@ -433,9 +449,7 @@ public class AttachmentService extends Service implements Runnable { // Check how long it's been since receiving a callback final long timeSinceCallback = now - dr.mLastCallbackTime; if (timeSinceCallback > callbackTimeout) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Download of " + dr.mAttachmentId + " timed out"); - } + LogUtils.d(LOG_TAG, "Timeout for DownloadRequest #%d ", dr.mAttachmentId); return true; } return false; @@ -446,14 +460,18 @@ public class AttachmentService extends Service implements Runnable { * have failed silently (the connection dropped, for example) */ void watchdogAlarm(final AttachmentService service, final int callbackTimeout) { + debugTrace("Received a timer callback in the watchdog"); + // We want to iterate on each of the downloads that are currently in progress and // cancel the ones that seem to be taking too long. final Collection inProgressRequests = service.mDownloadsInProgress.values(); for (DownloadRequest req: inProgressRequests) { + debugTrace("Checking in-progress request with id: %d", req.mAttachmentId); final boolean shouldCancelDownload = validateDownloadRequest(req, callbackTimeout, System.currentTimeMillis()); if (shouldCancelDownload) { + LogUtils.w(LOG_TAG, "Cancelling DownloadRequest #%d", req.mAttachmentId); service.cancelDownload(req); // TODO: Should we also mark the attachment as failed at this point in time? } @@ -467,9 +485,7 @@ public class AttachmentService extends Service implements Runnable { void issueNextWatchdogAlarm(final AttachmentService service) { if (!service.mDownloadsInProgress.isEmpty()) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "Reschedule watchdog..."); - } + debugTrace("Rescheduling watchdog..."); setWatchdogAlarm(service); } } @@ -477,8 +493,8 @@ public class AttachmentService extends Service implements Runnable { /** * We use an EmailServiceCallback to keep track of the progress of downloads. These callbacks - * come from either Controller (IMAP/POP) or ExchangeService (EAS). Note that we only implement the - * single callback that's defined by the EmailServiceCallback interface. + * come from either Controller (IMAP/POP) or ExchangeService (EAS). Note that we only + * implement the single callback that's defined by the EmailServiceCallback interface. */ class ServiceCallback extends IEmailServiceCallback.Stub { @@ -506,28 +522,23 @@ public class AttachmentService extends Service implements Runnable { @Override public void loadAttachmentStatus(final long messageId, final long attachmentId, final int statusCode, final int progress) { + debugTrace(LOG_TAG, "ServiceCallback for attachment #%d", attachmentId); + // Record status and progress final DownloadRequest req = mDownloadsInProgress.get(attachmentId); if (req != null) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - final String code; - switch(statusCode) { - case EmailServiceStatus.SUCCESS: code = "Success"; break; - case EmailServiceStatus.IN_PROGRESS: code = "In progress"; break; - default: code = Integer.toString(statusCode); break; - } - if (statusCode != EmailServiceStatus.IN_PROGRESS) { - LogUtils.d(LOG_TAG, ">> Attachment status " + attachmentId + ": " + code); - } else if (progress >= (req.mLastProgress + 10)) { - LogUtils.d(LOG_TAG, ">> Attachment progress %d: %d%%", attachmentId, - progress); - } - } + final long now = System.currentTimeMillis(); + debugTrace("ServiceCallback: status code changing from %d to %d", + req.mLastStatusCode, statusCode); + debugTrace("ServiceCallback: progress changing from %d to %d", + req.mLastProgress,progress); + debugTrace("ServiceCallback: last callback time changing from %d to %d", + req.mLastCallbackTime, now); // Update some state to keep track of the progress of the download req.mLastStatusCode = statusCode; req.mLastProgress = progress; - req.mLastCallbackTime = System.currentTimeMillis(); + req.mLastCallbackTime = now; // Update the attachment status in the provider. final Attachment attachment = @@ -545,6 +556,7 @@ public class AttachmentService extends Service implements Runnable { // It is assumed that any other error is either a success or an error // Either way, the final updates to the DownloadRequest and attachment // objects will be handed there. + LogUtils.d(LOG_TAG, "Attachment #%d is done", attachmentId); endDownload(attachmentId, statusCode); break; } @@ -566,39 +578,13 @@ public class AttachmentService extends Service implements Runnable { * @param flags the new flags for the attachment */ public static void attachmentChanged(final Context context, final long id, final int flags) { - synchronized (sAttachmentChangedQueue) { - sAttachmentChangedQueue.add(new long[]{id, flags}); - if (sAttachmentChangedTask == null) { - sAttachmentChangedTask = new AsyncTask() { - @Override - protected Void doInBackground(Void... params) { - while (true) { - final long[] change; - synchronized (sAttachmentChangedQueue) { - change = sAttachmentChangedQueue.poll(); - if (change == null) { - sAttachmentChangedTask = null; - return null; - } - } - final long id = change[0]; - final long flags = change[1]; - final Attachment attachment = - Attachment.restoreAttachmentWithId(context, id); - if (attachment == null) { - continue; - } - attachment.mFlags = (int) flags; - final Intent intent = new Intent(context, AttachmentService.class); - intent.putExtra(EXTRA_ATTACHMENT, attachment); - // This is result in a call to AttachmentService.onStartCommand() - // which will queue the attachment in its internal prioritized queue. - context.startService(intent); - } - } - }.executeOnExecutor(AsyncTask.THREAD_POOL_EXECUTOR); - } - } + LogUtils.d(LOG_TAG, "Attachment with id: %d will potentially be queued for download", id); + // Throw this info into an intent and send it to the attachment service. + final Intent intent = new Intent(context, AttachmentService.class); + debugTrace("Calling startService with extras %d & %d", id, flags); + intent.putExtra(EXTRA_ATTACHMENT_ID, id); + intent.putExtra(EXTRA_ATTACHMENT_FLAGS, flags); + context.startService(intent); } /** @@ -610,11 +596,20 @@ public class AttachmentService extends Service implements Runnable { if (sRunningService == null) { sRunningService = this; } - if (intent != null && intent.hasExtra(EXTRA_ATTACHMENT)) { - Attachment att = intent.getParcelableExtra(EXTRA_ATTACHMENT); - onChange(this, att); + if (intent != null) { + // Let's add this id/flags combo to the list of potential attachments to process. + final long attachment_id = intent.getLongExtra(EXTRA_ATTACHMENT_ID, -1); + final int attachment_flags = intent.getIntExtra(EXTRA_ATTACHMENT_FLAGS, -1); + if ((attachment_id >= 0) && (attachment_flags >= 0)) { + sAttachmentChangedQueue.add(new long[]{attachment_id, attachment_flags}); + // Process the queue if we're in a wait + kick(); + } else { + debugTrace("Received an invalid intent w/o the required extras %d & %d", + attachment_id, attachment_flags); + } } else { - LogUtils.wtf(LOG_TAG, "Received an invalid intent w/o EXTRA_ATTACHMENT"); + debugTrace("Received a null intent in onStartCommand"); } return Service.START_STICKY; } @@ -636,6 +631,9 @@ public class AttachmentService extends Service implements Runnable { @Override public void onDestroy() { + debugTrace("Destroying AttachmentService object"); + dumpInProgressDownloads(); + // Mark this instance of the service as stopped. Our main loop for the AttachmentService // checks for this flag along with the AttachmentWatchdog. mStop = true; @@ -668,11 +666,13 @@ public class AttachmentService extends Service implements Runnable { EmailContent.ID_PROJECTION, "(" + AttachmentColumns.FLAGS + " & ?) != 0", new String[] {Integer.toString(mask)}, null); try { - LogUtils.d(LOG_TAG, "Count: " + c.getCount()); + LogUtils.d(LOG_TAG, + "Count of previous downloads to resume (from db): %d", c.getCount()); while (c.moveToNext()) { final Attachment attachment = Attachment.restoreAttachmentWithId( this, c.getLong(EmailContent.ID_PROJECTION_COLUMN)); if (attachment != null) { + debugTrace("Attempting to download attachment #%d again.", attachment.mId); onChange(this, attachment); } } @@ -692,15 +692,24 @@ public class AttachmentService extends Service implements Runnable { } if (mStop) { // We might be bailing out here due to the service shutting down - LogUtils.d(LOG_TAG, "*** AttachmentService has been instructed to stop"); + LogUtils.d(LOG_TAG, "AttachmentService has been instructed to stop"); break; } + + // In advanced debug mode, let's look at the state of all in-progress downloads + // after processQueue() runs. + debugTrace("Downloads Map before processQueue"); + dumpInProgressDownloads(); processQueue(); - if (mDownloadQueue.isEmpty()) { - LogUtils.d(LOG_TAG, "*** All done; shutting down service"); + debugTrace("Downloads Map after processQueue"); + dumpInProgressDownloads(); + + if (mDownloadQueue.isEmpty() && (mDownloadsInProgress.size() < 1)) { + LogUtils.d(LOG_TAG, "Shutting down service. No in-progress or pending downloads."); stopSelf(); break; } + debugTrace("Run() wait for mLock"); synchronized(mLock) { try { mLock.wait(PROCESS_QUEUE_WAIT_TIME); @@ -708,6 +717,7 @@ public class AttachmentService extends Service implements Runnable { // That's ok; we'll just keep looping } } + debugTrace("Run() got mLock"); } // Unregister now that we're done @@ -735,37 +745,40 @@ public class AttachmentService extends Service implements Runnable { * existence of an attachment before acting on it. */ public synchronized void onChange(final Context context, final Attachment att) { + debugTrace("onChange() for Attachment: #%d", att.mId); DownloadRequest req = mDownloadQueue.findRequestById(att.mId); final long priority = getAttachmentPriority(att); if (priority == PRIORITY_NONE) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Attachment changed: " + att.mId); - } + LogUtils.d(LOG_TAG, "Attachment #%d has no priority and will not be downloaded", + att.mId); // In this case, there is no download priority for this attachment if (req != null) { // If it exists in the map, remove it // NOTE: We don't yet support deleting downloads in progress - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Attachment " + att.mId + " was in queue, removing"); - } mDownloadQueue.removeRequest(req); } } else { // Ignore changes that occur during download - if (mDownloadsInProgress.containsKey(att.mId)) return; + if (mDownloadsInProgress.containsKey(att.mId)) { + debugTrace("Attachment #%d was already in the queue", att.mId); + return; + } // If this is new, add the request to the queue if (req == null) { + LogUtils.d(LOG_TAG, "Attachment #%d is a new download request", att.mId); req = new DownloadRequest(context, att); final AttachmentInfo attachInfo = new AttachmentInfo(context, att); if (!attachInfo.isEligibleForDownload()) { + LogUtils.w(LOG_TAG, "Attachment #%d is not eligible for download", att.mId); // We can't download this file due to policy, depending on what type // of request we received, we handle the response differently. if (((att.mFlags & Attachment.FLAG_DOWNLOAD_USER_REQUEST) != 0) || ((att.mFlags & Attachment.FLAG_POLICY_DISALLOWS_DOWNLOAD) != 0)) { + LogUtils.w(LOG_TAG, "Attachment #%d cannot be downloaded ever", att.mId); // There are a couple of situations where we will not even allow this // request to go in the queue because we can already process it as a // failure. - // 1. The user explictly wants to download this attachment from the + // 1. The user explicitly wants to download this attachment from the // email view but they should not be able to...either because there is // no app to view it or because its been marked as a policy violation. // 2. The user is forwarding an email and the attachment has been @@ -781,12 +794,11 @@ public class AttachmentService extends Service implements Runnable { } mDownloadQueue.addRequest(req); } - // If the request already existed, we'll update the priority (so that the time is - // up-to-date); otherwise, we create a new request - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Download queued for attachment " + att.mId + ", class " + - req.mPriority + ", priority time " + req.mTime); - } + // TODO: If the request already existed, we'll update the priority (so that the time is + // up-to-date); otherwise, create a new request + LogUtils.d(LOG_TAG, + "Attachment #%d queued for download, priority: %d, created time: %d", + att.mId, req.mPriority, req.mCreatedTime); } // Process the queue if we're in a wait kick(); @@ -804,36 +816,64 @@ public class AttachmentService extends Service implements Runnable { att.update(this, cv); } + /** + * Set the bits in the provider to mark this download as completed. + * @param att The attachment that was downloaded. + */ + void markAttachmentAsCompleted(final Attachment att) { + final ContentValues cv = new ContentValues(); + final int flags = Attachment.FLAG_DOWNLOAD_FORWARD | Attachment.FLAG_DOWNLOAD_USER_REQUEST; + cv.put(AttachmentColumns.FLAGS, att.mFlags &= ~flags); + cv.put(AttachmentColumns.UI_STATE, AttachmentState.SAVED); + att.update(this, cv); + } + /** * Run through the AttachmentMap and find DownloadRequests that can be executed, enforcing * the limit on maximum downloads */ synchronized void processQueue() { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Checking attachment queue, " + mDownloadQueue.getSize() - + " entries"); + debugTrace("Processing changed queue, num entries: %d", sAttachmentChangedQueue.size()); + + // First thing we need to do is process the list of "potential downloads" that we + // added to sAttachmentChangedQueue + long[] change = sAttachmentChangedQueue.poll(); + while (change != null) { + // Process this change + final long id = change[0]; + final long flags = change[1]; + final Attachment attachment = Attachment.restoreAttachmentWithId(this, id); + if (attachment == null) { + LogUtils.w(LOG_TAG, "Could not restore attachment #%d", id); + continue; + } + attachment.mFlags = (int) flags; + onChange(this, attachment); + change = sAttachmentChangedQueue.poll(); } + debugTrace("Processing download queue, num entries: %d", mDownloadQueue.getSize()); + while (mDownloadsInProgress.size() < MAX_SIMULTANEOUS_DOWNLOADS) { final DownloadRequest req = mDownloadQueue.getNextRequest(); if (req == null) { // No more queued requests? We are done for now. break; } - // Enforce per-account limit here + // Enforce per-account limit here if (getDownloadsForAccount(req.mAccountId) >= MAX_SIMULTANEOUS_DOWNLOADS_PER_ACCOUNT) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Skip #" + req.mAttachmentId + "; maxed for acct #" + - req.mAccountId); - } + LogUtils.w(LOG_TAG, "Skipping #%d; maxed for acct %d", + req.mAttachmentId, req.mAccountId); continue; - } else if (Attachment.restoreAttachmentWithId(this, req.mAttachmentId) == null) { + } + if (Attachment.restoreAttachmentWithId(this, req.mAttachmentId) == null) { + LogUtils.e(LOG_TAG, "Could not load attachment: #%d", req.mAttachmentId); continue; } if (!req.mInProgress) { final long currentTime = SystemClock.elapsedRealtime(); if (req.mRetryCount > 0 && req.mRetryStartTime > currentTime) { - LogUtils.d(LOG_TAG, "== waiting to retry attachment %d", req.mAttachmentId); + debugTrace("Need to wait before retrying attachment #%d", req.mAttachmentId); mWatchdog.setWatchdogAlarm(this, CONNECTION_ERROR_RETRY_MILLIS, CALLBACK_TIMEOUT); continue; @@ -852,17 +892,23 @@ public class AttachmentService extends Service implements Runnable { (ecm.getActiveNetworkType() != ConnectivityManager.TYPE_WIFI)) { // Only prefetch if it if connectivity is available, prefetch is enabled // and we are on WIFI + LogUtils.d(LOG_TAG, "Skipping opportunistic downloads since WIFI is not available"); return; } // Then, try opportunistic download of appropriate attachments - final int backgroundDownloads = MAX_SIMULTANEOUS_DOWNLOADS - mDownloadsInProgress.size(); - if ((backgroundDownloads + 1) >= MAX_SIMULTANEOUS_DOWNLOADS) { + final int availableBackgroundThreads = + MAX_SIMULTANEOUS_DOWNLOADS - mDownloadsInProgress.size() - 1; + if (availableBackgroundThreads < 1) { // We want to leave one spot open for a user requested download that we haven't // started processing yet. + LogUtils.d(LOG_TAG, "Skipping opportunistic downloads, %d threads available", + availableBackgroundThreads); return; } + debugTrace("Launching up to %d opportunistic downloads", availableBackgroundThreads); + // We'll load up the newest 25 attachments that aren't loaded or queued // TODO: We are always looking for MAX_ATTACHMENTS_TO_CHECK, shouldn't this be // backgroundDownloads instead? We should fix and test this. @@ -881,6 +927,7 @@ public class AttachmentService extends Service implements Runnable { if (account == null) { // Clean up this orphaned attachment; there's no point in keeping it // around; then try to find another one + debugTrace("Found orphaned attachment #%d", att.mId); EmailContent.delete(this, Attachment.CONTENT_URI, att.mId); } else { // Check that the attachment meets system requirements for download @@ -890,11 +937,12 @@ public class AttachmentService extends Service implements Runnable { if (info.isEligibleForDownload()) { // Either the account must be able to prefetch or this must be // an inline attachment. - if (att.mContentId != null || - (canPrefetchForAccount(account, cacheDir))) { + if (att.mContentId != null || canPrefetchForAccount(account, cacheDir)) { final Integer tryCount = mAttachmentFailureMap.get(att.mId); if (tryCount != null && tryCount > MAX_DOWNLOAD_RETRIES) { // move onto the next attachment + LogUtils.w(LOG_TAG, + "Too many failed attempts for attachment #%d ", att.mId); continue; } // Start this download and we're done @@ -909,7 +957,7 @@ public class AttachmentService extends Service implements Runnable { // query results. We are most likely here for other reasons such // as the inability to view the attachment. In that case, let's just // skip it for now. - LogUtils.e(LOG_TAG, "== skip attachment %d, it is ineligible", att.mId); + LogUtils.w(LOG_TAG, "Skipping attachment #%d, it is ineligible", att.mId); } } } @@ -930,12 +978,12 @@ public class AttachmentService extends Service implements Runnable { // Do not download the same attachment multiple times boolean alreadyInProgress = mDownloadsInProgress.get(req.mAttachmentId) != null; - if (alreadyInProgress) return false; + if (alreadyInProgress) { + debugTrace("This attachment #%d is already in progress", req.mAttachmentId); + return false; + } try { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, ">> Starting download for attachment #" + req.mAttachmentId); - } startDownload(service, req); } catch (RemoteException e) { // TODO: Consider whether we need to do more in this case... @@ -955,6 +1003,7 @@ public class AttachmentService extends Service implements Runnable { */ private void startDownload(final EmailServiceProxy service, final DownloadRequest req) throws RemoteException { + LogUtils.d(LOG_TAG, "Starting download for Attachment #%d", req.mAttachmentId); req.mStartTime = System.currentTimeMillis(); req.mInProgress = true; mDownloadsInProgress.put(req.mAttachmentId, req); @@ -964,16 +1013,16 @@ public class AttachmentService extends Service implements Runnable { } synchronized void cancelDownload(final DownloadRequest req) { - LogUtils.d(LOG_TAG, "cancelDownload #%d", req.mAttachmentId); + LogUtils.d(LOG_TAG, "Cancelling download for Attachment #%d", req.mAttachmentId); req.mInProgress = false; mDownloadsInProgress.remove(req.mAttachmentId); // Remove the download from our queue, and then decide whether or not to add it back. mDownloadQueue.removeRequest(req); req.mRetryCount++; if (req.mRetryCount > CONNECTION_ERROR_MAX_RETRIES) { - LogUtils.d(LOG_TAG, "too many failures, giving up"); + LogUtils.w(LOG_TAG, "Too many failures giving up on Attachment #%d", req.mAttachmentId); } else { - LogUtils.d(LOG_TAG, "moving to end of queue, will retry"); + debugTrace("Moving to end of queue, will retry #%d", req.mAttachmentId); // The time field of DownloadRequest is final, because it's unsafe to change it // as long as the DownloadRequest is in the DownloadSet. It's needed for the // comparator, so changing time would make the request unfindable. @@ -990,6 +1039,8 @@ public class AttachmentService extends Service implements Runnable { * @param statusCode the EmailServiceStatus code returned by the Service */ synchronized void endDownload(final long attachmentId, final int statusCode) { + LogUtils.d(LOG_TAG, "Finishing download #%d", attachmentId); + // Say we're no longer downloading this mDownloadsInProgress.remove(attachmentId); @@ -1006,6 +1057,7 @@ public class AttachmentService extends Service implements Runnable { downloadCount = 0; } downloadCount += 1; + LogUtils.w(LOG_TAG, "This attachment failed, adding #%d to failure map", attachmentId); mAttachmentFailureMap.put(attachmentId, downloadCount); } @@ -1016,7 +1068,11 @@ public class AttachmentService extends Service implements Runnable { req.mRetryCount++; if (req.mRetryCount > CONNECTION_ERROR_MAX_RETRIES) { // We are done, we maxed out our total number of tries. - LogUtils.d(LOG_TAG, "Connection Error #%d, giving up", attachmentId); + // Not that we do not flag this attachment with any special flags so the + // AttachmentService will try to download this attachment again the next time + // that it starts up. + LogUtils.w(LOG_TAG, "Too many tried for connection errors, giving up #%d", + attachmentId); mDownloadQueue.removeRequest(req); // Note that we are not doing anything with the attachment right now // We will annotate it later in this function if needed. @@ -1026,7 +1082,7 @@ public class AttachmentService extends Service implements Runnable { // So now, for the first five errors, we'll retry immediately. For the next // five tries, we'll add a ten second delay between each. After that, we'll // give up. - LogUtils.d(LOG_TAG, "ConnectionError #%d, retried %d times, adding delay", + LogUtils.w(LOG_TAG, "ConnectionError #%d, retried %d times, adding delay", attachmentId, req.mRetryCount); req.mInProgress = false; req.mRetryStartTime = SystemClock.elapsedRealtime() + @@ -1034,7 +1090,7 @@ public class AttachmentService extends Service implements Runnable { mWatchdog.setWatchdogAlarm(this, CONNECTION_ERROR_RETRY_MILLIS, CALLBACK_TIMEOUT); } else { - LogUtils.d(LOG_TAG, "ConnectionError #%d, retried %d times, adding delay", + LogUtils.w(LOG_TAG, "ConnectionError for #%d, retried %d times, adding delay", attachmentId, req.mRetryCount); req.mInProgress = false; req.mRetryStartTime = 0; @@ -1049,15 +1105,15 @@ public class AttachmentService extends Service implements Runnable { mDownloadQueue.removeRequest(req); } - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { + if (ENABLE_ATTACHMENT_SERVICE_DEBUG > 0) { long secs = 0; if (req != null) { - secs = (System.currentTimeMillis() - req.mTime) / 1000; + secs = (System.currentTimeMillis() - req.mCreatedTime) / 1000; } final String status = (statusCode == EmailServiceStatus.SUCCESS) ? "Success" : "Error " + statusCode; - LogUtils.d(LOG_TAG, "<< Download finished for attachment #" + attachmentId + "; " + secs - + " seconds from request, status: " + status); + debugTrace("Download finished for attachment #%d; %d seconds from request, status: %s", + attachmentId, secs, status); } final Attachment attachment = Attachment.restoreAttachmentWithId(this, attachmentId); @@ -1080,32 +1136,36 @@ public class AttachmentService extends Service implements Runnable { NotificationController nc = NotificationController.getInstance(this); nc.showDownloadForwardFailedNotification(attachment); deleted = true; + LogUtils.w(LOG_TAG, "Deleting forwarded attachment #%d for message #%d", + attachmentId, attachment.mMessageKey); } // If we're an attachment on forwarded mail, and if we're not still blocked, // try to send pending mail now (as mediated by MailService) if ((req != null) && !Utility.hasUnloadedAttachments(this, attachment.mMessageKey)) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, "== Downloads finished for outgoing msg #" - + req.mMessageId); - } + debugTrace("Downloads finished for outgoing msg #%d", req.mMessageId); EmailServiceProxy service = EmailServiceUtils.getServiceForAccount( this, accountId); try { service.sendMail(accountId); } catch (RemoteException e) { - // We tried + LogUtils.e(LOG_TAG, "RemoteException while trying to send message: #%d, %s", + req.mMessageId, e.toString()); } } } if (statusCode == EmailServiceStatus.MESSAGE_NOT_FOUND) { Message msg = Message.restoreMessageWithId(this, attachment.mMessageKey); if (msg == null) { + LogUtils.w(LOG_TAG, "Deleting attachment #%d with no associated message #%d", + attachment.mId, attachment.mMessageKey); // If there's no associated message, delete the attachment EmailContent.delete(this, Attachment.CONTENT_URI, attachment.mId); } else { // If there really is a message, retry // TODO: How will this get retried? It's still marked as inProgress? + LogUtils.w(LOG_TAG, "Retrying attachment #%d with associated message #%d", + attachment.mId, attachment.mMessageKey); kick(); return; } @@ -1115,12 +1175,8 @@ public class AttachmentService extends Service implements Runnable { // ignore it and continue; otherwise, it was either 1) a user request, in which // case the user can retry manually or 2) an opportunistic download, in which // case the download wasn't critical - ContentValues cv = new ContentValues(); - int flags = - Attachment.FLAG_DOWNLOAD_FORWARD | Attachment.FLAG_DOWNLOAD_USER_REQUEST; - cv.put(AttachmentColumns.FLAGS, attachment.mFlags &= ~flags); - cv.put(AttachmentColumns.UI_STATE, AttachmentState.SAVED); - attachment.update(this, cv); + LogUtils.d(LOG_TAG, "Attachment #%d successfully downloaded!", attachment.mId); + markAttachmentAsCompleted(attachment); } } // Process the queue @@ -1169,14 +1225,20 @@ public class AttachmentService extends Service implements Runnable { if (account == null) return false; // First, check preference and quickly return if prefetch isn't allowed - if ((account.mFlags & Account.FLAGS_BACKGROUND_ATTACHMENTS) == 0) return false; + if ((account.mFlags & Account.FLAGS_BACKGROUND_ATTACHMENTS) == 0) { + debugTrace("Prefetch is not allowed for this account: %d", account.getId()); + return false; + } final long totalStorage = dir.getTotalSpace(); final long usableStorage = dir.getUsableSpace(); final long minAvailable = (long)(totalStorage * PREFETCH_MINIMUM_STORAGE_AVAILABLE); // If there's not enough overall storage available, stop now - if (usableStorage < minAvailable) return false; + if (usableStorage < minAvailable) { + debugTrace("Not enough physical storage for prefetch"); + return false; + } final int numberOfAccounts = mAccountManagerStub.getNumberOfAccounts(); // Calculate an even per-account storage although it would make a lot of sense to not @@ -1204,10 +1266,8 @@ public class AttachmentService extends Service implements Runnable { // Return true if we're using less than the maximum per account if (accountStorage >= perAccountMaxStorage) { - if (LogUtils.isLoggable(LOG_TAG, LogUtils.DEBUG)) { - LogUtils.d(LOG_TAG, ">> Prefetch not allowed for account " + account.mId + - "; used " + accountStorage + ", limit " + perAccountMaxStorage); - } + debugTrace("Prefetch not allowed for account %d; used: %d, limit %d", + account.mId, accountStorage, perAccountMaxStorage); return false; } return true; @@ -1221,6 +1281,33 @@ public class AttachmentService extends Service implements Runnable { } // For Debugging. + synchronized public void dumpInProgressDownloads() { + if (ENABLE_ATTACHMENT_SERVICE_DEBUG < 1) { + LogUtils.d(LOG_TAG, "Advanced logging not configured."); + } + for (final DownloadRequest req : mDownloadsInProgress.values()) { + LogUtils.d(LOG_TAG, "--BEGIN DownloadRequest DUMP--"); + LogUtils.d(LOG_TAG, "Account: #%d", req.mAccountId); + LogUtils.d(LOG_TAG, "Message: #%d", req.mMessageId); + LogUtils.d(LOG_TAG, "Attachment: #%d", req.mAttachmentId); + LogUtils.d(LOG_TAG, "Created Time: %d", req.mCreatedTime); + LogUtils.d(LOG_TAG, "Priority: %d", req.mPriority); + if (req.mInProgress == true) { + LogUtils.d(LOG_TAG, "This download is in progress"); + } else { + LogUtils.d(LOG_TAG, "This download is not in progress"); + } + LogUtils.d(LOG_TAG, "Start Time: %d", req.mStartTime); + LogUtils.d(LOG_TAG, "Retry Count: %d", req.mRetryCount); + LogUtils.d(LOG_TAG, "Retry Start Tiome: %d", req.mRetryStartTime); + LogUtils.d(LOG_TAG, "Last Status Code: %d", req.mLastStatusCode); + LogUtils.d(LOG_TAG, "Last Progress: %d", req.mLastProgress); + LogUtils.d(LOG_TAG, "Last Callback Time: %d", req.mLastCallbackTime); + LogUtils.d(LOG_TAG, "------------------------------"); + } + } + + @Override public void dump(final FileDescriptor fd, final PrintWriter pw, final String[] args) { pw.println("AttachmentService"); @@ -1234,7 +1321,7 @@ public class AttachmentService extends Service implements Runnable { // concern with this debug method. for (final DownloadRequest req : mDownloadQueue.mRequestMap.values()) { pw.println(" Account: " + req.mAccountId + ", Attachment: " + req.mAttachmentId); - pw.println(" Priority: " + req.mPriority + ", Time: " + req.mTime + + pw.println(" Priority: " + req.mPriority + ", Time: " + req.mCreatedTime + (req.mInProgress ? " [In progress]" : "")); final Attachment att = Attachment.restoreAttachmentWithId(this, req.mAttachmentId); if (att == null) { diff --git a/tests/src/com/android/email/service/AttachmentServiceTests.java b/tests/src/com/android/email/service/AttachmentServiceTests.java index 7ae06bb70..2794dafe5 100644 --- a/tests/src/com/android/email/service/AttachmentServiceTests.java +++ b/tests/src/com/android/email/service/AttachmentServiceTests.java @@ -391,7 +391,7 @@ public class AttachmentServiceTests extends TestCase { for (int i = 0; i < dq.getSize(); i++){ final AttachmentService.DownloadRequest returnRequest = dq.getNextRequest(); assertNotNull(returnRequest); - final long requestTime = returnRequest.mTime; + final long requestTime = returnRequest.mCreatedTime; // The time should be going up. assertTrue(requestTime >= lastTime); lastTime = requestTime;