Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit a9dca248 authored by Makoto Onuki's avatar Makoto Onuki
Browse files

Log sync details to rotating log files (userdebug/eng only)

Bug 62052247
Test: Manual test with setting debug.synclog to 0 and 1.

Change-Id: I553dc8d3457ae99cbca5bf6a74303b8a8d8817e7
parent 702d4d56
Loading
Loading
Loading
Loading
+5 −5
Original line number Diff line number Diff line
@@ -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;
+6 −3
Original line number Diff line number Diff line
@@ -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);
        }
+14 −2
Original line number Diff line number Diff line
@@ -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);
+252 −0
Original line number Diff line number Diff line
/*
 * 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) {
            }
        }
    }
}
+79 −35

File changed.

Preview size limit exceeded, changes collapsed.

Loading