1 /* 2 * Copyright (C) 2011 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package com.android.exchange; 18 19 import android.content.ContentResolver; 20 import android.content.ContentUris; 21 import android.content.ContentValues; 22 import android.content.Context; 23 import android.database.Cursor; 24 import android.net.TrafficStats; 25 import android.os.SystemClock; 26 import android.provider.CalendarContract; 27 import android.provider.ContactsContract; 28 import android.text.TextUtils; 29 import android.text.format.DateUtils; 30 31 import com.android.emailcommon.TrafficFlags; 32 import com.android.emailcommon.mail.MessagingException; 33 import com.android.emailcommon.provider.Account; 34 import com.android.emailcommon.provider.EmailContent; 35 import com.android.emailcommon.provider.EmailContent.AccountColumns; 36 import com.android.emailcommon.provider.EmailContent.HostAuthColumns; 37 import com.android.emailcommon.provider.EmailContent.MailboxColumns; 38 import com.android.emailcommon.provider.HostAuth; 39 import com.android.emailcommon.provider.Mailbox; 40 import com.android.emailcommon.provider.MailboxUtilities; 41 import com.android.emailcommon.provider.Policy; 42 import com.android.emailcommon.provider.ProviderUnavailableException; 43 import com.android.emailcommon.service.PolicyServiceProxy; 44 import com.android.exchange.CommandStatusException.CommandStatus; 45 import com.android.exchange.adapter.AccountSyncAdapter; 46 import com.android.exchange.adapter.FolderSyncParser; 47 import com.android.exchange.adapter.Parser.EasParserException; 48 import com.android.exchange.adapter.PingParser; 49 import com.android.exchange.adapter.Serializer; 50 import com.android.exchange.adapter.Tags; 51 import com.android.mail.utils.LogUtils; 52 import com.google.common.annotations.VisibleForTesting; 53 54 import org.apache.http.Header; 55 import org.apache.http.HttpStatus; 56 import org.apache.http.entity.ByteArrayEntity; 57 58 import java.io.IOException; 59 import java.io.InputStream; 60 import java.util.ArrayList; 61 import java.util.HashMap; 62 63 /** 64 * AccountMailbox handles sync for the EAS "account mailbox"; this includes sync of the mailbox list 65 * as well as management of mailbox push (using the EAS "Ping" command 66 */ 67 public class EasAccountService extends EasSyncService { 68 private static final String WHERE_ACCOUNT_AND_SYNC_INTERVAL_PING = 69 MailboxColumns.ACCOUNT_KEY + "=? and " + MailboxColumns.SYNC_INTERVAL + 70 '=' + Mailbox.CHECK_INTERVAL_PING; 71 private static final String AND_FREQUENCY_PING_PUSH_AND_NOT_ACCOUNT_MAILBOX = " AND " + 72 MailboxColumns.SYNC_INTERVAL + " IN (" + Mailbox.CHECK_INTERVAL_PING + 73 ',' + Mailbox.CHECK_INTERVAL_PUSH + ") AND " + MailboxColumns.TYPE + "!=\"" + 74 Mailbox.TYPE_EAS_ACCOUNT_MAILBOX + '\"'; 75 private static final String WHERE_PUSH_HOLD_NOT_ACCOUNT_MAILBOX = 76 MailboxColumns.ACCOUNT_KEY + "=? and " + MailboxColumns.SYNC_INTERVAL + 77 '=' + Mailbox.CHECK_INTERVAL_PUSH_HOLD; 78 private static final String WHERE_ACCOUNT_KEY_AND_SERVER_ID = 79 MailboxColumns.ACCOUNT_KEY + "=? and " + MailboxColumns.SERVER_ID + "=?"; 80 protected static final String WHERE_IN_ACCOUNT_AND_PUSHABLE = 81 MailboxColumns.ACCOUNT_KEY + "=? and type in (" + Mailbox.TYPE_INBOX + ',' 82 + Mailbox.TYPE_EAS_ACCOUNT_MAILBOX + ',' + Mailbox.TYPE_CONTACTS + ',' 83 + Mailbox.TYPE_CALENDAR + ')'; 84 85 /** 86 * We start with an 8 minute timeout, and increase/decrease by 3 minutes at a time. There's 87 * no point having a timeout shorter than 5 minutes, I think; at that point, we can just let 88 * the ping exception out. The maximum I use is 17 minutes, which is really an empirical 89 * choice; too long and we risk silent connection loss and loss of push for that period. Too 90 * short and we lose efficiency/battery life. 91 * 92 * If we ever have to drop the ping timeout, we'll never increase it again. There's no point 93 * going into hysteresis; the NAT timeout isn't going to change without a change in connection, 94 * which will cause the sync service to be restarted at the starting heartbeat and going through 95 * the process again. 96 */ 97 static private final int PING_MINUTES = 60; // in seconds 98 static private final int PING_FUDGE_LOW = 10; 99 static private final int PING_STARTING_HEARTBEAT = (8*PING_MINUTES)-PING_FUDGE_LOW; 100 static private final int PING_HEARTBEAT_INCREMENT = 3*PING_MINUTES; 101 102 static private final int PROTOCOL_PING_STATUS_COMPLETED = 1; 103 static private final int PROTOCOL_PING_STATUS_BAD_PARAMETERS = 3; 104 static private final int PROTOCOL_PING_STATUS_RETRY = 8; 105 106 // Fallbacks (in minutes) for ping loop failures 107 static private final int MAX_PING_FAILURES = 1; 108 static private final int PING_FALLBACK_INBOX = 5; 109 static private final int PING_FALLBACK_PIM = 25; 110 111 // The amount of time the account mailbox will sleep if there are no pingable mailboxes 112 // This could happen if the sync time is set to "never"; we always want to check in from time 113 // to time, however, for folder list/policy changes 114 static private final int ACCOUNT_MAILBOX_SLEEP_TIME = (int)(20 * DateUtils.MINUTE_IN_MILLIS); 115 static private final String ACCOUNT_MAILBOX_SLEEP_TEXT = "Account mailbox sleeping for " + 116 (ACCOUNT_MAILBOX_SLEEP_TIME / DateUtils.MINUTE_IN_MILLIS) + "m"; 117 118 // Our heartbeat when we are waiting for ping boxes to be ready 119 /*package*/ int mPingForceHeartbeat = 2*PING_MINUTES; 120 // The minimum heartbeat we will send 121 /*package*/ int mPingMinHeartbeat = (5*PING_MINUTES)-PING_FUDGE_LOW; 122 // The maximum heartbeat we will send 123 /*package*/ int mPingMaxHeartbeat = (17*PING_MINUTES)-PING_FUDGE_LOW; 124 // The ping time (in seconds) 125 /*package*/ int mPingHeartbeat = PING_STARTING_HEARTBEAT; 126 // The longest successful ping heartbeat 127 private int mPingHighWaterMark = 0; 128 // Whether we've ever lowered the heartbeat 129 /*package*/ boolean mPingHeartbeatDropped = false; 130 131 private final String[] mBindArguments = new String[2]; 132 private ArrayList<String> mPingChangeList; 133 134 protected EasAccountService(Context _context, Mailbox _mailbox) { 135 super(_context, _mailbox); 136 } 137 138 @VisibleForTesting 139 protected EasAccountService() { 140 } 141 142 @Override 143 public void run() { 144 mExitStatus = EXIT_DONE; 145 try { 146 // Make sure account and mailbox are still valid 147 if (!setupService()) return; 148 // If we've been stopped, we're done 149 if (mStop) return; 150 151 try { 152 mDeviceId = ExchangeService.getDeviceId(mContext); 153 int trafficFlags = TrafficFlags.getSyncFlags(mContext, mAccount); 154 TrafficStats.setThreadStatsTag(trafficFlags | TrafficFlags.DATA_EMAIL); 155 if ((mMailbox == null) || (mAccount == null)) { 156 return; 157 } else { 158 sync(); 159 } 160 } catch (EasAuthenticationException e) { 161 userLog("Caught authentication error"); 162 mExitStatus = EXIT_LOGIN_FAILURE; 163 } catch (IOException e) { 164 String message = e.getMessage(); 165 userLog("Caught IOException: ", (message == null) ? "No message" : message); 166 mExitStatus = EXIT_IO_ERROR; 167 } catch (Exception e) { 168 userLog("Uncaught exception in AccountMailboxService", e); 169 } finally { 170 ExchangeService.done(this); 171 if (!mStop) { 172 userLog("Sync finished"); 173 switch (mExitStatus) { 174 case EXIT_SECURITY_FAILURE: 175 // Ask for a new folder list. This should wake up the account mailbox; a 176 // security error in account mailbox should start provisioning 177 ExchangeService.reloadFolderList(mContext, mAccount.mId, true); 178 break; 179 case EXIT_EXCEPTION: 180 errorLog("Sync ended due to an exception."); 181 break; 182 } 183 } else { 184 userLog("Stopped sync finished."); 185 } 186 187 // Make sure ExchangeService knows about this 188 ExchangeService.kick("sync finished"); 189 } 190 } catch (ProviderUnavailableException e) { 191 LogUtils.e(TAG, "EmailProvider unavailable; sync ended prematurely"); 192 } 193 } 194 195 /** 196 * If possible, update the account to the new server address; report result 197 * @param resp the EasResponse from the current POST 198 * @return whether or not the redirect is handled and the POST should be retried 199 */ 200 private boolean canHandleAccountMailboxRedirect(EasResponse resp) { 201 userLog("AccountMailbox redirect error"); 202 HostAuth ha = 203 HostAuth.restoreHostAuthWithId(mContext, mAccount.mHostAuthKeyRecv); 204 if (ha != null && getValidateRedirect(resp, ha)) { 205 // Update the account's HostAuth with new values 206 ContentValues haValues = new ContentValues(); 207 haValues.put(HostAuthColumns.ADDRESS, ha.mAddress); 208 ha.update(mContext, haValues); 209 return true; 210 } 211 return false; 212 } 213 214 /** 215 * Performs FolderSync 216 * 217 * @throws IOException 218 * @throws EasParserException 219 */ 220 public void sync() throws IOException, EasParserException { 221 // Check that the account's mailboxes are consistent 222 MailboxUtilities.checkMailboxConsistency(mContext, mAccount.mId); 223 // Initialize exit status to success 224 try { 225 if (mAccount.mSyncKey == null) { 226 mAccount.mSyncKey = "0"; 227 userLog("Account syncKey INIT to 0"); 228 ContentValues cv = new ContentValues(); 229 cv.put(AccountColumns.SYNC_KEY, mAccount.mSyncKey); 230 mAccount.update(mContext, cv); 231 } 232 233 boolean firstSync = mAccount.mSyncKey.equals("0"); 234 if (firstSync) { 235 userLog("Initial FolderSync"); 236 } 237 238 // When we first start up, change all mailboxes to push. 239 ContentValues cv = new ContentValues(); 240 cv.put(Mailbox.SYNC_INTERVAL, Mailbox.CHECK_INTERVAL_PUSH); 241 if (mContentResolver.update(Mailbox.CONTENT_URI, cv, 242 WHERE_ACCOUNT_AND_SYNC_INTERVAL_PING, 243 new String[] {Long.toString(mAccount.mId)}) > 0) { 244 ExchangeService.kick("change ping boxes to push"); 245 } 246 247 // Determine our protocol version, if we haven't already and save it in the Account 248 // Also re-check protocol version at least once a day (in case of upgrade) 249 if (mAccount.mProtocolVersion == null || firstSync || 250 ((System.currentTimeMillis() - mMailbox.mSyncTime) > DateUtils.DAY_IN_MILLIS)) { 251 userLog("Determine EAS protocol version"); 252 EasResponse resp = sendHttpClientOptions(); 253 try { 254 int code = resp.getStatus(); 255 userLog("OPTIONS response: ", code); 256 if (code == HttpStatus.SC_OK) { 257 Header header = resp.getHeader("MS-ASProtocolCommands"); 258 userLog(header.getValue()); 259 header = resp.getHeader("ms-asprotocolversions"); 260 try { 261 setupProtocolVersion(this, header); 262 } catch (MessagingException e) { 263 // Since we've already validated, this can't really happen 264 // But if it does, we'll rethrow this... 265 throw new IOException(e); 266 } 267 // Save the protocol version 268 cv.clear(); 269 // Save the protocol version in the account; if we're using 12.0 or greater, 270 // set the flag for support of SmartForward 271 cv.put(Account.PROTOCOL_VERSION, mProtocolVersion); 272 if (mProtocolVersionDouble >= 12.0) { 273 cv.put(Account.FLAGS, 274 mAccount.mFlags | 275 Account.FLAGS_SUPPORTS_SMART_FORWARD | 276 Account.FLAGS_SUPPORTS_SEARCH | 277 Account.FLAGS_SUPPORTS_GLOBAL_SEARCH); 278 } 279 mAccount.update(mContext, cv); 280 cv.clear(); 281 // Save the sync time of the account mailbox to current time 282 cv.put(Mailbox.SYNC_TIME, System.currentTimeMillis()); 283 mMailbox.update(mContext, cv); 284 } else if (code == EAS_REDIRECT_CODE && canHandleAccountMailboxRedirect(resp)) { 285 // Cause this to re-run 286 throw new IOException("Will retry after a brief hold..."); 287 } else if (resp.isProvisionError()) { 288 throw new CommandStatusException(CommandStatus.NEEDS_PROVISIONING); 289 } else if (resp.isAuthError()) { 290 mExitStatus = EasSyncService.EXIT_LOGIN_FAILURE; 291 return; 292 } else { 293 errorLog("OPTIONS command failed; throwing IOException"); 294 throw new IOException(); 295 } 296 } finally { 297 resp.close(); 298 } 299 } 300 301 // Change all pushable boxes to push when we start the account mailbox 302 if (mAccount.mSyncInterval == Account.CHECK_INTERVAL_PUSH) { 303 cv.clear(); 304 cv.put(Mailbox.SYNC_INTERVAL, Mailbox.CHECK_INTERVAL_PUSH); 305 if (mContentResolver.update(Mailbox.CONTENT_URI, cv, 306 WHERE_IN_ACCOUNT_AND_PUSHABLE, 307 new String[] {Long.toString(mAccount.mId)}) > 0) { 308 userLog("Push account; set pushable boxes to push..."); 309 } 310 } 311 312 while (!isStopped()) { 313 // If we're not allowed to sync (e.g. roaming policy), leave now 314 if (!ExchangeService.canAutoSync(mAccount)) { 315 if (ExchangeService.onSecurityHold(mAccount)) { 316 mExitStatus = EasSyncService.EXIT_SECURITY_FAILURE; 317 } else { 318 // Use backoff rules, etc. 319 mExitStatus = EasSyncService.EXIT_IO_ERROR; 320 } 321 return; 322 } 323 userLog("Sending Account syncKey: ", mAccount.mSyncKey); 324 Serializer s = new Serializer(); 325 s.start(Tags.FOLDER_FOLDER_SYNC).start(Tags.FOLDER_SYNC_KEY) 326 .text(mAccount.mSyncKey).end().end().done(); 327 EasResponse resp = sendHttpClientPost("FolderSync", s.toByteArray()); 328 try { 329 if (isStopped()) break; 330 int code = resp.getStatus(); 331 if (code == HttpStatus.SC_OK) { 332 if (!resp.isEmpty()) { 333 InputStream is = resp.getInputStream(); 334 // Returns true if we need to sync again 335 if (new FolderSyncParser(is, 336 new AccountSyncAdapter(this)).parse()) { 337 continue; 338 } 339 } 340 } else if (resp.isProvisionError()) { 341 throw new CommandStatusException(CommandStatus.NEEDS_PROVISIONING); 342 } else if (resp.isAuthError()) { 343 mExitStatus = EasSyncService.EXIT_LOGIN_FAILURE; 344 return; 345 } else if (code == EAS_REDIRECT_CODE && canHandleAccountMailboxRedirect(resp)) { 346 // This will cause a retry of the FolderSync 347 continue; 348 } else { 349 userLog("FolderSync response error: ", code); 350 } 351 } finally { 352 resp.close(); 353 } 354 355 // Change all push/hold boxes to push 356 cv.clear(); 357 cv.put(Mailbox.SYNC_INTERVAL, Account.CHECK_INTERVAL_PUSH); 358 if (mContentResolver.update(Mailbox.CONTENT_URI, cv, 359 WHERE_PUSH_HOLD_NOT_ACCOUNT_MAILBOX, 360 new String[] {Long.toString(mAccount.mId)}) > 0) { 361 userLog("Set push/hold boxes to push..."); 362 } 363 364 // Before each run of the pingLoop, if this Account has a PolicySet, make sure it's 365 // active; otherwise, clear out the key/flag. This should cause a provisioning 366 // error on the next POST, and start the security sequence over again 367 String key = mAccount.mSecuritySyncKey; 368 if (!TextUtils.isEmpty(key)) { 369 Policy policy = Policy.restorePolicyWithId(mContext, mAccount.mPolicyKey); 370 if ((policy != null) && !PolicyServiceProxy.isActive(mContext, policy)) { 371 resetSecurityPolicies(); 372 } 373 } 374 375 // Wait for push notifications. 376 String threadName = Thread.currentThread().getName(); 377 try { 378 runPingLoop(); 379 } catch (StaleFolderListException e) { 380 // We break out if we get told about a stale folder list 381 userLog("Ping interrupted; folder list requires sync..."); 382 } catch (IllegalHeartbeatException e) { 383 // If we're sending an illegal heartbeat, reset either the min or the max to 384 // that heartbeat 385 resetHeartbeats(e.mLegalHeartbeat); 386 } finally { 387 Thread.currentThread().setName(threadName); 388 } 389 } 390 } catch (CommandStatusException e) { 391 // If the sync error is a provisioning failure (perhaps policies changed), 392 // let's try the provisioning procedure 393 // Provisioning must only be attempted for the account mailbox - trying to 394 // provision any other mailbox may result in race conditions and the 395 // creation of multiple policy keys. 396 int status = e.mStatus; 397 if (CommandStatus.isNeedsProvisioning(status)) { 398 if (!tryProvision(this)) { 399 // Set the appropriate failure status 400 mExitStatus = EasSyncService.EXIT_SECURITY_FAILURE; 401 return; 402 } 403 } else if (CommandStatus.isDeniedAccess(status)) { 404 mExitStatus = EasSyncService.EXIT_ACCESS_DENIED; 405 return; 406 } else { 407 userLog("Unexpected status: " + CommandStatus.toString(status)); 408 mExitStatus = EasSyncService.EXIT_EXCEPTION; 409 } 410 } 411 } 412 413 /** 414 * Reset either our minimum or maximum ping heartbeat to a heartbeat known to be legal 415 * @param legalHeartbeat a known legal heartbeat (from the EAS server) 416 */ 417 /*package*/ void resetHeartbeats(int legalHeartbeat) { 418 userLog("Resetting min/max heartbeat, legal = " + legalHeartbeat); 419 // We are here because the current heartbeat (mPingHeartbeat) is invalid. Depending on 420 // whether the argument is above or below the current heartbeat, we can infer the need to 421 // change either the minimum or maximum heartbeat 422 if (legalHeartbeat > mPingHeartbeat) { 423 // The legal heartbeat is higher than the ping heartbeat; therefore, our minimum was 424 // too low. We respond by raising either or both of the minimum heartbeat or the 425 // force heartbeat to the argument value 426 if (mPingMinHeartbeat < legalHeartbeat) { 427 mPingMinHeartbeat = legalHeartbeat; 428 } 429 if (mPingForceHeartbeat < legalHeartbeat) { 430 mPingForceHeartbeat = legalHeartbeat; 431 } 432 // If our minimum is now greater than the max, bring them together 433 if (mPingMinHeartbeat > mPingMaxHeartbeat) { 434 mPingMaxHeartbeat = legalHeartbeat; 435 } 436 } else if (legalHeartbeat < mPingHeartbeat) { 437 // The legal heartbeat is lower than the ping heartbeat; therefore, our maximum was 438 // too high. We respond by lowering the maximum to the argument value 439 mPingMaxHeartbeat = legalHeartbeat; 440 // If our maximum is now less than the minimum, bring them together 441 if (mPingMaxHeartbeat < mPingMinHeartbeat) { 442 mPingMinHeartbeat = legalHeartbeat; 443 } 444 } 445 // Set current heartbeat to the legal heartbeat 446 mPingHeartbeat = legalHeartbeat; 447 // Allow the heartbeat logic to run 448 mPingHeartbeatDropped = false; 449 } 450 451 private void pushFallback(long mailboxId) { 452 Mailbox mailbox = Mailbox.restoreMailboxWithId(mContext, mailboxId); 453 if (mailbox == null) { 454 return; 455 } 456 ContentValues cv = new ContentValues(); 457 int mins = PING_FALLBACK_PIM; 458 if (mailbox.mType == Mailbox.TYPE_INBOX) { 459 mins = PING_FALLBACK_INBOX; 460 } 461 cv.put(Mailbox.SYNC_INTERVAL, mins); 462 mContentResolver.update(ContentUris.withAppendedId(Mailbox.CONTENT_URI, mailboxId), 463 cv, null, null); 464 errorLog("*** PING ERROR LOOP: Set " + mailbox.mDisplayName + " to " + mins 465 + " min sync"); 466 ExchangeService.kick("push fallback"); 467 } 468 469 /** 470 * Simplistic attempt to determine a NAT timeout, based on experience with various carriers 471 * and networks. The string "reset by peer" is very common in these situations, so we look for 472 * that specifically. We may add additional tests here as more is learned. 473 * @param message 474 * @return whether this message is likely associated with a NAT failure 475 */ 476 private static boolean isLikelyNatFailure(String message) { 477 if (message == null) return false; 478 if (message.contains("reset by peer")) { 479 return true; 480 } 481 return false; 482 } 483 484 private void sleep(long ms, boolean runAsleep) { 485 if (runAsleep) { 486 ExchangeService.runAsleep(mMailboxId, ms + (5 * DateUtils.SECOND_IN_MILLIS)); 487 } 488 try { 489 Thread.sleep(ms); 490 } catch (InterruptedException e) { 491 // Doesn't matter whether we stop early; it's the thought that counts 492 } finally { 493 if (runAsleep) { 494 ExchangeService.runAwake(mMailboxId); 495 } 496 } 497 } 498 499 protected EasResponse sendPing(byte[] bytes, int heartbeat) throws IOException { 500 Thread.currentThread().setName(mAccount.mDisplayName + ": Ping"); 501 if (Eas.USER_LOG) { 502 userLog("Send ping, timeout: " + heartbeat + "s, high: " + mPingHighWaterMark + 's'); 503 } 504 return sendHttpClientPost(EasSyncService.PING_COMMAND, new ByteArrayEntity(bytes), 505 (int)((heartbeat + 5) * DateUtils.SECOND_IN_MILLIS)); 506 } 507 508 private void runPingLoop() throws IOException, StaleFolderListException, 509 IllegalHeartbeatException, CommandStatusException { 510 int pingHeartbeat = mPingHeartbeat; 511 userLog("runPingLoop"); 512 // Do push for all sync services here 513 long endTime = System.currentTimeMillis() + (30 * DateUtils.MINUTE_IN_MILLIS); 514 HashMap<String, Integer> pingErrorMap = new HashMap<String, Integer>(); 515 ArrayList<String> readyMailboxes = new ArrayList<String>(); 516 ArrayList<String> notReadyMailboxes = new ArrayList<String>(); 517 int pingWaitCount = 0; 518 long inboxId = -1; 519 android.accounts.Account amAccount = new android.accounts.Account(mAccount.mEmailAddress, 520 Eas.EXCHANGE_ACCOUNT_MANAGER_TYPE); 521 while ((System.currentTimeMillis() < endTime) && !isStopped()) { 522 // Count of pushable mailboxes 523 int pushCount = 0; 524 // Count of mailboxes that can be pushed right now 525 int canPushCount = 0; 526 // Count of uninitialized boxes 527 int uninitCount = 0; 528 529 Serializer s = new Serializer(); 530 Cursor c = mContentResolver.query(Mailbox.CONTENT_URI, Mailbox.CONTENT_PROJECTION, 531 MailboxColumns.ACCOUNT_KEY + '=' + mAccount.mId + 532 AND_FREQUENCY_PING_PUSH_AND_NOT_ACCOUNT_MAILBOX, null, null); 533 if (c == null) throw new ProviderUnavailableException(); 534 notReadyMailboxes.clear(); 535 readyMailboxes.clear(); 536 // Look for an inbox, and remember its id 537 if (inboxId == -1) { 538 inboxId = Mailbox.findMailboxOfType(mContext, mAccount.mId, Mailbox.TYPE_INBOX); 539 } 540 try { 541 // Loop through our pushed boxes seeing what is available to push 542 while (c.moveToNext()) { 543 pushCount++; 544 // Two requirements for push: 545 // 1) ExchangeService tells us the mailbox is syncable (not running/not stopped) 546 // 2) The syncKey isn't "0" (i.e. it's synced at least once) 547 long mailboxId = c.getLong(Mailbox.CONTENT_ID_COLUMN); 548 String mailboxName = c.getString(Mailbox.CONTENT_DISPLAY_NAME_COLUMN); 549 550 // See what type of box we've got and get authority 551 int mailboxType = c.getInt(Mailbox.CONTENT_TYPE_COLUMN); 552 String authority = EmailContent.AUTHORITY; 553 switch(mailboxType) { 554 case Mailbox.TYPE_CALENDAR: 555 authority = CalendarContract.AUTHORITY; 556 break; 557 case Mailbox.TYPE_CONTACTS: 558 authority = ContactsContract.AUTHORITY; 559 break; 560 } 561 562 // See whether we can ping for this mailbox 563 int pingStatus; 564 if (!ContentResolver.getSyncAutomatically(amAccount, authority)) { 565 pingStatus = ExchangeService.PING_STATUS_DISABLED; 566 } else { 567 pingStatus = ExchangeService.pingStatus(mailboxId); 568 569 } 570 571 if (pingStatus == ExchangeService.PING_STATUS_OK) { 572 String syncKey = c.getString(Mailbox.CONTENT_SYNC_KEY_COLUMN); 573 if ((syncKey == null) || syncKey.equals("0")) { 574 // We can't push until the initial sync is done 575 pushCount--; 576 uninitCount++; 577 continue; 578 } 579 580 if (canPushCount++ == 0) { 581 // Initialize the Ping command 582 s.start(Tags.PING_PING) 583 .data(Tags.PING_HEARTBEAT_INTERVAL, 584 Integer.toString(pingHeartbeat)) 585 .start(Tags.PING_FOLDERS); 586 } 587 588 String folderClass = getTargetCollectionClassFromCursor(c); 589 s.start(Tags.PING_FOLDER) 590 .data(Tags.PING_ID, c.getString(Mailbox.CONTENT_SERVER_ID_COLUMN)) 591 .data(Tags.PING_CLASS, folderClass) 592 .end(); 593 readyMailboxes.add(mailboxName); 594 } else if ((pingStatus == ExchangeService.PING_STATUS_RUNNING) || 595 (pingStatus == ExchangeService.PING_STATUS_WAITING)) { 596 notReadyMailboxes.add(mailboxName); 597 } else if (pingStatus == ExchangeService.PING_STATUS_UNABLE) { 598 pushCount--; 599 userLog(mailboxName, " in error state; ignore"); 600 continue; 601 } else if (pingStatus == ExchangeService.PING_STATUS_DISABLED) { 602 pushCount--; 603 userLog(mailboxName, " disabled by user; ignore"); 604 continue; 605 } 606 } 607 } finally { 608 c.close(); 609 } 610 611 if (Eas.USER_LOG) { 612 if (!notReadyMailboxes.isEmpty()) { 613 userLog("Ping not ready for: " + notReadyMailboxes); 614 } 615 if (!readyMailboxes.isEmpty()) { 616 userLog("Ping ready for: " + readyMailboxes); 617 } 618 } 619 620 // If we've waited 10 seconds or more, just ping with whatever boxes are ready 621 // But use a shorter than normal heartbeat 622 boolean forcePing = !notReadyMailboxes.isEmpty() && (pingWaitCount > 5); 623 624 if ((canPushCount > 0) && ((canPushCount == pushCount) || forcePing)) { 625 // If all pingable boxes are ready for push, send Ping to the server 626 s.end().end().done(); 627 pingWaitCount = 0; 628 mPostAborted = false; 629 mPostReset = false; 630 631 // If we've been stopped, this is a good time to return 632 if (isStopped()) return; 633 634 long pingTime = SystemClock.elapsedRealtime(); 635 try { 636 // Send the ping, wrapped by appropriate timeout/alarm 637 if (forcePing) { 638 userLog("Forcing ping after waiting for all boxes to be ready"); 639 } 640 EasResponse resp = 641 sendPing(s.toByteArray(), forcePing ? mPingForceHeartbeat : pingHeartbeat); 642 643 try { 644 int code = resp.getStatus(); 645 userLog("Ping response: ", code); 646 647 // If we're not allowed to sync (e.g. roaming policy), terminate gracefully 648 // now; otherwise we might start a sync based on the response 649 if (!ExchangeService.canAutoSync(mAccount)) { 650 stop(); 651 } 652 653 // Return immediately if we've been asked to stop during the ping 654 if (isStopped()) { 655 userLog("Stopping pingLoop"); 656 return; 657 } 658 659 if (code == HttpStatus.SC_OK) { 660 if (!resp.isEmpty()) { 661 InputStream is = resp.getInputStream(); 662 int pingResult = parsePingResult(is, mContentResolver, 663 pingErrorMap); 664 // If our ping completed (status = 1), and wasn't forced and we're 665 // not at the maximum, try increasing timeout by two minutes 666 if (pingResult == PROTOCOL_PING_STATUS_COMPLETED && !forcePing) { 667 if (pingHeartbeat > mPingHighWaterMark) { 668 mPingHighWaterMark = pingHeartbeat; 669 userLog("Setting high water mark at: ", mPingHighWaterMark); 670 } 671 if ((pingHeartbeat < mPingMaxHeartbeat) && 672 !mPingHeartbeatDropped) { 673 pingHeartbeat += PING_HEARTBEAT_INCREMENT; 674 if (pingHeartbeat > mPingMaxHeartbeat) { 675 pingHeartbeat = mPingMaxHeartbeat; 676 } 677 userLog("Increase ping heartbeat to ", pingHeartbeat, "s"); 678 } 679 } else if (pingResult == PROTOCOL_PING_STATUS_BAD_PARAMETERS || 680 pingResult == PROTOCOL_PING_STATUS_RETRY) { 681 // These errors appear to be server-related (I've seen a bad 682 // parameters result with known good parameters...) 683 userLog("Server error during Ping: " + pingResult); 684 // Act as if we have an IOException (backoff, etc.) 685 throw new IOException(); 686 } 687 // Make sure to clear out any pending sync errors 688 ExchangeService.removeFromSyncErrorMap(mMailboxId); 689 } else { 690 userLog("Ping returned empty result; throwing IOException"); 691 // Act as if we have an IOException (backoff, etc.) 692 throw new IOException(); 693 } 694 } else if (resp.isAuthError()) { 695 mExitStatus = EasSyncService.EXIT_LOGIN_FAILURE; 696 userLog("Authorization error during Ping: ", code); 697 throw new IOException(); 698 } 699 } finally { 700 resp.close(); 701 } 702 } catch (IOException e) { 703 String message = e.getMessage(); 704 // If we get the exception that is indicative of a NAT timeout and if we 705 // haven't yet "fixed" the timeout, back off by two minutes and "fix" it 706 boolean hasMessage = message != null; 707 userLog("IOException runPingLoop: " + (hasMessage ? message : "[no message]")); 708 if (mPostReset) { 709 // Nothing to do in this case; this is ExchangeService telling us to try 710 // another ping. 711 } else if (mPostAborted || isLikelyNatFailure(message)) { 712 long pingLength = SystemClock.elapsedRealtime() - pingTime; 713 if ((pingHeartbeat > mPingMinHeartbeat) && 714 (pingHeartbeat > mPingHighWaterMark)) { 715 pingHeartbeat -= PING_HEARTBEAT_INCREMENT; 716 mPingHeartbeatDropped = true; 717 if (pingHeartbeat < mPingMinHeartbeat) { 718 pingHeartbeat = mPingMinHeartbeat; 719 } 720 userLog("Decreased ping heartbeat to ", pingHeartbeat, "s"); 721 } else if (mPostAborted) { 722 // There's no point in throwing here; this can happen in two cases 723 // 1) An alarm, which indicates minutes without activity; no sense 724 // backing off 725 // 2) ExchangeService abort, due to sync of mailbox. Again, we want to 726 // keep on trying to ping 727 userLog("Ping aborted; retry"); 728 } else if (pingLength < 2000) { 729 userLog("Abort or NAT type return < 2 seconds; throwing IOException"); 730 throw e; 731 } else { 732 userLog("NAT type IOException"); 733 } 734 } else if (hasMessage && message.contains("roken pipe")) { 735 // The "broken pipe" error (uppercase or lowercase "b") seems to be an 736 // internal error, so let's not throw an exception (which leads to delays) 737 // but rather simply run through the loop again 738 } else { 739 throw e; 740 } 741 } 742 } else if (forcePing) { 743 // In this case, there aren't any boxes that are pingable, but there are boxes 744 // waiting (for IOExceptions) 745 userLog("pingLoop waiting 60s for any pingable boxes"); 746 sleep(60 * DateUtils.SECOND_IN_MILLIS, true); 747 } else if (pushCount > 0) { 748 // If we want to Ping, but can't just yet, wait a little bit 749 // TODO Change sleep to wait and use notify from ExchangeService when a sync ends 750 sleep(2 * DateUtils.SECOND_IN_MILLIS, false); 751 pingWaitCount++; 752 //userLog("pingLoop waited 2s for: ", (pushCount - canPushCount), " box(es)"); 753 } else if (uninitCount > 0) { 754 // In this case, we're doing an initial sync of at least one mailbox. Since this 755 // is typically a one-time case, I'm ok with trying again every 10 seconds until 756 // we're in one of the other possible states. 757 userLog("pingLoop waiting for initial sync of ", uninitCount, " box(es)"); 758 sleep(10 * DateUtils.SECOND_IN_MILLIS, true); 759 } else if (inboxId == -1) { 760 // In this case, we're still syncing mailboxes, so sleep for only a short time 761 sleep(45 * DateUtils.SECOND_IN_MILLIS, true); 762 } else { 763 // We've got nothing to do, so we'll check again in 20 minutes at which time 764 // we'll update the folder list, check for policy changes and/or remote wipe, etc. 765 // Let the device sleep in the meantime... 766 userLog(ACCOUNT_MAILBOX_SLEEP_TEXT); 767 sleep(ACCOUNT_MAILBOX_SLEEP_TIME, true); 768 } 769 } 770 771 // Save away the current heartbeat 772 mPingHeartbeat = pingHeartbeat; 773 } 774 775 private int parsePingResult(InputStream is, ContentResolver cr, 776 HashMap<String, Integer> errorMap) 777 throws IOException, StaleFolderListException, IllegalHeartbeatException, 778 CommandStatusException { 779 PingParser pp = new PingParser(is); 780 if (pp.parse()) { 781 // True indicates some mailboxes need syncing... 782 // syncList has the serverId's of the mailboxes... 783 mBindArguments[0] = Long.toString(mAccount.mId); 784 mPingChangeList = pp.getSyncList(); 785 for (String serverId: mPingChangeList) { 786 mBindArguments[1] = serverId; 787 Cursor c = cr.query(Mailbox.CONTENT_URI, Mailbox.CONTENT_PROJECTION, 788 WHERE_ACCOUNT_KEY_AND_SERVER_ID, mBindArguments, null); 789 if (c == null) throw new ProviderUnavailableException(); 790 try { 791 if (c.moveToFirst()) { 792 793 /** 794 * Check the boxes reporting changes to see if there really were any... 795 * We do this because bugs in various Exchange servers can put us into a 796 * looping behavior by continually reporting changes in a mailbox, even when 797 * there aren't any. 798 * 799 * This behavior is seemingly random, and therefore we must code defensively 800 * by backing off of push behavior when it is detected. 801 * 802 * One known cause, on certain Exchange 2003 servers, is acknowledged by 803 * Microsoft, and the server hotfix for this case can be found at 804 * http://support.microsoft.com/kb/923282 805 */ 806 807 // Check the status of the last sync 808 String status = c.getString(Mailbox.CONTENT_SYNC_STATUS_COLUMN); 809 int type = ExchangeService.getStatusType(status); 810 // This check should always be true... 811 if (type == ExchangeService.SYNC_PING) { 812 int changeCount = ExchangeService.getStatusChangeCount(status); 813 if (changeCount > 0) { 814 errorMap.remove(serverId); 815 } else if (changeCount == 0) { 816 // This means that a ping reported changes in error; we keep a count 817 // of consecutive errors of this kind 818 String name = c.getString(Mailbox.CONTENT_DISPLAY_NAME_COLUMN); 819 Integer failures = errorMap.get(serverId); 820 if (failures == null) { 821 userLog("Last ping reported changes in error for: ", name); 822 errorMap.put(serverId, 1); 823 } else if (failures > MAX_PING_FAILURES) { 824 // We'll back off of push for this box 825 pushFallback(c.getLong(Mailbox.CONTENT_ID_COLUMN)); 826 continue; 827 } else { 828 userLog("Last ping reported changes in error for: ", name); 829 errorMap.put(serverId, failures + 1); 830 } 831 } 832 } 833 834 // If there were no problems with previous sync, we'll start another one 835 ExchangeService.startManualSync(c.getLong(Mailbox.CONTENT_ID_COLUMN), 836 ExchangeService.SYNC_PING, null); 837 } 838 } finally { 839 c.close(); 840 } 841 } 842 } 843 return pp.getPingStatus(); 844 } 845 } 846
