Principle:Vespa engine Vespa Log Rotation and Special Handling
Log Rotation and Special Handling
Overview
Log rotation and special handling manages the lifecycle of log output streams in Vespa's logging framework. On each publish() call, the handler reopens the log target (enabling external log rotation), applies level control and reject filtering, then writes and flushes the formatted message. Special handling includes ZooKeeper log separation, noisy logger level reduction, and emergency fallback to stderr when the primary log target fails.
Motivation
In long-running server processes, log files grow continuously and must be rotated to prevent disk exhaustion. Vespa uses external log rotation (typically via logrotate or Vespa's own log rotation mechanism) where an external tool renames the current log file and expects the application to start writing to a new file.
This approach requires the logging handler to cooperate by:
- Reopening the log target on each write: If the file has been renamed, the next open creates a new file at the original path.
- Flushing after each write: Ensuring that log data is not buffered across multiple records, which would cause data loss if the process crashes.
- Closing file handles promptly: Preventing accumulation of open file descriptors.
Additionally, certain log sources (such as ZooKeeper client libraries) produce output that should be separated from the main log stream, and the handler must handle target failures gracefully without losing log data.
Reopen-On-Write Pattern
The core of Vespa's log rotation support is the reopen-on-write pattern:
For each log record:
1. Open the log target (file, fd, etc.)
2. Write the formatted log record
3. Flush the output stream
4. Close the file target (if applicable)
This pattern means that if an external tool renames the log file between two log records, the next open() call creates a new file at the original path. The process never holds a long-lived file handle to the log file.
For file descriptor targets (like fd:2 for stderr), the close step is skipped because file descriptors should not be closed by the logging handler.
Level Control in the Publish Path
Every publish() call performs two types of filtering before writing:
1. Level Control
LevelController ctrl = getLevelControl(loggerName);
if (!ctrl.shouldLog(level)) { return; }
The level controller check is the first gate in the publish path. If the level is disabled (either by default configuration or by runtime vespa-logctl changes), the method returns immediately without any formatting or I/O.
2. Reject Filtering
if (logRejectFilter.shouldReject(record.getMessage())) { return; }
The reject filter is a content-based filter that drops messages matching known-useless patterns. This provides a second layer of noise reduction beyond level control, targeting specific message text rather than log levels.
Level Reduction for Noisy Loggers
Before the level control check, the handler applies a level reduction step:
Level level = possiblyReduceLogLevel(loggerName, record.getLevel());
This step remaps log levels for specific noisy third-party loggers:
| Logger Prefix | Original Level | Reduced To | Rationale |
|---|---|---|---|
org.eclipse.jetty |
INFO | DEBUG | Jetty produces verbose operational messages at INFO |
org.apache.aries.spifly |
INFO | DEBUG | SPI-Fly produces verbose messages during service loading |
Since DEBUG is off by default, this effectively silences these loggers without completely suppressing them. An operator can still see their output by enabling DEBUG via vespa-logctl.
Emergency Fallback
If the log target fails to open (e.g., due to a full disk or permission error), the handler falls back to stderr:
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 emergency fallback ensures that:
- The failure itself is logged (via
emergencyLog()) - The original log record is still written (to stderr instead of the file)
- The process does not crash due to a logging infrastructure failure
ZooKeeper Log Separation
Vespa uses a ZooKeeperFilter to separate ZooKeeper client library log output from the main application log stream. ZooKeeper's client library uses JUL internally and can produce high volumes of log output during connection state changes, session events, and watch callbacks.
The filter intercepts log records from ZooKeeper-related loggers and redirects them to a separate log target, preventing ZooKeeper noise from overwhelming the main application log.
Synchronization
The publish() method is declared synchronized, ensuring that:
- Multiple threads cannot interleave log output within a single record
- The open-write-flush-close cycle is atomic with respect to concurrent log calls
- Level control state is consistently read (though the memory-mapped level byte is inherently atomic)
The synchronization scope covers the entire publish path, from level checking through writing and closing. While this creates a potential bottleneck under extreme logging load, it guarantees log line integrity.
Flush Semantics
After each record is written, the handler calls flush() to ensure the data is committed to the output stream:
super.publish(record);
flush();
closeFileTarget();
This means:
- No buffering: Each log record is independently flushed, so a process crash loses at most the record currently being written.
- Performance trade-off: Per-record flushing is slower than buffered writing, but log reliability is prioritized over throughput.
- External visibility: Log monitoring tools (e.g.,
tail -f) see records immediately after they are written.
Design Constraints
- Per-record open/close for files: File-based log targets are opened and closed on each publish call. This is necessary for external rotation support but adds syscall overhead per record.
- Synchronized publish: The method is synchronized, creating a single-threaded bottleneck for log writes. This is acceptable because logging should not be on the critical path.
- No internal rotation: Vespa does not implement its own log rotation. It relies on external tools to rename log files and trusts the reopen-on-write pattern to handle the transition.
- Emergency fallback is sticky: Once the handler falls back to stderr, it attempts to reopen the original target on the next call. If the target remains unavailable, it continues falling back to stderr.
Interaction with Other Components
- Logger Handler Installation: Configures the handler that implements the publish path.
- Log Message Formatting: The
VespaFormatterproduces the formatted string written during publish. - Runtime Level Control: The
shouldLog()check in the publish path reads the memory-mapped level control byte. - Log Target and Level Configuration: Provides the log target that is opened on each publish call.