Fix push failure edge case (#2161999)
* Unsafe (potentially stale) data was being written to the Mailbox table near the end of each sync. It would effectively undo changes made to the Mailbox in other threads that occurred while the Mailbox was syncing. * In this particular case, changes to sync interval (push/ping/timed) were being overwritten, which could cause push to get lost for as long as 30 minutes (the pingLoop timeout when there aren't any pingable mailboxes) * Watchdog alarm was being set to wrong time (typo) * Add extra user logging in case there are additional cases of push * Only set sync status and time on successful sync * Move ping error check into pingParser to avoid unnecessary sync Change-Id: Icb4494078480ada39b7494b3abf380fb08858406
This commit is contained in:
Marc Blank
parent
1eb0af5d80
commit
36842abe9f
@ -86,8 +86,6 @@ public class EasSyncService extends AbstractSyncService {
|
||||
private static final String WHERE_PUSH_HOLD_NOT_ACCOUNT_MAILBOX =
|
||||
MailboxColumns.ACCOUNT_KEY + "=? and " + MailboxColumns.SYNC_INTERVAL +
|
||||
'=' + Mailbox.CHECK_INTERVAL_PUSH_HOLD;
|
||||
private static final String[] SYNC_STATUS_PROJECTION =
|
||||
new String[] {MailboxColumns.ID, MailboxColumns.SYNC_STATUS};
|
||||
static private final int CHUNK_SIZE = 16*1024;
|
||||
|
||||
static private final String PING_COMMAND = "Ping";
|
||||
@ -113,8 +111,8 @@ public class EasSyncService extends AbstractSyncService {
|
||||
static private final int PING_HEARTBEAT_INCREMENT = 3*PING_MINUTES;
|
||||
static private final int PING_FORCE_HEARTBEAT = 2*PING_MINUTES;
|
||||
|
||||
static private final int PROTOCOL_PING_STATUS_UNAVAILABLE = -1;
|
||||
static private final int PROTOCOL_PING_STATUS_COMPLETED = 1;
|
||||
static private final int PROTOCOL_PING_STATUS_CHANGES_FOUND = 2;
|
||||
|
||||
// Fallbacks (in minutes) for ping loop failures
|
||||
static private final int MAX_PING_FAILURES = 1;
|
||||
@ -432,7 +430,7 @@ public class EasSyncService extends AbstractSyncService {
|
||||
method.setEntity(entity);
|
||||
synchronized(getSynchronizer()) {
|
||||
mPendingPost = method;
|
||||
SyncManager.runAsleep(mMailboxId, (timeout+10)*SECONDS);
|
||||
SyncManager.runAsleep(mMailboxId, timeout+(10*SECONDS));
|
||||
}
|
||||
try {
|
||||
return client.execute(method);
|
||||
@ -624,56 +622,6 @@ public class EasSyncService extends AbstractSyncService {
|
||||
SyncManager.kick("push fallback");
|
||||
}
|
||||
|
||||
/**
|
||||
* Check the boxes reporting changes to see if there really were any...
|
||||
* We do this because bugs in various Exchange servers can put us into a looping
|
||||
* behavior by continually reporting changes in a mailbox, even when there aren't any.
|
||||
*
|
||||
* This behavior is seemingly random, and therefore we must code defensively by
|
||||
* backing off of push behavior when it is detected.
|
||||
*
|
||||
* One known cause, on certain Exchange 2003 servers, is acknowledged by Microsoft, and the
|
||||
* server hotfix for this case can be found at http://support.microsoft.com/kb/923282
|
||||
*/
|
||||
|
||||
void checkPingErrors(HashMap<String, Integer> errorMap) {
|
||||
mBindArguments[0] = Long.toString(mAccount.mId);
|
||||
for (String serverId: mPingChangeList) {
|
||||
// Find the id and sync status for each box
|
||||
mBindArguments[1] = serverId;
|
||||
Cursor c = mContentResolver.query(Mailbox.CONTENT_URI, SYNC_STATUS_PROJECTION,
|
||||
WHERE_ACCOUNT_KEY_AND_SERVER_ID, mBindArguments, null);
|
||||
try {
|
||||
if (c.moveToFirst()) {
|
||||
String status = c.getString(1);
|
||||
int type = SyncManager.getStatusType(status);
|
||||
// This check should always be true...
|
||||
if (type == SyncManager.SYNC_PING) {
|
||||
int changeCount = SyncManager.getStatusChangeCount(status);
|
||||
if (changeCount > 0) {
|
||||
errorMap.remove(serverId);
|
||||
} else if (changeCount == 0) {
|
||||
// This means that a ping reported changes in error; we keep a count
|
||||
// of consecutive errors of this kind
|
||||
Integer failures = errorMap.get(serverId);
|
||||
if (failures == null) {
|
||||
errorMap.put(serverId, 1);
|
||||
} else if (failures > MAX_PING_FAILURES) {
|
||||
// We'll back off of push for this box
|
||||
pushFallback(c.getLong(0));
|
||||
return;
|
||||
} else {
|
||||
errorMap.put(serverId, failures + 1);
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
} finally {
|
||||
c.close();
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
void runPingLoop() throws IOException, StaleFolderListException {
|
||||
int pingHeartbeat = mPingHeartbeat;
|
||||
userLog("runPingLoop");
|
||||
@ -683,7 +631,7 @@ public class EasSyncService extends AbstractSyncService {
|
||||
ArrayList<String> readyMailboxes = new ArrayList<String>();
|
||||
ArrayList<String> notReadyMailboxes = new ArrayList<String>();
|
||||
int pingWaitCount = 0;
|
||||
|
||||
|
||||
while ((System.currentTimeMillis() < endTime) && !mStop) {
|
||||
// Count of pushable mailboxes
|
||||
int pushCount = 0;
|
||||
@ -789,10 +737,10 @@ public class EasSyncService extends AbstractSyncService {
|
||||
int len = (int)e.getContentLength();
|
||||
InputStream is = res.getEntity().getContent();
|
||||
if (len > 0) {
|
||||
int status = parsePingResult(is, mContentResolver);
|
||||
int pingResult = parsePingResult(is, mContentResolver, pingErrorMap);
|
||||
// If our ping completed (status = 1), and we weren't forced and we're
|
||||
// not at the maximum, try increasing timeout by two minutes
|
||||
if (status == PROTOCOL_PING_STATUS_COMPLETED && !forcePing) {
|
||||
if (pingResult == PROTOCOL_PING_STATUS_COMPLETED && !forcePing) {
|
||||
if (pingHeartbeat > mPingHighWaterMark) {
|
||||
mPingHighWaterMark = pingHeartbeat;
|
||||
userLog("Setting high water mark at: ", mPingHighWaterMark);
|
||||
@ -805,8 +753,6 @@ public class EasSyncService extends AbstractSyncService {
|
||||
}
|
||||
userLog("Increasing ping heartbeat to ", pingHeartbeat, "s");
|
||||
}
|
||||
} else if (status == PROTOCOL_PING_STATUS_CHANGES_FOUND) {
|
||||
checkPingErrors(pingErrorMap);
|
||||
}
|
||||
} else {
|
||||
userLog("Ping returned empty result; throwing IOException");
|
||||
@ -883,7 +829,8 @@ public class EasSyncService extends AbstractSyncService {
|
||||
}
|
||||
}
|
||||
|
||||
private int parsePingResult(InputStream is, ContentResolver cr)
|
||||
private int parsePingResult(InputStream is, ContentResolver cr,
|
||||
HashMap<String, Integer> errorMap)
|
||||
throws IOException, StaleFolderListException {
|
||||
PingParser pp = new PingParser(is, this);
|
||||
if (pp.parse()) {
|
||||
@ -897,6 +844,49 @@ public class EasSyncService extends AbstractSyncService {
|
||||
WHERE_ACCOUNT_KEY_AND_SERVER_ID, mBindArguments, null);
|
||||
try {
|
||||
if (c.moveToFirst()) {
|
||||
|
||||
/**
|
||||
* Check the boxes reporting changes to see if there really were any...
|
||||
* We do this because bugs in various Exchange servers can put us into a
|
||||
* looping behavior by continually reporting changes in a mailbox, even when
|
||||
* there aren't any.
|
||||
*
|
||||
* This behavior is seemingly random, and therefore we must code defensively
|
||||
* by backing off of push behavior when it is detected.
|
||||
*
|
||||
* One known cause, on certain Exchange 2003 servers, is acknowledged by
|
||||
* Microsoft, and the server hotfix for this case can be found at
|
||||
* http://support.microsoft.com/kb/923282
|
||||
*/
|
||||
|
||||
// Check the status of the last sync
|
||||
String status = c.getString(Mailbox.CONTENT_SYNC_STATUS_COLUMN);
|
||||
int type = SyncManager.getStatusType(status);
|
||||
// This check should always be true...
|
||||
if (type == SyncManager.SYNC_PING) {
|
||||
int changeCount = SyncManager.getStatusChangeCount(status);
|
||||
if (changeCount > 0) {
|
||||
errorMap.remove(serverId);
|
||||
} else if (changeCount == 0) {
|
||||
// This means that a ping reported changes in error; we keep a count
|
||||
// of consecutive errors of this kind
|
||||
String name = c.getString(Mailbox.CONTENT_DISPLAY_NAME_COLUMN);
|
||||
Integer failures = errorMap.get(serverId);
|
||||
if (failures == null) {
|
||||
userLog("Last ping reported changes in error for: ", name);
|
||||
errorMap.put(serverId, 1);
|
||||
} else if (failures > MAX_PING_FAILURES) {
|
||||
// We'll back off of push for this box
|
||||
pushFallback(c.getLong(Mailbox.CONTENT_ID_COLUMN));
|
||||
continue;
|
||||
} else {
|
||||
userLog("Last ping reported changes in error for: ", name);
|
||||
errorMap.put(serverId, failures + 1);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// If there were no problems with previous sync, we'll start another one
|
||||
SyncManager.startManualSync(c.getLong(Mailbox.CONTENT_ID_COLUMN),
|
||||
SyncManager.SYNC_PING, null);
|
||||
}
|
||||
@ -975,7 +965,7 @@ public class EasSyncService extends AbstractSyncService {
|
||||
Serializer s = new Serializer();
|
||||
String className = target.getCollectionName();
|
||||
String syncKey = target.getSyncKey();
|
||||
userLog("Sending ", className, " syncKey: ", syncKey);
|
||||
userLog("sync, sending ", className, " syncKey: ", syncKey);
|
||||
s.start(Tags.SYNC_SYNC)
|
||||
.start(Tags.SYNC_COLLECTIONS)
|
||||
.start(Tags.SYNC_COLLECTION)
|
||||
@ -1022,6 +1012,8 @@ public class EasSyncService extends AbstractSyncService {
|
||||
if (is != null) {
|
||||
moreAvailable = target.parse(is);
|
||||
target.cleanup();
|
||||
} else {
|
||||
userLog("Empty input stream in sync command response");
|
||||
}
|
||||
} else {
|
||||
userLog("Sync response error: ", code);
|
||||
@ -1097,7 +1089,7 @@ public class EasSyncService extends AbstractSyncService {
|
||||
userLog("Uncaught exception in EasSyncService", e);
|
||||
} finally {
|
||||
if (!mStop) {
|
||||
userLog(mMailbox.mDisplayName, ": sync finished");
|
||||
userLog("Sync finished");
|
||||
SyncManager.done(this);
|
||||
// If this is the account mailbox, wake up SyncManager
|
||||
// Because this box has a "push" interval, it will be restarted immediately
|
||||
@ -1125,15 +1117,17 @@ public class EasSyncService extends AbstractSyncService {
|
||||
// Don't care if this fails
|
||||
}
|
||||
|
||||
// Save the sync time and status
|
||||
ContentValues cv = new ContentValues();
|
||||
cv.put(Mailbox.SYNC_TIME, System.currentTimeMillis());
|
||||
String s = "S" + mSyncReason + ':' + status + ':' + mChangeCount;
|
||||
cv.put(Mailbox.SYNC_STATUS, s);
|
||||
mContentResolver.update(ContentUris
|
||||
.withAppendedId(Mailbox.CONTENT_URI, mMailboxId), cv, null, null);
|
||||
if (mExitStatus == EXIT_DONE) {
|
||||
// Save the sync time and status
|
||||
ContentValues cv = new ContentValues();
|
||||
cv.put(Mailbox.SYNC_TIME, System.currentTimeMillis());
|
||||
String s = "S" + mSyncReason + ':' + status + ':' + mChangeCount;
|
||||
cv.put(Mailbox.SYNC_STATUS, s);
|
||||
mContentResolver.update(ContentUris.withAppendedId(Mailbox.CONTENT_URI,
|
||||
mMailboxId), cv, null, null);
|
||||
}
|
||||
} else {
|
||||
userLog(mMailbox.mDisplayName, ": stopped thread finished.");
|
||||
userLog("Stopped sync finished.");
|
||||
}
|
||||
|
||||
// Make sure SyncManager knows about this
|
||||
|
||||
@ -1065,8 +1065,16 @@ public class SyncManager extends Service implements Runnable {
|
||||
static public String alarmOwner(long id) {
|
||||
if (id == SYNC_MANAGER_ID) {
|
||||
return "SyncManager";
|
||||
} else
|
||||
return "Mailbox " + Long.toString(id);
|
||||
} else {
|
||||
String name = Long.toString(id);
|
||||
if (Eas.USER_LOG && INSTANCE != null) {
|
||||
Mailbox m = Mailbox.restoreMailboxWithId(INSTANCE, id);
|
||||
if (m != null) {
|
||||
name = m.mDisplayName + '(' + m.mAccountKey + ')';
|
||||
}
|
||||
}
|
||||
return "Mailbox " + name;
|
||||
}
|
||||
}
|
||||
|
||||
private void clearAlarm(long id) {
|
||||
@ -1075,7 +1083,7 @@ public class SyncManager extends Service implements Runnable {
|
||||
if (pi != null) {
|
||||
AlarmManager alarmManager = (AlarmManager)getSystemService(Context.ALARM_SERVICE);
|
||||
alarmManager.cancel(pi);
|
||||
//log("+Alarm cleared for " + alarmOwner(id));
|
||||
log("+Alarm cleared for " + alarmOwner(id));
|
||||
mPendingIntents.remove(id);
|
||||
}
|
||||
}
|
||||
@ -1093,7 +1101,7 @@ public class SyncManager extends Service implements Runnable {
|
||||
|
||||
AlarmManager alarmManager = (AlarmManager)getSystemService(Context.ALARM_SERVICE);
|
||||
alarmManager.set(AlarmManager.RTC_WAKEUP, System.currentTimeMillis() + millis, pi);
|
||||
//log("+Alarm set for " + alarmOwner(id) + ", " + millis/1000 + "s");
|
||||
log("+Alarm set for " + alarmOwner(id) + ", " + millis/1000 + "s");
|
||||
}
|
||||
}
|
||||
}
|
||||
@ -1319,7 +1327,7 @@ public class SyncManager extends Service implements Runnable {
|
||||
(ConnectivityManager)getSystemService(Context.CONNECTIVITY_SERVICE);
|
||||
NetworkInfo info = cm.getActiveNetworkInfo();
|
||||
if (info != null) {
|
||||
log("NetworkInfo: " + info.getTypeName() + ", " + info.getState().name());
|
||||
//log("NetworkInfo: " + info.getTypeName() + ", " + info.getState().name());
|
||||
return;
|
||||
} else {
|
||||
|
||||
@ -1396,7 +1404,7 @@ public class SyncManager extends Service implements Runnable {
|
||||
}
|
||||
if (nextWait > 10*SECONDS) {
|
||||
log("Next awake in " + nextWait / 1000 + "s: " + mNextWaitReason);
|
||||
runAsleep(SYNC_MANAGER_ID, nextWait + 1000);
|
||||
runAsleep(SYNC_MANAGER_ID, nextWait + (3*SECONDS));
|
||||
}
|
||||
wait(nextWait);
|
||||
}
|
||||
|
||||
@ -183,6 +183,7 @@ public abstract class AbstractSyncParser extends Parser {
|
||||
}
|
||||
|
||||
// Let the caller know that there's more to do
|
||||
userLog("Returning moreAvailable = " + moreAvailable);
|
||||
return moreAvailable;
|
||||
}
|
||||
|
||||
|
||||
@ -444,9 +444,13 @@ public class EmailSyncAdapter extends AbstractSyncAdapter {
|
||||
.build());
|
||||
}
|
||||
}
|
||||
|
||||
// We only want to update the sync key here
|
||||
ContentValues mailboxValues = new ContentValues();
|
||||
mailboxValues.put(Mailbox.SYNC_KEY, mMailbox.mSyncKey);
|
||||
ops.add(ContentProviderOperation.newUpdate(
|
||||
ContentUris.withAppendedId(Mailbox.CONTENT_URI, mMailbox.mId)).withValues(
|
||||
mMailbox.toContentValues()).build());
|
||||
ContentUris.withAppendedId(Mailbox.CONTENT_URI, mMailbox.mId))
|
||||
.withValues(mailboxValues).build());
|
||||
|
||||
addCleanupOps(ops);
|
||||
|
||||
|
||||
Loading…
Reference in New Issue
Block a user