Implementation:Vespa engine Vespa VespaLogHandler Publish

VespaLogHandler.publish

Logging Observability

API Signature

public synchronized void publish(LogRecord record)

Source Location

• File: vespalog/src/main/java/com/yahoo/log/VespaLogHandler.java
• Lines: L64-90
• Class: class VespaLogHandler extends StreamHandler
• Package: com.yahoo.log

Description

The publish method is the hot path of Vespa's logging framework. It is called for every log record produced by any JUL logger in the process. The method applies level reduction, level control, reject filtering, and then opens the log target, writes the formatted record, flushes, and closes the file target. The method is synchronized to prevent interleaved output from concurrent threads.

Parameters

Parameter	Type	Description
record	LogRecord	The JUL log record to publish. Contains the level, logger name, message, thread ID, timestamp, optional thrown exception, and optional parameters.

Return Value

void -- The record is either written to the log target or silently dropped (if filtered out by level control or reject filter).

Full Method Source

public synchronized void publish(LogRecord record) {
    String loggerName = record.getLoggerName();

    Level level = possiblyReduceLogLevel(loggerName, record.getLevel());

    LevelController ctrl = getLevelControl(loggerName);
    if (!ctrl.shouldLog(level)) { return; }

    if (logRejectFilter.shouldReject(record.getMessage())) { return; }

    try {
        setOutputStream(logTarget.open());
    } catch (RuntimeException e) {
        LogRecord r = new LogRecord(Level.SEVERE, "Unable to open file target");
        r.setThrown(e);
        emergencyLog(r);
        setOutputStream(System.err);
    }

    super.publish(record);
    flush();
    closeFileTarget();
}

Step-by-Step Execution Flow

Step 1: Extract Logger Name

String loggerName = record.getLoggerName();

The logger name is the JUL logger name (e.g., "com.yahoo.search.handler.SearchHandler"). It is used for both level reduction and level control lookups.

Step 2: Apply Level Reduction

Level level = possiblyReduceLogLevel(loggerName, record.getLevel());

For certain noisy third-party loggers, the effective level is reduced. For example, Jetty INFO messages are treated as DEBUG. The possiblyReduceLogLevel() method checks if the logger name matches any prefix in the level reduction map. If it matches, the level is lowered; otherwise, the original level is returned unchanged.

This reduced level is used for the shouldLog() check but does not modify the LogRecord itself. The original level is preserved in the record for formatting purposes.

Step 3: Check Level Control

LevelController ctrl = getLevelControl(loggerName);
if (!ctrl.shouldLog(level)) { return; }

The level controller for the logger's component is retrieved from the LevelControllerRepo. The shouldLog() method reads a single byte from the memory-mapped control file to determine if the (possibly reduced) level is enabled.

If the level is disabled, the method returns immediately without performing any formatting, I/O, or synchronization beyond the method-level lock. This is the fast path for disabled levels.

Step 4: Apply Reject Filter

if (logRejectFilter.shouldReject(record.getMessage())) { return; }

Even if the level is enabled, the reject filter can drop messages that match known-useless patterns. This is a content-based filter that examines the actual message text. If the message is rejected, the method returns without writing anything.

Step 5: Open Log Target

try {
    setOutputStream(logTarget.open());
} catch (RuntimeException e) {
    LogRecord r = new LogRecord(Level.SEVERE, "Unable to open file target");
    r.setThrown(e);
    emergencyLog(r);
    setOutputStream(System.err);
}

The log target is opened on every publish call. This is the key mechanism that enables external log rotation:

• For file targets: open() opens the file at the configured path. If an external tool has renamed the file since the last call, the new open() creates a fresh file at the original path.
• For file descriptor targets (e.g., fd:2): open() returns the same file descriptor each time.

If the open fails (e.g., disk full, permission denied), the handler:

1. Creates a SEVERE log record describing the failure
2. Logs it via emergencyLog() (which writes to stderr)
3. Falls back to using System.err as the output stream

This ensures the original log record is still written (to stderr) even when the primary target is unavailable.

Step 6: Write the Record

super.publish(record);

Delegates to StreamHandler.publish(), which:

1. Calls the VespaFormatter.format(record) method to produce the tab-delimited log line
2. Writes the formatted string to the output stream set in Step 5

Step 7: Flush

flush();

Immediately flushes the output stream to ensure the record is committed to the underlying file or file descriptor. This guarantees that:

• Log monitoring tools see the record immediately
• A process crash loses at most the record currently being written

Step 8: Close File Target

closeFileTarget();

For file-based targets, the file is closed after each write. This:

• Releases the file descriptor
• Ensures the file can be rotated by external tools
• Prevents accumulation of open file handles

For file descriptor targets (fd:2, etc.), this is a no-op since the handler should not close shared file descriptors.

Synchronization Details

The method is declared synchronized, which means:

• Thread safety: Only one thread can execute publish() at a time, preventing interleaved output.
• Atomicity: The open-write-flush-close cycle is atomic with respect to other log calls.
• Bottleneck risk: Under extreme logging load, threads will contend on the monitor. However, logging should not be on the critical path of request processing.

Error Recovery

The error recovery strategy is designed for robustness over correctness:

• If the log target fails, output goes to stderr rather than being lost.
• The next publish() call will attempt to reopen the original target. If the underlying issue is resolved (e.g., disk space freed), normal operation resumes automatically.
• The emergency log record documents the failure for post-mortem analysis.

Performance Characteristics

Scenario	Operations	Cost
Level disabled	Memory read + return	Nanoseconds (fast path)
Message rejected	Memory read + string match + return	Microseconds
Normal write (fd target)	Format + write + flush	Tens of microseconds
Normal write (file target)	Open + format + write + flush + close	Hundreds of microseconds

The fast path (disabled level) is the most common case in production, where only a small fraction of log calls actually produce output.

Usage Context

This method is never called directly by application code. It is invoked by the JUL framework when any logger produces a log record:

// Application code:
Logger logger = Logger.getLogger("com.yahoo.search.handler");
logger.info("Query completed in 42ms");

// JUL framework internally calls:
// vespaLogHandler.publish(logRecord);

Implements Principle

Log Rotation and Special Handling

Related Implementations

• VespaLogHandler Constructor -- Constructs the handler and its dependencies
• VespaFormatter.format -- Formats the log record into the tab-delimited output
• vespa-logctl -- Modifies the level control bytes that shouldLog() reads
• VespaLevelControllerRepo Constructor -- Creates the level controller repo used by getLevelControl()

Related Pages

• Principle:Vespa_engine_Vespa_Log_Rotation_and_Special_Handling
• Heuristic:Vespa_engine_Vespa_Log_Level_Inheritance_Polling