pillar: libzfs ASSERT in namespace_reload() aborts zedbox via cgo, device reboots with no panic trail

[eriknordmark]

Describe the bug

On a ZFS-persist EVE-k device, zedbox was killed by abort() raised from an
assertion inside libzfs, reached through cgo from zfsmanager's periodic
storage-metrics collection. Losing zedbox takes every pillar agent with it, the
watchdog then finds /run/zedbox.pid pointing at a dead process, and the device
reboots — reporting BootReasonWatchdogPid.

The failure leaves none of the usual evidence a pillar crash leaves, which is
what makes it worth a dedicated issue: a C ASSERT raises SIGABRT before any Go
panic machinery runs, so there is no panic: line, no level=fatal, an empty
/persist/newlog/panicStacks, and an empty /persist/reboot-stack. Searching for
those (the natural first sweep) returns clean and the reboot looks unexplained.
The evidence is on stderr, which newlog carries under source: "pillar".

Recent release

Seen once on 0.0.0-rucoder_kube-init-go-620171de-k-amd64, a fork build. The
relevant code is unmodified with respect to master (checked at
38e378177): the call path, the locking, and the go-libzfs pin
(github.com/andrewd-zededa/go-libzfs v0.0.0-20251014191158-755aaeb96a92) are
identical, so master is expected to be equally exposed. Not yet reproduced on a
release build.

Duplicate

Searched the issue list for namespace_reload, libzfs, zfsIterLock,
PoolOpenAll, SIGABRT zfs — no existing issue.

How to reproduce

No deterministic reproducer. Observed once in ~4 days of continuous
test traffic on one device; the same assertion appears in zero of the four other
device-log windows captured from that run.

• EVE-OS version: 0.0.0-rucoder_kube-init-go-620171de-k-amd64 (EVE-k, k3s +
  KubeVirt + Longhorn), /persist on ZFS
• Architecture: amd64
• Conditions: 1-core box under sustained app create/destroy load, load average
  around 8 when idle and observed above 27 under test

Expected behavior

zedbox does not die because a metrics collector called into libzfs. Worst case a
metrics cycle fails and logs an error.

Error message

Device time 2026-08-10T02:31:10 UTC, newlog source: "pillar":

ASSERT at lib/libzfs/libzfs_config.c:190:namespace_reload()
uu_avl_find(hdl->libzfs_ns_avl, cn, NULL, &where) == NULL
  PID: 4280      COMM: zedbox
  TID: 6341      NAME: zedbox
SIGABRT: abort
PC=0x7f07114e1c2f m=13 sigcode=18446744073709551610
signal arrived during cgo execution

goroutine 4490 gp=0xc002b81500 m=13 mp=0xc0005f4808 [syscall]:
runtime.cgocall(0x59455e5, 0xc002d9b720)
        /usr/local/go/src/runtime/cgocall.go:167 +0x4b
github.com/andrewd-zededa/go-libzfs._Cfunc_zpool_list_openall()
        _cgo_gotypes.go:1753 +0x45
github.com/andrewd-zededa/go-libzfs.PoolOpenAll()
        /pillar/vendor/github.com/andrewd-zededa/go-libzfs/zpool.go:465 +0x34
github.com/lf-edge/eve/pkg/pillar/cmd/zfsmanager.collectAndPublishStorageMetrics(0xc000c2cc80)
        /pillar/cmd/zfsmanager/zfsstoragemetrics.go:39 +0xbc
github.com/lf-edge/eve/pkg/pillar/cmd/zfsmanager.storageMetricsPublisher(0xc000c2cc80)
        /pillar/cmd/zfsmanager/zfsstoragemetrics.go:30 +0x56
github.com/lf-edge/eve/pkg/pillar/cmd/zfsmanager.Run.gowrap4()
        /pillar/cmd/zfsmanager/zfsmanager.go:213 +0x25

The last log record from pid 4280 is collectAndPublishStorageMetrics start at
02:31:10.552 — the abort is 144 ms later, inside the call it had just announced.
The rest follows mechanically:

02:32:02+  watchdog  pinging process 4280 (/run/zedbox.pid) gave errno = 3 = 'No such process'
02:32:12   watchdog  Retry timed-out at 61 seconds for /run/zedbox.pid → runs the repair binary
02:33:12   watchdog  repair child 30942 timed out
02:33:12   watchdog  shutting down the system because of error 255 = 'unconditional reboot requested'

(Note for anyone correlating: the timestamp in the reported reboot reason is when
the repair binary was launched, ~60 s before the machine actually went down.)

Additional context

Why the assertion may be firing — libzfs handle use is only partially
serialized. libzfs is not thread-safe, and the namespace_reload() AVL
assertion is the classic symptom of one handle being used from more than one
thread. In pillar the serialization covers only part of the callers (line numbers
at 38e378177):

• zfsIterLock is declared at pkg/pillar/cmd/zfsmanager/zfsmanager.go:58 and
  taken at exactly two call sites, both inside zfsmanager —
  zfsstoragemetrics.go:37 and zfsstoragestatus.go:37.
• pkg/pillar/zfs/zfs.go — the shared helper used from other agents —
  contains no mutex at all and calls libzfs.DatasetOpen directly (e.g.
  GetDatasetUsageStat).
• pkg/pillar/cmd/zfsmanager/handlediskconfig.go calls libzfs.PoolOpen
  without taking the lock either.
• pkg/pillar/vault/handler_zfs.go is a further go-libzfs user.

Concretely, volumemgr reaches libzfs on every metrics cycle: on a ZFS-persist
device diskmetrics.PersistUsageStat routes /persist to
zfs.GetDatasetUsageStat(types.PersistDataset), from
createOrUpdateDiskMetrics. So at least two goroutines in the one zedbox process
call libzfs with no lock in common.

This is a hypothesis, not a demonstrated interleaving. Only one goroutine is
inside libzfs in the abort traceback, and volumemgr's metrics pass had logged its
last path 1.0 s earlier rather than concurrently. The assertion fires when
namespace_reload rebuilds a namespace AVL that is already inconsistent, so a
corrupting access that had already returned is compatible with the evidence — but
so is a fault with no concurrency in it. The missing lock is offered as the
leading suspect and as an audit worth doing on its own merits.

Impact. A single unlucky metrics cycle costs a full device reboot with no
diagnostic trail, and every application on the node goes down with it. In this
run it also cost two test verdicts as collateral.

Suggested next steps (happy to be redirected):

1. Audit every go-libzfs caller in pillar and put them behind one shared lock,
   rather than a lock private to zfsmanager's context.
2. Consider whether namespace_reload's assertion should be reachable from a
   metrics path at all, or whether pool enumeration for metrics can use a cached
   handle / a single owning goroutine.
3. Independently of the cause: a C-level abort in a cgo dependency should not be
   invisible. Nothing writes panicStacks on SIGABRT, so consider capturing
   the stderr traceback the way Go panics are captured, so the next occurrence is
   diagnosable without knowing to grep source: "pillar".

[eriknordmark]

Traced the mechanism through libzfs and the go binding, at 38e378177 and ZFS tag
zfs-2.3.6 (the version pkg/dom0-ztools/Dockerfile:14 builds).

Only two call sites can reach the assertion. namespace_reload() is static in
lib/libzfs/libzfs_config.c with two callers, zpool_iter() (:382) and
zfs_iter_root() (:421), so the only go-libzfs entry points that touch the
pool-namespace AVL are PoolOpenAll() and DatasetOpenAll(). That rules out a
duplicate name from the kernel (spa_all_configs() builds the nvlist with
fnvlist_alloc(), spa_config.c:383 → NV_UNIQUE_NAME, over unique spa_namespace
names, and the AVL is fully torn down at libzfs_config.c:169-174), and it also rules
out zfs.GetDatasetUsageStat as the second thread — that is DatasetOpen → zfs_open,
which cannot reach namespace_reload.

The unlocked reload caller is in the same volumemgr function as the
PersistUsageStat call: handlediskmetrics.go:297 GetAllDataSets() →
zvolhandler.go:44 → zfs/zfs.go:1052 libzfs.DatasetOpenAll(), with no lock anywhere,
once per disk-metrics pass (flextimer at 0.3–1.0× timer.metric.diskscan.interval,
default 300 s). zfsmanager's PoolOpenAll runs every 5 s and 30 s under zfsIterLock.
Two goroutines, one handle, no lock in common.

The "volumemgr logged 1.0 s earlier" datum is neutral rather than exculpatory:
createOrUpdateDiskMetrics logs nothing between FindLargeFiles (the walk in #6300)
and publishDiskMetrics, so a last line 1.0 s before the abort is what volumemgr
inside zfs_iter_root looks like. Go's SIGABRT handler dumps all goroutines, so
grepping that stderr burst for dataset_list_root / DatasetOpenAll would settle it.

Why once in four days. namespace_reload short-circuits unless the namespace
generation moved: spa_all_configs() returns EEXIST (spa_config.c:376) and the
reload returns untouched (libzfs_config.c:136-141). spa_config_generation++ happens
only in spa_write_cachefile() (spa_config.c:347) — create/import/export,
spa_vdev_add, spa_change_guid, spa_config_update, spa_async_thread on
SPA_ASYNC_CONFIG_UPDATE. So the mutating body runs only on the first call after zedbox
start (libzfs_ns_gen == 0, where both threads create their own tree and one leaks) or
after a pool config event. Checkable prediction: either pid 4280 was young at 02:31:10,
or a pool config event landed just before it.

Where a fix belongs. go-libzfs creates one process-global libzfsHandle
(common.c:8, from Go init()) and already ships a package mutex, Global.Mtx
(common.go:72), taken in seven Dataset methods but in neither DatasetOpenAll nor
PoolOpenAll — precisely the two AVL-mutating functions. libzfs itself documents no
thread-safety guarantee, so upstream would be a feature request; bicomsystems is
dormant (master unchanged since 2022-04-19); EVE pins andrewd-zededa/go-libzfs
755aaeb96a92 on branch zfs-2.3.3, which is the practical fix point and covers all
callers at once. Note pillar cannot just reuse Global.Mtx: DatasetOpenAll calls
Dataset.ReloadProperties() in its loop and sync.Mutex is not reentrant, so wrapping
it self-deadlocks (PoolOpenAll wraps safely). The EVE-only alternative is one
process-wide lock in pkg/pillar/zfs replacing zfsIterLock — but pair it with #6300,
since a global lock plus that slow dataset walk gives head-of-line blocking.

Containment is separate, and no in-process fix survives an abort.
libspl_assertf calls abort() (libspl/assert.c:115) and Go turns SIGABRT into
process death before any Go code runs; libspl_set_assert_ok(B_TRUE) only trades a
clean abort for an undefined one. So a libzfs assert stops costing a device reboot only
once the cgo calls leave the process hosting every other agent — cheaply by moving the
two enumerations to the CLI (precedent in the same file: zfs/zfs.go:452-490 already
shells out to types.ZPoolBinary), or structurally by marking zfsmanager
inline: inlineAlways (zedbox.go:109; the mechanism client already uses, with its
own watchdog pid entry) and having volumemgr consume published metrics.

Why there was no trail — four cause-agnostic gaps.

1. newlogd triggers capture only on the literal ;panic: (getMemlogMsg.go:277). A cgo
   abort prints ASSERT at … / SIGABRT: abort / signal arrived during cgo execution,
   so savePanicFiles never ran — hence the empty panicStacks and reboot-stack. The
   same gap swallows every Go fatal error:.
2. Capture is capped at 15 messages (getMemlogMsg.go:296), far short of an
   all-goroutine dump.
3. libspl_backtrace() is a no-op stub without libunwind/execinfo
   (libspl/backtrace.c:298-303); pkg/dom0-ztools/Dockerfile installs neither, and
   configure auto-detects (with_libunwind=auto). Adding it would have named the
   corrupting C path.
4. watchdog.conf.seed sets no repair-timeout, so watchdog 5.15 uses the compiled
   TIMER_MARGIN = 60 s while watchdog-report.sh may run collect-info.sh and ends
   with sleep 30 — the timeout costs the bundle, not the reboot (it exits 254
   deliberately). Its pkill -USR1 zedbox also fires only on the .touch branch, not
   .pid, leaving stderr as the sole stack source — which per (1) is not captured.

Suggested order: check the two device-side items above; land the diagnosability fixes
regardless of cause; then locking and process isolation together, sized against #6300.

[eriknordmark]

Pulled the 02:31:10 window off the device (/persist/newlog, keepSentQueue etc.).
The traceback is in the log — as ordinary source: "pillar" records, one per
line — which corrects the diagnosability item above in a useful direction: the
evidence survives, only the panic-file capture failed.

What the persisted burst shows: 2547 records / 172 KiB over 47 ms, 116 goroutines,
exactly one runtime.cgocall frame, and no dataset_list_root /
DatasetOpenAll anywhere. That is not enough to refute a concurrent second
libzfs caller: the burst ends mid-frame with no register dump, so it is
truncated, and goroutines print in ascending id order after the crashing one — ids
reach ~24000 here, so the lost tail is exactly where late-created agent goroutines
(volumemgr's disk-metrics one) would appear. volumemgr's main Run goroutine is
present; its metrics goroutine is not. Also, goroutine 2 reports force gc (idle), 14 minutes, so pid 4280 was ~14 min old — not the first PoolOpenAll after start,
which rules out the libzfs_ns_gen == 0 window and leaves a pool config event or
an already-inconsistent tree.

On gap 1: the trigger was dead code for every crash type, not just cgo aborts.
checkWatchdogRestart matched ";panic:" in the raw memlogd record — the
<time>;<source>;<msg> text form — but memlogd answers its query socket with
json.NewEncoder, and b3900fca7 ("Assume json from memlogd", 2023-06-28) dropped
the legacy parse. So plain Go panics have not been captured either, on master or on
any LTS branch. #6303 fixes that, raises the 15-record cap (gaps 1 and 2), and
carries the device sequence above as its test input.

[eriknordmark]

Chased the "which window was open" question on the device (pool history + event stream on sc-sm-e300-10). The interesting part is not the timing, it's why the window opens.

Not the first-call window. persist was imported 02:15:57Z, the abort was 02:31:10Z, and the traceback's goroutine 2 [force gc (idle), 14 minutes] agrees — libzfs_ns_gen had been non-zero for ~15 minutes.

zpool history shows no pool event in that window, and that is a red herring. The last logged entry before the abort is trim vdev=/dev/sda9 activated at 02:16:30 (14m40s earlier); nothing else until the post-crash import at 02:34:37. But the abort itself proves the generation moved: at zfs-2.3.6, spa_all_configs() returns EEXIST when the caller's generation matches, and namespace_reload() then returns before the teardown loop (libzfs_config.c:141) — so reaching the failing verify(uu_avl_find(...) == NULL) at :190 means ZFS_IOC_POOL_CONFIGS came back with a fresh config. spa_write_cachefile() is not history-logged, so history silence is not evidence.

What bumps the generation: a permanently failing cachefile write, every 300 s. zpool events on this device shows exactly one ereport.fs.zfs.config_cache_write just after import, then sysevent.fs.zfs.config_sync every ~5m02s indefinitely (11 of them in 50 minutes of uptime). That is the retry path: on a failed cachefile write spa_write_cachefile() re-requests SPA_ASYNC_CONFIG_UPDATE (spa_config.c:327), rate-limited to zfs_ccw_retry_interval = 300 s (spa.c:131, fixed — not a module parameter), and the spa_config_generation++ at spa_config.c:347 runs on the failing path too. The write fails because there is no writable /etc/zfs/zpool.cache: cachefile is default and the file exists nowhere on the device.

So this is not device-specific. Any EVE node with a ZFS persist pool re-opens the namespace_reload() window every 5 minutes, for as long as it is up. Extrapolating the cadence back to the 02:15:57 import puts a tick at ~02:31:03, 7 s before the abort — that alignment is a prediction from the measured cadence, not a measurement of that boot, since the event ring buffer is long gone.

Two consequences:

• The rarity is not in the window being open — it is in two unsynchronized callers straddling one bump. A single bump is enough for both: they read the same stale zc.zc_cookie, both get a full config, and both run teardown-then-insert against the one shared AVL, which asserts as soon as one thread's teardown precedes the other's inserts. With a single pool that is a one-node collision. So the lock is worth more than a "once in four days" rate suggests.
• There is an independent, cheap mitigation worth evaluating: give ZFS a cachefile it can write, or set cachefile=none, which skips the write entirely (scd_path == NULL short-circuit, spa_config.c:268) and stops the 300 s churn. EVE already imports the pool by name explicitly at boot (zpool import -f persist in the history above), so it does not depend on the cache — though that wants checking against the installer and vault paths before anyone acts on it.