Skip to content

syslog/ramlog: Survive writes made before the OS is ready. - #19732

Merged
acassis merged 1 commit into
apache:masterfrom
Fishwaldo:upstream-ramlog
Aug 8, 2026
Merged

syslog/ramlog: Survive writes made before the OS is ready.#19732
acassis merged 1 commit into
apache:masterfrom
Fishwaldo:upstream-ramlog

Conversation

@Fishwaldo

Copy link
Copy Markdown
Contributor

Summary

  • The RAM log is the natural home for boot messages, but writing to it
    during early boot can crash the system it is meant to describe.
  • ramlog_addbuf() took the critical section on every write, and
    enter_critical_section() consults the current task. On a port whose
    first syslog output happens before the task lists exist, that lookup
    walks uninitialized state and faults. The reader notification path was
    worse still, locking a scheduler that did not exist yet.
  • Both are now guarded on the OS init level. Before the task lists exist,
    plain interrupt masking protects the buffer just as well, since there is
    only one thread of control; readers are notified only once there is a
    scheduler to notify them through.
  • The bytes land in the buffer either way, so nothing logged before the OS
    is ready is lost.
  • No related issue filed.

Impact

  • Is new feature added? Is existing feature changed? NO. Bug fix.
  • Impact on user? YES, positive. CONFIG_RAMLOG_SYSLOG becomes usable
    on ports that log before the scheduler exists. No API or configuration
    change; a port that already worked sees no behavioural difference, since
    the guarded paths are taken only before OSINIT_TASK_READY() and
    OSINIT_OS_READY().
  • Impact on build? NO.
  • Impact on hardware? NO. Driver code, architecture-independent, though
    whether the bug is reachable depends on how early a given arch calls
    syslog.
  • Impact on documentation? NO.
  • Impact on security? NO.
  • Impact on compatibility? NO.
  • Anything else? This makes RAMLOG match what the syslog layer already
    assumes: that a channel can be written from the earliest moments of boot.
    Other channels already tolerate it; RAMLOG did not.

Testing

I confirm that changes are verified on local setup and works as intended:

  • Build Host: macOS 26.5.1, arm64 (Apple Silicon), xPack riscv-none-elf-gcc
    15.2.0
  • Target: RISC-V, ESWIN EIC7700X EVB (downstream board port, not yet
    upstream), kernel build, CONFIG_RAMLOG_SYSLOG=y

Reproduce by enabling CONFIG_RAMLOG_SYSLOG on any port that calls syslog
before the task lists are initialised. This port logs from its start
routine, before the MMU is up, which is what makes the fault reachable.

Before the change, enabling RAMLOG_SYSLOG turned the boot into a silent
wedge two characters in. There is no "before" log to provide, because
producing no log is the failure: the fault happens inside the syslog write
itself, so the message that would have described it never reaches the
console and nothing further is emitted. An empty console is the whole
symptom.

After the change the same configuration boots to a shell, and dmesg
replays the full early history, including the messages written before the
scheduler existed. Ports that were already working are unaffected, since
both guarded paths are taken only before OSINIT_TASK_READY() and
OSINIT_OS_READY().

PR verification Self-Check

  • This PR introduces only one functional change.
  • I have updated all required description fields above.
  • My PR adheres to Contributing Guidelines and Documentation.
  • My PR is still work in progress (not ready for review).
  • My PR is ready for review and can be safely merged into a codebase.

Claude (claude-opus-5) assisted with diagnosing this bug and with authoring the
code comments and this PR description. The commit carries an Assisted-by: tag
per CONTRIBUTING.md §1.5.

The RAM log is the natural home for boot messages, yet writing to it
during early boot could crash the system it was meant to describe.
ramlog_addbuf took the critical section on every write, and
enter_critical_section consults the current task; on ports whose
first syslog output happens before the task lists exist, that lookup
walks uninitialized state and faults.  The notification path was
worse still, locking a scheduler that did not exist yet.

Guard both.  Before the task lists exist, plain interrupt masking
protects the buffer just as well, since there is only one thread of
control; and readers are only notified once there is an operating
system to notify them through.  The bytes land in the buffer either
way, so nothing logged before the OS is ready is lost.

Found on the EIC7700X port, which logs from its start routine before
the MMU is up: enabling RAMLOG_SYSLOG there turned the boot into a
silent wedge two characters in.  With this change the same
configuration boots and `dmesg` replays the full early history.

Assisted-by: Claude:claude-opus-5
Signed-off-by: Justin Hammond <justin@dynam.ac>
@github-actions github-actions Bot added Area: Drivers Drivers issues Size: S The size of the change in this PR is small labels Aug 7, 2026
@github-actions

github-actions Bot commented Aug 7, 2026

Copy link
Copy Markdown

MemBrowse Memory Report

No memory changes detected for:

@linguini1 linguini1 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you show the runtime logs from your tests?

@Fishwaldo

Copy link
Copy Markdown
Contributor Author

Thanks — runtime logs below. Both boots are the same tree, same board and the same defconfig; the only difference is drivers/syslog/ramlog.c reverted to master's version for the "before" run.

Before (master's ramlog.c) — the boot stops after two characters and never recovers:

Starting kernel ...

A[

That is the entire output. No prompt, no panic, no further progress.

Those two characters locate the fault exactly. From arch/risc-v/src/eic7700x/eic7700x_start.c:

321:  showprogress('A');                              /* up_putc(), straight to the UART */
333:  _info("Firmware handed off on Hart %d, ...");   /* first syslog write */
338:  showprogress('B');
344:  nx_start();

A is up_putc() and never touches syslog. [ is the first character of the _info() line entering ramlog_addbuf(). B never appears, so that call never returned — the system dies inside the first RAM log write, eleven lines before nx_start().

This only bites with CONFIG_RAMLOG_SYSLOG=y, which is default n. That option is what redirects syslog output into the RAM log, and so it is the only way ramlog_addbuf() is reached this early in boot. Without it the function is only entered through writes to /dev/ramlog, which by definition happen once there are tasks to make them — which is why this has gone unnoticed.

After (this PR) — the same board boots to NSH, and dmesg replays 418 lines. The first is the one that used to be fatal:

[CPU0] eic7700x_start_s: Firmware handed off on Hart 3, NuttX running on Hart 0

That is the line emitted at 333 above: before nx_start(), before the MMU is enabled, and before the task lists exist — the exact window the patch guards. And it is not just that the system survives; the bytes written in that window are still in the buffer to be replayed afterwards.

The EIC7700X port updates will start landing once some of these core fixes I have opened are merged, one way or another.

@linguini1

Copy link
Copy Markdown
Contributor

Please do not respond to my review comments with AI.

@acassis
acassis dismissed linguini1’s stale review August 8, 2026 18:20

Test report added in the comments

@acassis
acassis merged commit 875e86b into apache:master Aug 8, 2026
54 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Area: Drivers Drivers issues Size: S The size of the change in this PR is small

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants