SureshJoshi.com ▼

File Logging in Android with Timber


2016-03-01

“Every time you log in production, a puppy dies.” - Jake Wharton

As I wrote about in my 4 Rules to Picking Android Libraries post some months ago, Jake Wharton’s Timber library is one of the first that goes into any Android application I write.

Replacing the Android Log might seem like a waste of time, but once you’ve a) stopped needing to make those ridiculous static final TAG constants in your classes, and b) enjoy a logger that has sane defaults, and can be turned on/off with one line of code - you’ll see the light.

What’s really cool about it is that it’s very extensible, and just by ‘Plant’ing a new Tree, you can create another log output. The natural example is a crash logger in Release mode (e.g. tied into Crashlytics/Flurry/etc) - with a different log ’volume’ than the vanilla debug logger.

Why Bother?

Sometimes there is just no replacement for getting logs from the field.

I ran into an issue recently where a tablet communicates with a hardware sensor over USB. As of a few days ago, a strange problem started occurring in the field (after months of problem-free operation). No crashes, but just some sort of inconsistent behaviour that would come and go. I couldn’t come close to replicating it myself, but when it happened again in the field - we had the logs to show the problem.

Turns out it was an environmental issue dealing with humidity where the sensor was used sometimes. Whack.

File Logging

Writing a file logging utility is a waste of time, given that there are dozens or hundreds already written out there - some of which are stable, mature, and well tuned. Also, writing your own new one can be problem-prone… I inherited a project where the original developer wrote their own file logging tools, and the logger was responsible for about 10% of crashes in the field.

For this project, I used Logback Android - which uses Logback and the SLF4J API.

I configured Logback using an XML file to generate HTML (more verbose, but easier for my client to dig through). I also set it up to roll logs when either the day changed, or a log file exceeds 5MB (and cap the number of log files at 30):

<configuration>
    <property name="LOG_DIR" value="/storage/emulated/0/Download/" />

    <appender name="ROLLING" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/log-latest.html</file>

        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <charset>UTF-8</charset>
            <layout class="ch.qos.logback.classic.html.HTMLLayout">
                <pattern>%d{HH:mm:ss.SSS}%thread%level%line%msg</pattern>
            </layout>
        </encoder>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover -->
            <fileNamePattern>${LOG_DIR}/log.%d{yyyy-MM-dd}.%i.html</fileNamePattern>

            <timeBasedFileNamingAndTriggeringPolicy
                class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- or whenever the file size reaches 5MB -->
                <maxFileSize>5MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>

            <!-- keep 30 days' worth of history -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>

    <root level="DEBUG">
        <appender-ref ref="ROLLING" />
    </root>
</configuration>

File logging is as simple as:

Logger logger = LoggerFactory.getLogger(SomeActivity.class);
...
logger.debug(logMessage);

2 Loggers Sucks!

Agreed… I refuse to have to make two calls to two loggers inside my code.

In many other mobile projects I’ve come into, where there is a traditional developer-centric console log, and a file logger, it’s often that there are two completely separate APIs - one for the file logger, one for the console logger. This makes no sense to me 95% of the time. Also, what happens when someone new joins the team, and doesn’t realize that they need to call 2 loggers and 2 log APIs to correctly save data. Ridiculous.

My solution to this was pretty simple. I created another Timber Tree, which implemented my file logging, and every call to Timber.(logVolume) would immediately call my DebugTree to print to the console AND go straight into my FileLogger - so that my console log would actually be cloned down into a file - which makes debugging much easier.

Note: I was a bit lazy, as I inherited from DebugTree so that I could use the already-written tag code.

public class FileLoggingTree extends Timber.DebugTree {

    static Logger mLogger = LoggerFactory.getLogger(FileLoggingTree.class);

    @Override
    protected void log(int priority, String tag, String message, Throwable t) {
        if (priority == Log.VERBOSE) {
            return;
        }

        String logMessage = tag + ": " + message;
        switch (priority) {
            case Log.DEBUG:
                mLogger.debug(logMessage);
                break;
            case Log.INFO:
                mLogger.info(logMessage);
                break;
            case Log.WARN:
                mLogger.warn(logMessage);
                break;
            case Log.ERROR:
                mLogger.error(logMessage);
                break;
        }
    }
}

Now, wherever you initialized Timber in the first place, use these lines:

Timber.plant(new Timber.DebugTree());
Timber.plant(new FileLoggingTree());

And you’re off to the races!

Update: November 23, 2016

In case you’re wondering, this is an example of how to switch the XML to code. The problem with the XML is that you need to specify an absolute log directory, which is a little bit brittle. Also, as of Android Marshmallow, you also need to request run-time permissions to access the external storage.

Here is an example of logging to the Android internal files directory.

public class FileLoggingTree extends Timber.DebugTree {
    private static Logger mLogger = LoggerFactory.getLogger(FileLoggingTree.class);
    private static final String LOG_PREFIX = "my-log";

    public FileLoggingTree(Context context) {
        final String logDirectory = context.getFilesDir() + "/logs";
        configureLogger(logDirectory);
    }

    private void configureLogger(String logDirectory) {
        // reset the default context (which may already have been initialized)
        // since we want to reconfigure it
        LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
        loggerContext.reset();

        RollingFileAppender<ILoggingEvent> rollingFileAppender = new RollingFileAppender<>();
        rollingFileAppender.setContext(loggerContext);
        rollingFileAppender.setAppend(true);
        rollingFileAppender.setFile(logDirectory + "/" + LOG_PREFIX + "-latest.html");

        SizeAndTimeBasedFNATP<ILoggingEvent> fileNamingPolicy = new SizeAndTimeBasedFNATP<>();
        fileNamingPolicy.setContext(loggerContext);
        fileNamingPolicy.setMaxFileSize("1MB");

        TimeBasedRollingPolicy<ILoggingEvent> rollingPolicy = new TimeBasedRollingPolicy<>();
        rollingPolicy.setContext(loggerContext);
        rollingPolicy.setFileNamePattern(logDirectory + "/" + LOG_PREFIX + ".%d{yyyy-MM-dd}.%i.html");
        rollingPolicy.setMaxHistory(5);
        rollingPolicy.setTimeBasedFileNamingAndTriggeringPolicy(fileNamingPolicy);
        rollingPolicy.setParent(rollingFileAppender);  // parent and context required!
        rollingPolicy.start();

        HTMLLayout htmlLayout = new HTMLLayout();
        htmlLayout.setContext(loggerContext);
        htmlLayout.setPattern("%d{HH:mm:ss.SSS}%level%thread%msg");
        htmlLayout.start();

        LayoutWrappingEncoder<ILoggingEvent> encoder = new LayoutWrappingEncoder<>();
        encoder.setContext(loggerContext);
        encoder.setLayout(htmlLayout);
        encoder.start();

        // Alternative text encoder - very clean pattern, takes up less space
//        PatternLayoutEncoder encoder = new PatternLayoutEncoder();
//        encoder.setContext(loggerContext);
//        encoder.setCharset(Charset.forName("UTF-8"));
//        encoder.setPattern("%date %level [%thread] %msg%n");
//        encoder.start();

        rollingFileAppender.setRollingPolicy(rollingPolicy);
        rollingFileAppender.setEncoder(encoder);
        rollingFileAppender.start();

        // add the newly created appenders to the root logger;
        // qualify Logger to disambiguate from org.slf4j.Logger
        ch.qos.logback.classic.Logger root = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
        root.setLevel(Level.DEBUG);
        root.addAppender(rollingFileAppender);

        // print any status messages (warnings, etc) encountered in logback config
        StatusPrinter.print(loggerContext);
    }

    @Override
    protected void log(int priority, String tag, String message, Throwable t) {
        if (priority == Log.VERBOSE) {
            return;
        }

        String logMessage = tag + ": " + message;
        switch (priority) {
            case Log.DEBUG:
                mLogger.debug(logMessage);
                break;
            case Log.INFO:
                mLogger.info(logMessage);
                break;
            case Log.WARN:
                mLogger.warn(logMessage);
                break;
            case Log.ERROR:
                mLogger.error(logMessage);
                break;
        }
    }
}