diff options
4 files changed, 145 insertions, 61 deletions
diff --git a/core/java/android/content/AbstractThreadedSyncAdapter.java b/core/java/android/content/AbstractThreadedSyncAdapter.java index 58bd5cda825d..2629929e91ce 100644 --- a/core/java/android/content/AbstractThreadedSyncAdapter.java +++ b/core/java/android/content/AbstractThreadedSyncAdapter.java @@ -17,11 +17,12 @@ package android.content; import android.accounts.Account; +import android.os.Build; import android.os.Bundle; import android.os.IBinder; import android.os.Process; -import android.os.RemoteException; import android.os.Trace; +import android.util.Log; import java.util.HashMap; import java.util.concurrent.atomic.AtomicInteger; @@ -95,6 +96,8 @@ import java.util.concurrent.atomic.AtomicInteger; * </ul> */ public abstract class AbstractThreadedSyncAdapter { + private static final String TAG = "SyncAdapter"; + /** * Kernel event log tag. Also listed in data/etc/event-log-tags. * @deprecated Private constant. May go away in the next release. @@ -102,6 +105,8 @@ public abstract class AbstractThreadedSyncAdapter { @Deprecated public static final int LOG_SYNC_DETAILS = 2743; + private static final boolean ENABLE_LOG = Build.IS_DEBUGGABLE && Log.isLoggable(TAG, Log.DEBUG); + private final Context mContext; private final AtomicInteger mNumSyncStarts; private final ISyncAdapterImpl mISyncAdapterImpl; @@ -163,71 +168,104 @@ public abstract class AbstractThreadedSyncAdapter { @Override public void startSync(ISyncContext syncContext, String authority, Account account, Bundle extras) { - final SyncContext syncContextClient = new SyncContext(syncContext); - - boolean alreadyInProgress; - // synchronize to make sure that mSyncThreads doesn't change between when we - // check it and when we use it - final Account threadsKey = toSyncKey(account); - synchronized (mSyncThreadLock) { - if (!mSyncThreads.containsKey(threadsKey)) { - if (mAutoInitialize - && extras != null - && extras.getBoolean(ContentResolver.SYNC_EXTRAS_INITIALIZE, false)) { - try { - if (ContentResolver.getIsSyncable(account, authority) < 0) { - ContentResolver.setIsSyncable(account, authority, 1); + if (ENABLE_LOG) { + if (extras != null) { + extras.size(); // Unparcel so its toString() will show the contents. + } + Log.d(TAG, "startSync() start " + authority + " " + account + " " + extras); + } + try { + final SyncContext syncContextClient = new SyncContext(syncContext); + + boolean alreadyInProgress; + // synchronize to make sure that mSyncThreads doesn't change between when we + // check it and when we use it + final Account threadsKey = toSyncKey(account); + synchronized (mSyncThreadLock) { + if (!mSyncThreads.containsKey(threadsKey)) { + if (mAutoInitialize + && extras != null + && extras.getBoolean( + ContentResolver.SYNC_EXTRAS_INITIALIZE, false)) { + try { + if (ContentResolver.getIsSyncable(account, authority) < 0) { + ContentResolver.setIsSyncable(account, authority, 1); + } + } finally { + syncContextClient.onFinished(new SyncResult()); } - } finally { - syncContextClient.onFinished(new SyncResult()); + return; + } + SyncThread syncThread = new SyncThread( + "SyncAdapterThread-" + mNumSyncStarts.incrementAndGet(), + syncContextClient, authority, account, extras); + mSyncThreads.put(threadsKey, syncThread); + syncThread.start(); + alreadyInProgress = false; + } else { + if (ENABLE_LOG) { + Log.d(TAG, " alreadyInProgress"); } - return; + alreadyInProgress = true; } - SyncThread syncThread = new SyncThread( - "SyncAdapterThread-" + mNumSyncStarts.incrementAndGet(), - syncContextClient, authority, account, extras); - mSyncThreads.put(threadsKey, syncThread); - syncThread.start(); - alreadyInProgress = false; - } else { - alreadyInProgress = true; } - } - // do this outside since we don't want to call back into the syncContext while - // holding the synchronization lock - if (alreadyInProgress) { - syncContextClient.onFinished(SyncResult.ALREADY_IN_PROGRESS); + // do this outside since we don't want to call back into the syncContext while + // holding the synchronization lock + if (alreadyInProgress) { + syncContextClient.onFinished(SyncResult.ALREADY_IN_PROGRESS); + } + } catch (RuntimeException | Error th) { + if (ENABLE_LOG) { + Log.d(TAG, "startSync() caught exception", th); + } + throw th; + } finally { + if (ENABLE_LOG) { + Log.d(TAG, "startSync() finishing"); + } } } @Override public void cancelSync(ISyncContext syncContext) { - // synchronize to make sure that mSyncThreads doesn't change between when we - // check it and when we use it - SyncThread info = null; - synchronized (mSyncThreadLock) { - for (SyncThread current : mSyncThreads.values()) { - if (current.mSyncContext.getSyncContextBinder() == syncContext.asBinder()) { - info = current; - break; + try { + // synchronize to make sure that mSyncThreads doesn't change between when we + // check it and when we use it + SyncThread info = null; + synchronized (mSyncThreadLock) { + for (SyncThread current : mSyncThreads.values()) { + if (current.mSyncContext.getSyncContextBinder() == syncContext.asBinder()) { + info = current; + break; + } } } - } - if (info != null) { - if (mAllowParallelSyncs) { - onSyncCanceled(info); + if (info != null) { + if (ENABLE_LOG) { + Log.d(TAG, "cancelSync() " + info.mAuthority + " " + info.mAccount); + } + if (mAllowParallelSyncs) { + onSyncCanceled(info); + } else { + onSyncCanceled(); + } } else { - onSyncCanceled(); + if (ENABLE_LOG) { + Log.w(TAG, "cancelSync() unknown context"); + } + } + } catch (RuntimeException | Error th) { + if (ENABLE_LOG) { + Log.d(TAG, "cancelSync() caught exception", th); + } + throw th; + } finally { + if (ENABLE_LOG) { + Log.d(TAG, "cancelSync() finishing"); } } } - - public void initialize(Account account, String authority) throws RemoteException { - Bundle extras = new Bundle(); - extras.putBoolean(ContentResolver.SYNC_EXTRAS_INITIALIZE, true); - startSync(null, authority, account, extras); - } } /** @@ -256,6 +294,10 @@ public abstract class AbstractThreadedSyncAdapter { public void run() { Process.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND); + if (ENABLE_LOG) { + Log.d(TAG, "Thread started"); + } + // Trace this sync instance. Note, conceptually this should be in // SyncStorageEngine.insertStartSyncEvent(), but the trace functions require unique // threads in order to track overlapping operations, so we'll do it here for now. @@ -265,8 +307,15 @@ public abstract class AbstractThreadedSyncAdapter { ContentProviderClient provider = null; try { if (isCanceled()) { + if (ENABLE_LOG) { + Log.d(TAG, "Already canceled"); + } return; } + if (ENABLE_LOG) { + Log.d(TAG, "Calling onPerformSync..."); + } + provider = mContext.getContentResolver().acquireContentProviderClient(mAuthority); if (provider != null) { AbstractThreadedSyncAdapter.this.onPerformSync(mAccount, mExtras, @@ -274,10 +323,23 @@ public abstract class AbstractThreadedSyncAdapter { } else { syncResult.databaseError = true; } + + if (ENABLE_LOG) { + Log.d(TAG, "onPerformSync done"); + } + } catch (SecurityException e) { + if (ENABLE_LOG) { + Log.d(TAG, "SecurityException", e); + } AbstractThreadedSyncAdapter.this.onSecurityException(mAccount, mExtras, mAuthority, syncResult); syncResult.databaseError = true; + } catch (RuntimeException | Error th) { + if (ENABLE_LOG) { + Log.d(TAG, "caught exception", th); + } + throw th; } finally { Trace.traceEnd(Trace.TRACE_TAG_SYNC_MANAGER); @@ -292,6 +354,10 @@ public abstract class AbstractThreadedSyncAdapter { synchronized (mSyncThreadLock) { mSyncThreads.remove(mThreadsKey); } + + if (ENABLE_LOG) { + Log.d(TAG, "Thread finished"); + } } } diff --git a/core/java/android/content/ISyncAdapter.aidl b/core/java/android/content/ISyncAdapter.aidl index dd9d14edc418..4660527925c5 100644 --- a/core/java/android/content/ISyncAdapter.aidl +++ b/core/java/android/content/ISyncAdapter.aidl @@ -44,12 +44,4 @@ oneway interface ISyncAdapter { * @param syncContext the ISyncContext that was passed to {@link #startSync} */ void cancelSync(ISyncContext syncContext); - - /** - * Initialize the SyncAdapter for this account and authority. - * - * @param account the account that should be synced - * @param authority the authority that should be synced - */ - void initialize(in Account account, String authority); } diff --git a/services/core/java/com/android/server/content/SyncLogger.java b/services/core/java/com/android/server/content/SyncLogger.java index db794643b4df..d93bdc9efabf 100644 --- a/services/core/java/com/android/server/content/SyncLogger.java +++ b/services/core/java/com/android/server/content/SyncLogger.java @@ -22,6 +22,7 @@ import android.os.Environment; import android.os.FileUtils; import android.os.SystemProperties; import android.text.format.DateUtils; +import android.util.Log; import android.util.Slog; import com.android.internal.annotations.GuardedBy; @@ -127,6 +128,8 @@ public class SyncLogger { @GuardedBy("mLock") private boolean mErrorShown; + private static final boolean DO_LOGCAT = Log.isLoggable(TAG, Log.DEBUG); + RotatingFileLogger() { mLogPath = new File(Environment.getDataSystemDirectory(), "syncmanager-log"); } @@ -158,6 +161,8 @@ public class SyncLogger { mStringBuilder.append(android.os.Process.myTid()); mStringBuilder.append(' '); + final int messageStart = mStringBuilder.length(); + for (Object o : message) { mStringBuilder.append(o); } @@ -166,6 +171,11 @@ public class SyncLogger { try { mLogWriter.append(mStringBuilder); mLogWriter.flush(); + + // Also write on logcat. + if (DO_LOGCAT) { + Log.d(TAG, mStringBuilder.substring(messageStart)); + } } catch (IOException e) { handleException("Failed to write log", e); } diff --git a/services/core/java/com/android/server/content/SyncManager.java b/services/core/java/com/android/server/content/SyncManager.java index c250005204ba..3e05d50b0355 100644 --- a/services/core/java/com/android/server/content/SyncManager.java +++ b/services/core/java/com/android/server/content/SyncManager.java @@ -1704,6 +1704,8 @@ public class SyncManager { // Include "this" in the message so that the handler can ignore it if this // ActiveSyncContext is no longer the mActiveSyncContext at message handling // time. + mLogger.log("onFinished result=", result, " endpoint=", + (mSyncOperation == null ? "null" : mSyncOperation.target)); sendSyncFinishedOrCanceledMessage(this, result); } @@ -1745,6 +1747,7 @@ public class SyncManager { Context.BIND_AUTO_CREATE | Context.BIND_NOT_FOREGROUND | Context.BIND_ALLOW_OOM_MANAGEMENT, new UserHandle(mSyncOperation.target.userId)); + mLogger.log("bindService() returned=", mBound, " for ", this); if (!bindResult) { mBound = false; } else { @@ -1767,6 +1770,7 @@ public class SyncManager { } if (mBound) { mBound = false; + mLogger.log("unbindService for ", this); mContext.unbindService(this); try { mBatteryStats.noteSyncFinish(mEventName, mSyncAdapterUid); @@ -2729,9 +2733,14 @@ public class SyncManager { // outstanding try { if (currentSyncContext.mSyncAdapter != null) { + mLogger.log("Calling cancelSync for SERVICE_DISCONNECTED ", + currentSyncContext, + " adapter=", currentSyncContext.mSyncAdapter); currentSyncContext.mSyncAdapter.cancelSync(currentSyncContext); + mLogger.log("Canceled"); } } catch (RemoteException e) { + mLogger.log("RemoteException ", Log.getStackTraceString(e)); // We don't need to retry this in this case. } @@ -3217,14 +3226,15 @@ public class SyncManager { mLogger.log("Sync start: account=" + syncOperation.target.account, " authority=", syncOperation.target.provider, " reason=", SyncOperation.reasonToString(null, syncOperation.reason), - " extras=", SyncOperation.extrasToString(syncOperation.extras)); + " extras=", SyncOperation.extrasToString(syncOperation.extras), + " adapter=", activeSyncContext.mSyncAdapter); activeSyncContext.mSyncAdapter = ISyncAdapter.Stub.asInterface(syncAdapter); activeSyncContext.mSyncAdapter .startSync(activeSyncContext, syncOperation.target.provider, syncOperation.target.account, syncOperation.extras); - mLogger.log("Sync finish"); + mLogger.log("Sync is running now..."); } catch (RemoteException remoteExc) { mLogger.log("Sync failed with RemoteException: ", remoteExc.toString()); Log.d(TAG, "maybeStartNextSync: caught a RemoteException, rescheduling", remoteExc); @@ -3297,7 +3307,6 @@ public class SyncManager { activeSyncContext.mSyncAdapter.asBinder().unlinkToDeath(activeSyncContext, 0); activeSyncContext.mIsLinkedToDeath = false; } - closeActiveSyncContext(activeSyncContext); final long elapsedTime = SystemClock.elapsedRealtime() - activeSyncContext.mStartTime; String historyMessage; int downstreamActivity; @@ -3355,8 +3364,12 @@ public class SyncManager { } if (activeSyncContext.mSyncAdapter != null) { try { + mLogger.log("Calling cancelSync for runSyncFinishedOrCanceled ", + activeSyncContext, " adapter=", activeSyncContext.mSyncAdapter); activeSyncContext.mSyncAdapter.cancelSync(activeSyncContext); + mLogger.log("Canceled"); } catch (RemoteException e) { + mLogger.log("RemoteException ", Log.getStackTraceString(e)); // we don't need to retry this in this case } } @@ -3365,6 +3378,9 @@ public class SyncManager { upstreamActivity = 0; } + // Close and unbind the service. Don't use activeSyncContext.mSyncAdapter after this. + closeActiveSyncContext(activeSyncContext); + stopSyncEvent(activeSyncContext.mHistoryRowId, syncOperation, historyMessage, upstreamActivity, downstreamActivity, elapsedTime); // Check for full-resync and schedule it after closing off the last sync. |