Low Level DesignWorked problems
Design a logging framework
Design a logging framework step by step for a low level design interview. Levels, records, formatters and appenders, a logger tree with inherited configuration, lazy messages, and an async appender that never loses a record on shutdown, with code in Java, Python, C#, Go and TypeScript.
- Read first
- Object modelingThread safety basics
- Building blocks
- Observability
“Design a logging framework like Log4j.” Levels, several outputs, formats you can configure, and it must not slow the application down.
A logging framework is the library that code calls to write lines like
12:00:01 WARN app.db.pool pool almost full. Developers read those lines to understand what the
application did, especially when something went wrong.
Everyone has used a logger, so the parts sound familiar: levels, outputs, formats. The design question is how they fit together, and what each one costs. How does setting one package to DEBUG reach every class in it, without configuring each one? Why does a debug line that’s switched off still cost time? And what happens to lines waiting in memory when the process shuts down?
The answer in one minute
Section titled “The answer in one minute”If you only have a minute, this is the design. The rest of the page explains how we get here.
- Each log call makes one record, and three separate parts handle it. The level decides whether to write it. A formatter decides how it looks. An appender decides where it goes (the console, a file). Each one changes without touching the others.
- Loggers form a tree by name.
app.db.poolsits underapp.db, which sits underapp. Settings made on a branch apply to everything below it. So a few settings configure thousands of loggers. - A switched-off call costs almost nothing. The message is built only after the level check
says yes, using placeholders like
"user {}", or a function that’s only called when needed. - Writing happens on a background thread. Callers drop the record into a queue with a size limit, and one writer thread saves it. A slow disk no longer slows down requests.
- Nothing is lost on shutdown. Closing the logger waits until every queued record is written. When the queue is full, low-importance lines are dropped and counted, but warnings and errors wait.
We’ll build this in four stages, then deal with many threads and a slow disk.
Scope it
Section titled “Scope it”Before drawing anything, we ask a few questions. Each answer changes a class. Anything that doesn’t, we assume and move on.
Design a logging framework.
Whether you ask about outputs, settings per package, and whether writes can block, in the first
few minutes, since those shape the whole design. Starting with an enum of levels and a print
is a one-class answer to a framework question.
Here are the questions that matter:
- Where do logs go? The console and files now, others later. With one fixed output, there’s no need for an appender interface.
- What format? Plain text for people, and JSON for tools that collect logs. With one format, the formatting can stay inside the output.
- Are settings per class, or per package? Per package, and everything below inherits them. With per-class settings only, there’s no tree.
- Can logging make a request wait? No. Writing should happen away from the request. If waiting were fine, stage 5’s background writer goes away.
- Is it ever OK to lose a line? DEBUG and INFO lines, under heavy load. Never WARN or ERROR. If the answer were “never”, the background writer must make callers wait instead of dropping.
These answers give us one promise that matters more than the others: logging must never hurt the application. A switched-off call costs one comparison. A slow disk doesn’t block requests. A shutdown doesn’t lose what was already logged. Two smaller promises come with it: lines from different threads never mix, and time is passed in, so tests can check the exact output.
We leave out sending logs to a central store (a separate system), splitting files by size or day, and adding a request ID to every line (both are extensions).
Go deeperThree more questions, and what each changes1 min
| Question | We assume | If the answer were different |
|---|---|---|
| Can levels change at runtime? | Yes, to debug a live issue | Fixed at startup lets the settings be plain fields |
| Request IDs in every line? | An extension (context fields) | Required now adds a per-thread or per-request context map |
| New file by size or day? | An extension | Required now adds a rolling file appender |
Build it
Section titled “Build it”We’ll build the design in four stages. Each stage adds only the classes that a new requirement needs. In each diagram, the new parts are outlined, and the colors show what each class does (the key is under every diagram).
Stage 1: A logger with a level
Section titled “Stage 1: A logger with a level”Start with the simplest thing: a logger with levels.
Whether levels are ordered so a check is one comparison, and whether you name what’s fixed in place and will have to move. Spending time on the print format here is the warning sign.
Start with the smallest thing that works. There are four levels, from least to most serious: DEBUG, INFO, WARN, ERROR. Each logger has a threshold level. Because the levels are in order, “should I write this?” is one comparison: is the record’s level at or above the threshold? If so, the logger prints it with the time, the level and the logger’s name.
- Color key
- Facade
- Entity
- Value object
- Enum
- Interface
- Implementation
- New in this step
// Ordered from least to most severe, so "is this enabled?" is one comparison.enum Level { DEBUG, INFO, WARN, ERROR }
final class Logger { private final String name; private Level threshold;
Logger(String name, Level threshold) { this.name = name; this.threshold = threshold; }
void setLevel(Level level) { this.threshold = level; }
void log(Level level, String message) { if (level.compareTo(threshold) < 0) return; // below the threshold: skip // flaw 1: the destination (stdout) and the layout are fixed. Stage 2. // flaw 2: every logger is configured on its own; no way to say "all of app.db". Stage 3. System.out.println(Instant.now() + " " + level + " " + name + " - " + message); }
// flaw 3: the caller builds the message string before we can say no. Stage 4. void debug(String message) { log(Level.DEBUG, message); } void info(String message) { log(Level.INFO, message); } void warn(String message) { log(Level.WARN, message); } void error(String message) { log(Level.ERROR, message); }}from datetime import datetime, timezonefrom enum import IntEnum
# Ordered from least to most severe, so "is this enabled?" is one comparison.class Level(IntEnum): DEBUG = 10 INFO = 20 WARN = 30 ERROR = 40
class Logger: def __init__(self, name: str, threshold: Level): self.name = name self.threshold = threshold
def log(self, level: Level, message: str) -> None: if level < self.threshold: return # below the threshold: skip # flaw 1: the destination (stdout) and the layout are fixed. Stage 2. # flaw 2: every logger is configured on its own; no way to say "all of app.db". Stage 3. print(f"{datetime.now(timezone.utc).isoformat()} {level.name} {self.name} - {message}")
# flaw 3: the caller builds the message (an f-string) before we can say no. Stage 4. def debug(self, message: str) -> None: self.log(Level.DEBUG, message) def info(self, message: str) -> None: self.log(Level.INFO, message) def warn(self, message: str) -> None: self.log(Level.WARN, message) def error(self, message: str) -> None: self.log(Level.ERROR, message)// Ordered from least to most severe, so "is this enabled?" is one comparison.public enum Level { Debug, Info, Warn, Error }
public sealed class Logger(string name, Level threshold){ public Level Threshold { get; set; } = threshold;
public void Log(Level level, string message) { if (level < Threshold) return; // below the threshold: skip // flaw 1: the destination (stdout) and the layout are fixed. Stage 2. // flaw 2: every logger is configured on its own; no way to say "all of App.Db". Stage 3. Console.WriteLine($"{DateTimeOffset.UtcNow:O} {level} {name} - {message}"); }
// flaw 3: the caller builds the message (an interpolated string) before we can say no. Stage 4. public void Debug(string message) => Log(Level.Debug, message); public void Info(string message) => Log(Level.Info, message); public void Warn(string message) => Log(Level.Warn, message); public void Error(string message) => Log(Level.Error, message);}// Level is ordered from least to most severe, so "is this enabled?" is one comparison.type Level int32
const ( Debug Level = iota Info Warn Error)
func (l Level) String() string { return [...]string{"DEBUG", "INFO", "WARN", "ERROR"}[l] }
type Logger struct { name string threshold Level}
func NewLogger(name string, threshold Level) *Logger { return &Logger{name: name, threshold: threshold}}
func (l *Logger) Log(level Level, message string) { if level < l.threshold { return // below the threshold: skip } // flaw 1: the destination (stdout) and the layout are fixed. Stage 2. // flaw 2: every logger is configured on its own; no way to say "all of app.db". Stage 3. fmt.Println(time.Now().UTC().Format(time.RFC3339), level, l.name, "-", message)}
// flaw 3: the caller builds the message (fmt.Sprintf) before we can say no. Stage 4.func (l *Logger) Debug(message string) { l.Log(Debug, message) }func (l *Logger) Info(message string) { l.Log(Info, message) }func (l *Logger) Warn(message string) { l.Log(Warn, message) }func (l *Logger) Error(message string) { l.Log(Error, message) }// Ordered from least to most severe, so "is this enabled?" is one comparison.enum Level { DEBUG = 10, INFO = 20, WARN = 30, ERROR = 40,}
class Logger { constructor( readonly name: string, public threshold: Level, ) {}
log(level: Level, message: string): void { if (level < this.threshold) return; // below the threshold: skip // flaw 1: the destination (stdout) and the layout are fixed. Stage 2. // flaw 2: every logger is configured on its own; no way to say "all of app.db". Stage 3. console.log(`${new Date().toISOString()} ${Level[level]} ${this.name} - ${message}`); }
// flaw 3: the caller builds the message (a template string) before we can say no. Stage 4. debug(message: string) { this.log(Level.DEBUG, message); } info(message: string) { this.log(Level.INFO, message); } warn(message: string) { this.log(Level.WARN, message); } error(message: string) { this.log(Level.ERROR, message); }}It works, but three things are wrong, and the next three stages fix one each.
- The output is fixed. It always prints to the console, in one layout.
- Each logger is set up on its own. Turning on DEBUG for the database code means finding every logger in it.
- A switched-off call still costs time.
log.debug("user " + user)builds the string before the logger can say no. So a debug line that’s off still joins strings and callstoString().
Go deeperWhat about TRACE, FATAL and OFF?1 min
Real frameworks add more levels at both ends. TRACE sits below DEBUG, for very detailed lines like “entered method”. FATAL sits above ERROR, for “the application is about to stop”. And OFF is a level above everything, so setting a logger to OFF switches it off completely.
None of them changes the design. Each level is a number in order, so adding one is adding a number between two others. The check stays one comparison. That’s why levels are stored as ordered numbers (an enum with a rank), not as a list of names to search.
Some teams also add custom levels, like AUDIT. Be careful: a custom level must still fit somewhere
in the order, or “everything at WARN and above” stops having a clear meaning. Often a separate
logger named audit is the better answer.
Stage 2: Records, formatters and appenders
Section titled “Stage 2: Records, formatters and appenders”We need the console in plain text and a file in JSON, at the same time.
Whether “how it looks” and “where it goes” become two separate interfaces, and whether the event
is captured once as a value. One class per combination (JsonFileLogger) is the answer that
doesn’t scale.
We split one log call into three ideas:
- A
LogRecordcaptures the event once: the time, level, logger name, thread, message and error. It never changes after it’s made. So every output can share it, and later, another thread can read it safely. - A
Formatterturns a record into text.TextFormatterwrites a line for people.JsonFormatterwrites one JSON object per line for log tools. It escapes quotes and line breaks, so a message can’t break one record into two. - An
Appendersends a record somewhere, and has its own formatter. So the console can use text while the file uses JSON, from the same record.
A logger holds a list of appenders and gives the record to each. Formatters and appenders are both the Strategy pattern: one interface, and a class for each choice.
- Color key
- Facade
- Entity
- Value object
- Enum
- Interface
- Implementation
- New in this step
// One log event, captured once and handed to every appender. A value: appenders on other// threads can read it without locks.record LogRecord(Instant time, Level level, String logger, String thread, String message, Throwable error) {}
// Turns a record into text. Separate from where the text goes, so the same JSON layout can go// to a file or a socket, and the console can stay human-readable.interface Formatter { String format(LogRecord r);}
// 2026-01-01T09:30:00Z WARN app.db [main] - pool exhaustedfinal class TextFormatter implements Formatter { public String format(LogRecord r) { String line = r.time() + " " + r.level() + " " + r.logger() + " [" + r.thread() + "] - " + r.message(); if (r.error() == null) return line; StringWriter trace = new StringWriter(); r.error().printStackTrace(new PrintWriter(trace)); return line + System.lineSeparator() + trace.toString().stripTrailing(); }}
// One JSON object per line, for log shippers. Escaping matters: a message with a quote or a// newline must not break the line into two records or into invalid JSON.final class JsonFormatter implements Formatter { public String format(LogRecord r) { StringBuilder b = new StringBuilder("{"); field(b, "time", r.time().toString()).append(','); field(b, "level", r.level().name()).append(','); field(b, "logger", r.logger()).append(','); field(b, "thread", r.thread()).append(','); field(b, "message", r.message()); if (r.error() != null) field(b.append(','), "error", r.error().toString()); return b.append('}').toString(); }
private static StringBuilder field(StringBuilder b, String key, String value) { b.append('"').append(key).append("\":\""); for (char c : value.toCharArray()) { switch (c) { case '"' -> b.append("\\\""); case '\\' -> b.append("\\\\"); case '\n' -> b.append("\\n"); case '\r' -> b.append("\\r"); case '\t' -> b.append("\\t"); default -> { if (c < 0x20) b.append(String.format("\\u%04x", (int) c)); // other control characters else b.append(c); } } } return b.append('"'); }}
// Where formatted records go. Each appender owns its formatter: the console can be plain text// while the file is JSON.interface Appender { void append(LogRecord r); default void close() {} // flush and release files; the async appender needs it}
final class ConsoleAppender implements Appender { private final PrintStream out; private final Formatter formatter;
ConsoleAppender(Formatter formatter) { this(System.out, formatter); } ConsoleAppender(PrintStream out, Formatter formatter) { this.out = out; this.formatter = formatter; }
public void append(LogRecord r) { out.println(formatter.format(r)); }}
final class FileAppender implements Appender { private final BufferedWriter out; private final Formatter formatter;
FileAppender(Path file, Formatter formatter) throws IOException { // Append, never truncate: a restart must not wipe the last run's logs. this.out = Files.newBufferedWriter(file, StandardOpenOption.CREATE, StandardOpenOption.APPEND); this.formatter = formatter; }
public void append(LogRecord r) { try { out.write(formatter.format(r)); out.newLine(); // Flush per record so a crash loses nothing that was logged. It costs a system call // per line; the async appender takes that cost off the caller's thread. out.flush(); } catch (IOException e) { // Logging must never take the application down. Report on stderr and carry on. System.err.println("FileAppender failed: " + e); } }
public void close() { try { out.close(); } catch (IOException e) { System.err.println("FileAppender close failed: " + e); } }}
final class Logger { private final String name; private final Clock clock; // injected so tests get stable timestamps private final List<Appender> appenders = new ArrayList<>(); private Level threshold;
Logger(String name, Level threshold, Clock clock) { this.name = name; this.threshold = threshold; this.clock = clock; }
void setLevel(Level level) { this.threshold = level; } void addAppender(Appender a) { appenders.add(a); }
void log(Level level, String message, Throwable error) { if (level.compareTo(threshold) < 0) return; // Build the record once; every appender gets the same one. LogRecord r = new LogRecord(clock.instant(), level, name, Thread.currentThread().getName(), message, error); for (Appender a : appenders) a.append(r); }
void debug(String message) { log(Level.DEBUG, message, null); } void info(String message) { log(Level.INFO, message, null); } void warn(String message) { log(Level.WARN, message, null); } void error(String message, Throwable error) { log(Level.ERROR, message, error); }}import jsonimport sysimport threadingimport tracebackfrom dataclasses import dataclassfrom datetime import datetime, timezonefrom typing import Callable, Optional, Protocol, TextIO
Clock = Callable[[], datetime]
def utc_now() -> datetime: return datetime.now(timezone.utc)
# One log event, captured once and handed to every appender. Frozen: appenders on other# threads can read it without locks.@dataclass(frozen=True)class LogRecord: time: datetime level: Level logger: str thread: str message: str error: Optional[BaseException] = None
# Turns a record into text. Separate from where the text goes, so the same JSON layout can go# to a file or a socket, and the console can stay human-readable.class Formatter(Protocol): def format(self, r: LogRecord) -> str: ...
def _iso(t: datetime) -> str: return t.isoformat().replace("+00:00", "Z")
# 2026-01-01T09:30:00Z WARN app.db [MainThread] - pool exhaustedclass TextFormatter: def format(self, r: LogRecord) -> str: line = f"{_iso(r.time)} {r.level.name} {r.logger} [{r.thread}] - {r.message}" if r.error is None: return line trace = "".join(traceback.format_exception(r.error)).rstrip() return f"{line}\n{trace}"
# One JSON object per line, for log shippers. json.dumps escapes quotes and newlines, so a# message can't break the line into two records or into invalid JSON.class JsonFormatter: def format(self, r: LogRecord) -> str: fields = {"time": _iso(r.time), "level": r.level.name, "logger": r.logger, "thread": r.thread, "message": r.message} if r.error is not None: fields["error"] = repr(r.error) return json.dumps(fields, separators=(",", ":"), ensure_ascii=False)
# Where formatted records go. Each appender owns its formatter: the console can be plain text# while the file is JSON.class Appender(Protocol): def append(self, r: LogRecord) -> None: ...
def close(self) -> None: ... # flush and release files; the async appender needs it
class ConsoleAppender: def __init__(self, formatter: Formatter, out: TextIO = sys.stdout): self._formatter = formatter self._out = out
def append(self, r: LogRecord) -> None: self._out.write(self._formatter.format(r) + "\n")
def close(self) -> None: self._out.flush()
class FileAppender: def __init__(self, path: str, formatter: Formatter): # Append, never truncate: a restart must not wipe the last run's logs. self._file = open(path, "a", encoding="utf-8") self._formatter = formatter
def append(self, r: LogRecord) -> None: try: self._file.write(self._formatter.format(r) + "\n") # Flush per record so a crash loses nothing that was logged. It costs a system # call per line; the async appender takes that cost off the caller's thread. self._file.flush() except OSError as e: # Logging must never take the application down. Report on stderr and carry on. print(f"FileAppender failed: {e}", file=sys.stderr)
def close(self) -> None: self._file.close()
class Logger: def __init__(self, name: str, threshold: Level, clock: Clock = utc_now): self.name = name self.threshold = threshold self._clock = clock # injected so tests get stable timestamps self._appenders: list[Appender] = []
def add_appender(self, a: Appender) -> None: self._appenders.append(a)
def log(self, level: Level, message: str, error: Optional[BaseException] = None) -> None: if level < self.threshold: return # Build the record once; every appender gets the same one. r = LogRecord(self._clock(), level, self.name, threading.current_thread().name, message, error) for a in self._appenders: a.append(r)
def debug(self, message: str) -> None: self.log(Level.DEBUG, message) def info(self, message: str) -> None: self.log(Level.INFO, message) def warn(self, message: str) -> None: self.log(Level.WARN, message) def error(self, message: str, error: Optional[BaseException] = None) -> None: self.log(Level.ERROR, message, error)// One log event, captured once and handed to every appender. Immutable, so appenders on other// threads can read it without locks.public sealed record LogRecord(DateTimeOffset Time, Level Level, string Logger, string Thread, string Message, Exception? Error);
// Turns a record into text. Separate from where the text goes, so the same JSON layout can go// to a file or a socket, and the console can stay human-readable.public interface IFormatter{ string Format(LogRecord r);}
// 2026-01-01T09:30:00Z WARN App.Db [1] - pool exhaustedpublic sealed class TextFormatter : IFormatter{ public string Format(LogRecord r) { var line = $"{r.Time.UtcDateTime:yyyy-MM-ddTHH:mm:ssZ} {r.Level.ToString().ToUpperInvariant()} {r.Logger} [{r.Thread}] - {r.Message}"; return r.Error is null ? line : line + Environment.NewLine + r.Error; // ToString() includes the stack trace }}
// One JSON object per line, for log shippers. Utf8JsonWriter escapes quotes and newlines, so a// message can't break the line into two records or into invalid JSON.public sealed class JsonFormatter : IFormatter{ public string Format(LogRecord r) { using var buffer = new MemoryStream(); using (var w = new Utf8JsonWriter(buffer)) { w.WriteStartObject(); w.WriteString("time", r.Time.UtcDateTime.ToString("yyyy-MM-ddTHH:mm:ssZ")); w.WriteString("level", r.Level.ToString().ToUpperInvariant()); w.WriteString("logger", r.Logger); w.WriteString("thread", r.Thread); w.WriteString("message", r.Message); if (r.Error is not null) w.WriteString("error", r.Error.ToString()); w.WriteEndObject(); } return Encoding.UTF8.GetString(buffer.ToArray()); }}
// Where formatted records go. Each appender owns its formatter: the console can be plain text// while the file is JSON.public interface IAppender : IDisposable // Dispose flushes and releases files; the async appender needs it{ void Append(LogRecord r);}
public sealed class ConsoleAppender(IFormatter formatter) : IAppender{ public void Append(LogRecord r) => Console.Out.WriteLine(formatter.Format(r)); public void Dispose() => Console.Out.Flush();}
public sealed class FileAppender : IAppender{ private readonly StreamWriter _out; private readonly IFormatter _formatter;
public FileAppender(string path, IFormatter formatter) { // Append, never truncate: a restart must not wipe the last run's logs. // AutoFlush writes each record through, so a crash loses nothing that was logged. It // costs a system call per line; the async appender takes that off the caller. _out = new StreamWriter(path, append: true) { AutoFlush = true }; _formatter = formatter; }
public void Append(LogRecord r) { try { _out.WriteLine(_formatter.Format(r)); } catch (IOException e) { Console.Error.WriteLine($"FileAppender failed: {e.Message}"); } // never crash the app }
public void Dispose() => _out.Dispose();}
public sealed class Logger(string name, Level threshold, TimeProvider time){ private readonly List<IAppender> _appenders = []; public Level Threshold { get; set; } = threshold;
public void AddAppender(IAppender a) => _appenders.Add(a);
public void Log(Level level, string message, Exception? error = null) { if (level < Threshold) return; // Build the record once; every appender gets the same one. TimeProvider is injected so // tests get stable timestamps. var r = new LogRecord(time.GetUtcNow(), level, name, Environment.CurrentManagedThreadId.ToString(), message, error); foreach (var a in _appenders) a.Append(r); }
public void Debug(string message) => Log(Level.Debug, message); public void Info(string message) => Log(Level.Info, message); public void Warn(string message) => Log(Level.Warn, message); public void Error(string message, Exception? error = null) => Log(Level.Error, message, error);}// Record is one log event, captured once and handed to every appender. Passed by value, so// appenders on other goroutines can read it without locks.type Record struct { Time time.Time Level Level Logger string Message string Err error}
// Formatter turns a record into text. Separate from where the text goes, so the same JSON// layout can go to a file or a socket, and the console can stay human-readable.type Formatter interface { Format(r Record) string}
// TextFormatter: 2026-01-01T09:30:00Z WARN app.db - pool exhaustedtype TextFormatter struct{}
func (TextFormatter) Format(r Record) string { line := fmt.Sprintf("%s %s %s - %s", r.Time.UTC().Format(time.RFC3339), r.Level, r.Logger, r.Message) if r.Err != nil { line += ": " + r.Err.Error() } return line}
// JSONFormatter writes one JSON object per line, for log shippers. encoding/json escapes// quotes and newlines, so a message can't break the line into two records or invalid JSON.type JSONFormatter struct{}
func (JSONFormatter) Format(r Record) string { fields := struct { Time string `json:"time"` Level string `json:"level"` Logger string `json:"logger"` Message string `json:"message"` Error string `json:"error,omitempty"` }{r.Time.UTC().Format(time.RFC3339), r.Level.String(), r.Logger, r.Message, ""} if r.Err != nil { fields.Error = r.Err.Error() } b, _ := json.Marshal(fields) // a struct of strings can't fail to marshal return string(b)}
// Appender is where formatted records go. Each appender owns its formatter: the console can// be plain text while the file is JSON.type Appender interface { Append(r Record) Close() error // flush and release files; the async appender needs it}
type WriterAppender struct { w io.Writer formatter Formatter}
// NewConsoleAppender writes to stdout; any io.Writer works the same way.func NewConsoleAppender(f Formatter) *WriterAppender { return &WriterAppender{os.Stdout, f} }
func (a *WriterAppender) Append(r Record) { // One Write call per record: the line and its newline go out together. if _, err := io.WriteString(a.w, a.formatter.Format(r)+"\n"); err != nil { // Logging must never take the application down. Report on stderr and carry on. fmt.Fprintln(os.Stderr, "appender failed:", err) }}
func (a *WriterAppender) Close() error { return nil }
type FileAppender struct { WriterAppender f *os.File}
func NewFileAppender(path string, formatter Formatter) (*FileAppender, error) { // Append, never truncate: a restart must not wipe the last run's logs. An unbuffered // *os.File makes each record one write system call, so a crash loses nothing that was // logged; the async appender takes that cost off the caller's goroutine. f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o644) if err != nil { return nil, err } return &FileAppender{WriterAppender{f, formatter}, f}, nil}
func (a *FileAppender) Close() error { return a.f.Close() }
type Logger struct { name string threshold Level clock func() time.Time // injected so tests get stable timestamps appenders []Appender}
func NewLogger(name string, threshold Level, clock func() time.Time) *Logger { return &Logger{name: name, threshold: threshold, clock: clock}}
func (l *Logger) AddAppender(a Appender) { l.appenders = append(l.appenders, a) }
func (l *Logger) Log(level Level, message string, err error) { if level < l.threshold { return } // Build the record once; every appender gets the same one. r := Record{l.clock(), level, l.name, message, err} for _, a := range l.appenders { a.Append(r) }}
func (l *Logger) Debug(message string) { l.Log(Debug, message, nil) }func (l *Logger) Info(message string) { l.Log(Info, message, nil) }func (l *Logger) Warn(message string) { l.Log(Warn, message, nil) }func (l *Logger) Error(message string, err error) { l.Log(Error, message, err) }import { appendFileSync } from 'node:fs';
// One log event, captured once and handed to every appender. Readonly, so no appender can// change what the next one sees.interface LogRecord { readonly time: Date; readonly level: Level; readonly logger: string; readonly message: string; readonly error?: Error;}
// Turns a record into text. Separate from where the text goes, so the same JSON layout can go// to a file or a socket, and the console can stay human-readable.interface Formatter { format(r: LogRecord): string;}
// Seconds precision, like 2026-01-01T09:30:00Z, to match the other languages.const iso = (t: Date) => t.toISOString().replace(/\.\d{3}Z$/, 'Z');
// 2026-01-01T09:30:00Z WARN app.db - pool exhaustedclass TextFormatter implements Formatter { format(r: LogRecord): string { const line = `${iso(r.time)} ${Level[r.level]} ${r.logger} - ${r.message}`; return r.error ? `${line}\n${r.error.stack ?? r.error}` : line; }}
// One JSON object per line, for log shippers. JSON.stringify escapes quotes and newlines, so// a message can't break the line into two records or into invalid JSON.class JsonFormatter implements Formatter { format(r: LogRecord): string { return JSON.stringify({ time: iso(r.time), level: Level[r.level], logger: r.logger, message: r.message, ...(r.error && { error: String(r.error) }), }); }}
// Where formatted records go. Each appender owns its formatter: the console can be plain text// while the file is JSON.interface Appender { append(r: LogRecord): void; close(): void | Promise<void>; // flush and release files; the async appender needs it}
class ConsoleAppender implements Appender { constructor(private readonly formatter: Formatter) {} append(r: LogRecord) { console.log(this.formatter.format(r)); } close() {}}
class FileAppender implements Appender { constructor( private readonly path: string, private readonly formatter: Formatter, ) {}
append(r: LogRecord): void { try { // Synchronous and appending: the line is on disk when append returns, so a crash loses // nothing. But it blocks the event loop for a system call per record; the async appender // batches. appendFileSync(this.path, this.formatter.format(r) + '\n'); } catch (e) { // Logging must never take the application down. Report on stderr and carry on. console.error('FileAppender failed:', e); } }
close() {}}
class Logger { private readonly appenders: Appender[] = [];
constructor( readonly name: string, public threshold: Level, private readonly clock: () => Date = () => new Date(), // injected for stable timestamps ) {}
addAppender(a: Appender) { this.appenders.push(a); }
log(level: Level, message: string, error?: Error): void { if (level < this.threshold) return; // Build the record once; every appender gets the same one. const r: LogRecord = { time: this.clock(), level, logger: this.name, message, error }; for (const a of this.appenders) a.append(r); }
debug(message: string) { this.log(Level.DEBUG, message); } info(message: string) { this.log(Level.INFO, message); } warn(message: string) { this.log(Level.WARN, message); } error(message: string, error?: Error) { this.log(Level.ERROR, message, error); }}Two details in the file appender matter. It opens the file to add to the end, never to replace
it, so a restart keeps the previous run’s logs. And it catches its own errors, reporting them on
the error output. A full disk must never turn every log.info into an exception that breaks a
request.
What does the split buy? Any format with any output: three formats and four appenders are seven classes, not twelve. And a formatter is a plain function from record to text, so it’s tested with no files at all. The cost is small: two appenders with the same formatter format the record twice.
Go deeperWhy not give each appender a level too?1 min
Real frameworks do: the console shows WARN and up, while the file keeps everything. It’s one
threshold check at the top of append, or a filter in front of the appender. We leave it out to
keep the stages small. But it fits without changing anything else, which is the point of the
split.
Stage 3: A tree of loggers
Section titled “Stage 3: A tree of loggers”We have 400 classes. I want DEBUG for everything in
app.db, and WARN everywhere else.
Whether you arrange loggers in a tree by name, with levels and appenders inherited, and whether you know additivity. A map from class name to level, checked with string prefixes on every call, is the answer they mark down.
Loggers are named after the code that uses them, like app.db.pool. The dots make a tree:
app.db.pool is a child of app.db, which is a child of app, which is a child of the root
logger. Code never builds a logger itself. It asks a LoggerRegistry for one by name. The
registry creates any missing parents on the way, so the tree is always complete.
Two things are inherited down the tree:
- The level. A logger’s level can be left unset, meaning “use my parent’s”. Its real level is the first one set on the way up. The root always has one.
- The appenders. A record goes to the logger’s own appenders, then to its parent’s, and so on up to the root. Each logger handles the record and passes it up. This is the Chain of Responsibility pattern. A logger can be marked non-additive, which stops the record going further up. That flag is called additivity.
So the whole setup is a few lines: the root at WARN with a console appender, and app.db at DEBUG.
All 400 loggers inherit the rest.
- Color key
- Database
- Color key
- Facade
- Entity
- Value object
- Enum
- Interface
- Implementation
- New in this step
// Loggers form a tree by name: "app.db.pool" is a child of "app.db", a child of "app", a child// of the root. Configuration is set on a few branches and inherited by everything below.final class Logger { private final String name; private final Logger parent; // null only for the root private final Clock clock; private final List<Appender> appenders = new ArrayList<>(); private Level level; // null means "inherit from my parent" private boolean additive = true; // also send my records to my parent's appenders?
Logger(String name, Logger parent, Level level, Clock clock) { this.name = name; this.parent = parent; this.level = level; this.clock = clock; }
void setLevel(Level level) { this.level = level; } // null goes back to inheriting void setAdditive(boolean additive) { this.additive = additive; } void addAppender(Appender a) { appenders.add(a); }
// The nearest level set on the way up. The root always has one, so this always ends. Level effectiveLevel() { for (Logger l = this; ; l = l.parent) { if (l.level != null) return l.level; } }
boolean isEnabled(Level level) { return level.compareTo(effectiveLevel()) >= 0; }
void log(Level level, String message, Throwable error) { // The level is checked once, here, against this logger's effective level. Parents' // levels don't filter it again on the way up: setting "app" to WARN means app's own // records, and those of children that don't override it. if (!isEnabled(level)) return; LogRecord r = new LogRecord(clock.instant(), level, name, Thread.currentThread().getName(), message, error); // Chain of responsibility: my appenders, then my parent's, and so on to the root, // until a logger marked non-additive stops the walk. for (Logger l = this; l != null; l = l.parent) { for (Appender a : l.appenders) a.append(r); if (!l.additive) break; } }
void debug(String message) { log(Level.DEBUG, message, null); } void info(String message) { log(Level.INFO, message, null); } void warn(String message) { log(Level.WARN, message, null); } void error(String message, Throwable error) { log(Level.ERROR, message, error); }}
// Hands out one logger per name, creating the parents on the way. Code asks for a logger by// name and never builds one, so the tree is always whole.final class LoggerRegistry { private final Map<String, Logger> loggers = new HashMap<>(); private final Logger root; private final Clock clock;
LoggerRegistry(Clock clock) { this.clock = clock; this.root = new Logger("root", null, Level.INFO, clock); // the root always has a level }
Logger root() { return root; }
Logger get(String name) { Logger existing = loggers.get(name); if (existing != null) return existing; // Not computeIfAbsent: creating "app.db" first creates "app", which would modify the // map from inside its own compute call. int dot = name.lastIndexOf('.'); Logger parent = dot < 0 ? root : get(name.substring(0, dot)); Logger created = new Logger(name, parent, null, clock); loggers.put(name, created); return created; }}# Loggers form a tree by name: "app.db.pool" is a child of "app.db", a child of "app", a child# of the root. Configuration is set on a few branches and inherited by everything below.class Logger: def __init__(self, name: str, parent: Optional["Logger"], level: Optional[Level], clock: Clock): self.name = name self.parent = parent # None only for the root self.level = level # None means "inherit from my parent" self.additive = True # also send my records to my parent's appenders? self._clock = clock self._appenders: list[Appender] = []
def add_appender(self, a: Appender) -> None: self._appenders.append(a)
# The nearest level set on the way up. The root always has one, so this always ends. def effective_level(self) -> Level: l = self while l.level is None: l = l.parent return l.level
def is_enabled(self, level: Level) -> bool: return level >= self.effective_level()
def log(self, level: Level, message: str, error: Optional[BaseException] = None) -> None: # The level is checked once, here, against this logger's effective level. Parents' # levels don't filter it again on the way up. if not self.is_enabled(level): return r = LogRecord(self._clock(), level, self.name, threading.current_thread().name, message, error) # Chain of responsibility: my appenders, then my parent's, and so on to the root, # until a logger marked non-additive stops the walk. l = self while l is not None: for a in l._appenders: a.append(r) if not l.additive: break l = l.parent
def debug(self, message: str) -> None: self.log(Level.DEBUG, message) def info(self, message: str) -> None: self.log(Level.INFO, message) def warn(self, message: str) -> None: self.log(Level.WARN, message) def error(self, message: str, error: Optional[BaseException] = None) -> None: self.log(Level.ERROR, message, error)
# Hands out one logger per name, creating the parents on the way. Code asks for a logger by# name and never builds one, so the tree is always whole.class LoggerRegistry: def __init__(self, clock: Clock = utc_now): self._clock = clock self._loggers: dict[str, Logger] = {} self.root = Logger("root", None, Level.INFO, clock) # the root always has a level
def get(self, name: str) -> Logger: existing = self._loggers.get(name) if existing is not None: return existing parent_name, dot, _ = name.rpartition(".") parent = self.get(parent_name) if dot else self.root created = self._loggers[name] = Logger(name, parent, None, self._clock) return created// Loggers form a tree by name: "App.Db.Pool" is a child of "App.Db", a child of "App", a child// of the root. Configuration is set on a few branches and inherited by everything below.public sealed class Logger(string name, Logger? parent, Level? level, TimeProvider time){ private readonly List<IAppender> _appenders = [];
public string Name => name; public Logger? Parent => parent; // null only for the root public Level? Level { get; set; } = level; // null means "inherit from my parent" public bool Additive { get; set; } = true; // also send my records to my parent's appenders?
public void AddAppender(IAppender a) => _appenders.Add(a);
// The nearest level set on the way up. The root always has one, so this always ends. public Level EffectiveLevel { get { for (var l = this; ; l = l.Parent!) if (l.Level is { } own) return own; } }
public bool IsEnabled(Level level) => level >= EffectiveLevel;
public void Log(Level level, string message, Exception? error = null) { // The level is checked once, here, against this logger's effective level. Parents' // levels don't filter it again on the way up. if (!IsEnabled(level)) return; var r = new LogRecord(time.GetUtcNow(), level, name, Environment.CurrentManagedThreadId.ToString(), message, error); // Chain of responsibility: my appenders, then my parent's, and so on to the root, // until a logger marked non-additive stops the walk. for (var l = this; l is not null; l = l.Parent) { foreach (var a in l._appenders) a.Append(r); if (!l.Additive) break; } }
public void Debug(string message) => Log(global::Level.Debug, message); public void Info(string message) => Log(global::Level.Info, message); public void Warn(string message) => Log(global::Level.Warn, message); public void Error(string message, Exception? error = null) => Log(global::Level.Error, message, error);}
// Hands out one logger per name, creating the parents on the way. Code asks for a logger by// name and never builds one, so the tree is always whole.public sealed class LoggerRegistry(TimeProvider time){ private readonly Dictionary<string, Logger> _loggers = new(); public Logger Root { get; } = new("root", null, Level.Info, time); // the root always has a level
public Logger Get(string name) { if (_loggers.TryGetValue(name, out var existing)) return existing; int dot = name.LastIndexOf('.'); var parent = dot < 0 ? Root : Get(name[..dot]); return _loggers[name] = new Logger(name, parent, null, time); }}// Inherit as a logger's level means "use my parent's".const Inherit Level = -1
// Logger is a node in a tree by name: "app.db.pool" is a child of "app.db", a child of// "app", a child of the root. Configuration is set on a few branches and inherited below.type Logger struct { name string parent *Logger // nil only for the root level Level // Inherit, or a level of its own nonAdditive bool // false (the zero value): also send records to the parent's appenders clock func() time.Time appenders []Appender}
// NewLogger makes a logger with no parent, for code that doesn't use a Registry.func NewLogger(name string, level Level, clock func() time.Time) *Logger { return &Logger{name: name, level: level, clock: clock}}
func (l *Logger) SetLevel(level Level) { l.level = level }func (l *Logger) SetAdditive(add bool) { l.nonAdditive = !add }func (l *Logger) AddAppender(a Appender) { l.appenders = append(l.appenders, a) }
// EffectiveLevel is the nearest level set on the way up. The root always has one.func (l *Logger) EffectiveLevel() Level { n := l for n.level == Inherit { n = n.parent } return n.level}
func (l *Logger) Enabled(level Level) bool { return level >= l.EffectiveLevel() }
func (l *Logger) Log(level Level, message string, err error) { // The level is checked once, here, against this logger's effective level. Parents' // levels don't filter it again on the way up. if !l.Enabled(level) { return } r := Record{l.clock(), level, l.name, message, err} // Chain of responsibility: my appenders, then my parent's, and so on to the root, // until a logger marked non-additive stops the walk. for n := l; n != nil; n = n.parent { for _, a := range n.appenders { a.Append(r) } if n.nonAdditive { break } }}
func (l *Logger) Debug(message string) { l.Log(Debug, message, nil) }func (l *Logger) Info(message string) { l.Log(Info, message, nil) }func (l *Logger) Warn(message string) { l.Log(Warn, message, nil) }func (l *Logger) Error(message string, err error) { l.Log(Error, message, err) }
// Registry hands out one logger per name, creating the parents on the way. Code asks for a// logger by name and never builds one, so the tree is always whole.type Registry struct { clock func() time.Time root *Logger loggers map[string]*Logger}
func NewRegistry(clock func() time.Time) *Registry { root := &Logger{name: "root", level: Info, clock: clock} // the root always has a level return &Registry{clock: clock, root: root, loggers: map[string]*Logger{}}}
func (g *Registry) Root() *Logger { return g.root }
func (g *Registry) Get(name string) *Logger { if l, ok := g.loggers[name]; ok { return l } parent := g.root if dot := strings.LastIndexByte(name, '.'); dot >= 0 { parent = g.Get(name[:dot]) } l := &Logger{name: name, parent: parent, level: Inherit, clock: g.clock} g.loggers[name] = l return l}// Loggers form a tree by name: "app.db.pool" is a child of "app.db", a child of "app", a child// of the root. Configuration is set on a few branches and inherited by everything below.class Logger { private readonly appenders: Appender[] = []; additive = true; // also send my records to my parent's appenders?
constructor( readonly name: string, readonly parent: Logger | undefined, // undefined only for the root public level: Level | undefined, // undefined means "inherit from my parent" private readonly clock: () => Date, ) {}
addAppender(a: Appender) { this.appenders.push(a); }
// The nearest level set on the way up. The root always has one, so this always ends. effectiveLevel(): Level { let l: Logger = this; while (l.level === undefined) l = l.parent!; return l.level; }
isEnabled(level: Level): boolean { return level >= this.effectiveLevel(); }
log(level: Level, message: string, error?: Error): void { // The level is checked once, here, against this logger's effective level. Parents' // levels don't filter it again on the way up. if (!this.isEnabled(level)) return; const r: LogRecord = { time: this.clock(), level, logger: this.name, message, error }; // Chain of responsibility: my appenders, then my parent's, and so on to the root, // until a logger marked non-additive stops the walk. for (let l: Logger | undefined = this; l; l = l.parent) { for (const a of l.appenders) a.append(r); if (!l.additive) break; } }
debug(message: string) { this.log(Level.DEBUG, message); } info(message: string) { this.log(Level.INFO, message); } warn(message: string) { this.log(Level.WARN, message); } error(message: string, error?: Error) { this.log(Level.ERROR, message, error); }}
// Hands out one logger per name, creating the parents on the way. Code asks for a logger by// name and never builds one, so the tree is always whole.class LoggerRegistry { private readonly loggers = new Map<string, Logger>(); readonly root: Logger;
constructor(private readonly clock: () => Date = () => new Date()) { this.root = new Logger('root', undefined, Level.INFO, clock); // the root always has a level }
get(name: string): Logger { let l = this.loggers.get(name); if (!l) { const dot = name.lastIndexOf('.'); const parent = dot < 0 ? this.root : this.get(name.slice(0, dot)); l = new Logger(name, parent, undefined, this.clock); this.loggers.set(name, l); } return l; }}Here is one record’s journey. app.db.pool logs a WARN. Its own level is unset, so it walks up and
finds DEBUG on app.db. WARN is above DEBUG, so the record is made. It goes to app.db’s file
appender, then up to the root’s console appender.
- Color key
- Database
Notice that the level is checked once, at the logger where the record starts. Parents’ levels
don’t filter it again on the way up. That’s how Log4j and Logback behave, and it’s what makes “DEBUG
for app.db” work. If the root’s WARN filtered again, app.db’s debug lines would never reach the
root’s console.
What does the tree cost? Every call walks up the tree to find its real level, even calls that end up switched off. The walk is short, since trees are shallow. Logback avoids it by storing the real level in each logger, and pushing changes down to the children when a level is set. That makes the check one field read, but updates get more complex.
Go deeperWhy can't the registry use computeIfAbsent?1 min
Creating app.db first creates its parent app, which adds to the same map from inside the
computeIfAbsent call. Java’s HashMap throws a ConcurrentModificationException for that, and
ConcurrentHashMap can hang, or throw IllegalStateException: Recursive update. A plain get, then
create the parent, then put, avoids it. Stage 5 wraps those steps in one lock.
Stage 4: Saying no for free
Section titled “Stage 4: Saying no for free”Profiling shows 8% of CPU in debug logging, and debug is off in production.
Whether you see that the cost is where the call is made (building the message string), not inside the logger, and whether you offer both placeholders and a lazy function. “Remove the debug lines” is the answer they don’t want.
Look closely at log.debug("request " + request). The language joins the strings, and calls
request.toString(), before debug even runs. Then the logger says no, and the work is thrown
away. Three tools fix this, each for a different cost:
- Placeholders.
log.debug("user {} from {}", id, ip)passes the values as they are. The string is built only if the level is on. The values are still worked out, but passing them costs almost nothing. - A function.
log.debug(() -> expensiveSummary())passes a function instead of a string. When the level is off, the function is never called. Use it for messages that are costly to build. isEnabled.if (log.isEnabled(DEBUG)) { ... }for setup that takes more than one line.
One convention, from the SLF4J library: if the last value after the placeholders is an error, it becomes the record’s error, not a value in the message.
- Color key
- Facade
- Entity
- Value object
- Enum
- Interface
- Implementation
- New in this step
// A named logger in the tree, with ways to say no before any work is done. A disabled debug call should// cost one comparison: no string building, no toString() on big objects, no record.final class Logger { private final String name; private final Logger parent; private final Clock clock; private final List<Appender> appenders = new ArrayList<>(); private Level level; private boolean additive = true;
Logger(String name, Logger parent, Level level, Clock clock) { this.name = name; this.parent = parent; this.level = level; this.clock = clock; }
void setLevel(Level level) { this.level = level; } void setAdditive(boolean additive) { this.additive = additive; } void addAppender(Appender a) { appenders.add(a); }
Level effectiveLevel() { for (Logger l = this; ; l = l.parent) { if (l.level != null) return l.level; } }
// For callers with expensive setup: if (log.isEnabled(DEBUG)) { ...compute... } boolean isEnabled(Level level) { return level.compareTo(effectiveLevel()) >= 0; }
// Placeholders: log.info("user {} logged in from {}", id, ip). The args are already // computed, but the string is only assembled if the level is enabled. void log(Level level, String template, Object... args) { if (!isEnabled(level)) return; Throwable error = args.length > 0 && args[args.length - 1] instanceof Throwable t ? t : null; emit(level, fill(template, args), error); }
// A supplier: the message isn't even computed when disabled. For messages that call // something costly, like serializing a request. void log(Level level, Supplier<String> message) { if (isEnabled(level)) emit(level, message.get(), null); }
private void emit(Level level, String message, Throwable error) { LogRecord r = new LogRecord(clock.instant(), level, name, Thread.currentThread().getName(), message, error); for (Logger l = this; l != null; l = l.parent) { for (Appender a : l.appenders) a.append(r); if (!l.additive) break; } }
// Each "{}" takes the next argument; extra placeholders stay as "{}". A trailing // Throwable is the record's error, not a placeholder value. static String fill(String template, Object[] args) { StringBuilder b = new StringBuilder(); int from = 0, next = 0; for (int at; (at = template.indexOf("{}", from)) >= 0 && next < args.length; from = at + 2) { if (args[next] instanceof Throwable && next == args.length - 1) break; b.append(template, from, at).append(args[next++]); } return b.append(template, from, template.length()).toString(); }
void debug(String template, Object... args) { log(Level.DEBUG, template, args); } void debug(Supplier<String> message) { log(Level.DEBUG, message); } void info(String template, Object... args) { log(Level.INFO, template, args); } void warn(String template, Object... args) { log(Level.WARN, template, args); } void error(String template, Object... args) { log(Level.ERROR, template, args); }}# A named logger in the tree, with ways to say no before any work is done. A disabled debug call should# cost one comparison: no string building, no repr() of big objects, no record.class Logger: def __init__(self, name: str, parent: Optional["Logger"], level: Optional[Level], clock: Clock): self.name = name self.parent = parent self.level = level self.additive = True self._clock = clock self._appenders: list[Appender] = []
def add_appender(self, a: Appender) -> None: self._appenders.append(a)
# A logger with no level of its own uses its parent's, and so on up to the root, which # always has one. def effective_level(self) -> Level: l = self while l.level is None: l = l.parent return l.level
# For callers with expensive setup: if log.is_enabled(Level.DEBUG): ...compute... def is_enabled(self, level: Level) -> bool: return level >= self.effective_level()
# Placeholders: log.info("user {} logged in from {}", uid, ip). The args are already # computed, but the string is only assembled if the level is enabled. A message can also # be a callable, which isn't even called when the level is off. def log(self, level: Level, message: str | Callable[[], str], *args: object, error: Optional[BaseException] = None) -> None: if not self.is_enabled(level): return text = message() if callable(message) else self.fill(message, args) self._emit(level, text, error)
# One record, given to this logger's appenders, then to each parent's, until a logger that # isn't additive stops it. def _emit(self, level: Level, message: str, error: Optional[BaseException]) -> None: r = LogRecord(self._clock(), level, self.name, threading.current_thread().name, message, error) l = self while l is not None: for a in l._appenders: a.append(r) if not l.additive: break l = l.parent
# Each "{}" takes the next argument; extra placeholders stay as "{}". Not str.format: # a message with braces in it ("{id: 7}") must not be an error. @staticmethod def fill(template: str, args: tuple[object, ...]) -> str: parts = template.split("{}", len(args)) out = [parts[0]] for arg, part in zip(args, parts[1:]): out.append(str(arg)) out.append(part) return "".join(out) if len(parts) > 1 else template
def debug(self, message, *args, **kw) -> None: self.log(Level.DEBUG, message, *args, **kw) def info(self, message, *args, **kw) -> None: self.log(Level.INFO, message, *args, **kw) def warn(self, message, *args, **kw) -> None: self.log(Level.WARN, message, *args, **kw) def error(self, message, *args, **kw) -> None: self.log(Level.ERROR, message, *args, **kw)// A named logger in the tree, with ways to say no before any work is done. A disabled debug call should// cost one comparison: no string building, no ToString() on big objects, no record.public sealed class Logger(string name, Logger? parent, Level? level, TimeProvider time){ private readonly List<IAppender> _appenders = [];
public string Name => name; public Logger? Parent => parent; public Level? Level { get; set; } = level; public bool Additive { get; set; } = true;
public void AddAppender(IAppender a) => _appenders.Add(a);
// A logger with no level of its own uses its parent's, and so on up to the root, which // always has one. public Level EffectiveLevel { get { for (var l = this; ; l = l.Parent!) if (l.Level is { } own) return own; } }
// For callers with expensive setup: if (log.IsEnabled(Level.Debug)) { ...compute... } public bool IsEnabled(Level level) => level >= EffectiveLevel;
// Placeholders: log.Info("user {} logged in from {}", id, ip). The args are already // computed, but the string is only assembled if the level is enabled. public void Log(Level level, string template, params object?[] args) { if (!IsEnabled(level)) return; var error = args.Length > 0 ? args[^1] as Exception : null; Emit(level, Fill(template, error is null ? args : args[..^1]), error); }
// A delegate: the message isn't even computed when disabled. For messages that call // something costly, like serializing a request. public void Log(Level level, Func<string> message) { if (IsEnabled(level)) Emit(level, message(), null); }
// One record, given to this logger's appenders, then to each parent's, until a logger that // isn't additive stops it. private void Emit(Level level, string message, Exception? error) { var r = new LogRecord(time.GetUtcNow(), level, name, Environment.CurrentManagedThreadId.ToString(), message, error); for (var l = this; l is not null; l = l.Parent) { foreach (var a in l._appenders) a.Append(r); if (!l.Additive) break; } }
// Each "{}" takes the next argument; extra placeholders stay as "{}". Not string.Format: // a message with braces in it ("{id: 7}") must not throw. public static string Fill(string template, object?[] args) { var b = new StringBuilder(); int from = 0, next = 0; for (int at; next < args.Length && (at = template.IndexOf("{}", from, StringComparison.Ordinal)) >= 0; from = at + 2) b.Append(template, from, at - from).Append(args[next++]); return b.Append(template, from, template.Length - from).ToString(); }
public void Debug(string template, params object?[] args) => Log(global::Level.Debug, template, args); public void Debug(Func<string> message) => Log(global::Level.Debug, message); public void Info(string template, params object?[] args) => Log(global::Level.Info, template, args); public void Warn(string template, params object?[] args) => Log(global::Level.Warn, template, args); public void Error(string template, params object?[] args) => Log(global::Level.Error, template, args);}// A named logger in the tree, with ways to say no before any work is done. A disabled debug call should// cost one comparison: no Sprintf, no String() on big values, no record.//// Printf style: the args are already computed, but the string is only built if enabled.//// log.Infof("user %s logged in from %s", id, ip)func (l *Logger) Logf(level Level, format string, args ...any) { if l.Enabled(level) { l.emit(level, fmt.Sprintf(format, args...), nil) }}
// LogFunc: the message isn't even computed when disabled. For messages that call something// costly, like serializing a request.func (l *Logger) LogFunc(level Level, message func() string) { if l.Enabled(level) { l.emit(level, message(), nil) }}
func (l *Logger) Log(level Level, message string, err error) { if l.Enabled(level) { l.emit(level, message, err) }}
func (l *Logger) emit(level Level, message string, err error) { r := Record{l.clock(), level, l.name, message, err} for n := l; n != nil; n = n.parent { for _, a := range n.appenders { a.Append(r) } if n.nonAdditive { break } }}
func (l *Logger) Debugf(format string, args ...any) { l.Logf(Debug, format, args...) }func (l *Logger) DebugFunc(message func() string) { l.LogFunc(Debug, message) }func (l *Logger) Infof(format string, args ...any) { l.Logf(Info, format, args...) }func (l *Logger) Warnf(format string, args ...any) { l.Logf(Warn, format, args...) }func (l *Logger) Errorf(format string, args ...any) { l.Logf(Error, format, args...) }// A message can be a string with {} placeholders, or a function that builds it.type Message = string | (() => string);
// A named logger in the tree, with ways to say no before any work is done. A disabled debug call should// cost one comparison: no string building, no JSON.stringify of big objects, no record.class Logger { private readonly appenders: Appender[] = []; additive = true;
constructor( readonly name: string, readonly parent: Logger | undefined, public level: Level | undefined, private readonly clock: () => Date, ) {}
addAppender(a: Appender) { this.appenders.push(a); }
// A logger with no level of its own uses its parent's, and so on up to the root, which always // has one. effectiveLevel(): Level { let l: Logger = this; while (l.level === undefined) l = l.parent!; return l.level; }
// For callers with expensive setup: if (log.isEnabled(Level.DEBUG)) { ...compute... } isEnabled(level: Level): boolean { return level >= this.effectiveLevel(); }
// Placeholders: log.info('user {} logged in from {}', id, ip). The args are already // computed, but the string is only assembled if the level is enabled. A function message // isn't even called when the level is off. A trailing Error is the record's error. log(level: Level, message: Message, ...args: unknown[]): void { if (!this.isEnabled(level)) return; const error = args.at(-1) instanceof Error ? (args.pop() as Error) : undefined; const text = typeof message === 'function' ? message() : Logger.fill(message, args); const r: LogRecord = { time: this.clock(), level, logger: this.name, message: text, error }; for (let l: Logger | undefined = this; l; l = l.parent) { for (const a of l.appenders) a.append(r); if (!l.additive) break; } }
// Each "{}" takes the next argument; extra placeholders stay as "{}". static fill(template: string, args: unknown[]): string { let i = 0; return template.replace(/\{\}/g, (p) => (i < args.length ? String(args[i++]) : p)); }
debug(message: Message, ...args: unknown[]) { this.log(Level.DEBUG, message, ...args); } info(message: Message, ...args: unknown[]) { this.log(Level.INFO, message, ...args); } warn(message: Message, ...args: unknown[]) { this.log(Level.WARN, message, ...args); } error(message: Message, ...args: unknown[]) { this.log(Level.ERROR, message, ...args); }}Go uses its own style (Debugf with fmt verbs, plus DebugFunc), since {} placeholders would
look out of place there. And the placeholder filler is deliberately not String.format or
str.format. A message that happens to contain braces, like a piece of JSON, must be logged as
written, not throw an error.
What does it cost? A method that takes “any number of values” makes a small array on every call,
even when the level is off. SLF4J avoids that with fixed versions for one and two values,
debug(String, Object) and debug(String, Object, Object).
This is enough for a mid-level answer. The record, formatter and appender are separate, and the logger tree inherits levels. The rest of the page is what makes it a senior answer.
The full design
Section titled “The full design”Here is everything together. Each class is here because a requirement needed it.
- Color key
- Facade
- Entity
- Value object
- Enum
- Interface
- Implementation
// The complete design, built from every stage on this page.
import java.util.*;import java.util.concurrent.*;import java.util.concurrent.atomic.*;import java.util.function.*;import java.time.*;import java.io.*;import java.nio.file.*;
// Ordered from least to most severe, so "is this enabled?" is one comparison.enum Level { DEBUG, INFO, WARN, ERROR }
// The logger's configuration can change while other threads log (an operator turns on DEBUG// for one package). volatile makes a level change visible to every thread at once, and a// copy-on-write list lets threads walk the appenders while one is added. Both suit data// that's read millions of times and written a handful.final class Logger { private final String name; private final Logger parent; private final Clock clock; private final List<Appender> appenders = new CopyOnWriteArrayList<>(); private volatile Level level; private volatile boolean additive = true;
Logger(String name, Logger parent, Level level, Clock clock) { this.name = name; this.parent = parent; this.level = level; this.clock = clock; }
void setLevel(Level level) { this.level = level; } void setAdditive(boolean additive) { this.additive = additive; } void addAppender(Appender a) { appenders.add(a); }
// A logger with no level of its own uses its parent's, and so on up to the root, which // always has one. Level effectiveLevel() { for (Logger l = this; ; l = l.parent) { Level own = l.level; // read the volatile once if (own != null) return own; } }
boolean isEnabled(Level level) { return level.compareTo(effectiveLevel()) >= 0; }
// The template form. The "{}" placeholders are filled only if the level is on. A Throwable // as the last argument is the error, not a value to fill in. void log(Level level, String template, Object... args) { if (!isEnabled(level)) return; Throwable error = args.length > 0 && args[args.length - 1] instanceof Throwable t ? t : null; emit(level, fill(template, args), error); }
// The lazy form: the message is built only if the level is on. void log(Level level, Supplier<String> message) { if (isEnabled(level)) emit(level, message.get(), null); }
// One record, given to this logger's appenders, then to each parent's, until a logger that // isn't additive stops it. private void emit(Level level, String message, Throwable error) { LogRecord r = new LogRecord(clock.instant(), level, name, Thread.currentThread().getName(), message, error); for (Logger l = this; l != null; l = l.parent) { for (Appender a : l.appenders) a.append(r); if (!l.additive) break; } }
// Replaces each "{}" with the next argument, left to right. Placeholders with no argument // left stay as they are. static String fill(String template, Object[] args) { StringBuilder b = new StringBuilder(); int from = 0, next = 0; for (int at; (at = template.indexOf("{}", from)) >= 0 && next < args.length; from = at + 2) { if (args[next] instanceof Throwable && next == args.length - 1) break; b.append(template, from, at).append(args[next++]); } return b.append(template, from, template.length()).toString(); }
void debug(String template, Object... args) { log(Level.DEBUG, template, args); } void debug(Supplier<String> message) { log(Level.DEBUG, message); } void info(String template, Object... args) { log(Level.INFO, template, args); } void warn(String template, Object... args) { log(Level.WARN, template, args); } void error(String template, Object... args) { log(Level.ERROR, template, args); }}
// One log event, captured once and handed to every appender. A value: appenders on other// threads can read it without locks.record LogRecord(Instant time, Level level, String logger, String thread, String message, Throwable error) {}
// Turns a record into text. Separate from where the text goes, so the same JSON layout can go// to a file or a socket, and the console can stay human-readable.interface Formatter { String format(LogRecord r);}
// 2026-01-01T09:30:00Z WARN app.db [main] - pool exhaustedfinal class TextFormatter implements Formatter { public String format(LogRecord r) { String line = r.time() + " " + r.level() + " " + r.logger() + " [" + r.thread() + "] - " + r.message(); if (r.error() == null) return line; StringWriter trace = new StringWriter(); r.error().printStackTrace(new PrintWriter(trace)); return line + System.lineSeparator() + trace.toString().stripTrailing(); }}
// One JSON object per line, for log shippers. Escaping matters: a message with a quote or a// newline must not break the line into two records or into invalid JSON.final class JsonFormatter implements Formatter { public String format(LogRecord r) { StringBuilder b = new StringBuilder("{"); field(b, "time", r.time().toString()).append(','); field(b, "level", r.level().name()).append(','); field(b, "logger", r.logger()).append(','); field(b, "thread", r.thread()).append(','); field(b, "message", r.message()); if (r.error() != null) field(b.append(','), "error", r.error().toString()); return b.append('}').toString(); }
private static StringBuilder field(StringBuilder b, String key, String value) { b.append('"').append(key).append("\":\""); for (char c : value.toCharArray()) { switch (c) { case '"' -> b.append("\\\""); case '\\' -> b.append("\\\\"); case '\n' -> b.append("\\n"); case '\r' -> b.append("\\r"); case '\t' -> b.append("\\t"); default -> { if (c < 0x20) b.append(String.format("\\u%04x", (int) c)); // other control characters else b.append(c); } } } return b.append('"'); }}
// Where formatted records go. Each appender owns its formatter: the console can be plain text// while the file is JSON.interface Appender { void append(LogRecord r); default void close() {} // flush and release files; the async appender needs it}
// Appenders called directly from many threads lock around the write, so two records' lines// never interleave in the file. (Not needed behind AsyncAppender, but cheap when uncontended.)final class FileAppender implements Appender { private final BufferedWriter out; private final Formatter formatter;
FileAppender(Path file, Formatter formatter) throws IOException { this.out = Files.newBufferedWriter(file, StandardOpenOption.CREATE, StandardOpenOption.APPEND); this.formatter = formatter; }
public void append(LogRecord r) { String text = formatter.format(r); // format outside the lock: it's the slow part synchronized (this) { try { out.write(text); out.newLine(); out.flush(); } catch (IOException e) { System.err.println("FileAppender failed: " + e); } } }
public synchronized void close() { try { out.close(); } catch (IOException e) { System.err.println("FileAppender close failed: " + e); } }}
// Loggers are usually fetched once per class, into a static field, so a synchronized get// costs nothing that matters, and it keeps "create the parents first" one atomic step.final class LoggerRegistry { private final Map<String, Logger> loggers = new HashMap<>(); private final Logger root; private final Clock clock;
LoggerRegistry(Clock clock) { this.clock = clock; this.root = new Logger("root", null, Level.INFO, clock); }
Logger root() { return root; }
synchronized Logger get(String name) { // re-entrant, so the recursive call is fine Logger existing = loggers.get(name); if (existing != null) return existing; int dot = name.lastIndexOf('.'); Logger parent = dot < 0 ? root : get(name.substring(0, dot)); Logger created = new Logger(name, parent, null, clock); loggers.put(name, created); return created; }}
// What a full queue does with one more record.enum Overflow { BLOCK, // the caller waits: nothing is lost, but a slow disk slows the app DROP_BELOW_WARN // DEBUG and INFO are dropped (and counted); WARN and ERROR still wait}
// A decorator: wraps any appender and moves its work onto one background thread. Callers only// pay for putting the record in a queue, and the wrapped appender is only ever called from// that one thread, so it needs no lock of its own.final class AsyncAppender implements Appender { // A record that means "stop": the worker sees it after everything queued before it. private static final LogRecord STOP = new LogRecord(Instant.EPOCH, Level.ERROR, "", "", "", null);
private final Appender inner; private final Overflow overflow; private final BlockingQueue<LogRecord> queue; private final AtomicLong dropped = new AtomicLong(); private final Thread worker; private volatile boolean closed;
AsyncAppender(Appender inner, int capacity, Overflow overflow) { this.inner = inner; this.overflow = overflow; // Bounded: if the disk stalls, memory doesn't grow until the process dies. this.queue = new ArrayBlockingQueue<>(capacity); this.worker = new Thread(this::drain, "log-writer"); this.worker.setDaemon(true); // never keeps the process alive on its own this.worker.start(); }
// Called on the caller's thread. Usually it just drops the record in the queue; only a full // queue makes the Overflow rule matter. public void append(LogRecord r) { if (closed || queue.offer(r)) return; // the fast path: there was room if (overflow == Overflow.DROP_BELOW_WARN && r.level().compareTo(Level.WARN) < 0) { dropped.incrementAndGet(); // counted, so it can be reported as "N records dropped" return; } try { // Wait for room, but give up if the appender closes meanwhile; a plain put() // could block forever once the worker has stopped. while (!closed && !queue.offer(r, 100, TimeUnit.MILLISECONDS)) { } } catch (InterruptedException e) { Thread.currentThread().interrupt(); // keep the caller's interrupt; drop this record } }
// The worker: writes records in order until STOP, then closes the wrapped appender. private void drain() { try { for (LogRecord r = queue.take(); r != STOP; r = queue.take()) { try { inner.append(r); } catch (RuntimeException e) { System.err.println("appender failed: " + e); // one bad record must not kill the worker } } } catch (InterruptedException e) { Thread.currentThread().interrupt(); } finally { inner.close(); } }
long dropped() { return dropped.get(); }
// Flush on shutdown: everything queued before close() is written before it returns. // Call it from a shutdown hook, or the last seconds of logs before a crash are lost. public void close() { if (closed) return; closed = true; try { queue.put(STOP); // waits for room, which the worker is making worker.join(); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } }}# The complete design, built from every stage on this page.
from __future__ import annotations
import jsonimport queueimport sysimport threadingimport tracebackfrom dataclasses import dataclassfrom datetime import datetime, timezonefrom enum import Enum, IntEnumfrom typing import Callable, Optional, Protocol
# Ordered from least to most severe, so "is this enabled?" is one comparison.class Level(IntEnum): DEBUG = 10 INFO = 20 WARN = 30 ERROR = 40
# A named logger in the tree, with ways to say no before any work is done. A disabled debug call should# cost one comparison: no string building, no repr() of big objects, no record.class Logger: def __init__(self, name: str, parent: Optional["Logger"], level: Optional[Level], clock: Clock): self.name = name self.parent = parent self.level = level self.additive = True self._clock = clock self._appenders: list[Appender] = []
def add_appender(self, a: Appender) -> None: self._appenders.append(a)
# A logger with no level of its own uses its parent's, and so on up to the root, which # always has one. def effective_level(self) -> Level: l = self while l.level is None: l = l.parent return l.level
# For callers with expensive setup: if log.is_enabled(Level.DEBUG): ...compute... def is_enabled(self, level: Level) -> bool: return level >= self.effective_level()
# Placeholders: log.info("user {} logged in from {}", uid, ip). The args are already # computed, but the string is only assembled if the level is enabled. A message can also # be a callable, which isn't even called when the level is off. def log(self, level: Level, message: str | Callable[[], str], *args: object, error: Optional[BaseException] = None) -> None: if not self.is_enabled(level): return text = message() if callable(message) else self.fill(message, args) self._emit(level, text, error)
# One record, given to this logger's appenders, then to each parent's, until a logger that # isn't additive stops it. def _emit(self, level: Level, message: str, error: Optional[BaseException]) -> None: r = LogRecord(self._clock(), level, self.name, threading.current_thread().name, message, error) l = self while l is not None: for a in l._appenders: a.append(r) if not l.additive: break l = l.parent
# Each "{}" takes the next argument; extra placeholders stay as "{}". Not str.format: # a message with braces in it ("{id: 7}") must not be an error. @staticmethod def fill(template: str, args: tuple[object, ...]) -> str: parts = template.split("{}", len(args)) out = [parts[0]] for arg, part in zip(args, parts[1:]): out.append(str(arg)) out.append(part) return "".join(out) if len(parts) > 1 else template
def debug(self, message, *args, **kw) -> None: self.log(Level.DEBUG, message, *args, **kw) def info(self, message, *args, **kw) -> None: self.log(Level.INFO, message, *args, **kw) def warn(self, message, *args, **kw) -> None: self.log(Level.WARN, message, *args, **kw) def error(self, message, *args, **kw) -> None: self.log(Level.ERROR, message, *args, **kw)
Clock = Callable[[], datetime]
def utc_now() -> datetime: return datetime.now(timezone.utc)
# One log event, captured once and handed to every appender. Frozen: appenders on other# threads can read it without locks.@dataclass(frozen=True)class LogRecord: time: datetime level: Level logger: str thread: str message: str error: Optional[BaseException] = None
# Turns a record into text. Separate from where the text goes, so the same JSON layout can go# to a file or a socket, and the console can stay human-readable.class Formatter(Protocol): def format(self, r: LogRecord) -> str: ...
def _iso(t: datetime) -> str: return t.isoformat().replace("+00:00", "Z")
# 2026-01-01T09:30:00Z WARN app.db [MainThread] - pool exhaustedclass TextFormatter: def format(self, r: LogRecord) -> str: line = f"{_iso(r.time)} {r.level.name} {r.logger} [{r.thread}] - {r.message}" if r.error is None: return line trace = "".join(traceback.format_exception(r.error)).rstrip() return f"{line}\n{trace}"
# One JSON object per line, for log shippers. json.dumps escapes quotes and newlines, so a# message can't break the line into two records or into invalid JSON.class JsonFormatter: def format(self, r: LogRecord) -> str: fields = {"time": _iso(r.time), "level": r.level.name, "logger": r.logger, "thread": r.thread, "message": r.message} if r.error is not None: fields["error"] = repr(r.error) return json.dumps(fields, separators=(",", ":"), ensure_ascii=False)
# Where formatted records go. Each appender owns its formatter: the console can be plain text# while the file is JSON.class Appender(Protocol): def append(self, r: LogRecord) -> None: ...
def close(self) -> None: ... # flush and release files; the async appender needs it
# Appenders called directly from many threads lock around the write, so two records' lines# never interleave in the file. (Not needed behind AsyncAppender, but cheap when uncontended.)class FileAppender: def __init__(self, path: str, formatter: Formatter): self._file = open(path, "a", encoding="utf-8") self._formatter = formatter self._lock = threading.Lock()
def append(self, r: LogRecord) -> None: text = self._formatter.format(r) + "\n" # format outside the lock: it's the slow part with self._lock: try: self._file.write(text) self._file.flush() except OSError as e: print(f"FileAppender failed: {e}", file=sys.stderr)
def close(self) -> None: with self._lock: self._file.close()
# Loggers are usually fetched once per module, at import, so one lock around get costs# nothing that matters, and it keeps "create the parents first" one atomic step. RLock,# because get calls itself for the parent.class LoggerRegistry: def __init__(self, clock: Clock = utc_now): self._clock = clock self._loggers: dict[str, Logger] = {} self._lock = threading.RLock() self.root = Logger("root", None, Level.INFO, clock)
def get(self, name: str) -> Logger: with self._lock: existing = self._loggers.get(name) if existing is not None: return existing parent_name, dot, _ = name.rpartition(".") parent = self.get(parent_name) if dot else self.root created = self._loggers[name] = Logger(name, parent, None, self._clock) return created
# What a full queue does with one more record.class Overflow(Enum): BLOCK = "block" # the caller waits: nothing lost, but a slow disk slows the app DROP_BELOW_WARN = "drop_below_warn" # DEBUG and INFO dropped (and counted); WARN and ERROR wait
_STOP = object() # tells the worker to finish: it sees it after everything queued before it
# A decorator: wraps any appender and moves its work onto one background thread. Callers only# pay for putting the record in a queue, and the wrapped appender is only ever called from# that one thread, so it needs no lock of its own.class AsyncAppender: def __init__(self, inner: Appender, capacity: int, overflow: Overflow = Overflow.DROP_BELOW_WARN): self._inner = inner self._overflow = overflow # Bounded: if the disk stalls, memory doesn't grow until the process dies. self._queue: queue.Queue = queue.Queue(maxsize=capacity) self._closed = False self.dropped = 0 # only the callers that drop write it, under _drop_lock self._drop_lock = threading.Lock() # daemon: never keeps the process alive on its own self._worker = threading.Thread(target=self._drain, name="log-writer", daemon=True) self._worker.start()
# Called on the caller's thread. Usually it just drops the record in the queue; only a full # queue makes the Overflow rule matter. def append(self, r: LogRecord) -> None: if self._closed: return try: self._queue.put_nowait(r) # the fast path: there was room return except queue.Full: pass if self._overflow is Overflow.DROP_BELOW_WARN and r.level < Level.WARN: with self._drop_lock: self.dropped += 1 # counted, so it can be reported as "N records dropped" return # Wait for room, but give up if the appender closes meanwhile; a plain put() could # block forever once the worker has stopped. while not self._closed: try: self._queue.put(r, timeout=0.1) return except queue.Full: continue
# The worker: writes records in order until _STOP, then closes the wrapped appender. def _drain(self) -> None: try: while (r := self._queue.get()) is not _STOP: try: self._inner.append(r) except Exception as e: # one bad record must not kill the worker print(f"appender failed: {e!r}", file=sys.stderr) finally: self._inner.close()
# Flush on shutdown: everything queued before close() is written before it returns. # Register it with atexit, or the last seconds of logs before an exit are lost. def close(self) -> None: if self._closed: return self._closed = True self._queue.put(_STOP) # waits for room, which the worker is making self._worker.join()// The complete design, built from every stage on this page.
using System.Text;using System.Text.Json;using System.Threading.Channels;
// Ordered from least to most severe, so "is this enabled?" is one comparison.public enum Level { Debug, Info, Warn, Error }
// A named logger in the tree, with ways to say no before any work is done. A disabled debug call should// cost one comparison: no string building, no ToString() on big objects, no record.public sealed class Logger(string name, Logger? parent, Level? level, TimeProvider time){ private readonly List<IAppender> _appenders = [];
public string Name => name; public Logger? Parent => parent; public Level? Level { get; set; } = level; public bool Additive { get; set; } = true;
public void AddAppender(IAppender a) => _appenders.Add(a);
// A logger with no level of its own uses its parent's, and so on up to the root, which // always has one. public Level EffectiveLevel { get { for (var l = this; ; l = l.Parent!) if (l.Level is { } own) return own; } }
// For callers with expensive setup: if (log.IsEnabled(Level.Debug)) { ...compute... } public bool IsEnabled(Level level) => level >= EffectiveLevel;
// Placeholders: log.Info("user {} logged in from {}", id, ip). The args are already // computed, but the string is only assembled if the level is enabled. public void Log(Level level, string template, params object?[] args) { if (!IsEnabled(level)) return; var error = args.Length > 0 ? args[^1] as Exception : null; Emit(level, Fill(template, error is null ? args : args[..^1]), error); }
// A delegate: the message isn't even computed when disabled. For messages that call // something costly, like serializing a request. public void Log(Level level, Func<string> message) { if (IsEnabled(level)) Emit(level, message(), null); }
// One record, given to this logger's appenders, then to each parent's, until a logger that // isn't additive stops it. private void Emit(Level level, string message, Exception? error) { var r = new LogRecord(time.GetUtcNow(), level, name, Environment.CurrentManagedThreadId.ToString(), message, error); for (var l = this; l is not null; l = l.Parent) { foreach (var a in l._appenders) a.Append(r); if (!l.Additive) break; } }
// Each "{}" takes the next argument; extra placeholders stay as "{}". Not string.Format: // a message with braces in it ("{id: 7}") must not throw. public static string Fill(string template, object?[] args) { var b = new StringBuilder(); int from = 0, next = 0; for (int at; next < args.Length && (at = template.IndexOf("{}", from, StringComparison.Ordinal)) >= 0; from = at + 2) b.Append(template, from, at - from).Append(args[next++]); return b.Append(template, from, template.Length - from).ToString(); }
public void Debug(string template, params object?[] args) => Log(global::Level.Debug, template, args); public void Debug(Func<string> message) => Log(global::Level.Debug, message); public void Info(string template, params object?[] args) => Log(global::Level.Info, template, args); public void Warn(string template, params object?[] args) => Log(global::Level.Warn, template, args); public void Error(string template, params object?[] args) => Log(global::Level.Error, template, args);}
// One log event, captured once and handed to every appender. Immutable, so appenders on other// threads can read it without locks.public sealed record LogRecord(DateTimeOffset Time, Level Level, string Logger, string Thread, string Message, Exception? Error);
// Turns a record into text. Separate from where the text goes, so the same JSON layout can go// to a file or a socket, and the console can stay human-readable.public interface IFormatter{ string Format(LogRecord r);}
// 2026-01-01T09:30:00Z WARN App.Db [1] - pool exhaustedpublic sealed class TextFormatter : IFormatter{ public string Format(LogRecord r) { var line = $"{r.Time.UtcDateTime:yyyy-MM-ddTHH:mm:ssZ} {r.Level.ToString().ToUpperInvariant()} {r.Logger} [{r.Thread}] - {r.Message}"; return r.Error is null ? line : line + Environment.NewLine + r.Error; // ToString() includes the stack trace }}
// One JSON object per line, for log shippers. Utf8JsonWriter escapes quotes and newlines, so a// message can't break the line into two records or into invalid JSON.public sealed class JsonFormatter : IFormatter{ public string Format(LogRecord r) { using var buffer = new MemoryStream(); using (var w = new Utf8JsonWriter(buffer)) { w.WriteStartObject(); w.WriteString("time", r.Time.UtcDateTime.ToString("yyyy-MM-ddTHH:mm:ssZ")); w.WriteString("level", r.Level.ToString().ToUpperInvariant()); w.WriteString("logger", r.Logger); w.WriteString("thread", r.Thread); w.WriteString("message", r.Message); if (r.Error is not null) w.WriteString("error", r.Error.ToString()); w.WriteEndObject(); } return Encoding.UTF8.GetString(buffer.ToArray()); }}
// Where formatted records go. Each appender owns its formatter: the console can be plain text// while the file is JSON.public interface IAppender : IDisposable // Dispose flushes and releases files; the async appender needs it{ void Append(LogRecord r);}
// Appenders called directly from many threads lock around the write, so two records' lines// never interleave in the file. (Not needed behind AsyncAppender, but cheap when uncontended.)public sealed class FileAppender : IAppender{ private readonly Lock _lock = new(); private readonly StreamWriter _out; private readonly IFormatter _formatter;
public FileAppender(string path, IFormatter formatter) { _out = new StreamWriter(path, append: true) { AutoFlush = true }; _formatter = formatter; }
public void Append(LogRecord r) { var text = _formatter.Format(r); // format outside the lock: it's the slow part lock (_lock) { try { _out.WriteLine(text); } catch (IOException e) { Console.Error.WriteLine($"FileAppender failed: {e.Message}"); } } }
public void Dispose() { lock (_lock) _out.Dispose(); }}
// Loggers are usually fetched once per class, into a static field, so one lock around Get// costs nothing that matters, and keeps "create the parents first" one atomic step. C# locks// are re-entrant, so the recursive call for the parent is fine.public sealed class LoggerRegistry(TimeProvider time){ private readonly Lock _lock = new(); private readonly Dictionary<string, Logger> _loggers = new(); public Logger Root { get; } = new("root", null, Level.Info, time);
public Logger Get(string name) { lock (_lock) { if (_loggers.TryGetValue(name, out var existing)) return existing; int dot = name.LastIndexOf('.'); var parent = dot < 0 ? Root : Get(name[..dot]); return _loggers[name] = new Logger(name, parent, null, time); } }}
// What a full queue does with one more record.public enum Overflow{ Block, // the caller waits: nothing is lost, but a slow disk slows the app DropBelowWarn, // Debug and Info are dropped (and counted); Warn and Error still wait}
// A decorator: wraps any appender and moves its work onto one background task. Callers only// pay for writing the record to a channel, and the wrapped appender is only ever called from// that one task, so it needs no lock of its own.public sealed class AsyncAppender : IAppender{ private readonly IAppender _inner; private readonly Overflow _overflow; private readonly Channel<LogRecord> _channel; private readonly Task _worker; private long _dropped;
public AsyncAppender(IAppender inner, int capacity, Overflow overflow) { _inner = inner; _overflow = overflow; // Bounded: if the disk stalls, memory doesn't grow until the process dies. _channel = Channel.CreateBounded<LogRecord>(new BoundedChannelOptions(capacity) { SingleReader = true, FullMode = BoundedChannelFullMode.Wait, }); _worker = Task.Run(DrainAsync); }
public long Dropped => Interlocked.Read(ref _dropped);
// Called on the caller's thread. Usually it just drops the record in the queue; only a full // queue makes the Overflow rule matter. public void Append(LogRecord r) { if (_channel.Writer.TryWrite(r)) return; // the fast path: there was room if (_overflow == Overflow.DropBelowWarn && r.Level < Level.Warn) { Interlocked.Increment(ref _dropped); // counted, so it can be reported as "N dropped" return; } try { // Wait for room. Append is synchronous, so the caller blocks here; after Dispose // the write fails instead of waiting forever. _channel.Writer.WriteAsync(r).AsTask().GetAwaiter().GetResult(); } catch (ChannelClosedException) { } // logged during shutdown: dropped }
// The worker: writes records in order until the channel is completed and empty. private async Task DrainAsync() { try { await foreach (var r in _channel.Reader.ReadAllAsync()) // ends when completed and empty { try { _inner.Append(r); } catch (Exception e) { Console.Error.WriteLine($"appender failed: {e.Message}"); } // keep going } } finally { _inner.Dispose(); } }
// Flush on shutdown: everything written before Dispose is appended before it returns. // Hook it to IHostApplicationLifetime.ApplicationStopping, or the last logs are lost. public void Dispose() { _channel.Writer.TryComplete(); _worker.GetAwaiter().GetResult(); }}// The complete design, built from every stage on this page.
package loggingframework
import ( "encoding/json" "fmt" "slices" "strings" "sync" "sync/atomic" "time")
// Level is ordered from least to most severe, so "is this enabled?" is one comparison.type Level int32
const ( Debug Level = iota Info Warn Error)
func (l Level) String() string { return [...]string{"DEBUG", "INFO", "WARN", "ERROR"}[l] }
// Record is one log event, captured once and handed to every appender. Passed by value, so// appenders on other goroutines can read it without locks.type Record struct { Time time.Time Level Level Logger string Message string Err error}
// Formatter turns a record into text. Separate from where the text goes, so the same JSON// layout can go to a file or a socket, and the console can stay human-readable.type Formatter interface { Format(r Record) string}
// TextFormatter: 2026-01-01T09:30:00Z WARN app.db - pool exhaustedtype TextFormatter struct{}
func (TextFormatter) Format(r Record) string { line := fmt.Sprintf("%s %s %s - %s", r.Time.UTC().Format(time.RFC3339), r.Level, r.Logger, r.Message) if r.Err != nil { line += ": " + r.Err.Error() } return line}
// JSONFormatter writes one JSON object per line, for log shippers. encoding/json escapes// quotes and newlines, so a message can't break the line into two records or invalid JSON.type JSONFormatter struct{}
func (JSONFormatter) Format(r Record) string { fields := struct { Time string `json:"time"` Level string `json:"level"` Logger string `json:"logger"` Message string `json:"message"` Error string `json:"error,omitempty"` }{r.Time.UTC().Format(time.RFC3339), r.Level.String(), r.Logger, r.Message, ""} if r.Err != nil { fields.Error = r.Err.Error() } b, _ := json.Marshal(fields) // a struct of strings can't fail to marshal return string(b)}
// Appender is where formatted records go. Each appender owns its formatter: the console can// be plain text while the file is JSON.type Appender interface { Append(r Record) Close() error // flush and release files; the async appender needs it}
// Inherit as a logger's level means "use my parent's".const Inherit Level = -1
// Overflow is what a full queue does with one more record.type Overflow int
const ( Block Overflow = iota // the caller waits: nothing lost, but a slow disk slows the app DropBelowWarn // Debug and Info dropped (and counted); Warn and Error wait)
// AsyncAppender is a decorator: it wraps any appender and moves its work onto one goroutine.// Callers only pay for a channel send, and the wrapped appender is only ever called from// that goroutine, so it needs no lock of its own.type AsyncAppender struct { inner Appender overflow Overflow records chan Record // buffered: if the disk stalls, memory doesn't grow without limit done chan struct{} dropped atomic.Int64 mu sync.RWMutex // Append holds it shared; Close takes it alone to close the channel closed bool}
func NewAsyncAppender(inner Appender, capacity int, overflow Overflow) *AsyncAppender { a := &AsyncAppender{inner: inner, overflow: overflow, records: make(chan Record, capacity), done: make(chan struct{})} go a.drain() return a}
// Append runs on the caller's goroutine. Usually it just sends the record on the channel; only// a full channel makes the Overflow rule matter.func (a *AsyncAppender) Append(r Record) { // Sending on a closed channel panics, so Append holds the read lock: many senders at // once, but never while Close is closing the channel. a.mu.RLock() defer a.mu.RUnlock() if a.closed { return } select { case a.records <- r: // the fast path: there was room return default: } if a.overflow == DropBelowWarn && r.Level < Warn { a.dropped.Add(1) // counted, so it can be reported as "N records dropped" return } a.records <- r // wait for room; the drain goroutine is making it}
// drain is the worker: it writes records in order until the channel is closed, then closes the// wrapped appender.func (a *AsyncAppender) drain() { defer close(a.done) for r := range a.records { // ends when the channel is closed and empty a.inner.Append(r) } a.inner.Close()}
func (a *AsyncAppender) Dropped() int64 { return a.dropped.Load() }
// Close flushes on shutdown: everything sent before Close is written before it returns.// Call it before main returns, or the last records are lost with the process.func (a *AsyncAppender) Close() error { a.mu.Lock() // waits for senders in flight, including ones blocked on a full channel if !a.closed { a.closed = true close(a.records) } a.mu.Unlock() <-a.done return nil}
// LockedAppender serializes writes for an appender called from many goroutines, so two// records never interleave. (Not needed behind AsyncAppender.)type LockedAppender struct { mu sync.Mutex inner Appender}
func (a *LockedAppender) Append(r Record) { a.mu.Lock() defer a.mu.Unlock() a.inner.Append(r)}
func (a *LockedAppender) Close() error { a.mu.Lock() defer a.mu.Unlock() return a.inner.Close()}
// Logger's configuration can change while other goroutines log (an operator turns on Debug// for one package). Atomics make a change visible at once, and the appender list is// replaced, never changed in place, so a goroutine walking the old slice is never surprised.type Logger struct { name string parent *Logger level atomic.Int32 // a Level, or Inherit nonAdditive atomic.Bool clock func() time.Time mu sync.Mutex // serializes AddAppender appenders atomic.Pointer[[]Appender] // read without a lock on every record}
func newLogger(name string, parent *Logger, level Level, clock func() time.Time) *Logger { l := &Logger{name: name, parent: parent, clock: clock} l.level.Store(int32(level)) l.appenders.Store(&[]Appender{}) return l}
func NewLogger(name string, level Level, clock func() time.Time) *Logger { return newLogger(name, nil, level, clock)}
func (l *Logger) SetLevel(level Level) { l.level.Store(int32(level)) }
func (l *Logger) SetAdditive(add bool) { l.nonAdditive.Store(!add) }
func (l *Logger) AddAppender(a Appender) { l.mu.Lock() defer l.mu.Unlock() next := append(slices.Clone(*l.appenders.Load()), a) // copy on write l.appenders.Store(&next)}
// EffectiveLevel: a logger with no level of its own uses its parent's, and so on up to the// root, which always has one.func (l *Logger) EffectiveLevel() Level { n := l for Level(n.level.Load()) == Inherit { n = n.parent } return Level(n.level.Load())}
// emit builds one record and gives it to this logger's appenders, then to each parent's, until// a logger that isn't additive stops it.func (l *Logger) emit(level Level, message string, err error) { r := Record{l.clock(), level, l.name, message, err} for n := l; n != nil; n = n.parent { for _, a := range *n.appenders.Load() { a.Append(r) } if n.nonAdditive.Load() { break } }}
// Registry: loggers are usually fetched once, into a package variable, so one mutex around// Get costs nothing that matters, and keeps "create the parents first" one atomic step.type Registry struct { mu sync.Mutex clock func() time.Time root *Logger loggers map[string]*Logger}
func NewRegistry(clock func() time.Time) *Registry { return &Registry{clock: clock, root: newLogger("root", nil, Info, clock), loggers: map[string]*Logger{}}}
func (g *Registry) Get(name string) *Logger { g.mu.Lock() defer g.mu.Unlock() return g.get(name)}
// get is Get without the lock, so it can recurse for the parent (Go mutexes aren't re-entrant).func (g *Registry) get(name string) *Logger { if l, ok := g.loggers[name]; ok { return l } parent := g.root if dot := strings.LastIndexByte(name, '.'); dot >= 0 { parent = g.get(name[:dot]) } l := newLogger(name, parent, Inherit, g.clock) g.loggers[name] = l return l}// The complete design, built from every stage on this page.
import { appendFileSync } from 'node:fs';import { appendFile } from 'node:fs/promises';
// Ordered from least to most severe, so "is this enabled?" is one comparison.enum Level { DEBUG = 10, INFO = 20, WARN = 30, ERROR = 40,}
// A named logger in the tree, with ways to say no before any work is done. A disabled debug call should// cost one comparison: no string building, no JSON.stringify of big objects, no record.class Logger { private readonly appenders: Appender[] = []; additive = true;
constructor( readonly name: string, readonly parent: Logger | undefined, public level: Level | undefined, private readonly clock: () => Date, ) {}
addAppender(a: Appender) { this.appenders.push(a); }
// A logger with no level of its own uses its parent's, and so on up to the root, which always // has one. effectiveLevel(): Level { let l: Logger = this; while (l.level === undefined) l = l.parent!; return l.level; }
// For callers with expensive setup: if (log.isEnabled(Level.DEBUG)) { ...compute... } isEnabled(level: Level): boolean { return level >= this.effectiveLevel(); }
// Placeholders: log.info('user {} logged in from {}', id, ip). The args are already // computed, but the string is only assembled if the level is enabled. A function message // isn't even called when the level is off. A trailing Error is the record's error. log(level: Level, message: Message, ...args: unknown[]): void { if (!this.isEnabled(level)) return; const error = args.at(-1) instanceof Error ? (args.pop() as Error) : undefined; const text = typeof message === 'function' ? message() : Logger.fill(message, args); const r: LogRecord = { time: this.clock(), level, logger: this.name, message: text, error }; for (let l: Logger | undefined = this; l; l = l.parent) { for (const a of l.appenders) a.append(r); if (!l.additive) break; } }
// Each "{}" takes the next argument; extra placeholders stay as "{}". static fill(template: string, args: unknown[]): string { let i = 0; return template.replace(/\{\}/g, (p) => (i < args.length ? String(args[i++]) : p)); }
debug(message: Message, ...args: unknown[]) { this.log(Level.DEBUG, message, ...args); } info(message: Message, ...args: unknown[]) { this.log(Level.INFO, message, ...args); } warn(message: Message, ...args: unknown[]) { this.log(Level.WARN, message, ...args); } error(message: Message, ...args: unknown[]) { this.log(Level.ERROR, message, ...args); }}
// One log event, captured once and handed to every appender. Readonly, so no appender can// change what the next one sees.interface LogRecord { readonly time: Date; readonly level: Level; readonly logger: string; readonly message: string; readonly error?: Error;}
// Turns a record into text. Separate from where the text goes, so the same JSON layout can go// to a file or a socket, and the console can stay human-readable.interface Formatter { format(r: LogRecord): string;}
// Seconds precision, like 2026-01-01T09:30:00Z, to match the other languages.const iso = (t: Date) => t.toISOString().replace(/\.\d{3}Z$/, 'Z');
// 2026-01-01T09:30:00Z WARN app.db - pool exhaustedclass TextFormatter implements Formatter { format(r: LogRecord): string { const line = `${iso(r.time)} ${Level[r.level]} ${r.logger} - ${r.message}`; return r.error ? `${line}\n${r.error.stack ?? r.error}` : line; }}
// One JSON object per line, for log shippers. JSON.stringify escapes quotes and newlines, so// a message can't break the line into two records or into invalid JSON.class JsonFormatter implements Formatter { format(r: LogRecord): string { return JSON.stringify({ time: iso(r.time), level: Level[r.level], logger: r.logger, message: r.message, ...(r.error && { error: String(r.error) }), }); }}
// Where formatted records go. Each appender owns its formatter: the console can be plain text// while the file is JSON.interface Appender { append(r: LogRecord): void; close(): void | Promise<void>; // flush and release files; the async appender needs it}
// Hands out one logger per name, creating the parents on the way. Code asks for a logger by// name and never builds one, so the tree is always whole.class LoggerRegistry { private readonly loggers = new Map<string, Logger>(); readonly root: Logger;
constructor(private readonly clock: () => Date = () => new Date()) { this.root = new Logger('root', undefined, Level.INFO, clock); // the root always has a level }
get(name: string): Logger { let l = this.loggers.get(name); if (!l) { const dot = name.lastIndexOf('.'); const parent = dot < 0 ? this.root : this.get(name.slice(0, dot)); l = new Logger(name, parent, undefined, this.clock); this.loggers.set(name, l); } return l; }}
// A message can be a string with {} placeholders, or a function that builds it.type Message = string | (() => string);
// Node has one thread, so two records can never interleave mid-line: each append runs to// completion. The cost Node does have is time on that thread. A synchronous write per record// blocks every request while the disk works. So the async appender batches: records go into// an array, and one write per turn of the event loop sends them all.class AsyncFileAppender implements Appender { private buffer: string[] = []; private scheduled = false; private writing: Promise<void> = Promise.resolve(); // writes happen in order, one at a time dropped = 0;
constructor( private readonly path: string, private readonly formatter: Formatter, private readonly capacity = 10_000, ) {}
append(r: LogRecord): void { // Bounded: if the disk stalls, memory doesn't grow until the process dies. Node can't // make the caller wait (that would block the event loop), so a full buffer drops // DEBUG and INFO, and counts them. WARN and ERROR are kept even past the bound. if (this.buffer.length >= this.capacity && r.level < Level.WARN) { this.dropped++; return; } this.buffer.push(this.formatter.format(r)); if (!this.scheduled) { this.scheduled = true; setImmediate(() => this.flush()); // after the current request's work, not during it } }
// Writes everything buffered so far, after any write already in flight. flush(): Promise<void> { this.scheduled = false; if (this.buffer.length === 0) return this.writing; const batch = this.buffer.join('\n') + '\n'; this.buffer = []; this.writing = this.writing .then(() => appendFile(this.path, batch)) .catch((e) => console.error('AsyncFileAppender failed:', e)); // never crash the app return this.writing; }
// Flush on shutdown: await it before process.exit, or the last batch is lost. close(): Promise<void> { return this.flush(); }}Three ideas hold it together:
- Whether, how and where are separate. The logger decides whether to write (level) and passes the record up the tree (Chain of Responsibility). The formatter decides how it looks, and the appender where it lands (both Strategy). Each one changes alone.
- Settings are made on branches and inherited. A few settings configure thousands of loggers, and code never configures its own. A branch standing for everything below it is the Composite pattern.
- Speed is a wrapper. The background writer in the next section wraps any appender (a Decorator), so the file and console appenders stay simple. And code just asks the registry for a logger by name, never seeing the tree being built (a facade).
Stress it
Section titled “Stress it”The design works for one thread. But every request thread in a server logs. And the file might be on a network disk that sometimes stops for a second.
Many threads, and a slow disk
Section titled “Many threads, and a slow disk”Every request thread logs. The file is on a network disk that sometimes stalls for a second.
Whether you move writes off the request thread with a queue that has a size limit, say what happens when it’s full, and write out everything on shutdown. A queue with no limit is the warning sign: it turns a slow disk into an out-of-memory crash.
Three problems appear with many threads:
- Lines mix. Two threads writing to one file at the same moment can produce half of one line followed by half of another.
- Writes block requests. If the appender writes right away, every request waits for the disk. When the disk stalls, the whole service stalls.
- Settings change while threads log. An operator turns on DEBUG while thousands of threads are reading the level.
The clearly correct fix is a lock per appender. Each appender writes under its own lock, so lines never mix. But the request thread still waits for the disk, and a stalled disk still stalls every request.
The better fix is a background writer. We wrap the appender in an AsyncAppender. Its append
only puts the record into a queue with a size limit, and returns at once. One background thread
takes records off the queue and passes them to the real appender. Since the real appender only ever
runs on that one thread, it doesn’t need a lock, and lines can’t mix.
| Option | How | The request thread waits when |
|---|---|---|
| 1. Lock per appender | Each appender writes under its own lock | Always, for the disk |
| 2. Background writer (our choice) | A queue with a size limit; one background thread writes | Only when the queue is full |
| 3. Queue with no limit | The same, but the queue never fills | Never, until memory runs out |
| 4. Lock-free ring (Log4j 2) | A fixed circular buffer and counters (LMAX Disruptor) | Only when the ring is full |
What happens when the queue is full? That’s the overflow policy. BLOCK makes the caller wait:
nothing is lost, but a stalled disk slows requests. DROP_BELOW_WARN drops DEBUG and INFO records
and counts them, while WARN and ERROR still wait. We pick the second, matching the answer from
scoping: losing a debug line is acceptable, losing an error is not.
And shutdown? close puts a special stop marker at the end of the queue, and waits for the
writer thread to reach it. The queue is first in, first out. So everything logged before close is
written before close returns.
// What a full queue does with one more record.enum Overflow { BLOCK, // the caller waits: nothing is lost, but a slow disk slows the app DROP_BELOW_WARN // DEBUG and INFO are dropped (and counted); WARN and ERROR still wait}
// A decorator: wraps any appender and moves its work onto one background thread. Callers only// pay for putting the record in a queue, and the wrapped appender is only ever called from// that one thread, so it needs no lock of its own.final class AsyncAppender implements Appender { // A record that means "stop": the worker sees it after everything queued before it. private static final LogRecord STOP = new LogRecord(Instant.EPOCH, Level.ERROR, "", "", "", null);
private final Appender inner; private final Overflow overflow; private final BlockingQueue<LogRecord> queue; private final AtomicLong dropped = new AtomicLong(); private final Thread worker; private volatile boolean closed;
AsyncAppender(Appender inner, int capacity, Overflow overflow) { this.inner = inner; this.overflow = overflow; // Bounded: if the disk stalls, memory doesn't grow until the process dies. this.queue = new ArrayBlockingQueue<>(capacity); this.worker = new Thread(this::drain, "log-writer"); this.worker.setDaemon(true); // never keeps the process alive on its own this.worker.start(); }
// Called on the caller's thread. Usually it just drops the record in the queue; only a full // queue makes the Overflow rule matter. public void append(LogRecord r) { if (closed || queue.offer(r)) return; // the fast path: there was room if (overflow == Overflow.DROP_BELOW_WARN && r.level().compareTo(Level.WARN) < 0) { dropped.incrementAndGet(); // counted, so it can be reported as "N records dropped" return; } try { // Wait for room, but give up if the appender closes meanwhile; a plain put() // could block forever once the worker has stopped. while (!closed && !queue.offer(r, 100, TimeUnit.MILLISECONDS)) { } } catch (InterruptedException e) { Thread.currentThread().interrupt(); // keep the caller's interrupt; drop this record } }
// The worker: writes records in order until STOP, then closes the wrapped appender. private void drain() { try { for (LogRecord r = queue.take(); r != STOP; r = queue.take()) { try { inner.append(r); } catch (RuntimeException e) { System.err.println("appender failed: " + e); // one bad record must not kill the worker } } } catch (InterruptedException e) { Thread.currentThread().interrupt(); } finally { inner.close(); } }
long dropped() { return dropped.get(); }
// Flush on shutdown: everything queued before close() is written before it returns. // Call it from a shutdown hook, or the last seconds of logs before a crash are lost. public void close() { if (closed) return; closed = true; try { queue.put(STOP); // waits for room, which the worker is making worker.join(); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } }}
// Appenders called directly from many threads lock around the write, so two records' lines// never interleave in the file. (Not needed behind AsyncAppender, but cheap when uncontended.)final class FileAppender implements Appender { private final BufferedWriter out; private final Formatter formatter;
FileAppender(Path file, Formatter formatter) throws IOException { this.out = Files.newBufferedWriter(file, StandardOpenOption.CREATE, StandardOpenOption.APPEND); this.formatter = formatter; }
public void append(LogRecord r) { String text = formatter.format(r); // format outside the lock: it's the slow part synchronized (this) { try { out.write(text); out.newLine(); out.flush(); } catch (IOException e) { System.err.println("FileAppender failed: " + e); } } }
public synchronized void close() { try { out.close(); } catch (IOException e) { System.err.println("FileAppender close failed: " + e); } }}
// The logger's configuration can change while other threads log (an operator turns on DEBUG// for one package). volatile makes a level change visible to every thread at once, and a// copy-on-write list lets threads walk the appenders while one is added. Both suit data// that's read millions of times and written a handful.final class Logger { private final String name; private final Logger parent; private final Clock clock; private final List<Appender> appenders = new CopyOnWriteArrayList<>(); private volatile Level level; private volatile boolean additive = true;
Logger(String name, Logger parent, Level level, Clock clock) { this.name = name; this.parent = parent; this.level = level; this.clock = clock; }
void setLevel(Level level) { this.level = level; } void setAdditive(boolean additive) { this.additive = additive; } void addAppender(Appender a) { appenders.add(a); }
// A logger with no level of its own uses its parent's, and so on up to the root, which // always has one. Level effectiveLevel() { for (Logger l = this; ; l = l.parent) { Level own = l.level; // read the volatile once if (own != null) return own; } }
boolean isEnabled(Level level) { return level.compareTo(effectiveLevel()) >= 0; }
// The template form. The "{}" placeholders are filled only if the level is on. A Throwable // as the last argument is the error, not a value to fill in. void log(Level level, String template, Object... args) { if (!isEnabled(level)) return; Throwable error = args.length > 0 && args[args.length - 1] instanceof Throwable t ? t : null; emit(level, fill(template, args), error); }
// The lazy form: the message is built only if the level is on. void log(Level level, Supplier<String> message) { if (isEnabled(level)) emit(level, message.get(), null); }
// One record, given to this logger's appenders, then to each parent's, until a logger that // isn't additive stops it. private void emit(Level level, String message, Throwable error) { LogRecord r = new LogRecord(clock.instant(), level, name, Thread.currentThread().getName(), message, error); for (Logger l = this; l != null; l = l.parent) { for (Appender a : l.appenders) a.append(r); if (!l.additive) break; } }
// Replaces each "{}" with the next argument, left to right. Placeholders with no argument // left stay as they are. static String fill(String template, Object[] args) { StringBuilder b = new StringBuilder(); int from = 0, next = 0; for (int at; (at = template.indexOf("{}", from)) >= 0 && next < args.length; from = at + 2) { if (args[next] instanceof Throwable && next == args.length - 1) break; b.append(template, from, at).append(args[next++]); } return b.append(template, from, template.length()).toString(); }
void debug(String template, Object... args) { log(Level.DEBUG, template, args); } void debug(Supplier<String> message) { log(Level.DEBUG, message); } void info(String template, Object... args) { log(Level.INFO, template, args); } void warn(String template, Object... args) { log(Level.WARN, template, args); } void error(String template, Object... args) { log(Level.ERROR, template, args); }}
// Loggers are usually fetched once per class, into a static field, so a synchronized get// costs nothing that matters, and it keeps "create the parents first" one atomic step.final class LoggerRegistry { private final Map<String, Logger> loggers = new HashMap<>(); private final Logger root; private final Clock clock;
LoggerRegistry(Clock clock) { this.clock = clock; this.root = new Logger("root", null, Level.INFO, clock); }
Logger root() { return root; }
synchronized Logger get(String name) { // re-entrant, so the recursive call is fine Logger existing = loggers.get(name); if (existing != null) return existing; int dot = name.lastIndexOf('.'); Logger parent = dot < 0 ? root : get(name.substring(0, dot)); Logger created = new Logger(name, parent, null, clock); loggers.put(name, created); return created; }}import queuefrom enum import Enum
# What a full queue does with one more record.class Overflow(Enum): BLOCK = "block" # the caller waits: nothing lost, but a slow disk slows the app DROP_BELOW_WARN = "drop_below_warn" # DEBUG and INFO dropped (and counted); WARN and ERROR wait
_STOP = object() # tells the worker to finish: it sees it after everything queued before it
# A decorator: wraps any appender and moves its work onto one background thread. Callers only# pay for putting the record in a queue, and the wrapped appender is only ever called from# that one thread, so it needs no lock of its own.class AsyncAppender: def __init__(self, inner: Appender, capacity: int, overflow: Overflow = Overflow.DROP_BELOW_WARN): self._inner = inner self._overflow = overflow # Bounded: if the disk stalls, memory doesn't grow until the process dies. self._queue: queue.Queue = queue.Queue(maxsize=capacity) self._closed = False self.dropped = 0 # only the callers that drop write it, under _drop_lock self._drop_lock = threading.Lock() # daemon: never keeps the process alive on its own self._worker = threading.Thread(target=self._drain, name="log-writer", daemon=True) self._worker.start()
# Called on the caller's thread. Usually it just drops the record in the queue; only a full # queue makes the Overflow rule matter. def append(self, r: LogRecord) -> None: if self._closed: return try: self._queue.put_nowait(r) # the fast path: there was room return except queue.Full: pass if self._overflow is Overflow.DROP_BELOW_WARN and r.level < Level.WARN: with self._drop_lock: self.dropped += 1 # counted, so it can be reported as "N records dropped" return # Wait for room, but give up if the appender closes meanwhile; a plain put() could # block forever once the worker has stopped. while not self._closed: try: self._queue.put(r, timeout=0.1) return except queue.Full: continue
# The worker: writes records in order until _STOP, then closes the wrapped appender. def _drain(self) -> None: try: while (r := self._queue.get()) is not _STOP: try: self._inner.append(r) except Exception as e: # one bad record must not kill the worker print(f"appender failed: {e!r}", file=sys.stderr) finally: self._inner.close()
# Flush on shutdown: everything queued before close() is written before it returns. # Register it with atexit, or the last seconds of logs before an exit are lost. def close(self) -> None: if self._closed: return self._closed = True self._queue.put(_STOP) # waits for room, which the worker is making self._worker.join()
# Appenders called directly from many threads lock around the write, so two records' lines# never interleave in the file. (Not needed behind AsyncAppender, but cheap when uncontended.)class FileAppender: def __init__(self, path: str, formatter: Formatter): self._file = open(path, "a", encoding="utf-8") self._formatter = formatter self._lock = threading.Lock()
def append(self, r: LogRecord) -> None: text = self._formatter.format(r) + "\n" # format outside the lock: it's the slow part with self._lock: try: self._file.write(text) self._file.flush() except OSError as e: print(f"FileAppender failed: {e}", file=sys.stderr)
def close(self) -> None: with self._lock: self._file.close()
# Loggers are usually fetched once per module, at import, so one lock around get costs# nothing that matters, and it keeps "create the parents first" one atomic step. RLock,# because get calls itself for the parent.class LoggerRegistry: def __init__(self, clock: Clock = utc_now): self._clock = clock self._loggers: dict[str, Logger] = {} self._lock = threading.RLock() self.root = Logger("root", None, Level.INFO, clock)
def get(self, name: str) -> Logger: with self._lock: existing = self._loggers.get(name) if existing is not None: return existing parent_name, dot, _ = name.rpartition(".") parent = self.get(parent_name) if dot else self.root created = self._loggers[name] = Logger(name, parent, None, self._clock) return created
# The Logger itself is unchanged from stage 4. Assigning logger.level is one atomic store in# CPython, so a level change is seen by the next call on any thread. Adding an appender while# others log should replace the list (self._appenders = [*self._appenders, a]) rather than# append to it, so a thread walking the old list never sees it change.// What a full queue does with one more record.public enum Overflow{ Block, // the caller waits: nothing is lost, but a slow disk slows the app DropBelowWarn, // Debug and Info are dropped (and counted); Warn and Error still wait}
// A decorator: wraps any appender and moves its work onto one background task. Callers only// pay for writing the record to a channel, and the wrapped appender is only ever called from// that one task, so it needs no lock of its own.public sealed class AsyncAppender : IAppender{ private readonly IAppender _inner; private readonly Overflow _overflow; private readonly Channel<LogRecord> _channel; private readonly Task _worker; private long _dropped;
public AsyncAppender(IAppender inner, int capacity, Overflow overflow) { _inner = inner; _overflow = overflow; // Bounded: if the disk stalls, memory doesn't grow until the process dies. _channel = Channel.CreateBounded<LogRecord>(new BoundedChannelOptions(capacity) { SingleReader = true, FullMode = BoundedChannelFullMode.Wait, }); _worker = Task.Run(DrainAsync); }
public long Dropped => Interlocked.Read(ref _dropped);
// Called on the caller's thread. Usually it just drops the record in the queue; only a full // queue makes the Overflow rule matter. public void Append(LogRecord r) { if (_channel.Writer.TryWrite(r)) return; // the fast path: there was room if (_overflow == Overflow.DropBelowWarn && r.Level < Level.Warn) { Interlocked.Increment(ref _dropped); // counted, so it can be reported as "N dropped" return; } try { // Wait for room. Append is synchronous, so the caller blocks here; after Dispose // the write fails instead of waiting forever. _channel.Writer.WriteAsync(r).AsTask().GetAwaiter().GetResult(); } catch (ChannelClosedException) { } // logged during shutdown: dropped }
// The worker: writes records in order until the channel is completed and empty. private async Task DrainAsync() { try { await foreach (var r in _channel.Reader.ReadAllAsync()) // ends when completed and empty { try { _inner.Append(r); } catch (Exception e) { Console.Error.WriteLine($"appender failed: {e.Message}"); } // keep going } } finally { _inner.Dispose(); } }
// Flush on shutdown: everything written before Dispose is appended before it returns. // Hook it to IHostApplicationLifetime.ApplicationStopping, or the last logs are lost. public void Dispose() { _channel.Writer.TryComplete(); _worker.GetAwaiter().GetResult(); }}
// Appenders called directly from many threads lock around the write, so two records' lines// never interleave in the file. (Not needed behind AsyncAppender, but cheap when uncontended.)public sealed class FileAppender : IAppender{ private readonly Lock _lock = new(); private readonly StreamWriter _out; private readonly IFormatter _formatter;
public FileAppender(string path, IFormatter formatter) { _out = new StreamWriter(path, append: true) { AutoFlush = true }; _formatter = formatter; }
public void Append(LogRecord r) { var text = _formatter.Format(r); // format outside the lock: it's the slow part lock (_lock) { try { _out.WriteLine(text); } catch (IOException e) { Console.Error.WriteLine($"FileAppender failed: {e.Message}"); } } }
public void Dispose() { lock (_lock) _out.Dispose(); }}
// Loggers are usually fetched once per class, into a static field, so one lock around Get// costs nothing that matters, and keeps "create the parents first" one atomic step. C# locks// are re-entrant, so the recursive call for the parent is fine.public sealed class LoggerRegistry(TimeProvider time){ private readonly Lock _lock = new(); private readonly Dictionary<string, Logger> _loggers = new(); public Logger Root { get; } = new("root", null, Level.Info, time);
public Logger Get(string name) { lock (_lock) { if (_loggers.TryGetValue(name, out var existing)) return existing; int dot = name.LastIndexOf('.'); var parent = dot < 0 ? Root : Get(name[..dot]); return _loggers[name] = new Logger(name, parent, null, time); } }}
// The Logger, made safe for threads in two ways. Level and Additive are kept in int// fields read and written with Volatile.Read and Volatile.Write (a nullable can't be// volatile, so -1 stands for "inherit"), so a change is seen by every thread at once. And the// appender list becomes an ImmutableArray swapped with ImmutableInterlocked.Update, so a// thread walking the old list never sees it change underneath.// Overflow is what a full queue does with one more record.type Overflow int
const ( Block Overflow = iota // the caller waits: nothing lost, but a slow disk slows the app DropBelowWarn // Debug and Info dropped (and counted); Warn and Error wait)
// AsyncAppender is a decorator: it wraps any appender and moves its work onto one goroutine.// Callers only pay for a channel send, and the wrapped appender is only ever called from// that goroutine, so it needs no lock of its own.type AsyncAppender struct { inner Appender overflow Overflow records chan Record // buffered: if the disk stalls, memory doesn't grow without limit done chan struct{} dropped atomic.Int64 mu sync.RWMutex // Append holds it shared; Close takes it alone to close the channel closed bool}
func NewAsyncAppender(inner Appender, capacity int, overflow Overflow) *AsyncAppender { a := &AsyncAppender{inner: inner, overflow: overflow, records: make(chan Record, capacity), done: make(chan struct{})} go a.drain() return a}
// Append runs on the caller's goroutine. Usually it just sends the record on the channel; only// a full channel makes the Overflow rule matter.func (a *AsyncAppender) Append(r Record) { // Sending on a closed channel panics, so Append holds the read lock: many senders at // once, but never while Close is closing the channel. a.mu.RLock() defer a.mu.RUnlock() if a.closed { return } select { case a.records <- r: // the fast path: there was room return default: } if a.overflow == DropBelowWarn && r.Level < Warn { a.dropped.Add(1) // counted, so it can be reported as "N records dropped" return } a.records <- r // wait for room; the drain goroutine is making it}
// drain is the worker: it writes records in order until the channel is closed, then closes the// wrapped appender.func (a *AsyncAppender) drain() { defer close(a.done) for r := range a.records { // ends when the channel is closed and empty a.inner.Append(r) } a.inner.Close()}
func (a *AsyncAppender) Dropped() int64 { return a.dropped.Load() }
// Close flushes on shutdown: everything sent before Close is written before it returns.// Call it before main returns, or the last records are lost with the process.func (a *AsyncAppender) Close() error { a.mu.Lock() // waits for senders in flight, including ones blocked on a full channel if !a.closed { a.closed = true close(a.records) } a.mu.Unlock() <-a.done return nil}
// LockedAppender serializes writes for an appender called from many goroutines, so two// records never interleave. (Not needed behind AsyncAppender.)type LockedAppender struct { mu sync.Mutex inner Appender}
func (a *LockedAppender) Append(r Record) { a.mu.Lock() defer a.mu.Unlock() a.inner.Append(r)}
func (a *LockedAppender) Close() error { a.mu.Lock() defer a.mu.Unlock() return a.inner.Close()}
// Logger's configuration can change while other goroutines log (an operator turns on Debug// for one package). Atomics make a change visible at once, and the appender list is// replaced, never changed in place, so a goroutine walking the old slice is never surprised.type Logger struct { name string parent *Logger level atomic.Int32 // a Level, or Inherit nonAdditive atomic.Bool clock func() time.Time mu sync.Mutex // serializes AddAppender appenders atomic.Pointer[[]Appender] // read without a lock on every record}
func newLogger(name string, parent *Logger, level Level, clock func() time.Time) *Logger { l := &Logger{name: name, parent: parent, clock: clock} l.level.Store(int32(level)) l.appenders.Store(&[]Appender{}) return l}
func NewLogger(name string, level Level, clock func() time.Time) *Logger { return newLogger(name, nil, level, clock)}
func (l *Logger) SetLevel(level Level) { l.level.Store(int32(level)) }func (l *Logger) SetAdditive(add bool) { l.nonAdditive.Store(!add) }
func (l *Logger) AddAppender(a Appender) { l.mu.Lock() defer l.mu.Unlock() next := append(slices.Clone(*l.appenders.Load()), a) // copy on write l.appenders.Store(&next)}
// EffectiveLevel: a logger with no level of its own uses its parent's, and so on up to the// root, which always has one.func (l *Logger) EffectiveLevel() Level { n := l for Level(n.level.Load()) == Inherit { n = n.parent } return Level(n.level.Load())}
// emit builds one record and gives it to this logger's appenders, then to each parent's, until// a logger that isn't additive stops it.func (l *Logger) emit(level Level, message string, err error) { r := Record{l.clock(), level, l.name, message, err} for n := l; n != nil; n = n.parent { for _, a := range *n.appenders.Load() { a.Append(r) } if n.nonAdditive.Load() { break } }}
// Registry: loggers are usually fetched once, into a package variable, so one mutex around// Get costs nothing that matters, and keeps "create the parents first" one atomic step.type Registry struct { mu sync.Mutex clock func() time.Time root *Logger loggers map[string]*Logger}
func NewRegistry(clock func() time.Time) *Registry { return &Registry{clock: clock, root: newLogger("root", nil, Info, clock), loggers: map[string]*Logger{}}}
func (g *Registry) Get(name string) *Logger { g.mu.Lock() defer g.mu.Unlock() return g.get(name)}
// get is Get without the lock, so it can recurse for the parent (Go mutexes aren't re-entrant).func (g *Registry) get(name string) *Logger { if l, ok := g.loggers[name]; ok { return l } parent := g.root if dot := strings.LastIndexByte(name, '.'); dot >= 0 { parent = g.get(name[:dot]) } l := newLogger(name, parent, Inherit, g.clock) g.loggers[name] = l return l}import { appendFile } from 'node:fs/promises';
// Node has one thread, so two records can never interleave mid-line: each append runs to// completion. The cost Node does have is time on that thread. A synchronous write per record// blocks every request while the disk works. So the async appender batches: records go into// an array, and one write per turn of the event loop sends them all.class AsyncFileAppender implements Appender { private buffer: string[] = []; private scheduled = false; private writing: Promise<void> = Promise.resolve(); // writes happen in order, one at a time dropped = 0;
constructor( private readonly path: string, private readonly formatter: Formatter, private readonly capacity = 10_000, ) {}
append(r: LogRecord): void { // Bounded: if the disk stalls, memory doesn't grow until the process dies. Node can't // make the caller wait (that would block the event loop), so a full buffer drops // DEBUG and INFO, and counts them. WARN and ERROR are kept even past the bound. if (this.buffer.length >= this.capacity && r.level < Level.WARN) { this.dropped++; return; } this.buffer.push(this.formatter.format(r)); if (!this.scheduled) { this.scheduled = true; setImmediate(() => this.flush()); // after the current request's work, not during it } }
// Writes everything buffered so far, after any write already in flight. flush(): Promise<void> { this.scheduled = false; if (this.buffer.length === 0) return this.writing; const batch = this.buffer.join('\n') + '\n'; this.buffer = []; this.writing = this.writing .then(() => appendFile(this.path, batch)) .catch((e) => console.error('AsyncFileAppender failed:', e)); // never crash the app return this.writing; }
// Flush on shutdown: await it before process.exit, or the last batch is lost. close(): Promise<void> { return this.flush(); }}Why is this correct? The queue is the only thing callers and the writer share, and it’s built
for many threads. The record never changes after it’s made, so the writer reads it without a lock.
The stop marker sits behind every record logged before close, so the writer saves them all before
it stops. A caller waiting on a full queue checks a “closed” flag while it waits, so it can’t wait
forever after the writer has gone.
What does it cost? When log returns, the line isn’t on disk yet. A hard crash (kill -9, a
power cut) loses whatever was in the queue. That’s exactly the last few lines before the crash,
often the ones you wanted most. Some teams keep ERROR lines written right away for that reason.
Go deeperSettings that change while threads log1 min
A logger’s settings are read on every call, and changed rarely. So Java and Go store the level and the additive flag in fields that every thread sees right away (atomic or volatile fields).
The appender list needs more care. If an operator adds an appender while a thread is walking the list, the thread could see it half changed. So we never change the list in place. We build a new list with the change, and swap it in with one assignment. A thread already walking the old list finishes with the old list. This is called copy on write.
Appenders used without the background writer take their own lock around the write. They format the record before taking the lock, since formatting is the slow part.
Go deeperHow each language builds the background writer1 min
Java uses a BlockingQueue with a size limit and one thread. Python uses queue.Queue and a
thread. C# uses a Channel with a size limit. Go uses a channel with a buffer, plus a read lock
that stops Append from sending on a channel that’s already closed.
TypeScript in Node has one thread, so lines never mix. Its stage 5 groups writes together instead: one disk write per turn of the event loop. Past the limit it drops DEBUG and INFO, since Node can’t make one caller wait without blocking everything.
Go deeperWhy one writer thread, not a pool?1 min
A pool of threads would write records out of order, and the file appender would need its lock back. One writer keeps the order and needs no lock. And disk writes happen one after another anyway, so more threads wouldn’t make the disk faster. If one thread can’t keep up, group several records into one write, which is what the TypeScript stage 5 does.
How you’d prove it works
Section titled “How you’d prove it works”Each test protects one promise:
- A switched-off record is skipped, and its function is never called.
- A child inherits its parent’s level and sends records to its parent’s appenders.
- A non-additive logger keeps its records to itself.
- JSON output stays one valid line, even with a quote and a line break in the message.
- The background writer loses nothing under 8 threads with a tiny queue, and
closereturns only after every record is written.
The tests use a list appender (records go into a list in memory) and a clock that never moves, so each line can be compared exactly. The background writer test uses a queue of just 16 records, so callers really do hit a full queue. Then it checks that all 8,000 different lines arrived.
Go deeperThe tests in five languages2 min
// An appender that keeps formatted lines in memory, for assertions.static final class ListAppender implements Appender { final List<String> lines = Collections.synchronizedList(new ArrayList<>()); private final Formatter formatter; ListAppender(Formatter formatter) { this.formatter = formatter; } public void append(LogRecord r) { lines.add(formatter.format(r)); }}
// A clock that never moves, so every timestamp in a test is the same known value.final Clock clock = Clock.fixed(Instant.parse("2026-01-01T09:30:00Z"), ZoneOffset.UTC);final LoggerRegistry registry = new LoggerRegistry(clock);final ListAppender out = new ListAppender(new TextFormatter());{ registry.root().addAppender(out); }
@Testvoid disabledRecordsAreSkippedAndTheirMessagesNeverBuilt() { int[] built = {0}; registry.get("app.db").debug(() -> { built[0]++; return "expensive"; }); // root is INFO assertEquals(0, built[0]); assertTrue(out.lines.isEmpty());}
@Testvoid childrenInheritTheirParentsLevelAndAppenders() { registry.get("app").setLevel(Level.WARN); Logger db = registry.get("app.db"); // no level, no appenders of its own db.info("connected"); // app says WARN: skipped db.warn("pool {} of {} in use", 10, 10); assertEquals(List.of("2026-01-01T09:30:00Z WARN app.db [main] - pool 10 of 10 in use"), out.lines);}
@Testvoid aNonAdditiveLoggerKeepsItsRecordsToItself() { Logger audit = registry.get("audit"); ListAppender auditFile = new ListAppender(new JsonFormatter()); audit.addAppender(auditFile); audit.setAdditive(false); audit.info("user \"ana\" signed in\nfrom 10.0.0.1"); assertTrue(out.lines.isEmpty()); // never reached the root's console // One line of valid JSON, even with a quote and a newline in the message. assertEquals(List.of("{\"time\":\"2026-01-01T09:30:00Z\",\"level\":\"INFO\",\"logger\":\"audit\",\"thread\":\"main\"," + "\"message\":\"user \\\"ana\\\" signed in\\nfrom 10.0.0.1\"}"), auditFile.lines);}
@Testvoid anAsyncAppenderLosesNothingAndFlushesOnClose() throws Exception { // A tiny queue, so callers really do wait on a full queue, and 8 threads x 1,000 records. ListAppender sink = new ListAppender(new TextFormatter()); AsyncAppender async = new AsyncAppender(sink, 16, Overflow.BLOCK); Logger log = registry.get("load"); log.setAdditive(false); log.addAppender(async); ExecutorService pool = Executors.newFixedThreadPool(8); for (int t = 0; t < 8; t++) { int id = t; pool.submit(() -> { for (int i = 0; i < 1_000; i++) log.info("t{} n{}", id, i); }); } pool.shutdown(); pool.awaitTermination(30, TimeUnit.SECONDS); async.close(); // returns only after the queue is drained assertEquals(8_000, sink.lines.size()); assertEquals(8_000L, sink.lines.stream().distinct().count());}from concurrent.futures import ThreadPoolExecutorfrom datetime import datetime, timezone
# An appender that keeps formatted lines in memory, for assertions.class ListAppender: def __init__(self, formatter: Formatter): self.lines: list[str] = [] self._formatter = formatter
def append(self, r: LogRecord) -> None: self.lines.append(self._formatter.format(r)) # list.append is atomic in CPython
def close(self) -> None: pass
# A clock that never moves, so every timestamp in a test is the same known value.FIXED = datetime(2026, 1, 1, 9, 30, tzinfo=timezone.utc)
def setup() -> tuple[LoggerRegistry, ListAppender]: registry = LoggerRegistry(lambda: FIXED) out = ListAppender(TextFormatter()) registry.root.add_appender(out) return registry, out
def test_disabled_records_are_skipped_and_their_messages_never_built(): registry, out = setup() built = [] registry.get("app.db").debug(lambda: built.append(1) or "expensive") # root is INFO assert built == [] and out.lines == []
def test_children_inherit_their_parents_level_and_appenders(): registry, out = setup() registry.get("app").level = Level.WARN db = registry.get("app.db") # no level, no appenders of its own db.info("connected") # app says WARN: skipped db.warn("pool {} of {} in use", 10, 10) assert out.lines == ["2026-01-01T09:30:00Z WARN app.db [MainThread] - pool 10 of 10 in use"]
def test_a_non_additive_logger_keeps_its_records_to_itself(): registry, out = setup() audit = registry.get("audit") audit_file = ListAppender(JsonFormatter()) audit.add_appender(audit_file) audit.additive = False audit.info('user "ana" signed in\nfrom 10.0.0.1') assert out.lines == [] # never reached the root's console # One line of valid JSON, even with a quote and a newline in the message. assert audit_file.lines == ['{"time":"2026-01-01T09:30:00Z","level":"INFO","logger":"audit",' '"thread":"MainThread","message":"user \\"ana\\" signed in\\nfrom 10.0.0.1"}']
def test_an_async_appender_loses_nothing_and_flushes_on_close(): # A tiny queue, so callers really do wait on a full queue, and 8 threads x 1,000 records. registry, _ = setup() sink = ListAppender(TextFormatter()) async_appender = AsyncAppender(sink, 16, Overflow.BLOCK) log = registry.get("load") log.additive = False log.add_appender(async_appender)
def write(t: int) -> None: for i in range(1_000): log.info("t{} n{}", t, i)
with ThreadPoolExecutor(max_workers=8) as pool: list(pool.map(write, range(8))) async_appender.close() # returns only after the queue is drained assert len(sink.lines) == 8_000 and len(set(sink.lines)) == 8_000// An appender that keeps formatted lines in memory, for assertions.private sealed class ListAppender(IFormatter formatter) : IAppender{ public ConcurrentQueue<string> Lines { get; } = new(); public void Append(LogRecord r) => Lines.Enqueue(formatter.Format(r)); public void Dispose() { }}
// FakeTimeProvider (Microsoft.Extensions.TimeProvider.Testing) doesn't move unless told to,// so every timestamp in a test is the same known value.private readonly LoggerRegistry _registry;private readonly ListAppender _out = new(new TextFormatter());
public LoggingTests(){ _registry = new LoggerRegistry(new FakeTimeProvider(new DateTimeOffset(2026, 1, 1, 9, 30, 0, TimeSpan.Zero))); _registry.Root.AddAppender(_out);}
[Fact]public void DisabledRecordsAreSkippedAndTheirMessagesNeverBuilt(){ int built = 0; _registry.Get("App.Db").Debug(() => { built++; return "expensive"; }); // root is Info Assert.Equal(0, built); Assert.Empty(_out.Lines);}
[Fact]public void ChildrenInheritTheirParentsLevelAndAppenders(){ _registry.Get("App").Level = Level.Warn; var db = _registry.Get("App.Db"); // no level, no appenders of its own db.Info("connected"); // App says Warn: skipped db.Warn("pool {} of {} in use", 10, 10); var line = Assert.Single(_out.Lines); Assert.Equal($"2026-01-01T09:30:00Z WARN App.Db [{Environment.CurrentManagedThreadId}] - pool 10 of 10 in use", line);}
[Fact]public void ANonAdditiveLoggerKeepsItsRecordsToItself(){ var audit = _registry.Get("Audit"); var auditFile = new ListAppender(new JsonFormatter()); audit.AddAppender(auditFile); audit.Additive = false; audit.Info("user \"ana\" signed in\nfrom 10.0.0.1"); Assert.Empty(_out.Lines); // never reached the root's console // One line of valid JSON, even with a quote and a newline in the message. using var doc = JsonDocument.Parse(Assert.Single(auditFile.Lines)); Assert.Equal("user \"ana\" signed in\nfrom 10.0.0.1", doc.RootElement.GetProperty("message").GetString());}
[Fact]public void AnAsyncAppenderLosesNothingAndFlushesOnDispose(){ // A tiny channel, so callers really do wait when it's full, and 8 threads x 1,000 records. var sink = new ListAppender(new TextFormatter()); var async = new AsyncAppender(sink, 16, Overflow.Block); var log = _registry.Get("Load"); log.Additive = false; log.AddAppender(async); Parallel.For(0, 8, new ParallelOptions { MaxDegreeOfParallelism = 8 }, t => { for (int i = 0; i < 1_000; i++) log.Info("t{} n{}", t, i); }); async.Dispose(); // returns only after the channel is drained Assert.Equal(8_000, sink.Lines.Count); Assert.Equal(8_000, sink.Lines.Distinct().Count());}// listAppender keeps formatted lines in memory, for assertions.type listAppender struct { mu sync.Mutex lines []string formatter Formatter}
func (a *listAppender) Append(r Record) { a.mu.Lock() defer a.mu.Unlock() a.lines = append(a.lines, a.formatter.Format(r))}
func (a *listAppender) Close() error { return nil }
// A clock that never moves, so every timestamp in a test is the same known value.func fixed() time.Time { return time.Date(2026, 1, 1, 9, 30, 0, 0, time.UTC) }
func setup() (*Registry, *listAppender) { g := NewRegistry(fixed) out := &listAppender{formatter: TextFormatter{}} g.Root().AddAppender(out) return g, out}
func TestDisabledRecordsAreSkippedAndTheirMessagesNeverBuilt(t *testing.T) { g, out := setup() built := 0 g.Get("app.db").DebugFunc(func() string { built++; return "expensive" }) // root is Info if built != 0 || len(out.lines) != 0 { t.Fatalf("built=%d lines=%v", built, out.lines) }}
func TestChildrenInheritTheirParentsLevelAndAppenders(t *testing.T) { g, out := setup() g.Get("app").SetLevel(Warn) db := g.Get("app.db") // no level, no appenders of its own db.Infof("connected") // app says Warn: skipped db.Warnf("pool %d of %d in use", 10, 10) want := []string{"2026-01-01T09:30:00Z WARN app.db - pool 10 of 10 in use"} if !slices.Equal(out.lines, want) { t.Fatalf("got %q, want %q", out.lines, want) }}
func TestANonAdditiveLoggerKeepsItsRecordsToItself(t *testing.T) { g, out := setup() audit := g.Get("audit") auditFile := &listAppender{formatter: JSONFormatter{}} audit.AddAppender(auditFile) audit.SetAdditive(false) audit.Infof("user %q signed in\nfrom 10.0.0.1", "ana") if len(out.lines) != 0 { t.Fatalf("reached the root: %q", out.lines) // never reached the root's console } // One line of valid JSON, even with a quote and a newline in the message. want := `{"time":"2026-01-01T09:30:00Z","level":"INFO","logger":"audit","message":"user \"ana\" signed in\nfrom 10.0.0.1"}` if len(auditFile.lines) != 1 || auditFile.lines[0] != want { t.Fatalf("got %q", auditFile.lines) }}
// Run with: go test -race ./... The race detector flags any unguarded access.func TestAnAsyncAppenderLosesNothingAndFlushesOnClose(t *testing.T) { // A tiny buffer, so senders really do wait on a full channel, and 8 goroutines x 1,000. g, _ := setup() sink := &listAppender{formatter: TextFormatter{}} async := NewAsyncAppender(sink, 16, Block) log := g.Get("load") log.SetAdditive(false) log.AddAppender(async) var wg sync.WaitGroup for id := range 8 { wg.Add(1) go func() { defer wg.Done() for i := range 1000 { log.Infof("g%d n%d", id, i) } }() } wg.Wait() async.Close() // returns only after the channel is drained seen := map[string]bool{} for _, l := range sink.lines { seen[l] = true } if len(sink.lines) != 8000 || len(seen) != 8000 { t.Fatalf("lines=%d distinct=%d", len(sink.lines), len(seen)) }}import { test } from 'node:test';import assert from 'node:assert/strict';import { mkdtempSync, readFileSync } from 'node:fs';import { tmpdir } from 'node:os';import { join } from 'node:path';
// An appender that keeps formatted lines in memory, for assertions.class ListAppender implements Appender { readonly lines: string[] = []; constructor(private readonly formatter: Formatter) {} append(r: LogRecord) { this.lines.push(this.formatter.format(r)); } close() {}}
// A clock that never moves, so every timestamp in a test is the same known value.const fixed = () => new Date('2026-01-01T09:30:00Z');function setup() { const registry = new LoggerRegistry(fixed); const out = new ListAppender(new TextFormatter()); registry.root.addAppender(out); return { registry, out };}
test('disabled records are skipped and their messages never built', () => { const { registry, out } = setup(); let built = 0; registry.get('app.db').debug(() => { built++; return 'expensive'; }); // root is INFO assert.equal(built, 0); assert.deepEqual(out.lines, []);});
test("children inherit their parents' level and appenders", () => { const { registry, out } = setup(); registry.get('app').level = Level.WARN; const db = registry.get('app.db'); // no level, no appenders of its own db.info('connected'); // app says WARN: skipped db.warn('pool {} of {} in use', 10, 10); assert.deepEqual(out.lines, ['2026-01-01T09:30:00Z WARN app.db - pool 10 of 10 in use']);});
test('a non-additive logger keeps its records to itself', () => { const { registry, out } = setup(); const audit = registry.get('audit'); const auditFile = new ListAppender(new JsonFormatter()); audit.addAppender(auditFile); audit.additive = false; audit.info('user "ana" signed in\nfrom 10.0.0.1'); assert.deepEqual(out.lines, []); // never reached the root's console // One line of valid JSON, even with a quote and a newline in the message. assert.deepEqual(auditFile.lines, [ '{"time":"2026-01-01T09:30:00Z","level":"INFO","logger":"audit","message":"user \\"ana\\" signed in\\nfrom 10.0.0.1"}', ]);});
test('the async appender batches, drops only below WARN when full, and flushes on close', async () => { const path = join(mkdtempSync(join(tmpdir(), 'log-')), 'app.log'); const { registry } = setup(); const file = new AsyncFileAppender(path, new TextFormatter(), 100); const log = registry.get('load'); log.additive = false; log.addAppender(file); // All in one synchronous burst, so nothing is written until the burst ends. for (let i = 0; i < 1_000; i++) log.info('n{}', i); log.error('still kept'); await file.close(); const lines = readFileSync(path, 'utf8').trimEnd().split('\n'); assert.equal(lines.length, 101); // the first 100 INFO, plus the ERROR past the bound assert.equal(file.dropped, 900); assert.match(lines.at(-1)!, /ERROR load - still kept$/);});Go deeperEvery edge case, and where it is handled2 min
| Case | What happens | Where |
|---|---|---|
| Message contains a quote or line break | Escaped in JSON; one line per record | JsonFormatter |
Message contains {} but no values |
Left as written | fill |
| More values than placeholders | Extras ignored; a last error becomes the record’s error | fill, log |
| Appender throws (disk full) | Reported on the error output; the application never sees it | appenders, background writer |
| A logger asked for before its parent | Parents created on the way | LoggerRegistry.get |
| Same appender on a logger and its parent | Line written twice | setup (additivity) |
Logging during close |
Dropped; close won’t wait forever for it |
AsyncAppender.append |
close called twice |
The second call does nothing | AsyncAppender.close |
| Logging from inside an appender | Can loop; frameworks guard with a per-thread “in logging” flag | extension |
Wrap up
Section titled “Wrap up”The decisions, and what each one costs
Section titled “The decisions, and what each one costs”| Decision | We chose | We gave up |
|---|---|---|
| Event | One unchanging LogRecord per call |
One object made per enabled call |
| Format and output | Formatter and Appender interfaces |
Formatting once per appender |
| Settings | A logger tree; level and appenders inherited | A walk up the tree per call (or a cache to update) |
| Passing records up | Chain of Responsibility with additivity | The duplicate-line trap |
| Switched-off calls | Placeholders, functions and isEnabled |
Small arrays, unless fixed versions exist |
| Slow disks | A background writer with a size limit, one thread | Lines in memory are lost on a hard crash |
| Full queue | Drop DEBUG and INFO and count them; WARN and ERROR wait | Some low-importance lines under heavy load |
| Shutdown | close empties the queue behind a stop marker |
A shutdown hook must be registered |
Go deeperGenuinely different designs, and when to pick them2 min
Log to the console, and let the platform handle the rest. In containers, a common approach is to write JSON lines to standard output and let the platform (Docker, Kubernetes, or a helper like Fluent Bit) handle files, rotation and shipping. The framework shrinks to levels, formatting and context, and the appender tree mostly disappears.
Garbage-free logging (Log4j 2). Reuse record objects and string builders from a ring, so a log call creates no new objects. It matters in systems where a garbage collection pause costs more than the log line is worth.
Structured events instead of sentences. Log event=payment_failed amount=42 reason=declined
as fields, not a sentence. Searches and dashboards work on fields, and the message template becomes
a label. OpenTelemetry’s log model goes this way, linking each record to the request trace it
belongs to.
How to spend 45 minutes
Section titled “How to spend 45 minutes”- 0 to 3. Outputs, formats, settings by package, background writing, can lines be lost.
- 3 to 5. The promises. Name “logging must never hurt the application” as the hard one.
- 5 to 25. The level check, then record, formatter and appender, then the logger tree with additivity (code it fully), then placeholders and functions.
- 25 to 27. Walk through the full diagram: whether, how and where, set on branches.
- 27 to 36. Mixed lines and slow disks, the background writer, the overflow policy, flushing on close.
- 36 to 45. One extension, usually request IDs or rotation, then your own questions.
If time is short, describe the JSON formatter in a sentence. Always code the logger tree and the walk up the parents. That’s the part that gets checked line by line.
Follow-up questions
Section titled “Follow-up questions”Every line from one HTTP request should carry its request ID, without passing it to every method.
Whether you know the context map idea (often called MDC), where it lives (per thread, or per async flow), and that the background writer needs it copied into the record, since the writer thread has a different context.
Most extensions fit into one place:
| Extension | What changes | Touches the logger? |
|---|---|---|
| Request IDs (context map) | A per-thread map, copied into each LogRecord when it’s made |
One field |
| File rotation | A RollingFileAppender: a new file by size or by day, old ones renamed |
No |
| Levels per appender | A threshold check in the appender, or a filter in front of it | No |
| Settings from a file | A loader that reads levels and appenders and calls the same setters | No |
| Sampling | A filter that passes 1 in N DEBUG records | No |
| Structured fields | log.info("paid", kv("amount", 42)); the record carries fields, JSON writes them |
The record |
Go deeperAdding request IDs, step by step2 min
We want every line written while handling one request to include that request’s ID, like
req=7f3a. Passing the ID into every method that logs would touch hundreds of methods. Instead,
we keep it somewhere the logger can find it.
- A context map per thread. It’s a small map of extra fields, like
{req: "7f3a"}. Each thread has its own, so two requests running at once don’t see each other’s ID. In Node and .NET, where one request can jump between threads, it’s kept per async flow instead (AsyncLocalStorage,AsyncLocal). - Set it at the start of the request, clear it at the end. A small piece of code at the front of the web layer puts the ID in, and takes it out when the request is done. Forgetting to clear it is a real bug: threads are reused, so the next request would log the old ID.
- Copy it into the record. When a
LogRecordis made, it takes a copy of the current map. This is the important step. With the background writer, the record is formatted later, on the writer thread, which has its own empty context. If the formatter read the context then, it would find nothing, or worse, another request’s ID. - The formatter writes the fields. The text formatter adds
req=7f3ato the line, and the JSON formatter adds a"req"field.
Only the record changed (one new field). The levels, the tree and the appenders didn’t notice.
Go deeperAdding file rotation, step by step2 min
A log file that only grows will fill the disk sooner or later. Rotation means starting a new
file now and then, and keeping only a few old ones. It’s a new appender, RollingFileAppender. No
other class changes.
It has two questions to answer, and each is a small interface of its own:
- When do we start a new file? That’s the trigger. A size trigger says “when the file passes 100 MB”. A time trigger says “at midnight”. The appender asks the trigger before each write: “should I roll now?”
- What happens to the old files? That’s the policy. A common one renames
app.logtoapp.2026-10-29.log, compresses it, and deletes files older than 14 days.
Rolling itself is four steps, done inside the appender: close the current file, rename it, open a
new empty app.log, then let the policy clean up older files.
Three details make it safe:
- Only one thread rolls. With the background writer, the real appender runs on one thread, so rolling needs no extra lock. Without it, rolling happens under the appender’s own lock, so no thread writes to a file that’s being renamed.
- Clean up away from the write. Compressing an old file can take seconds. Doing it on the writer thread would let the queue fill up. So the clean-up runs on its own small thread.
- Time comes from the clock we pass in. Then a test can move the clock past midnight and check that a new file was started, without waiting a day.
Notice what stayed the same. The formatter doesn’t know files rotate. The logger tree doesn’t know either. The new appender just goes where the old file appender was.
Go deeperThree more follow-up questions2 min
Interviewer asksHow would you change a level in production without a restart?
Make the registry’s setLevel available through an admin page or a watched settings file. Because
the real level is worked out from the tree (or pushed down on change), setting app.db to DEBUG
takes effect on the next call in every thread. Add a time limit, so a forgotten DEBUG setting goes
back after an hour, since debug logging in production is expensive.
Interviewer asksA log line contains a user's password. How do you stop that?
Stop it at the source with types: a Secret wrapper whose toString returns ***. Then add a
masking step in the formatter for known patterns (card numbers, tokens) as a safety net. Never
rely on masking alone: patterns miss things, and checking every line costs CPU.
Interviewer asksWhat was the Log4Shell vulnerability, in design terms?
Log4j 2 looked up ${...} expressions inside logged messages, including lookups that could load
code from another server. So logging user input (a header, a username) ran lookups the attacker
chose. The design lesson: a logger must treat the message as data and never interpret it. Our
placeholder filler only replaces {} in the template, never anything inside the values.
Further reading
Section titled “Further reading”- Chain of responsibility, Strategy pattern, Decorator pattern
- Thread safety basics, Observability
- Design a pub/sub system, which also fans events out to subscribers through a queue
- Logback manual: Architecture, the logger tree, effective levels and additivity
- Log4j 2: Asynchronous loggers, the ring buffer design
- The Twelve-Factor App: Logs, logs as an event stream on stdout
The designbeyondcode digest, every Saturday
New deep dives, interview tips and site news in one short email. Free. Leave with one click.
We never sell or share your email. We only use it to send this newsletter.