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