Skip to content

Commit 51edfea

Browse files
calmkartgyuho
andauthored
[LEP-5065] feat(nfs): detect NFS hangs from kmsg and flip node Unhealthy (#1245)
## Summary Adds a kmsg-based detection path to the `nfs` component that catches NFS hangs the existing read/write prober cannot — specifically the case where the NFS client kernel module is spinning on its own writeback locks while kubelet's main thread keeps reporting Ready. When a hang is detected, the component flips to `Unhealthy` with a `SuggestedActions{REBOOT_SYSTEM}`, which lets cluster-operator's auto-fixer cordon and reboot the node automatically. Repeated hangs across reboots are upgraded to `HARDWARE_INSPECTION` via the existing `eventstore.EvaluateSuggestedActions` machinery, so this does not introduce a reboot loop. ## Motivation A worker node ran for 3.5 days in a state where: - kubelet's main goroutine kept writing logs and reporting heartbeats (node `Ready=True`) - one CPU core was 100% pinned inside `nfs_lock_and_join_requests` → `_raw_spin_lock`, triggered by a user-issued `mksquashfs` writing a large file to `/nfs/home` - any goroutine touching the filesystem (kubelet's pod admit / volume mount / cAdvisor) blocked forever - new pods could be scheduled to the node but never admitted dmesg reported `watchdog: BUG: soft lockup` every ~28 seconds from the first 26-second stuck event onward, but nothing was listening for it. The current `components/cpu` matcher already recognises `soft lockup` text but only records it as an event — it never affects health state. This change makes that signal actionable, scoped to NFS so the generic `soft lockup` semantics in `components/cpu` are unchanged. ## What's in this PR Two commits, each independently buildable and testable: 1. **`feat(nfs): add kmsg matcher and hang evaluator for NFS hang detection`** Pure additions, no wiring: - `kmsg_matcher.go`: four NFS-specific regexes (server not responding, server OK recovery, lock reclaim failed, NFS writeback functions in stack traces) + a `Match` function for `kmsg.Syncer`. - `hang_evaluator.go`: `collectNFSHangEvents()` applies conjunction rules — lock-reclaim failed counts unconditionally, "not responding" is cancelled by a later "OK", writeback stack hints require ≥ 2 occurrences in the lookback window (which, combined with the 300-second dedup, means ≥ 5 minutes of sustained hang and filters out one-shot sysrq dumps). 2. **`feat(nfs): wire kmsg-based hang detection into component health`** Hooks the detector into the component: - New fields `eventBucket`, `kmsgSyncer`, `rebootEventStore`, `lookbackPeriod` (3 days, aligned with `eventstore.DefaultRetention`). - `newComponent()` testable inner constructor; `kmsg.Syncer` started on `linux + euid==0 + EventStore!=nil` with `WithCacheKeyTruncateSeconds(300)`. - `Check()` evaluates kmsg events before the prober. If a hang is present, query reboot history, sort ascending (see note below), and let `EvaluateSuggestedActions` decide whether to suggest reboot or hardware inspection. If a reboot already happened after the hang, fall through to the prober for live re-check rather than reporting stale state. - `Start()` now runs `Check()` immediately on the first iteration instead of waiting one tick, matching `components/disk`. - `Close()` shuts the syncer before the bucket. - `Events()` returns bucket contents instead of `nil`. - `checkResult.suggestedActions` surfaced through `HealthStates()`. ## Notable design points - **Ordering quirk**: `Bucket.Get` and `RebootEventStore.GetRebootEvents` both return events in **descending** order (latest first), but `eventstore.EvaluateSuggestedActions` expects **ascending** input (see `pkg/eventstore/suggested_actions_test.go` case 4 where `failureEvents[0]` is the earliest). This PR sorts ascending before calling. `components/disk` happens to pass the descending slice directly — that may be a latent issue worth addressing in a separate PR but is out of scope here. - **Lookback = 3 days** (not longer), because `EventStore` doesn't support per-bucket retention overrides and the global default is 3 days. Within this window we get accurate reboot-vs-hang ordering; beyond it we'd just be reading nothing. - **kmsg `Message` preserves leading whitespace** (parsed by `strings.SplitN(line, ";", 2)` in `pkg/kmsg/watcher.go`), so the writeback regex uses `(^|\s)…` to tolerate the leading space typical of kernel stack trace lines. ## Testing ```text go test ./components/nfs/ -short -race -count=1 ok github.com/leptonai/gpud/components/nfs 1.7s 56 tests pass (all pre-existing + 25 newly added across matcher, evaluator, and component layers). Highlights: - Reboot-loop guard: TestCheckKmsgHangWithRebootLoop — two hangs with two interleaved reboots upgrades to HARDWARE_INSPECTION. - No-loop safety: TestCheckKmsgHangAfterReboot — hang followed by a later reboot returns nil from EvaluateSuggestedActions and falls through to the prober. - Robustness: TestCheckNilRebootEventStore — nil reboot store does not panic. - Probe skip: TestCheckSkipsProberWhenHangDetected — confirms the kmsg path returns before a probe is issued on a known-hung mount. - Cold-start latency: TestStartImmediateFirstCheck — Start() runs Check() before the first ticker fire (also fixes pre-existing behaviour where the first health state would only appear after a full minute). Risk & limitations - Repeated sysrq within 5 minutes could trigger a false positive (two writeback stack hints needed). This is a controlled human action and the resulting cordon is a safe side-effect. - gpud's own probe goroutines are still vulnerable to NFS hangs that occur mid-execution: the existing 5-second ctx.WithTimeout cannot cancel an in-kernel NFS syscall. This PR mitigates by skipping new probes on known-hung mounts but does not rescue already-stuck goroutines. Pre-existing; out of scope. - components/cpu is intentionally untouched: its existing soft lockup matcher still only writes events and does not affect health, since the generic CPU lockup signal is too noisy to act on unconditionally. Manual verification on a real node # 1. Inject "server not responding" (no OK to cancel) -> Unhealthy within 60s echo 'nfs: server 192.168.1.100 not responding, timed out' | sudo tee /dev/kmsg sleep 65 curl -sk https://localhost:15132/v1/states | jq '.[] | select(.name=="nfs")' # 2. Single writeback stack hint -> still Healthy (below threshold) echo ' nfs_lock_and_join_requests+0x61/0x2b0 [nfs]' | sudo tee /dev/kmsg sleep 65 # 3. Second writeback hint 5+ minutes later (defeats dedup) -> Unhealthy sleep 305 echo ' nfs_lock_and_join_requests+0x82/0x2b0 [nfs]' | sudo tee /dev/kmsg sleep 65 # Expect: .health == "Unhealthy" # .suggested_actions.repair_actions == ["REBOOT_SYSTEM"] # .suggested_actions.description == "NFS hang requires immediate reboot; drain may hang on NFS volumes" --------- Co-authored-by: Gyuho Lee <gyuhol@nvidia.com>
1 parent c570f0a commit 51edfea

6 files changed

Lines changed: 1121 additions & 10 deletions

File tree

components/nfs/component.go

Lines changed: 157 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,9 @@ import (
66
"context"
77
"errors"
88
"fmt"
9+
"os"
10+
"runtime"
11+
"sort"
912
"strings"
1013
"sync"
1114
"time"
@@ -16,15 +19,27 @@ import (
1619
apiv1 "github.com/leptonai/gpud/api/v1"
1720
"github.com/leptonai/gpud/components"
1821
"github.com/leptonai/gpud/pkg/disk"
22+
"github.com/leptonai/gpud/pkg/eventstore"
23+
pkghost "github.com/leptonai/gpud/pkg/host"
24+
"github.com/leptonai/gpud/pkg/kmsg"
1925
"github.com/leptonai/gpud/pkg/log"
2026
pkgnfschecker "github.com/leptonai/gpud/pkg/nfs-checker"
2127
)
2228

2329
// Name is the name of the NFS component.
2430
const Name = "nfs"
2531

32+
// defaultLookbackPeriod is how far back to query kmsg and reboot history when
33+
// evaluating NFS hang suggested actions. Bounded by eventstore.DefaultRetention
34+
// (3 days) — querying further yields no events (design doc §9 U3).
35+
const defaultLookbackPeriod = 3 * 24 * time.Hour
36+
2637
var _ components.Component = &component{}
2738

39+
type kmsgSyncerCloser interface {
40+
Close()
41+
}
42+
2843
type component struct {
2944
ctx context.Context
3045
cancel context.CancelFunc
@@ -42,12 +57,42 @@ type component struct {
4257
checkChecker func(ctx context.Context, checker pkgnfschecker.Checker) pkgnfschecker.CheckResult
4358
cleanChecker func(checker pkgnfschecker.Checker) error
4459

60+
// eventBucket stores NFS-related kmsg events for the kmsg-based hang
61+
// detection path. Nil when no EventStore is configured (e.g., in unit
62+
// tests that exercise only the prober path).
63+
eventBucket eventstore.Bucket
64+
// kmsgSyncer streams kernel messages into eventBucket; only created when
65+
// running as root on Linux.
66+
kmsgSyncer kmsgSyncerCloser
67+
// rebootEventStore is consulted to decide between REBOOT_SYSTEM and
68+
// HARDWARE_INSPECTION when an NFS hang is detected. May be nil.
69+
rebootEventStore pkghost.RebootEventStore
70+
// lookbackPeriod controls how far back we query events when evaluating
71+
// suggested actions.
72+
lookbackPeriod time.Duration
73+
4574
lastMu sync.RWMutex
4675
lastCheckResult *checkResult
4776
}
4877

4978
// New creates the NFS component.
5079
func New(gpudInstance *components.GPUdInstance) (components.Component, error) {
80+
return newComponent(gpudInstance, runtime.GOOS, os.Geteuid(), kmsg.NewSyncer)
81+
}
82+
83+
// newComponent is the testable constructor. It accepts the runtime OS, the
84+
// effective UID, and a kmsg syncer factory so tests can exercise the
85+
// EventStore wiring without privileged kernel access.
86+
func newComponent(
87+
gpudInstance *components.GPUdInstance,
88+
goos string,
89+
euid int,
90+
newKmsgSyncerFunc func(ctx context.Context, matchFunc kmsg.MatchFunc, eventBucket eventstore.Bucket, opts ...kmsg.OpOption) (*kmsg.Syncer, error),
91+
) (components.Component, error) {
92+
if newKmsgSyncerFunc == nil {
93+
newKmsgSyncerFunc = kmsg.NewSyncer
94+
}
95+
5196
cctx, ccancel := context.WithCancel(gpudInstance.RootCtx)
5297
c := &component{
5398
ctx: cctx,
@@ -73,6 +118,35 @@ func New(gpudInstance *components.GPUdInstance) (components.Component, error) {
73118
cleanChecker: func(checker pkgnfschecker.Checker) error {
74119
return checker.Clean()
75120
},
121+
122+
rebootEventStore: gpudInstance.RebootEventStore,
123+
lookbackPeriod: defaultLookbackPeriod,
124+
}
125+
126+
if gpudInstance.EventStore != nil {
127+
bucket, err := gpudInstance.EventStore.Bucket(Name)
128+
if err != nil {
129+
ccancel()
130+
return nil, err
131+
}
132+
c.eventBucket = bucket
133+
134+
// Only sync kmsg on Linux as root — /dev/kmsg is privileged.
135+
if goos == "linux" && euid == 0 {
136+
syncer, err := newKmsgSyncerFunc(
137+
cctx,
138+
Match,
139+
c.eventBucket,
140+
// Coalesce repeated kmsg lines (e.g., bursty writeback stacks)
141+
// within a 5-minute window to keep the event store bounded.
142+
kmsg.WithCacheKeyTruncateSeconds(300),
143+
)
144+
if err != nil {
145+
ccancel()
146+
return nil, err
147+
}
148+
c.kmsgSyncer = syncer
149+
}
76150
}
77151

78152
return c, nil
@@ -96,13 +170,15 @@ func (c *component) Start() error {
96170
defer ticker.Stop()
97171

98172
for {
173+
// Run an initial check immediately so the first health state is
174+
// available without waiting one tick interval.
175+
_ = c.Check()
176+
99177
select {
100178
case <-c.ctx.Done():
101179
return
102180
case <-ticker.C:
103181
}
104-
105-
_ = c.Check()
106182
}
107183
}()
108184
return nil
@@ -115,15 +191,29 @@ func (c *component) LastHealthStates() apiv1.HealthStates {
115191
return lastCheckResult.HealthStates()
116192
}
117193

118-
func (c *component) Events(_ context.Context, _ time.Time) (apiv1.Events, error) {
119-
return nil, nil
194+
func (c *component) Events(ctx context.Context, since time.Time) (apiv1.Events, error) {
195+
if c.eventBucket == nil {
196+
return nil, nil
197+
}
198+
evs, err := c.eventBucket.Get(ctx, since)
199+
if err != nil {
200+
return nil, err
201+
}
202+
return evs.Events(), nil
120203
}
121204

122205
func (c *component) Close() error {
123206
log.Logger.Debugw("closing component")
124207

125208
c.cancel()
126209

210+
if c.kmsgSyncer != nil {
211+
c.kmsgSyncer.Close()
212+
}
213+
if c.eventBucket != nil {
214+
c.eventBucket.Close()
215+
}
216+
127217
return nil
128218
}
129219

@@ -140,6 +230,58 @@ func (c *component) Check() components.CheckResult {
140230
c.lastMu.Unlock()
141231
}()
142232

233+
// kmsg-based NFS hang detection takes priority over the prober: when the
234+
// kernel has already reported writeback hangs / lock-reclaim failures /
235+
// unresponsive servers, a probe-issued open()/write() may itself hang
236+
// forever, so we surface the suggested action and skip the prober for
237+
// this tick. If a reboot has already been observed after the hang
238+
// events, EvaluateSuggestedActions returns nil and we fall through to
239+
// the prober for live verification (design doc §3.6).
240+
if c.eventBucket != nil {
241+
evs, err := c.eventBucket.Get(c.ctx, cr.ts.Add(-c.lookbackPeriod))
242+
if err != nil {
243+
log.Logger.Warnw("failed to query nfs event bucket", "error", err)
244+
} else {
245+
hangEvents, hangReason := collectNFSHangEvents(evs)
246+
if len(hangEvents) > 0 {
247+
var rebootEvents eventstore.Events
248+
if c.rebootEventStore != nil {
249+
var err error
250+
rebootEvents, err = c.rebootEventStore.GetRebootEvents(c.ctx, cr.ts.Add(-c.lookbackPeriod))
251+
if err != nil {
252+
cr.err = err
253+
cr.health = apiv1.HealthStateTypeUnhealthy
254+
cr.reason = "failed to get reboot events"
255+
log.Logger.Warnw(cr.reason, "error", cr.err)
256+
return cr
257+
}
258+
// GetRebootEvents returns events in DESCENDING order
259+
// (latest first), but EvaluateSuggestedActions expects
260+
// ASCENDING order (oldest first) — see design doc §9 U2.
261+
sort.Slice(rebootEvents, func(i, j int) bool {
262+
return rebootEvents[i].Time.Before(rebootEvents[j].Time)
263+
})
264+
if len(rebootEvents) > 0 {
265+
hangEvents, hangReason = collectNFSHangEvents(nfsEventsOnOrAfter(evs, rebootEvents[0].Time))
266+
}
267+
}
268+
if len(hangEvents) > 0 {
269+
sa := eventstore.EvaluateSuggestedActions(rebootEvents, hangEvents, 2)
270+
if sa != nil {
271+
sa.Description = "NFS hang requires immediate reboot; drain may hang on NFS volumes"
272+
cr.health = apiv1.HealthStateTypeUnhealthy
273+
cr.reason = hangReason
274+
cr.suggestedActions = sa
275+
return cr
276+
}
277+
}
278+
// No unresolved post-reboot hang evidence, or sa == nil
279+
// because reboot history already resolved the hang; fall
280+
// through to the prober for live verification.
281+
}
282+
}
283+
}
284+
143285
groupConfigs := c.getGroupConfigsFunc()
144286
if len(groupConfigs) == 0 {
145287
cr.health = apiv1.HealthStateTypeHealthy
@@ -275,6 +417,10 @@ type checkResult struct {
275417

276418
// tracks the healthy evaluation result of the last check
277419
health apiv1.HealthStateType
420+
// suggestedActions is populated when the kmsg-based hang detection
421+
// determines the system needs a reboot or hardware inspection. It is a
422+
// pointer so the JSON encoder elides it when unset.
423+
suggestedActions *apiv1.SuggestedActions
278424
// tracks the reason of the last check
279425
reason string
280426
}
@@ -339,12 +485,13 @@ func (cr *checkResult) HealthStates() apiv1.HealthStates {
339485
}
340486

341487
state := apiv1.HealthState{
342-
Time: metav1.NewTime(cr.ts),
343-
Component: Name,
344-
Name: Name,
345-
Reason: cr.reason,
346-
Error: cr.getError(),
347-
Health: cr.health,
488+
Time: metav1.NewTime(cr.ts),
489+
Component: Name,
490+
Name: Name,
491+
Reason: cr.reason,
492+
Error: cr.getError(),
493+
Health: cr.health,
494+
SuggestedActions: cr.suggestedActions,
348495
}
349496

350497
return apiv1.HealthStates{state}

0 commit comments

Comments
 (0)