Log Levels and Structured Logging

The previous lesson measured how a name enters the path: through a declaration, through order, or not at all. This lesson holds the same set of calls fixed and turns the one thing that changes into a threshold. The facade carried a logging call to the implementation; the question now is who decides whether that call actually turns into a record. Is it the call site, or a setting given by whoever runs the program?

The concepts of log level and structured logging are not new in this course — Observability and Operations and Performance Anti-Patterns and Monitoring both established them as concepts: that levels form an ordered scale, and how a structured record differs from free text. This lesson does not redefine those concepts; the only thing it asks is how these two concepts behave at runtime in Java’s standard logging library. The measurement is done with java.util.logging — not a third-party logging implementation, but the language’s own standard library. The facade/implementation distinction from the previous lesson still holds here: a call site writing logger.info(...) is no guarantee that the call will turn into a record. The difference is that the previous lesson looked at the question “was an implementation found,” while this lesson looks at “did it pass the level threshold” — both are answers the call site does not know, given by the runtime setup.

The Threshold Is Decided at Runtime, Not at the Call Site

LO9. Whether a log call is processed is decided by comparing the level the call carries against the threshold currently assigned to the logger. LO10. This comparison happens at runtime; the same compiled set of calls produces a different number of records depending on the threshold given at execution time.

// ThresholdCounter.java — how many records the same set of calls produces at two different runtime thresholds
import java.util.logging.*;
import java.util.ArrayList;
import java.util.List;

public class ThresholdCounter {
    static class CountingHandler extends Handler {
        List<String> published = new ArrayList<>();
        public void publish(LogRecord r) { published.add(r.getLevel() + " " + r.getMessage()); }
        public void flush() { }
        public void close() { }
    }

    static int run(Level threshold) {
        Logger logger = Logger.getLogger("ThresholdTrial-" + threshold);
        logger.setUseParentHandlers(false);
        CountingHandler h = new CountingHandler();
        h.setLevel(Level.ALL);
        logger.addHandler(h);
        logger.setLevel(threshold);

        logger.fine("detail");
        logger.info("progress");
        logger.warning("warning");
        logger.severe("critical");

        return h.published.size();
    }

    public static void main(String[] args) {
        int infoThresholdCount = run(Level.INFO);
        int warningThresholdCount = run(Level.WARNING);

        System.out.println("four calls: fine, info, warning, severe");
        System.out.println("records produced at threshold INFO   : " + infoThresholdCount);
        System.out.println("records produced at threshold WARNING: " + warningThresholdCount);
    }
}

four calls: fine, info, warning, severe
records produced at threshold INFO   : 3
records produced at threshold WARNING: 2

The run method makes exactly the same four calls in both cases: fine, info, warning, severe. The only thing that changes is the value given to the logger.setLevel(threshold) line. At the INFO threshold, the fine call is filtered out; the remaining three (info, warning, severe) reach the handler (LO9). When the threshold is raised to WARNING, info is filtered out too; only two remain. Both runs use the same class file — there is no recompilation at all — and produce a different number of records solely from a value given at execution time (LO10). The logger.info(...) line at the call site knows neither whether INFO will pass nor whether it will not; the party that knows this is the runtime setup that assigns the threshold to the logger.

LO11. The threshold is not a single setting: the logger’s own threshold and the threshold of each handler attached to it are applied separately; for a record to be published, it must pass both.

// TwoTierThreshold.java — the logger and the handler have separate thresholds, a record must pass both
import java.util.logging.*;
import java.util.ArrayList;
import java.util.List;

public class TwoTierThreshold {
    static class FilteringHandler extends Handler {
        List<String> published = new ArrayList<>();
        public void publish(LogRecord r) {
            if (!isLoggable(r)) return;
            published.add(r.getLevel() + " " + r.getMessage());
        }
        public void flush() { }
        public void close() { }
    }

    static int run(Level loggerThreshold, Level handlerThreshold) {
        Logger logger = Logger.getLogger("TwoTier-" + loggerThreshold + "-" + handlerThreshold);
        logger.setUseParentHandlers(false);
        FilteringHandler h = new FilteringHandler();
        h.setLevel(handlerThreshold);
        logger.addHandler(h);
        logger.setLevel(loggerThreshold);

        logger.info("progress");
        logger.warning("warning");
        logger.severe("critical");

        return h.published.size();
    }

    public static void main(String[] args) {
        System.out.println("three calls: info, warning, severe");
        System.out.println("logger ALL, handler ALL     -> produced: " + run(Level.ALL, Level.ALL));
        System.out.println("logger ALL, handler WARNING -> produced: " + run(Level.ALL, Level.WARNING));
        System.out.println("logger WARNING, handler ALL -> produced: " + run(Level.WARNING, Level.ALL));
    }
}

three calls: info, warning, severe
logger ALL, handler ALL     -> produced: 3
logger ALL, handler WARNING -> produced: 2
logger WARNING, handler ALL -> produced: 2

All three setups make the same three calls. When both the logger and the handler have their threshold at ALL, all three pass. When only one of the two is raised to WARNING — it does not matter which — the result is the same: two records (LO11). Reading the threshold as belonging only to the logger would be wrong; if FilteringHandler.publish did not run its own isLoggable check, the handler’s setLevel call would filter nothing, and the last two lines would also produce three records. The threshold being decided at runtime is therefore not a single number, but a decision made independently by every link in the chain. This has a practical consequence when more than one handler is attached to a logger: the same set of records can appear in one handler and not in another, because each handler applies its own threshold on its own, and the logger’s threshold is only the first filter.

Structured Records: Field Consistency, Not Field Count

LO12. A structured record’s field names are not chosen arbitrarily at the call site; they sit in a fixed declaration the producing side commits to, and the reading side knows which field to look for by consulting that declaration. LO13. A log stream’s readability is measured not by the number of fields a single record carries, but by whether the same field is present in every record.

The measurement below compares two designs. In the first, every record carries the same two fields: event and count. In the second, call sites act on their own: some add an extra source field, some never write the count field at all. The formatter is the same in both — the record is already built as full text at the call site, and the formatter only passes it along without adding a time field (the ban on machine-dependent data applies here too: no timestamp is ever printed).

// FieldConsistency.java — readability is measured not by total field count but by whether the same field is present in every record
import java.util.logging.*;
import java.util.ArrayList;
import java.util.List;

public class FieldConsistency {
    static class FieldFormatter extends Formatter {
        public String format(LogRecord r) { return r.getMessage() + System.lineSeparator(); }
    }

    static class CollectingHandler extends Handler {
        List<String> records = new ArrayList<>();
        Formatter b = new FieldFormatter();
        public void publish(LogRecord r) { records.add(b.format(r)); }
        public void flush() { }
        public void close() { }
    }

    static boolean hasBothFields(String record) {
        return record.contains("event=") && record.contains("count=");
    }

    static int totalFieldCount(List<String> records) {
        int total = 0;
        for (String r : records) {
            for (String part : r.trim().split(" ")) if (part.contains("=")) total++;
        }
        return total;
    }

    public static void main(String[] args) {
        List<String> consistent = new ArrayList<>();
        for (int i = 1; i <= 5; i++) consistent.add("event=order count=" + i);

        List<String> inconsistent = List.of(
                "event=order count=1 source=web",
                "event=order count=2 source=web",
                "event=order count=3 source=mobile",
                "event=order",
                "event=order");

        long consistentComplete = consistent.stream().filter(FieldConsistency::hasBothFields).count();
        long inconsistentComplete = inconsistent.stream().filter(FieldConsistency::hasBothFields).count();

        System.out.println("consistent design   - total fields: " + totalFieldCount(consistent)
                + ", records carrying both fields: " + consistentComplete + "/" + consistent.size());
        System.out.println("inconsistent design - total fields: " + totalFieldCount(inconsistent)
                + ", records carrying both fields: " + inconsistentComplete + "/" + inconsistent.size());
    }
}

consistent design   - total fields: 10, records carrying both fields: 5/5
inconsistent design - total fields: 11, records carrying both fields: 3/5

FieldFormatter and CollectingHandler are not doing the real work in this measurement — they collect the record as is, because the real difference is built at the call site. The inconsistent design’s total field count is higher than the consistent one’s: 11 against 10 (LO12’s obligation to follow a declaration does not apply here; each call site makes its own decision). Even so, a parser that looks for the count field in every record reads all five of the five records in the consistent design, but only three of them in the inconsistent design (LO13). Two records carry only event; these records have no count, and for the parser, “absent” and “zero” are not the same thing. Adding an extra field — source, in the third and fourth records — does not increase parseability; it only reduces how many fields are missing. What makes a log stream machine-readable is that every record carries the same fixed set of fields, not which fields belong to that set.

This distinction’s practical consequence shows up in the behavior of whatever later processes a log stream. A reader that wants to compute a total over the count field across thousands of records can safely process all five of the five records in the consistent stream; in the inconsistent stream, it has to either skip two records or treat them as a special case. The field count changing from record to record is not a bug — no exception is thrown anywhere in the FieldConsistency example, no call is rejected — but the reader’s inability to assume every field is present forces it to read that stream by hand, record by record. This is where structured logging’s real payoff lies: tying field names to a fixed declaration frees the reader from that assumption.

Limiting Measurement: A Call Below the Threshold Is Not Free

LO14. The expression carried by a call that falls below the threshold is evaluated regardless of level when the call is written with string concatenation. LO15. When the same call is written with a Supplier, the expression is evaluated only while the level is enabled; for calls that fall below the threshold, the evaluation never runs at all.

The previous two measurements showed that the threshold decides how many records are produced. From this it looks as if the conclusion “a call below the threshold is free” could be drawn, but that is wrong: the threshold decides only whether the record is published, not whether the argument given to the call is computed — the timing of that computation is a matter of Java’s method-invocation rule, not of the logging framework.

// CostlyCall.java — the argument of a call below the threshold is always evaluated with string concatenation, only while the level is enabled with a Supplier
import java.util.logging.*;

public class CostlyCall {
    static int evaluatedExpressions = 0;

    static String expensiveExpression() {
        evaluatedExpressions++;
        return "value=" + evaluatedExpressions;
    }

    public static void main(String[] args) {
        Logger logger = Logger.getLogger("CostTrial");
        logger.setUseParentHandlers(false);
        logger.addHandler(new Handler() {
            public void publish(LogRecord r) { }
            public void flush() { }
            public void close() { }
        });
        logger.setLevel(Level.WARNING);

        evaluatedExpressions = 0;
        for (int i = 0; i < 5; i++) {
            logger.fine("detail: " + expensiveExpression());
        }
        int eagerEvaluationCount = evaluatedExpressions;

        evaluatedExpressions = 0;
        for (int i = 0; i < 5; i++) {
            logger.log(Level.FINE, () -> "detail: " + expensiveExpression());
        }
        int lazyEvaluationCount = evaluatedExpressions;

        System.out.println("the logger's threshold is WARNING, all five calls are at level FINE");
        System.out.println("expressions evaluated with string concatenation (eager) : " + eagerEvaluationCount);
        System.out.println("expressions evaluated with a Supplier (lazy)            : " + lazyEvaluationCount);
    }
}

the logger's threshold is WARNING, all five calls are at level FINE
expressions evaluated with string concatenation (eager) : 5
expressions evaluated with a Supplier (lazy)            : 0

The logger’s threshold is WARNING; all five calls are at the lower level FINE, and none of them turns into a record. Even so, on the line logger.fine("detail: " + expensiveExpression()), expensiveExpression() runs all five times, and the counter climbs to five (LO14): Java computes a method’s arguments before calling it, and this order does not change even when the call itself will fall below the threshold. The second loop makes the same five calls with the Logger.log(Level, Supplier<String>) overload; this overloaded form calls the Supplier only if the level is enabled — for all five calls that fall below the threshold, get() never runs at all, and the counter stays at zero (LO15). Both forms use the same four levels and the same threshold; the only difference is when the argument is computed. What this lesson measures is not a duration — no time is measured anywhere — only the number of expressions evaluated.

This difference comes from Java’s method-invocation rule, not from a shortcoming of the logging framework: before logger.fine(message) is called, the value of the message expression must be ready, because Java computes a call’s arguments before the call itself happens — this order is independent of whether the fine method performs a threshold check internally. A Supplier does not change this order; it only hides the computation behind another method — get() — and moves the decision of whether to call that method into the fine method, after the threshold check. The facade itself is open to the same choice: if a logging facade offers the caller only a signature that takes a Supplier, the expression never runs at all when the implementation rejects the threshold; if the facade offers only a signature that takes a string, the caller cannot escape paying that cost no matter how carefully it writes the call. This shows that a facade’s choice of which methods to offer, not only which methods to call, is a measurable consequence too.

Summary

• Whether a log call turns into a record is decided by comparing the call’s level against the threshold assigned to the logger at runtime; the same compiled set of calls produces a different number of records at different thresholds.
• A structured record’s field names form a fixed set the producing side commits to in a declaration; the reading side knows which field to look for by consulting that set.
• A log stream’s readability is measured not by total field count but by whether the same field is present in every record; adding extra fields does not compensate for a field that is missing.
• Limiting measurement: the argument of a call below the threshold is still computed when written with string concatenation; it is computed only while the level is enabled when written with a Supplier.
• What is measured is not a duration but a count: how many records were produced, how many fields were consistent, how many expressions were evaluated.

Next Step

Everything measured across these two lessons lived inside the same runtime: the same virtual machine, the same class file format, sources coming from a single source language. The next lesson removes this last assumption: is a class file that enters the runtime class path met the same way even when its source was never written in the Java language at all, and does the caller notice?