Design a logging library. | androidinterview.com

A logging library is a leveled API in front of a set of swappable trees, with a batching writer behind the tree that persists to disk. The API has to be cheap enough to leave switched on in hot paths. The writer has to be safe enough that a crash while logging never takes down the thing it was trying to diagnose.

What I'd clarify first

Is this console-only for development, or does it also persist logs to disk and upload them for crash diagnostics in production.
Do different parts of the app need different log levels or destinations, verbose for one module while the rest of the app stays quiet.
Is there a compliance rule that logs must never contain PII like emails or tokens, and does the library have to enforce it rather than trusting callers.

Core components

A leveled API, verbose, debug, info, warn, error, each a cheap call when the line will not be emitted.
A tree system, like Timber's planted Trees, where the core library owns the API and swappable trees decide what happens to a line.
A bounded queue in front of a rotating file sink, so log volume can never fill the heap or the device's storage.
An upload path, batching persisted logs and sending them opportunistically, on Wi-Fi, on foreground or attached to a crash report.

The level check comes before any string formatting, because building a message nobody will read is work paid at every call site. The tree seam is what lets a debug build print to Logcat and a release build write to a file and a crash reporter with no call site changing. The upload path never blocks the calling thread on a network call just because something got logged.

How a log call flows

A call site logs a level, a tag and a message. The library looks up the level for that tag, which is a per tag override if one is set and the global minimum otherwise. If the line is below it, the call returns early. That early return, before anything is formatted, is the whole reason leveled logging is cheap enough to leave in production. It is also why the per tag override lives on the logger and not in a tree, because a tree is only consulted after the message exists. If the line passes, it is handed to every planted tree that accepts it. The batching tree redacts it and appends it to a queue, and a background executor drains that queue to the sink. That tree is the only one the library promises is asynchronous. A tree that writes synchronously has made that choice itself, and a crash reporter tree may make it on purpose.

Two seams and the order they sit in. The level is compared at the top, before a message is ever built, and a per tag override is part of that same comparison. Everything below it is swappable. A tree decides when a line gets written and a sink decides only where it goes.

The level filter with its per tag override, the tree seam and the batching writer. Redaction happens on the way into the queue rather than on the way out of it.

Java

com.androidinterview.logging.BatchingTree.java

package com.androidinterview.logging;

import java.util.ArrayList;
import java.util.List;
import java.util.Queue;
import java.util.concurrent.ConcurrentLinkedQueue;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.regex.Pattern;

// The tree a release build plants. Nothing here runs on the calling thread
// except appending to a queue, because a log call from the main thread must
// never wait on a file.
public final class BatchingTree implements Tree {

    // A rotating file or an upload endpoint. The tree decides when to write,
    // the sink decides where, and neither needs to know the other. flush is
    // synchronized, so a sink is only ever called from one thread at a time
    // and never has to lock anything of its own.
    public interface Sink {
        void write(List<String> lines);
    }

    // Redaction happens before the line is queued, not before it is uploaded.
    // A line that reaches the queue with a token in it is already a leak,
    // because a crash dump would carry it out of the process.
    //
    // Two shapes. A keyed secret, token=abc in a query string or "token":"abc"
    // in a JSON body a call site dumped whole, and a bare email address in
    // free text, which no key based rule would ever see. This is a backstop.
    // The real control is an allowlist of the fields a call site may log.
    private static final Pattern KEYED_SECRET = Pattern.compile(
            "(?i)\\b(token|password|authorization)\\b\"?\\s*[=:]\\s*\"?(?:Bearer\\s+)?[^\\s\",}]+");
    private static final Pattern EMAIL = Pattern.compile("[\\w.+-]+@[\\w-]+(\\.[\\w-]+)+");

    private final Sink sink;
    private final Level minimum;
    private final int batchSize;
    private final int maxPending;
    private final Queue<String> pending = new ConcurrentLinkedQueue<>();
    // size() on a ConcurrentLinkedQueue walks the whole queue, so the count is
    // kept beside it. This runs on every log call and has to stay O(1).
    private final AtomicInteger count = new AtomicInteger();
    private final AtomicInteger dropped = new AtomicInteger();
    private final ScheduledExecutorService writer = Executors.newSingleThreadScheduledExecutor();

    public BatchingTree(Sink sink, Level minimum, int batchSize, int maxPending, long flushIntervalMillis) {
        this.sink = sink;
        this.minimum = minimum;
        this.batchSize = batchSize;
        this.maxPending = maxPending;
        // Two triggers, whichever comes first. A size trigger alone leaves the
        // last few lines of a quiet app sitting in memory forever, and an
        // interval alone lets a burst pile up between ticks.
        //
        // The body is guarded because a scheduled task that throws is
        // cancelled by the executor and never runs again. A full disk would
        // otherwise switch off logging for the rest of the process, silently.
        writer.scheduleWithFixedDelay(() -> {
            try {
                flush();
            } catch (RuntimeException sinkFailed) {
                // The next tick tries again with whatever has queued since.
            }
        }, flushIntervalMillis, flushIntervalMillis, TimeUnit.MILLISECONDS);
    }

    // This tree filters on level only. The per tag override that lets one
    // module run at verbose lives on Logger, because that check has to happen
    // before the message is built.
    @Override
    public boolean isLoggable(String tag, Level level) {
        return level.compareTo(minimum) >= 0;
    }

    @Override
    public void log(Level level, String tag, String message, Throwable error) {
        pending.add(redact(level + " " + tag + " " + message + (error == null ? "" : " " + error)));
        // A bounded queue that drops its oldest line, which is what a ring
        // buffer is. A slow sink must never turn into an OutOfMemoryError,
        // and the drop is counted so the gap shows up in the log itself.
        if (count.incrementAndGet() > maxPending && pending.poll() != null) {
            count.decrementAndGet();
            dropped.incrementAndGet();
        }
        if (count.get() >= batchSize) {
            writer.execute(this::flush);
        }
    }

    static String redact(String line) {
        String keyed = KEYED_SECRET.matcher(line).replaceAll("$1=REDACTED");
        return EMAIL.matcher(keyed).replaceAll("EMAIL_REDACTED");
    }

    // The crash handler calls this on the way down, and it runs on the calling
    // thread on purpose. Async writing is right for normal logging and exactly
    // wrong for the last few lines before a crash, which are the only ones
    // anybody is ever going to read.
    //
    // Synchronized because the scheduler, the size trigger and the crash
    // handler can all arrive at once, and two drains of one queue would hand
    // the sink two interleaved halves of the same burst.
    public synchronized void flush() {
        List<String> batch = new ArrayList<>();
        for (String line = pending.poll(); line != null; line = pending.poll()) {
            batch.add(line);
        }
        count.addAndGet(-batch.size());
        int lost = dropped.getAndSet(0);
        if (lost > 0) {
            batch.add(0, Level.WARN + " logging dropped " + lost + " lines under load");
        }
        if (!batch.isEmpty()) {
            // A batch the sink rejects is lost. Requeuing it would refill the
            // queue the sink just failed to drain.
            sink.write(batch);
        }
    }
}

com.androidinterview.logging.Level.java

package com.androidinterview.logging;

// Ordered lowest to highest, because the filter is a comparison and nothing
// more. Declaration order is the filter.
public enum Level {
    VERBOSE,
    DEBUG,
    INFO,
    WARN,
    ERROR
}

com.androidinterview.logging.Logger.java

package com.androidinterview.logging;

import java.util.List;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.CopyOnWriteArrayList;
import java.util.function.Supplier;

// The API surface, and the only thing a call site sees.
public final class Logger {

    private static final List<Tree> TREES = new CopyOnWriteArrayList<>();
    private static volatile Level minimum = Level.INFO;
    // Per tag overrides, consulted before the global minimum. This is what
    // lets one noisy module run at verbose while the rest of the app stays at
    // warn. It lives here and not in a tree because the gate that decides
    // whether a message is built at all runs before any tree is asked.
    private static final Map<String, Level> OVERRIDES = new ConcurrentHashMap<>();

    private Logger() {
    }

    public static void plant(Tree tree) {
        TREES.add(tree);
    }

    // Raised remotely for one user session when someone is chasing a reported
    // bug, which is why these are fields rather than build constants.
    public static void setMinimum(Level level) {
        minimum = level;
    }

    public static void setMinimum(String tag, Level level) {
        OVERRIDES.put(tag, level);
    }

    static Level levelFor(String tag) {
        return OVERRIDES.getOrDefault(tag, minimum);
    }

    // The eager overloads. The level is checked before String.format runs, but
    // the varargs array and any boxing are paid at the call site before the
    // check, and a call site that concatenates its own message defeats the
    // check entirely. That is the trap the Supplier overload below avoids.
    public static void d(String tag, String format, Object... args) {
        log(Level.DEBUG, tag, null, format, args);
    }

    public static void e(String tag, Throwable error, String format, Object... args) {
        log(Level.ERROR, tag, error, format, args);
    }

    // The overload for a hot path. The message is only built if something is
    // going to read it, so a filtered call in a loop costs one comparison.
    public static void d(String tag, Supplier<String> message) {
        if (Level.DEBUG.compareTo(levelFor(tag)) < 0) {
            return;
        }
        dispatch(Level.DEBUG, tag, message.get(), null);
    }

    // The filter comes before the formatting, and that is the whole reason
    // leveled logging is cheap enough to leave switched on in production.
    // Building a string nobody will read is work paid at every call site.
    private static void log(Level level, String tag, Throwable error, String format, Object... args) {
        if (level.compareTo(levelFor(tag)) < 0) {
            return;
        }
        dispatch(level, tag, args.length == 0 ? format : String.format(format, args), error);
    }

    // Synchronous on the calling thread. Only the batching tree moves its work
    // off this thread, and a tree that writes synchronously has chosen to.
    private static void dispatch(Level level, String tag, String message, Throwable error) {
        for (Tree tree : TREES) {
            if (tree.isLoggable(tag, level)) {
                tree.log(level, tag, message, error);
            }
        }
    }
}

com.androidinterview.logging.Tree.java

package com.androidinterview.logging;

// Where a log line actually goes. The core library owns the API and knows
// nothing about destinations, so a debug build plants a Logcat tree, a release
// build plants a file tree and a crash reporting tree, and no call site
// changes between them.
//
// isLoggable is the tree's own filter, applied after the Logger gate. The tag
// is there so a tree can decline a whole module, a crash reporting tree that
// wants nothing from a chatty network module for instance. The per tag
// verbosity override lives on Logger, because it has to be checked before the
// message is built and a tree is only consulted after.
public interface Tree {

    boolean isLoggable(String tag, Level level);

    void log(Level level, String tag, String message, Throwable error);
}

Kotlin

com.androidinterview.logging.BatchingTree.kt

package com.androidinterview.logging

import java.util.concurrent.ConcurrentLinkedQueue
import java.util.concurrent.Executors
import java.util.concurrent.TimeUnit
import java.util.concurrent.atomic.AtomicInteger

// Redaction happens before the line is queued, not before it is uploaded. A
// line that reaches the queue with a token in it is already a leak, because a
// crash dump would carry it out of the process.
//
// Two shapes. A keyed secret, token=abc in a query string or "token":"abc" in
// a JSON body a call site dumped whole, and a bare email address in free text,
// which no key based rule would ever see. This is a backstop. The real control
// is an allowlist of the fields a call site may log.
private val KEYED_SECRET =
    Regex("""(?i)\b(token|password|authorization)\b"?\s*[=:]\s*"?(?:Bearer\s+)?[^\s",}]+""")
private val EMAIL = Regex("""[\w.+-]+@[\w-]+(\.[\w-]+)+""")

internal fun redact(line: String): String =
    EMAIL.replace(KEYED_SECRET.replace(line, "$1=REDACTED"), "EMAIL_REDACTED")

// A rotating file or an upload endpoint. The tree decides when to write, the
// sink decides where, and neither needs to know the other. flush is
// synchronized, so a sink is only ever called from one thread at a time and
// never has to lock anything of its own.
fun interface Sink {
    fun write(lines: List<String>)
}

// The tree a release build plants. Nothing here runs on the calling thread
// except appending to a queue, because a log call from the main thread must
// never wait on a file.
class BatchingTree(
    private val sink: Sink,
    private val minimum: Level = Level.WARN,
    private val batchSize: Int = 50,
    private val maxPending: Int = 10_000,
    flushIntervalMillis: Long = 30_000,
) : Tree {

    private val pending = ConcurrentLinkedQueue<String>()
    // size on a ConcurrentLinkedQueue walks the whole queue, so the count is
    // kept beside it. This runs on every log call and has to stay O(1).
    private val count = AtomicInteger()
    private val dropped = AtomicInteger()
    private val writer = Executors.newSingleThreadScheduledExecutor()

    init {
        // Two triggers, whichever comes first. A size trigger alone leaves the
        // last few lines of a quiet app in memory forever, and an interval
        // alone lets a burst pile up between ticks.
        //
        // runCatching, because a scheduled task that throws is cancelled by
        // the executor and never runs again. A full disk would otherwise
        // switch off logging for the rest of the process, silently.
        writer.scheduleWithFixedDelay(
            { runCatching { flush() } }, flushIntervalMillis, flushIntervalMillis, TimeUnit.MILLISECONDS,
        )
    }

    // This tree filters on level only. The per tag override that lets one
    // module run at verbose lives on Logger, because that check has to happen
    // before the message is built.
    override fun isLoggable(tag: String, level: Level) = level >= minimum

    override fun log(level: Level, tag: String, message: String, error: Throwable?) {
        pending += redact("$level $tag $message" + error?.let { " $it" }.orEmpty())
        // A bounded queue that drops its oldest line, which is what a ring
        // buffer is. A slow sink must never turn into an OutOfMemoryError, and
        // the drop is counted so the gap shows up in the log itself.
        if (count.incrementAndGet() > maxPending && pending.poll() != null) {
            count.decrementAndGet()
            dropped.incrementAndGet()
        }
        if (count.get() >= batchSize) writer.execute(::flush)
    }

    // The crash handler calls this on the way down, and it runs on the calling
    // thread on purpose. Async writing is right for normal logging and exactly
    // wrong for the last few lines before a crash, which are the only ones
    // anybody is ever going to read.
    //
    // Synchronized because the scheduler, the size trigger and the crash
    // handler can all arrive at once, and two drains of one queue would hand
    // the sink two interleaved halves of the same burst.
    @Synchronized
    fun flush() {
        val batch = generateSequence(pending::poll).toMutableList()
        count.addAndGet(-batch.size)
        val lost = dropped.getAndSet(0)
        if (lost > 0) batch.add(0, "${Level.WARN} logging dropped $lost lines under load")
        // A batch the sink rejects is lost. Requeuing it would refill the
        // queue the sink just failed to drain.
        if (batch.isNotEmpty()) sink.write(batch)
    }
}

com.androidinterview.logging.Logger.kt

package com.androidinterview.logging

import java.util.concurrent.ConcurrentHashMap
import java.util.concurrent.CopyOnWriteArrayList

// Ordered lowest to highest, because the filter is a comparison and nothing
// more. Declaration order is the filter.
enum class Level { VERBOSE, DEBUG, INFO, WARN, ERROR }

// Where a log line actually goes. The core library owns the API and knows
// nothing about destinations, so a debug build plants a Logcat tree, a release
// build plants a file tree and a crash reporting tree, and no call site
// changes between them.
//
// isLoggable is the tree's own filter, applied after the Logger gate. The tag
// is there so a tree can decline a whole module, a crash reporting tree that
// wants nothing from a chatty network module for instance. The per tag
// verbosity override lives on Logger, because it has to be checked before the
// message is built and a tree is only consulted after.
interface Tree {
    fun isLoggable(tag: String, level: Level): Boolean
    fun log(level: Level, tag: String, message: String, error: Throwable?)
}

// The API surface, and the only thing a call site sees.
object Logger {

    @PublishedApi
    internal val trees = CopyOnWriteArrayList<Tree>()

    // Raised remotely for one user session when someone is chasing a reported
    // bug, which is why this is a field rather than a build constant.
    @Volatile
    var minimum = Level.INFO

    // Per tag overrides, consulted before the global minimum. This is what
    // lets one noisy module run at verbose while the rest of the app stays at
    // warn. It lives here and not in a tree because the gate that decides
    // whether a message is built at all runs before any tree is asked.
    @PublishedApi
    internal val overrides = ConcurrentHashMap<String, Level>()

    fun plant(tree: Tree) {
        trees += tree
    }

    fun setMinimum(tag: String, level: Level) {
        overrides[tag] = level
    }

    @PublishedApi
    internal fun levelFor(tag: String): Level = overrides[tag] ?: minimum

    inline fun d(tag: String, error: Throwable? = null, message: () -> String) =
        log(Level.DEBUG, tag, error, message)

    inline fun e(tag: String, error: Throwable? = null, message: () -> String) =
        log(Level.ERROR, tag, error, message)

    // The message is a lambda and the function is inline, so a filtered call
    // builds no string, allocates no lambda and makes no call. This is the
    // check before formatting that the Java version has to ask call sites to
    // remember, except here the compiler does it and nobody can forget.
    inline fun log(level: Level, tag: String, error: Throwable? = null, message: () -> String) {
        if (level < levelFor(tag)) return
        dispatch(level, tag, message(), error)
    }

    // Synchronous on the calling thread. Only the batching tree moves its work
    // off this thread, and a tree that writes synchronously has chosen to.
    @PublishedApi
    internal fun dispatch(level: Level, tag: String, message: String, error: Throwable?) =
        trees.forEach { if (it.isLoggable(tag, level)) it.log(level, tag, message, error) }
}

Tradeoffs I'd call out

Synchronous vs asynchronous writes. A synchronous write is durable the instant the call returns, which matters right before a crash, but it can block the caller. An async write is cheap for the caller but can lose the last few lines if the process dies before the flush. That is exactly the moment you most want them. The middle ground is async for normal logging and a synchronous flush from the crash handler on the way down.
Verbosity in production vs diagnostic value. Logging aggressively makes a production issue much easier to debug after the fact. It costs storage, a little CPU at every call site, and the risk of capturing something sensitive. Most teams persist warn and above by default and raise verbosity remotely for one user session, or for one tag, while chasing a reported issue.
A pluggable tree system vs a fixed pipeline. Pluggable destinations make the library reusable across very different apps, at the cost of more API surface to document. It is worth it once there is more than one real destination, and over-engineered if Logcat plus a file is all that is ever needed.
A static API vs an injected logger. The static Logger is what keeps a call site to one line. The cost is that tests have to plant a fake tree and unplant it afterwards, because there is nothing to inject.

What breaks at scale

The two real failure modes are not crashes. The first is unbounded growth, on the heap when a sink is slow and on disk when a file never rotates. The queue in front of the sink is capped and drops its oldest line when full, and it counts the drops so the gap shows up in the log itself. The sink rotates a fixed number of capped files for the same reason. A related trap is the scheduled flush itself. A scheduled task that throws once, on a full disk say, is cancelled by the executor forever, so the scheduled body catches and the next tick tries again.

The second failure is PII leaking into a crash report because a call site logged a raw request body that carried a user's email or auth token. The redaction step catches a keyed secret in a query string or a JSON body and a bare email in free text, and it runs before the line is queued. It is a backstop, though. A regex over free text will miss shapes nobody predicted, so the real control is an allowlist of the fields a call site is allowed to log.