diff options
6 files changed, 369 insertions, 45 deletions
diff --git a/core/java/android/os/FileUtils.java b/core/java/android/os/FileUtils.java index 50b4f8c7facf..56d6e0a62f94 100644 --- a/core/java/android/os/FileUtils.java +++ b/core/java/android/os/FileUtils.java @@ -369,11 +369,11 @@ public class FileUtils { * constraints remain. * * @param minCount Always keep at least this many files. - * @param minAge Always keep files younger than this age. + * @param minAgeMs Always keep files younger than this age, in milliseconds. * @return if any files were deleted. */ - public static boolean deleteOlderFiles(File dir, int minCount, long minAge) { - if (minCount < 0 || minAge < 0) { + public static boolean deleteOlderFiles(File dir, int minCount, long minAgeMs) { + if (minCount < 0 || minAgeMs < 0) { throw new IllegalArgumentException("Constraints must be positive or 0"); } @@ -393,9 +393,9 @@ public class FileUtils { for (int i = minCount; i < files.length; i++) { final File file = files[i]; - // Keep files newer than minAge + // Keep files newer than minAgeMs final long age = System.currentTimeMillis() - file.lastModified(); - if (age > minAge) { + if (age > minAgeMs) { if (file.delete()) { Log.d(TAG, "Deleted old file " + file); deleted = true; diff --git a/services/core/java/com/android/server/content/ContentService.java b/services/core/java/com/android/server/content/ContentService.java index 13054a643e52..468cb2990b67 100644 --- a/services/core/java/com/android/server/content/ContentService.java +++ b/services/core/java/com/android/server/content/ContentService.java @@ -60,6 +60,7 @@ import android.util.SparseArray; import android.util.SparseIntArray; import com.android.internal.annotations.GuardedBy; +import com.android.internal.util.ArrayUtils; import com.android.internal.util.DumpUtils; import com.android.internal.util.IndentingPrintWriter; import com.android.server.LocalServices; @@ -166,6 +167,8 @@ public final class ContentService extends IContentService.Stub { if (!DumpUtils.checkDumpAndUsageStatsPermission(mContext, TAG, pw_)) return; final IndentingPrintWriter pw = new IndentingPrintWriter(pw_, " "); + final boolean dumpAll = ArrayUtils.contains(args, "-a"); + // This makes it so that future permission checks will be in the context of this // process rather than the caller's process. We will restore this before returning. final long identityToken = clearCallingIdentity(); @@ -173,7 +176,7 @@ public final class ContentService extends IContentService.Stub { if (mSyncManager == null) { pw.println("No SyncManager created! (Disk full?)"); } else { - mSyncManager.dump(fd, pw); + mSyncManager.dump(fd, pw, dumpAll); } pw.println(); pw.println("Observer tree:"); @@ -603,7 +606,7 @@ public final class ContentService extends IContentService.Stub { SyncStorageEngine.EndPoint info; info = new SyncStorageEngine.EndPoint(account, authority, userId); syncManager.clearScheduledSyncOperations(info); - syncManager.cancelActiveSync(info, null /* all syncs for this adapter */); + syncManager.cancelActiveSync(info, null /* all syncs for this adapter */, "API"); } } finally { restoreCallingIdentity(identityToken); @@ -631,7 +634,7 @@ public final class ContentService extends IContentService.Stub { } // Cancel active syncs and clear pending syncs from the queue. syncManager.cancelScheduledSyncOperation(info, extras); - syncManager.cancelActiveSync(info, extras); + syncManager.cancelActiveSync(info, extras, "API"); } finally { restoreCallingIdentity(identityToken); } diff --git a/services/core/java/com/android/server/content/SyncJobService.java b/services/core/java/com/android/server/content/SyncJobService.java index a621d7376b7f..1f02ebfc4972 100644 --- a/services/core/java/com/android/server/content/SyncJobService.java +++ b/services/core/java/com/android/server/content/SyncJobService.java @@ -34,6 +34,8 @@ public class SyncJobService extends JobService { private Messenger mMessenger; private SparseArray<JobParameters> jobParamsMap = new SparseArray<JobParameters>(); + private final SyncLogger mLogger = SyncLogger.getInstance(); + /** * This service is started by the SyncManager which passes a messenger object to * communicate back with it. It never stops while the device is running. @@ -63,6 +65,9 @@ public class SyncJobService extends JobService { @Override public boolean onStartJob(JobParameters params) { + + mLogger.purgeOldLogs(); + boolean isLoggable = Log.isLoggable(TAG, Log.VERBOSE); synchronized (jobParamsMap) { jobParamsMap.put(params.getJobId(), params); @@ -70,6 +75,9 @@ public class SyncJobService extends JobService { Message m = Message.obtain(); m.what = SyncManager.SyncHandler.MESSAGE_START_SYNC; SyncOperation op = SyncOperation.maybeCreateFromJobExtras(params.getExtras()); + + mLogger.log("onStopJob() jobid=", params.getJobId(), " op=", op); + if (op == null) { Slog.e(TAG, "Got invalid job " + params.getJobId()); return false; @@ -88,7 +96,7 @@ public class SyncJobService extends JobService { Slog.v(TAG, "onStopJob called " + params.getJobId() + ", reason: " + params.getStopReason()); } - + mLogger.log("onStopJob() ", mLogger.jobParametersToString(params)); synchronized (jobParamsMap) { jobParamsMap.remove(params.getJobId()); } @@ -108,9 +116,13 @@ public class SyncJobService extends JobService { return false; } - public void callJobFinished(int jobId, boolean needsReschedule) { + public void callJobFinished(int jobId, boolean needsReschedule, String why) { synchronized (jobParamsMap) { JobParameters params = jobParamsMap.get(jobId); + mLogger.log("callJobFinished()", + " needsReschedule=", needsReschedule, + " ", mLogger.jobParametersToString(params), + " why=", why); if (params != null) { jobFinished(params, needsReschedule); jobParamsMap.remove(jobId); diff --git a/services/core/java/com/android/server/content/SyncLogger.java b/services/core/java/com/android/server/content/SyncLogger.java new file mode 100644 index 000000000000..db794643b4df --- /dev/null +++ b/services/core/java/com/android/server/content/SyncLogger.java @@ -0,0 +1,252 @@ +/* + * Copyright (C) 2017 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License + */ + +package com.android.server.content; + +import android.app.job.JobParameters; +import android.os.Build; +import android.os.Environment; +import android.os.FileUtils; +import android.os.SystemProperties; +import android.text.format.DateUtils; +import android.util.Slog; + +import com.android.internal.annotations.GuardedBy; + +import libcore.io.IoUtils; + +import java.io.BufferedReader; +import java.io.File; +import java.io.FileReader; +import java.io.FileWriter; +import java.io.IOException; +import java.io.PrintWriter; +import java.io.Reader; +import java.io.Writer; +import java.text.SimpleDateFormat; +import java.util.Arrays; +import java.util.Date; +import java.util.concurrent.TimeUnit; + +/** + * Implements a rotating file logger for the sync manager, which is enabled only on userdebug/eng + * builds (unless debug.synclog is set to 1). + * + * Note this class could be used for other purposes too, but in general we don't want various + * system components to log to files, so it's put in a local package here. + */ +public class SyncLogger { + private static final String TAG = "SyncLogger"; + + private static SyncLogger sInstance; + + SyncLogger() { + } + + /** + * @return the singleton instance. + */ + public static synchronized SyncLogger getInstance() { + if (sInstance == null) { + final boolean enable = "1".equals(SystemProperties.get("debug.synclog", + Build.IS_DEBUGGABLE ? "1" : "0")); + if (enable) { + sInstance = new RotatingFileLogger(); + } else { + sInstance = new SyncLogger(); + } + } + return sInstance; + } + + /** + * Write strings to the log file. + */ + public void log(Object... message) { + } + + /** + * Remove old log files. + */ + public void purgeOldLogs() { + // The default implementation is no-op. + } + + public String jobParametersToString(JobParameters params) { + // The default implementation is no-op. + return ""; + } + + /** + * Dump all existing log files into a given writer. + */ + public void dumpAll(PrintWriter pw) { + } + + /** + * Actual implementation which is only used on userdebug/eng builds (by default). + */ + private static class RotatingFileLogger extends SyncLogger { + private final Object mLock = new Object(); + + private final long mKeepAgeMs = TimeUnit.DAYS.toMillis(7); + + private static final SimpleDateFormat sTimestampFormat + = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS"); + + private static final SimpleDateFormat sFilenameDateFormat + = new SimpleDateFormat("yyyy-MM-dd"); + + @GuardedBy("mLock") + private final Date mCachedDate = new Date(); + + @GuardedBy("mLock") + private final StringBuilder mStringBuilder = new StringBuilder(); + + private final File mLogPath; + + @GuardedBy("mLock") + private long mCurrentLogFileDayTimestamp; + + @GuardedBy("mLock") + private Writer mLogWriter; + + @GuardedBy("mLock") + private boolean mErrorShown; + + RotatingFileLogger() { + mLogPath = new File(Environment.getDataSystemDirectory(), "syncmanager-log"); + } + + private void handleException(String message, Exception e) { + if (!mErrorShown) { + Slog.e(TAG, message, e); + mErrorShown = true; + } + } + + @Override + public void log(Object... message) { + if (message == null) { + return; + } + synchronized (mLock) { + final long now = System.currentTimeMillis(); + openLogLocked(now); + if (mLogWriter == null) { + return; // Couldn't open log file? + } + + mStringBuilder.setLength(0); + mCachedDate.setTime(now); + mStringBuilder.append(sTimestampFormat.format(mCachedDate)); + mStringBuilder.append(' '); + + mStringBuilder.append(android.os.Process.myTid()); + mStringBuilder.append(' '); + + for (Object o : message) { + mStringBuilder.append(o); + } + mStringBuilder.append('\n'); + + try { + mLogWriter.append(mStringBuilder); + mLogWriter.flush(); + } catch (IOException e) { + handleException("Failed to write log", e); + } + } + } + + private void openLogLocked(long now) { + // If we already have a log file opened and the date has't changed, just use it. + final long day = now % DateUtils.DAY_IN_MILLIS; + if ((mLogWriter != null) && (day == mCurrentLogFileDayTimestamp)) { + return; + } + + // Otherwise create a new log file. + closeCurrentLogLocked(); + + mCurrentLogFileDayTimestamp = day; + + mCachedDate.setTime(now); + final String filename = "synclog-" + sFilenameDateFormat.format(mCachedDate) + ".log"; + final File file = new File(mLogPath, filename); + + file.getParentFile().mkdirs(); + + try { + mLogWriter = new FileWriter(file, /* append= */ true); + } catch (IOException e) { + handleException("Failed to open log file: " + file, e); + } + } + + private void closeCurrentLogLocked() { + IoUtils.closeQuietly(mLogWriter); + mLogWriter = null; + } + + @Override + public void purgeOldLogs() { + synchronized (mLock) { + FileUtils.deleteOlderFiles(mLogPath, /* keepCount= */ 1, mKeepAgeMs); + } + } + + @Override + public String jobParametersToString(JobParameters params) { + if (params == null) { + return "job:null"; + } else { + return "job:#" + params.getJobId() + ":" + + SyncOperation.maybeCreateFromJobExtras(params.getExtras()); + } + } + + @Override + public void dumpAll(PrintWriter pw) { + synchronized (mLock) { + final String[] files = mLogPath.list(); + if (files == null || (files.length == 0)) { + return; + } + Arrays.sort(files); + + for (String file : files) { + dumpFile(pw, new File(mLogPath, file)); + } + } + } + + private void dumpFile(PrintWriter pw, File file) { + Slog.w(TAG, "Dumping " + file); + final char[] buffer = new char[32 * 1024]; + + try (Reader in = new BufferedReader(new FileReader(file))) { + int read; + while ((read = in.read(buffer)) >= 0) { + if (read > 0) { + pw.write(buffer, 0, read); + } + } + } catch (IOException e) { + } + } + } +} diff --git a/services/core/java/com/android/server/content/SyncManager.java b/services/core/java/com/android/server/content/SyncManager.java index e3e26583b686..35591420af50 100644 --- a/services/core/java/com/android/server/content/SyncManager.java +++ b/services/core/java/com/android/server/content/SyncManager.java @@ -241,6 +241,8 @@ public class SyncManager { private final Random mRand; + private final SyncLogger mLogger; + private boolean isJobIdInUseLockedH(int jobId, List<JobInfo> pendingJobs) { for (JobInfo job: pendingJobs) { if (job.getId() == jobId) { @@ -289,13 +291,15 @@ public class SyncManager { mStorageIsLow = true; cancelActiveSync( SyncStorageEngine.EndPoint.USER_ALL_PROVIDER_ALL_ACCOUNTS_ALL, - null /* any sync */); + null /* any sync */, + "storage low"); } else if (Intent.ACTION_DEVICE_STORAGE_OK.equals(action)) { if (Log.isLoggable(TAG, Log.VERBOSE)) { Slog.v(TAG, "Internal storage is ok."); } mStorageIsLow = false; - rescheduleSyncs(EndPoint.USER_ALL_PROVIDER_ALL_ACCOUNTS_ALL); + rescheduleSyncs(EndPoint.USER_ALL_PROVIDER_ALL_ACCOUNTS_ALL, + "storage ok"); } } }; @@ -378,15 +382,16 @@ public class SyncManager { if (Log.isLoggable(TAG, Log.VERBOSE)) { Slog.v(TAG, "Reconnection detected: clearing all backoffs"); } + // Note the location of this code was wrong from nyc to oc; fixed in DR. + clearAllBackoffs("network reconnect"); } - clearAllBackoffs(); } } }; - private void clearAllBackoffs() { + private void clearAllBackoffs(String why) { mSyncStorageEngine.clearAllBackoffsLocked(); - rescheduleSyncs(EndPoint.USER_ALL_PROVIDER_ALL_ACCOUNTS_ALL); + rescheduleSyncs(EndPoint.USER_ALL_PROVIDER_ALL_ACCOUNTS_ALL, why); } private boolean readDataConnectionState() { @@ -502,6 +507,8 @@ public class SyncManager { // and creating threads and so on; it may fail if the disk is full. mContext = context; + mLogger = SyncLogger.getInstance(); + SyncStorageEngine.init(context); mSyncStorageEngine = SyncStorageEngine.getSingleton(); mSyncStorageEngine.setOnSyncRequestListener(new OnSyncRequestListener() { @@ -1145,8 +1152,12 @@ public class SyncManager { mSyncHandler.sendMessage(msg); } - private void sendCancelSyncsMessage(final SyncStorageEngine.EndPoint info, Bundle extras) { + private void sendCancelSyncsMessage(final SyncStorageEngine.EndPoint info, Bundle extras, + String why) { if (Log.isLoggable(TAG, Log.VERBOSE)) Slog.v(TAG, "sending MESSAGE_CANCEL"); + + mLogger.log("sendCancelSyncsMessage() ep=", info, " why=", why); + Message msg = mSyncHandler.obtainMessage(); msg.what = SyncHandler.MESSAGE_CANCEL; msg.setData(extras); @@ -1227,7 +1238,7 @@ public class SyncManager { } } - private void clearBackoffSetting(EndPoint target) { + private void clearBackoffSetting(EndPoint target, String why) { Pair<Long, Long> backoff = mSyncStorageEngine.getBackoff(target); if (backoff != null && backoff.first == SyncStorageEngine.NOT_IN_BACKOFF_MODE && backoff.second == SyncStorageEngine.NOT_IN_BACKOFF_MODE) { @@ -1240,7 +1251,7 @@ public class SyncManager { SyncStorageEngine.NOT_IN_BACKOFF_MODE, SyncStorageEngine.NOT_IN_BACKOFF_MODE); - rescheduleSyncs(target); + rescheduleSyncs(target, why); } private void increaseBackoffSetting(EndPoint target) { @@ -1281,14 +1292,16 @@ public class SyncManager { Slog.v(TAG, "Backoff until: " + backoff + ", delayTime: " + newDelayInMs); } mSyncStorageEngine.setBackoff(target, backoff, newDelayInMs); - rescheduleSyncs(target); + rescheduleSyncs(target, "increaseBackoffSetting"); } /** * Reschedule all scheduled syncs for this EndPoint. The syncs will be scheduled according * to current backoff and delayUntil values of this EndPoint. */ - private void rescheduleSyncs(EndPoint target) { + private void rescheduleSyncs(EndPoint target, String why) { + mLogger.log("rescheduleSyncs() ep=", target, " why=", why); + List<SyncOperation> ops = getAllPendingSyncs(); int count = 0; for (SyncOperation op: ops) { @@ -1316,7 +1329,7 @@ public class SyncManager { if (Log.isLoggable(TAG, Log.VERBOSE)) { Slog.v(TAG, "Delay Until time set to " + newDelayUntilTime + " for " + target); } - rescheduleSyncs(target); + rescheduleSyncs(target, "delayUntil newDelayUntilTime: " + newDelayUntilTime); } private boolean isAdapterDelayed(EndPoint target) { @@ -1338,8 +1351,8 @@ public class SyncManager { * have null account/provider info to specify all accounts/providers. * @param extras if non-null, specifies the exact sync to remove. */ - public void cancelActiveSync(SyncStorageEngine.EndPoint info, Bundle extras) { - sendCancelSyncsMessage(info, extras); + public void cancelActiveSync(SyncStorageEngine.EndPoint info, Bundle extras, String why) { + sendCancelSyncsMessage(info, extras, why); } /** @@ -1599,7 +1612,8 @@ public class SyncManager { null /* any account */, null /* any authority */, userId), - null /* any sync. */ + null /* any sync. */, + "onUserStopped" ); } @@ -1759,10 +1773,15 @@ public class SyncManager { } } - protected void dump(FileDescriptor fd, PrintWriter pw) { + protected void dump(FileDescriptor fd, PrintWriter pw, boolean dumpAll) { final IndentingPrintWriter ipw = new IndentingPrintWriter(pw, " "); dumpSyncState(ipw); dumpSyncAdapters(ipw); + + if (dumpAll) { + ipw.println("Detailed Sync History"); + mLogger.dumpAll(pw); + } } static String formatTime(long time) { @@ -2644,7 +2663,7 @@ public class SyncManager { Log.d(TAG, "handleSyncHandlerMessage: MESSAGE_CANCEL: " + endpoint + " bundle: " + extras); } - cancelActiveSyncH(endpoint, extras); + cancelActiveSyncH(endpoint, extras, "MESSAGE_CANCEL"); break; case SyncHandler.MESSAGE_SYNC_FINISHED: @@ -2660,7 +2679,8 @@ public class SyncManager { Slog.v(TAG, "syncFinished" + payload.activeSyncContext.mSyncOperation); } mSyncJobService.callJobFinished( - payload.activeSyncContext.mSyncOperation.jobId, false); + payload.activeSyncContext.mSyncOperation.jobId, false, + "sync finished"); runSyncFinishedOrCanceledH(payload.syncResult, payload.activeSyncContext); break; @@ -2704,7 +2724,8 @@ public class SyncManager { SyncResult syncResult = new SyncResult(); syncResult.stats.numIoExceptions++; mSyncJobService.callJobFinished( - currentSyncContext.mSyncOperation.jobId, false); + currentSyncContext.mSyncOperation.jobId, false, + "service disconnected"); runSyncFinishedOrCanceledH(syncResult, currentSyncContext); } break; @@ -2722,7 +2743,8 @@ public class SyncManager { "Detected sync making no progress for %s. cancelling.", monitoredSyncContext)); mSyncJobService.callJobFinished( - monitoredSyncContext.mSyncOperation.jobId, false); + monitoredSyncContext.mSyncOperation.jobId, false, + "no network activity"); runSyncFinishedOrCanceledH( null /* cancel => no result */, monitoredSyncContext); } else { @@ -2754,8 +2776,10 @@ public class SyncManager { * delay. This is equivalent to a failure. If this is a periodic sync, a delayed one-off * sync will be scheduled. */ - private void deferSyncH(SyncOperation op, long delay) { - mSyncJobService.callJobFinished(op.jobId, false); + private void deferSyncH(SyncOperation op, long delay, String why) { + mLogger.log("deferSyncH() ", (op.isPeriodic ? "periodic " : ""), + "sync. op=", op, " delay=", delay, " why=", why); + mSyncJobService.callJobFinished(op.jobId, false, why); if (op.isPeriodic) { scheduleSyncOperationH(op.createOneTimeSyncOperation(), delay); } else { @@ -2779,10 +2803,10 @@ public class SyncManager { /** * Cancel an active sync and reschedule it on the JobScheduler with some delay. */ - private void deferActiveSyncH(ActiveSyncContext asc) { + private void deferActiveSyncH(ActiveSyncContext asc, String why) { SyncOperation op = asc.mSyncOperation; runSyncFinishedOrCanceledH(null, asc); - deferSyncH(op, SYNC_DELAY_ON_CONFLICT); + deferSyncH(op, SYNC_DELAY_ON_CONFLICT, why); } private void startSyncH(SyncOperation op) { @@ -2790,7 +2814,7 @@ public class SyncManager { if (isLoggable) Slog.v(TAG, op.toString()); if (mStorageIsLow) { - deferSyncH(op, SYNC_DELAY_ON_LOW_STORAGE); + deferSyncH(op, SYNC_DELAY_ON_LOW_STORAGE, "storage low"); return; } @@ -2800,7 +2824,8 @@ public class SyncManager { List<SyncOperation> ops = getAllPendingSyncs(); for (SyncOperation syncOperation: ops) { if (syncOperation.sourcePeriodicId == op.jobId) { - mSyncJobService.callJobFinished(op.jobId, false); + mSyncJobService.callJobFinished(op.jobId, false, + "periodic sync, pending"); return; } } @@ -2808,13 +2833,14 @@ public class SyncManager { // executing according to some backoff criteria. for (ActiveSyncContext asc: mActiveSyncContexts) { if (asc.mSyncOperation.sourcePeriodicId == op.jobId) { - mSyncJobService.callJobFinished(op.jobId, false); + mSyncJobService.callJobFinished(op.jobId, false, + "periodic sync, already running"); return; } } // Check for adapter delays. if (isAdapterDelayed(op.target)) { - deferSyncH(op, 0 /* No minimum delay */); + deferSyncH(op, 0 /* No minimum delay */, "backing off"); return; } } @@ -2828,13 +2854,13 @@ public class SyncManager { if (isLoggable) { Slog.v(TAG, "Rescheduling sync due to conflict " + op.toString()); } - deferSyncH(op, SYNC_DELAY_ON_CONFLICT); + deferSyncH(op, SYNC_DELAY_ON_CONFLICT, "delay on conflict"); return; } else { if (isLoggable) { Slog.v(TAG, "Pushing back running sync due to a higher priority sync"); } - deferActiveSyncH(asc); + deferActiveSyncH(asc, "preempted"); break; } } @@ -2844,12 +2870,13 @@ public class SyncManager { switch (syncOpState) { case SYNC_OP_STATE_INVALID_NO_ACCOUNT_ACCESS: case SYNC_OP_STATE_INVALID: { - mSyncJobService.callJobFinished(op.jobId, false); + mSyncJobService.callJobFinished(op.jobId, false, + "invalid op state: " + syncOpState); } return; } if (!dispatchSyncOperation(op)) { - mSyncJobService.callJobFinished(op.jobId, false); + mSyncJobService.callJobFinished(op.jobId, false, "dispatchSyncOperation() failed"); } setAuthorityPendingState(op.target); @@ -3019,7 +3046,8 @@ public class SyncManager { if (op.sourcePeriodicId == syncOperation.jobId || op.jobId == syncOperation.jobId) { ActiveSyncContext asc = findActiveSyncContextH(syncOperation.jobId); if (asc != null) { - mSyncJobService.callJobFinished(syncOperation.jobId, false); + mSyncJobService.callJobFinished(syncOperation.jobId, false, + "removePeriodicSyncInternalH"); runSyncFinishedOrCanceledH(null, asc); } getJobScheduler().cancel(op.jobId); @@ -3131,6 +3159,8 @@ public class SyncManager { final RegisteredServicesCache.ServiceInfo<SyncAdapterType> syncAdapterInfo; syncAdapterInfo = mSyncAdapters.getServiceInfo(syncAdapterType, info.userId); if (syncAdapterInfo == null) { + mLogger.log("dispatchSyncOperation() failed: no sync adapter info for ", + syncAdapterType); Log.d(TAG, "can't find a sync adapter for " + syncAdapterType + ", removing settings for it"); mSyncStorageEngine.removeAuthority(info); @@ -3151,6 +3181,8 @@ public class SyncManager { postMonitorSyncProgressMessage(activeSyncContext); if (!activeSyncContext.bindToSyncAdapter(targetComponent, info.userId)) { + mLogger.log("dispatchSyncOperation() failed: bind failed. target: ", + targetComponent); Slog.e(TAG, "Bind attempt failed - target: " + targetComponent); closeActiveSyncContext(activeSyncContext); return false; @@ -3166,16 +3198,25 @@ public class SyncManager { activeSyncContext.mIsLinkedToDeath = true; syncAdapter.linkToDeath(activeSyncContext, 0); + mLogger.log("Sync start: account=" + syncOperation.target.account, + " authority=", syncOperation.target.provider, + " reason=", SyncOperation.reasonToString(null, syncOperation.reason), + " extras=", SyncOperation.extrasToString(syncOperation.extras)); + activeSyncContext.mSyncAdapter = ISyncAdapter.Stub.asInterface(syncAdapter); activeSyncContext.mSyncAdapter .startSync(activeSyncContext, syncOperation.target.provider, syncOperation.target.account, syncOperation.extras); + + mLogger.log("Sync finish"); } catch (RemoteException remoteExc) { + mLogger.log("Sync failed with RemoteException: ", remoteExc.toString()); Log.d(TAG, "maybeStartNextSync: caught a RemoteException, rescheduling", remoteExc); closeActiveSyncContext(activeSyncContext); increaseBackoffSetting(syncOperation.target); scheduleSyncOperationH(syncOperation); } catch (RuntimeException exc) { + mLogger.log("Sync failed with RuntimeException: ", exc.toString()); closeActiveSyncContext(activeSyncContext); Slog.e(TAG, "Caught RuntimeException while starting the sync " + syncOperation, exc); } @@ -3186,7 +3227,8 @@ public class SyncManager { * @param info Can have null fields to indicate all the active syncs for that field. * @param extras Can be null to indicate <strong>all</strong> syncs for the given endpoint. */ - private void cancelActiveSyncH(SyncStorageEngine.EndPoint info, Bundle extras) { + private void cancelActiveSyncH(SyncStorageEngine.EndPoint info, Bundle extras, + String why) { ArrayList<ActiveSyncContext> activeSyncs = new ArrayList<ActiveSyncContext>(mActiveSyncContexts); for (ActiveSyncContext activeSyncContext : activeSyncs) { @@ -3202,7 +3244,8 @@ public class SyncManager { false /* no config settings */)) { continue; } - mSyncJobService.callJobFinished(activeSyncContext.mSyncOperation.jobId, false); + mSyncJobService.callJobFinished(activeSyncContext.mSyncOperation.jobId, false, + why); runSyncFinishedOrCanceledH(null /* cancel => no result */, activeSyncContext); } } @@ -3250,6 +3293,7 @@ public class SyncManager { // potentially rescheduling all pending jobs to respect new backoff values. getJobScheduler().cancel(syncOperation.jobId); } + mLogger.log("runSyncFinishedOrCanceledH() op=", syncOperation, " result=", syncResult); if (syncResult != null) { if (isLoggable) { @@ -3262,7 +3306,7 @@ public class SyncManager { // TODO: set these correctly when the SyncResult is extended to include it downstreamActivity = 0; upstreamActivity = 0; - clearBackoffSetting(syncOperation.target); + clearBackoffSetting(syncOperation.target, "sync success"); // If the operation completes successfully and it was scheduled due to // a periodic operation failing, we reschedule the periodic operation to diff --git a/services/core/java/com/android/server/content/SyncOperation.java b/services/core/java/com/android/server/content/SyncOperation.java index b46426cc4a05..7d2cc0035847 100644 --- a/services/core/java/com/android/server/content/SyncOperation.java +++ b/services/core/java/com/android/server/content/SyncOperation.java @@ -237,6 +237,9 @@ public class SyncOperation { * contain a valid sync operation. */ static SyncOperation maybeCreateFromJobExtras(PersistableBundle jobExtras) { + if (jobExtras == null) { + return null; + } String accountName, accountType; String provider; int userId, owningUid; @@ -445,6 +448,10 @@ public class SyncOperation { } static void extrasToStringBuilder(Bundle bundle, StringBuilder sb) { + if (bundle == null) { + sb.append("null"); + return; + } sb.append("["); for (String key : bundle.keySet()) { sb.append(key).append("=").append(bundle.get(key)).append(" "); @@ -452,6 +459,12 @@ public class SyncOperation { sb.append("]"); } + static String extrasToString(Bundle bundle) { + final StringBuilder sb = new StringBuilder(); + extrasToStringBuilder(bundle, sb); + return sb.toString(); + } + String wakeLockName() { if (wakeLockName != null) { return wakeLockName; |