Skip to content

Boot Log

Jump to bottom
opencode-agent[bot] edited this page Sep 6, 2026 · 3 revisions

Boot Log

JNode's logging system: pre-log4j boot logging, Log4j runtime configuration, and serial debug output.

Overview

JNode has a multi-layered logging system that operates from the earliest boot stages through full runtime. Understanding the layers is critical for debugging boot crashes, driver issues, and network problems.

Layer Mechanism When Active Output Target
Assembly KDB kdb_send_char in kdb.asm Earliest boot → forever VGA + COM1 (if kdb flag)
BootLog BootLogImpl After InitialNaming → forever F7 console / Unsafe.debug()
Log4j Log4jConfigurePlugin Plugin startup → forever F7 console + active screen + serial (if lkd flag)

Boot Flags

Two kernel command-line flags control serial output:

Flag Purpose Enables
kdb Assembly-level kernel debugger serial I/O All Unsafe.debug() output + every VGA character to COM1
lkd Log4j serial appender SerialAppender on root logger — all Log4j messages to COM1

GRUB config (all/conf/x86/menu-cdrom.lst):

serial --unit=0 --speed=115200 --word=8 --parity=no --stop=1
kernel /jnode32.gz mp=no kdb lkd

Phase 1: Assembly KDB (Earliest Boot)

File: core/src/native/x86/kdb.asm

Before Java is initialized, the assembly kernel debugger provides serial I/O:

  • kdb_init reads BIOS Data Area at 0x400 to detect COM1 port address
  • Enables RTS and DTR via Modem Control Register
  • Scans multiboot command line for kdb — if found, sets kdb_enabled flag
  • kdb_send_char waits for THR Empty (LSR bit 5), writes character to data register

Integration with VGA console (console.asm:149):

sys_do_print_char:
    ; ... write to VGA screen memory ...
    call kdb_send_char    ; simultaneously send to serial

Every character printed to VGA (via PRINT_STR, PRINT_INT, Unsafe.debug()) is simultaneously sent to COM1 when kdb is enabled. This is how early boot messages appear in serial logs.

Baud rate: Inherited from BIOS/GRUB settings (typically 9600 or 115200 depending on GRUB's serial --speed= directive).

Phase 2: BootLog (Pre-Log4j)

Files: core/src/core/org/jnode/bootlog/BootLog.java, core/src/core/org/jnode/vm/BootLogImpl.java

After InitialNaming is set up, BootLogImpl.initialize() registers a lightweight logger:

VmSystem.initialize()
  └─> InitialNaming.setNameSpace(new DefaultNameSpace())
  └─> BootLogImpl.initialize()
       └─> BootLogInstance.set(new BootLogImpl())

Timestamp Prefix

BootLogImpl formats timestamps using kernel uptime (VmSystem.currentKernelMillis()) rather than wall-clock time (VmSystem.currentTimeMillis()). This avoids an epoch-hours glitch where lines written after the RTC service starts would print absurd timestamps (e.g., 496697:28:26,317). The kernel uptime counter is monotonically increasing from boot and always correct.

Logging Levels

Level Constant Output Target
DEBUG 1 debugOut PrintStream (if set) or Unsafe.debug()
INFO 2 System.out
WARN 3 System.out
ERROR 4 System.err
FATAL 5 System.err

Fallback Behavior

If debugOut is null (before Log4jConfigurePlugin sets it), BootLogImpl.debug() falls back to Unsafe.debug() which goes to serial via KDB:

private void log(int level, PrintStream ps, String levelStr, String msg, Throwable ex) {
    if (ps != null) {
        writePrefix(ps, levelStr);
        ps.println(msg);
    } else {
        writePrefixUnsafe(levelStr);
        Unsafe.debug(msg);
        Unsafe.debug("\n");
    }
}

Gotchas

  • No level filtering — All debug(), info(), warn(), error(), fatal() calls print unconditionally
  • No category separation — Single global logger, no per-package filtering
  • setDebugOut() only affects DEBUG — Other levels use System.out/System.err directly

Phase 3: Log4j (Runtime)

File: core/src/core/org/jnode/log4j/config/Log4jConfigurePlugin.java

Log4jConfigurePlugin is a JNode plugin that completely replaces the logging configuration at runtime.

Appenders Created

Appender Threshold Target Purpose
debugApp DEBUG F7 "Log4j" console (hidden) Captures all messages for debugging
infoApp INFO Active/visible screen User-visible output
serialApp DEBUG COM1 UART (if lkd flag) Serial debug output
UnsafeDebugAppender DEBUG Unsafe.debug() (fallback) Used if SerialAppender fails

Root Logger Level

The root logger is set to INFO by default:

root.setLevel(Level.INFO);

This means:

  • INFO, WARN, ERROR, FATAL messages are processed by all appenders
  • DEBUG messages are filtered at the logger level — they never reach appenders
  • Exception: loggers with explicit levels (e.g., set via log4j --setLevel) override this

SerialAppender

File: core/src/core/org/jnode/log4j/config/SerialAppender.java

When the lkd boot flag is present, SerialAppender writes to COM1 via SerialPortDriver's API:

  • Port: serial0 (COM1, 0x3F8)
  • Data format: 8N1
  • Conversion: \n → \r\n
  • Lazy initialization: The serial port device may not be available when this appender is created (plugins start before device finders). SerialWriter.init() uses DeviceUtils.getAPI() to acquire SerialPortAPI, and buffers pending output (up to 8KB) until the device becomes available. Once the device is acquired, buffered data is drained before new writes go direct.
  • Fallback: If SerialAppender fails to acquire the device after retries, falls back to UnsafeDebugAppender which routes through Unsafe.debug() (VGA + serial at assembly level).

Runtime Control

The log4j shell command provides runtime control:

# List all loggers and their effective levels
log4j --list

# Set root logger level (systemwide)
log4j --setLevel DEBUG       # enable debug everywhere
log4j --setLevel INFO        # back to default

# Set specific logger level
log4j --setLevel DEBUG org.jnode.driver.bus.ide
log4j --setLevel WARN org.jnode.driver.net.eepro100

# Load configuration from file
log4j /path/to/log4j.properties

What Appears on Serial

Scenario What's on COM1
Boot with kdb lkd Assembly boot messages + all Log4j INFO+ messages
log4j --setLevel DEBUG pkg Assembly boot + Log4j INFO+ + DEBUG from that package
log4j --setLevel DEBUG Assembly boot + all Log4j DEBUG+ messages

Key Components

Component File Purpose
BootLog core/src/core/org/jnode/bootlog/BootLog.java Interface defining logging methods
BootLogInstance core/src/core/org/jnode/bootlog/BootLogInstance.java Singleton accessor
BootLogImpl core/src/core/org/jnode/vm/BootLogImpl.java Default implementation
Log4jConfigurePlugin core/src/core/org/jnode/log4j/config/Log4jConfigurePlugin.java Runtime Log4j setup
SerialAppender core/src/core/org/jnode/log4j/config/SerialAppender.java Log4j appender for COM1 UART
VirtualConsoleAppender core/src/core/org/jnode/log4j/config/VirtualConsoleAppender.java Log4j appender for VGA consoles
UnsafeDebugAppender core/src/core/org/jnode/log4j/config/UnsafeDebugAppender.java Fallback appender via Unsafe.debug()
kdb.asm core/src/native/x86/kdb.asm Assembly KDB serial I/O
console.asm core/src/native/x86/console.asm VGA console + KDB integration
Log4jCommand cli/src/commands/org/jnode/command/system/Log4jCommand.java Shell command for log4j control

Usage Patterns

Early Boot (BootLog)

BootLogInstance.get().debug("Found " + extensions.length + " device finders");
BootLogInstance.get().warn("Ignoring unrecognised descriptor element: " + elementName);
BootLogInstance.get().error("Cannot find finder class " + className, ex);

Runtime (Log4j)

private static final Logger log = Logger.getLogger(MyClass.class);

log.debug("Detailed state: " + state);      // only if DEBUG enabled for this package
log.info("Processing started");              // always visible (INFO+)
log.error("Failed to initialize", ex);       // always visible

Debugging a Driver

# Enable debug for IDE driver
log4j --setLevel DEBUG org.jnode.driver.bus.ide

# Check what loggers exist
log4j --list

# Reset to default
log4j --setLevel INFO

Serial Port Configuration Summary

Component Port Baud Rate Configured By
GRUB serial console COM1 115200 serial --unit=0 --speed=115200 in GRUB config
KDB assembly COM1 Inherited from BIOS/GRUB kdb_init in kdb.asm
SerialAppender COM1 (serial0) 9600 default Via SerialPortDriver API
SerialPortDriver COM1-COM4 9600 default SerialPortDriver.java
SerialConsolePlugin COM2 115200 SerialConsolePlugin.java

Note: There is a baud rate mismatch between GRUB (115200), KDB (inherited), and SerialAppender (9600). If capturing serial at 115200, KDB output will be readable but SerialAppender output may be garbled. The SerialAppender now uses the device API (SerialPortAPI) rather than directly programming UART registers, so the baud rate is inherited from the SerialPortDriver's default.

Gotchas

  • Early boot DEBUG messages — Lines from assembly KDB before Log4jConfigurePlugin loads cannot be filtered by log4j. They always appear when kdb flag is set.
  • Per-sector logging — IDEReadSectorsCommand and IDEWriteSectorsCommand log debug messages for every sector. A 1MB read produces 512 debug messages.
  • Per-packet logging — EEPRO100Buffer logs debug messages for every transmitted packet.
  • Hardcoded DEBUG levels — Some classes (e.g., AbstractFontProvider, BDFFontContainer) previously hardcoded log.setLevel(Level.DEBUG), bypassing root logger settings. These have been removed.
  • Single serial client — The serial pipe (/tmp/jnode.serial2) supports only one client at a time.
  • Socket not recreated — If you delete the serial socket while VM is running, VirtualBox does not recreate it. Restart the VM.
  • System.out routed to loggers — DefaultAliasManager and DefaultSyntaxManager now log refresh messages at DEBUG level via Log4j instead of printing to System.out. This prevents shell initialization chatter from appearing on the active screen.
  • Compiler warnings via BootLog — X86BytecodeVisitor and X86StackFrame now report unbalanced item-factory warnings and negative slot counts via BootLogInstance instead of System.out, ensuring these diagnostics appear in the serial log.

Related Pages

Home | index

Architecture

Subsystems

Development

Reference

Clone this wiki locally