Boot dies with "Kernel pid terminated (logger)" when a lazy module load races code_server init (registered before persistent_term is put)

[bruckner]

Describe the bug

During kernel start, code_server:init/4 registers the code_server name
as its first action but only stores its mode in persistent_term as its
last action, after the full code-path setup:

init(Ref, Parent, [Root,Mode]) ->
    register(?MODULE, self()),          % name visible immediately
    ...                                 % path scan — O(code path) work
    persistent_term:put(?MODULE, Mode), % term visible only here
    Parent ! {Ref,{ok,self()}},
    loop(State).

error_handler routes undefined-function resolution by whether the
code_server name resolves. Inside the init window (registered, term not
yet put), a lazy load therefore reaches code:ensure_loaded/1 →
code_server:get_mode() → persistent_term:get(code_server) → badarg.

When the process hitting that window is the logger kernel process
(started earlier by init as a kernelProcess), the badarg is raised inside
logger_backend:call_handlers/3 while logger is handling early kernel-
start work that touches not-yet-loaded stdlib modules (maps:without/2,
then sys:get_log/1, queue in our traces). logger dies, init halts:

Kernel pid terminated (logger) ({badarg,[
  {persistent_term,get,[code_server],...},
  {code_server,get_mode,0,[{file,"code_server.erl"},{line,84}]},
  {code,ensure_loaded,1,[{file,"code.erl"},{line,576}]},
  {error_handler,undefined_function,3,...},
  {logger_backend,call_handlers,3,[{file,"logger_backend.erl"},{line,53}]},
  {proc_lib,exit_p,3,...}]})

Whether the load lands in the window is scheduler timing. On our
1-vCPU cloud host (steal time present) the race flipped and stayed
flipped: the same release binaries that booted correctly for hours
began failing 100% of boots — every session shape, env -i, fresh
$HOME, multiple independent release copies — and the already-running
node was unaffected. -kernel logger_level none boots fine (the event
is filtered before delivery), which we used to bisect. The stable flip
turned out to be environmental: our deploy tooling always ran with an
unreadable cwd (root's home, after runuser to the service user),
which generates the trigger reports on every boot — see the
deterministic reproduction below.

Why vanilla erl doesn't hit it, and who does

The stock start_clean.script in an OTP install has three primLoad
phases and loads all kernel+stdlib modules before any kernelProcess
starts, so nothing lazy-loads during the window. Boot scripts generated
for Elixir (mix release) contain only the ~29-module bootstrap
primLoad (error_handler, code, code_server, logger*, proc_lib, ...)
— no maps, sys, queue, io_lib — and load applications lazily.
Every bin/<release> eval (how Elixir deployments run DB migrations)
boots that shape, so a loaded host can make deploy tooling fail
fleet-wide while the running app stays healthy. That is how we found it.

To Reproduce (deterministic)

The trigger is any early-boot logger event; a reliable, portable source
is an unreadable working directory — the interactive-mode code path
probes "." on every lazy module load, and an EACCES there makes
erl_prim_loader emit a file_error report. The script below builds a
bootstrap-only boot script (stock start_clean with only the first
primLoad kept — the shape mix release generates for every Elixir
release, so kernel/stdlib modules lazy-load during boot) and boots it
twice as an unprivileged user; only the cwd differs:

#!/bin/sh
# Reproduces the code_server-init / logger boot race.
# Run as root on Linux with Erlang/OTP installed. Uses only OTP.
set -e

ROOT=$(erl -noshell -eval 'io:format("~s",[code:root_dir()]),halt().')
cp "$ROOT"/releases/*/start_clean.script /tmp/mini.script

# Keep only the first (bootstrap) primLoad — the shape mix-release
# boot scripts have — so kernel/stdlib modules lazy-load during boot.
erl -noshell -eval '
  {ok,[{script,Info,Instrs}]} = file:consult("/tmp/mini.script"),
  {Out,_} = lists:foldl(
      fun({primLoad,L},{Acc,0}) -> {[{primLoad,L}|Acc],1};
         ({primLoad,_},{Acc,N}) -> {Acc,N};
         (I,{Acc,N})            -> {[I|Acc],N}
      end, {[],0}, Instrs),
  ok = file:write_file("/tmp/mini.script",
                       io_lib:format("~p.~n",[{script,Info,lists:reverse(Out)}])),
  ok = systools:script2boot("/tmp/mini"),
  halt().'
chmod 644 /tmp/mini.boot

echo "--- cwd unreadable by nobody (expect boot crash, exit != 0):"
cd /root
runuser -u nobody -- erl -boot /tmp/mini -noshell -eval 'erlang:halt(0).' \
  && echo "RESULT: booted (no repro)" || echo "RESULT: CRASHED exit=$?"

echo "--- cwd readable (expect clean boot, exit 0):"
cd /tmp
runuser -u nobody -- erl -boot /tmp/mini -noshell -eval 'erlang:halt(0).' \
  && echo "RESULT: booted" || echo "RESULT: CRASHED exit=$?"

Verified: crash/pass flips exactly with cwd readability on

• OTP 28 (erts 16.4), x86_64 Debian 13, kerl-built — 5/5 crash vs 5/5 pass
• OTP 27, arm64 Debian 13 container, Debian erlang-nox packages —
  same signature (line numbers shift with the version:
  code_server.erl:80, code.erl:558)

Crash output: exit 1, (no logger present) unexpected logger message ... <0.43.0> ... badarg persistent_term get code_server. <0.43.0>
is the registered logger process (confirmed via process_info in a
logger_level none boot; -kernel logger_level none also makes the
crashing variant boot, since the trigger event is filtered at source).

Without a deterministic trigger the same boot is a scheduler-timing
lottery — how we met it in production: a 1-vCPU cloud host flipped
stably between all-boots-pass (hours) and all-boots-fail on identical
binaries, because our deploy tooling always ran with cwd under /root
after runuser to the service user.

Diagnostic trail (error_handler instrumented with erlang:display of
each undef MFA) immediately before death:

{undef_mfa,os,internal_init_cmd_shell,0}
{undef_mfa,peer,supervision_child_spec,0}
{undef_mfa,beam_lib,module_info,1}
{undef_mfa,binary,module_info,1}
{undef_mfa,gb_sets,module_info,1}
{undef_mfa,gb_trees,module_info,1}
{undef_mfa,unicode,module_info,1}
{undef_mfa,erl_features,enabled,0}
{undef_mfa,maps,without,2}
{undef_mfa,sys,get_log,1}
{undef_mfa,maps,without,2}     <- lands in the window, badarg, logger dies

Crash dump available (from a logger_level none-adjacent failing run,
written via ERL_CRASH_DUMP): shows kernel_sup blocked in
code_server:start_link/1 and code_server waiting in
init:request/1 — i.e. code_server mid-init at time of death.
Happy to share privately per the wiki's core-dump guidance.

Expected behavior

A lazy load during code_server's init should block (or fall back to the
init loader) rather than crash the caller; boot should not be able to
kill the logger kernel process through this path.

Affected versions

Confirmed on OTP 28 (erts 16.4, kernel 10.6.3, kerl build, x86_64) and
OTP 27 (Debian arm64 packages). The same init ordering exists on
maint-28 and master (lib/kernel/src/code_server.erl).

Suggested fix

Make the persistent term visible no later than the registered name —
mode is an init argument, so it can simply move first:

 init(Ref, Parent, [Root,Mode]) ->
+    persistent_term:put(?MODULE, Mode),
     register(?MODULE, self()),
     ...
-    persistent_term:put(?MODULE, Mode),
     Parent ! {Ref,{ok,self()}},

Callers that reach code:ensure_loaded/1 in the window then block in
the gen call until loop/1 starts serving, which is the pre-existing
semantics for calls arriving just after init completes. (Belt and
braces: error_handler could also catch this badarg and fall back to
its init-loader path.)

Downstream mitigation we deployed (works, verified 3/3 on the affected
host): extend primLoad in generated boot scripts with the modules the
early logger path can touch — maps sys queue binary gb_sets gb_trees
beam_lib os io io_lib io_lib_format io_lib_pretty unicode string
calendar proplists gen_statem logger_olp logger_proxy logger_h_common
logger_std_h logger_formatter erl_features. The Elixir project may want
this in mix release's script generation regardless.

[josevalim]

FWIW, I cannot get Elixir to generate the faulty script files mentioned above.

However, I believe there is a bug here indeed and it is related to interactive mode. In interactive mode, any primLoad after {kernel_load_completed} is ignored, which will cause stdlib to lazy load. Then, because we don't have permission to access the . directory (user nobody), erl_prim_loader is going to fail and call the logger:

otp/erts/preloaded/src/erl_prim_loader.erl

Line 458 in 9c28888

logger ! {log,error,#{label=>{?MODULE,file_error},report=>Report},

Logger will attempt to use modules which are not available which will cause the error_handler to be invoked:

otp/lib/kernel/src/error_handler.erl

Line 195 in 9c28888

code:ensure_loaded(Module);

Which will fail on the persistent term lookup here:

https://github.com/erlang/otp/blob/master/lib/kernel/src/code.erl#L585

So part of the root cause analysis was wrong, but I believe the bug is indeed there and the fix is correct.

[bruckner]

You're right, and thank you for the correction — I've now verified both
halves of your analysis empirically.

My codegen claim was wrong. Re-inspecting the exact release that
failed in production: its start_clean.script contains 67
primLoad blocks — the full kernel set (85 modules, logger_std_h
included), full stdlib (maps, sys, queue included), then every
app. My "only the bootstrap primLoad" statement came from an inspection
error on my side (I examined only the first block, and -init_debug
doesn't echo the instructions it skips — which turned out to be the
actual clue).

Your interactive-mode explanation checks out with a much simpler
reproduction. Since init ignores primLoad after
{kernel_load_completed} in interactive mode, stock erl should be
exposed too — and it is. On a fresh debian:13 container with Debian's
OTP 27 packages, no custom boot script at all:

cd /root && runuser -u nobody -- erl -noshell -eval 'erlang:halt(0).'  # crash
cd /tmp  && runuser -u nobody -- erl -noshell -eval 'erlang:halt(0).'  # boots

Same slogan as reported. So please disregard the boot-script-stripping
step in my reproduction and the "why vanilla erl doesn't hit it"
section — the exposure is any interactive-mode boot where an early-boot
event reaches the logger during code_server init, and the
erl_prim_loader EACCES report for the "." path entry is simply a
reliable event source.

One practical footnote for anyone who lands here needing a workaround
before a patch release: extending the first primLoad (before
{kernel_load_completed}) with the modules the logger path touches
does work, precisely because that's the only block interactive mode
honors.