cephfs: avoid hanging os.Stat() in NodeGetVolumeStats after restart - #6418
cephfs: avoid hanging os.Stat() in NodeGetVolumeStats after restart#6418SanjalKatiyar wants to merge 1 commit into
Conversation
SanjalKatiyar
changed the title
SanjalKatiyar
changed the title
02b1603 to
826812b
Compare
| } | ||
|
|
||
| // warning: stat() may hang on an unhealthy volume | ||
| // no indefinite block/hang, if flow reaches here |
There was a problem hiding this comment.
this comment is not very descriptive anymore. maybe add a warning, or at least something like 'should not be reachable if volume is unhealthy'.
| // checker (re)start scenarios, e.g. following a node-plugin restart | ||
| // where the volume was already mounted. | ||
| checked bool | ||
|
|
There was a problem hiding this comment.
can't lastUpdate not be used for this? Maybe it should not be initialized to time.Now()
There was a problem hiding this comment.
@nixpanic lastUpdate and checked has different meanings.
Currently lastUpdate is set only when os.Stat() succeeds (https://github.com/ceph/ceph-csi/blob/devel/internal/health-checker/statchecker.go#L63), whereas checked doesn't care about the result, it only cares that os.Stat() call has completed (successful or not) atleast once.
That said, we can definitely re-purpose lastUpdate, but there will be some behavioural changes:
lastUpdatewill update on os.Stat() completion (successful or not).- Currently,
lastUpdateis initialised totime.Now()and the volume is Intermediately "healthy". If os.Stat() is still stuck, afterc.interval + c.timeout(75s) thedelaycheck (https://github.com/ceph/ceph-csi/blob/devel/internal/health-checker/checker.go#L95) kicks-in and marks the volume "unhealthy" automatically, which is a desired behaviour so far.
But, with re-purposedlastUpdate(initialised to zero or nil), as long as os.Stat() is stuck, we will have to agree upon either of the two behaviours:
a. We always keep on returninghealth: true, error: fmt.Errorf("health-check has not completed its first check yet").
b. Or, always keep on returninghealth: false, error: fmt.Errorf("health-check has not responded for %f seconds", delay.Seconds()).
If that's acceptable, I can remove checked and shift to lastUpdate instead, but please let me know whether you prefer behaviour 2a or 2b mentioned above. Or, maybe some other suggestion which I might be missing ??
There was a problem hiding this comment.
@nixpanic I tested the checked flag flow proposed in this PR and it works as expected. I did notice one related behaviour worth mentioning, we can decide whether to address it or accept it as-is.
The scenario this PR fixes: If the MDS goes down and the nodeplugin restarts, checked resets to false, so NodeGetVolumeStats returns early without calling the synchronous os.Stat(). The volumes are correctly reported as unhealthy once the health-checker's 75s timeout elapses. No hangs, no blocks, exactly as desired.
A related scenario that still exists: If the MDS goes down while the nodeplugin is already running, the health-checker has already completed its first cycle (so checked is true) and last reported the volume as healthy. During the window between the last successful health-check and the next timeout detection (~75s), NodeGetVolumeStats sees a healthy result and falls through to the synchronous os.Stat(), which blocks on the unresponsive mount while holding the VolumeLock. This causes subsequent calls for that path to fail with "Aborted". Though, good news is, I noticed the SlowGRPCRestart mechanism (https://github.com/ceph/ceph-csi/blob/devel/internal/csi-common/utils.go#L148) automatically kills the process after 10mins of a stuck gRPC calls, K8s restarts the container, and the fix from this PR then kicks in, so the issue is self-healing (eventually), just with a 10min degraded window.
Even "re-purposed lastUpdate" fix suggested above won't solve this issue, so IMHO we should live with this edge case as-is, it will anyway eventually gets auto-fixed.
826812b to
3a20768
Compare
There was a problem hiding this comment.
| // If healthy and an error is returned, it means either the checker | |
| // has not been started, or it is running but has not completed its | |
| // first health-check cycle yet. |
| // holding the VolumeLock (acquired above) and preventing all future | ||
| // calls for this path from reaching isHealthy(). | ||
| // The background checker will do the stat(), the next periodic | ||
| // call will pick up the result (or detect the 75s timeout). |
There was a problem hiding this comment.
| // call will pick up the result (or detect the 75s timeout). | |
| // call will pick up the result (or detect the timeout). |
Doing this will allow us to update timeouts without rotting this comment.
3a20768 to
019a465
Compare
If a node-plugin pod restarts while the backend (e.g. MDS) is down, NodeGetVolumeStats used to call os.Stat() on the target path immediately after (re)starting the health checker, before the checker had a chance to detect the outage. Since os.Stat() blocks in the kernel on an unresponsive mount, this held the VolumeLock forever and made every later call for that path fail with Aborted. Return early with an "not yet available" condition instead of calling os.Stat() when the checker was just (re)started, for CephFS. Signed-off-by: SanjalKatiyar <sanjaldhir@gmail.com>
019a465 to
5d1c78a
Compare
| // checker (re)start scenarios, e.g. following a node-plugin restart | ||
| // where the volume was already mounted. | ||
| checked bool | ||
|
|
| // FileChecker is started with the stagingTargetPath, but we can't | ||
| // get the stagingPath from the request easily. | ||
| // TODO: resolve the stagingPath like rbd.getStagingPath() does | ||
| // NOTE: rbd.getStagingPath() uses os.Stat() internally which |
There was a problem hiding this comment.
resolve the stagingPath like rbd.getStagingPath() does
this comment was already present in the cephfs flow and suggested taking rbd.getStagingPath as a reference from the RBD implementation. I added an additional "NOTE" on it to highlight that following the same implementation here could again lead to issues or hangs.
There was a problem hiding this comment.
Pull request overview
This PR updates the CephFS NodeGetVolumeStats path to avoid potentially indefinite blocking on os.Stat() right after a node-plugin restart, by returning an early “not yet available” volume condition until the background health checker has completed at least one check cycle.
Changes:
- Track whether a health checker has completed its first cycle (
checked) and report a distinct “not yet checked” status fromisHealthy(). - Update CephFS
NodeGetVolumeStatsto return early (instead of calling synchronousos.Stat()) when the checker is newly started / not yet checked. - Add/adjust unit tests for the “not yet checked” behavior across checkers.
Reviewed changes
Copilot reviewed 7 out of 7 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| internal/health-checker/checker.go | Adds checked state and updates isHealthy() semantics for first-cycle completion. |
| internal/health-checker/checker_test.go | Adds tests validating “not yet checked” and timeout behaviors. |
| internal/health-checker/statchecker.go | Marks checked on first cycle and refactors stat error handling. |
| internal/health-checker/statchecker_test.go | Updates tests to assert “not yet checked” behavior before the first tick. |
| internal/health-checker/filechecker.go | Marks checked on cycles (including error paths). |
| internal/health-checker/filechecker_test.go | Updates tests to assert “not yet checked” behavior before the first tick. |
| internal/cephfs/nodeserver.go | Avoids synchronous os.Stat() after restart by returning early “status not yet available”. |
Comments suppressed due to low confidence (6)
internal/health-checker/filechecker.go:69
- Update lastUpdate when the check cycle fails. Without refreshing lastUpdate on readTimestamp() errors, isHealthy() can start reporting a timeout even though the checker is still actively running and returning errors.
fc.mutex.Lock()
fc.checked = true
fc.healthy = false
fc.err = err
fc.mutex.Unlock()
internal/health-checker/filechecker.go:80
- Update lastUpdate when the check cycle fails. If the timestamp mismatch happens quickly but lastUpdate isn't refreshed, isHealthy() can later return a generic "has not responded" timeout instead of the actual mismatch error.
fc.mutex.Lock()
fc.checked = true
fc.healthy = false
fc.err = errors.New("timestamp read from file does not match what was written")
fc.mutex.Unlock()
internal/health-checker/statchecker_test.go:37
- These sleeps make the unit test take ~15s (and it’s easy to accidentally sleep past the first tick, defeating the "before first tick" assertion). Consider using a sub-second interval and short polling to keep the test fast and deterministic.
This issue also appears on line 55 of the same file.
checker.interval = time.Second * 3
// start the checker
checker.start()
internal/health-checker/statchecker_test.go:58
- The per-iteration 1s sleep makes this test significantly slower without adding much signal (the checker state should remain healthy between reads). A short sleep (or none) is usually enough here.
healthy, msg = checker.isHealthy()
if !healthy || msg != nil {
t.Errorf("volume is unhealthy after %d tries", i+1)
}
internal/health-checker/filechecker_test.go:37
- These sleeps make the unit test take multiple seconds. Consider using a sub-second interval and short polling to keep the test fast and avoid accidentally sleeping past the first tick (which would defeat the "before first tick" assertion).
This issue also appears on line 55 of the same file.
checker.interval = time.Second * 3
// start the checker
checker.start()
internal/health-checker/filechecker_test.go:58
- The per-iteration 1s sleep makes this test significantly slower without adding much signal. A short sleep (or none) is usually enough once the first check cycle has completed.
healthy, msg = checker.isHealthy()
if !healthy || msg != nil {
t.Error("volume is unhealthy")
}
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| sc.mutex.Lock() | ||
| sc.healthy = true | ||
| sc.err = nil | ||
| sc.lastUpdate = now | ||
| sc.checked = true | ||
| if statErr != nil { | ||
| sc.healthy = false | ||
| sc.err = statErr |
There was a problem hiding this comment.
This is an existing behaviour (not introduced by this PR).
There was a problem hiding this comment.
IMHO we should have a GH issue instead ??
| fc.mutex.Lock() | ||
| fc.checked = true | ||
| fc.healthy = false | ||
| fc.err = err | ||
| fc.mutex.Unlock() |
There was a problem hiding this comment.
This is an existing behaviour (not introduced by this PR).
There was a problem hiding this comment.
IMHO we should have a GH issue instead ??
|
@SanjalKatiyar please open required github issues and fix the CI lint failures? we are good to get this merged |
If a node-plugin pod restarts while the backend (e.g. MDS) is down, NodeGetVolumeStats used to call os.Stat() on the target path immediately after (re)starting the health checker, before the checker had a chance to detect the outage. Since os.Stat() blocks in the kernel on an unresponsive mount, this held the VolumeLock forever and made every later call for that path fail with Aborted.
Return early with an "not yet available" condition instead of calling os.Stat() when the checker was just (re)started, for CephFS.
Issue:
Slow GRPC calls and connection refused errors when nodeplugin pod restarts while MDS is down.
Logs of
openshift-storage.cephfs.csi.ceph.com-nodeplugin-<HASH>pod:openshift-storage.cephfs.csi.ceph.com-nodeplugin-csi-addonft2qx logs: