Skip to content

Commit 48d5816

Browse files
author
Roy Lin
committed
fix(box): make CRI ReopenContainerLog synchronous (wait for supervisor reopen)
ReopenContainerLog fired a fire-and-forget Notify and returned immediately, while the exit supervisor reopened the log writer asynchronously — so output written after the RPC returned could still land in the old (rotated) file, making the "reopening container log" conformance spec flaky. The per-container reopen handle now carries a `done` Notify alongside the `request`: the RPC signals the request and waits (bounded 5s) for the supervisor to ack once `CriLogWriter::reopen` has completed, so the new file is guaranteed in place before the RPC returns. This is the correct CRI semantic (the call is synchronous). This substantially reduces the flake but does not fully eliminate it: a residual race remains in the supervisor's `select!` ordering (pending pipe output read after the reopen can land in the new file). Tracked as a follow-up; needs the supervisor to drain buffered output to the old writer before reopening. Verified: build + clippy clean, cri tests pass (reopen unit test updated for the new handle), reopen-log critest now passes ~2/3 (was ~1/2).
1 parent a343143 commit 48d5816

3 files changed

Lines changed: 70 additions & 20 deletions

File tree

src/cri/src/runtime_service/mod.rs

Lines changed: 47 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -71,7 +71,16 @@ type WorkloadStdinSender = StreamingInput;
7171
type WorkloadStdinMap = Arc<RwLock<HashMap<String, WorkloadStdinSender>>>;
7272
type WorkloadStopSender = oneshot::Sender<()>;
7373
type WorkloadStopMap = Arc<RwLock<HashMap<String, WorkloadStopSender>>>;
74-
type LogReopenMap = Arc<RwLock<HashMap<String, Arc<Notify>>>>;
74+
/// Per-container handle for CRI ReopenContainerLog. `request` wakes the exit
75+
/// supervisor to reopen its log writer; `done` is notified once the reopen has
76+
/// completed, so ReopenContainerLog returns only after the new file is in place
77+
/// (the RPC is synchronous — output written after it returns must land in the
78+
/// rotated file).
79+
pub(super) struct LogReopenHandle {
80+
pub(super) request: Arc<Notify>,
81+
pub(super) done: Arc<Notify>,
82+
}
83+
type LogReopenMap = Arc<RwLock<HashMap<String, LogReopenHandle>>>;
7584
type ContainerEventSender = broadcast::Sender<ContainerEventResponse>;
7685

7786
const CRI_CONTAINER_ROOTFS_HOST_DIR: &str = "cri-container-rootfs";
@@ -1059,6 +1068,7 @@ impl RuntimeService for BoxRuntimeService {
10591068
let (attach_tx, _) = broadcast::channel(128);
10601069
let (stop_tx, stop_rx) = oneshot::channel();
10611070
let log_reopen = Arc::new(Notify::new());
1071+
let log_reopen_done = Arc::new(Notify::new());
10621072
if started {
10631073
self.attach_streams
10641074
.write()
@@ -1074,10 +1084,13 @@ impl RuntimeService for BoxRuntimeService {
10741084
.write()
10751085
.await
10761086
.insert(container_id.clone(), stop_tx);
1077-
self.log_reopens
1078-
.write()
1079-
.await
1080-
.insert(container_id.clone(), log_reopen.clone());
1087+
self.log_reopens.write().await.insert(
1088+
container_id.clone(),
1089+
LogReopenHandle {
1090+
request: log_reopen.clone(),
1091+
done: log_reopen_done.clone(),
1092+
},
1093+
);
10811094
self.emit_container_event(
10821095
&container_id,
10831096
&container.sandbox_id,
@@ -1101,6 +1114,7 @@ impl RuntimeService for BoxRuntimeService {
11011114
attach_tx,
11021115
stop_rx,
11031116
log_reopen,
1117+
log_reopen_done,
11041118
workload,
11051119
});
11061120

@@ -2254,11 +2268,34 @@ impl RuntimeService for BoxRuntimeService {
22542268
);
22552269

22562270
// Signal the container's supervisor to reopen its log writer at
2257-
// `log_path`. The kubelet rotates by renaming the current file before
2258-
// calling this, so the supervisor must drop the stale handle and open a
2259-
// fresh file at the original path (see `CriLogWriter::reopen`).
2260-
if let Some(reopen) = self.log_reopens.read().await.get(container_id) {
2261-
reopen.notify_one();
2271+
// `log_path` and WAIT for it to finish. The kubelet rotates by renaming
2272+
// the current file before calling this, so the supervisor must drop the
2273+
// stale handle and open a fresh file at the original path (see
2274+
// `CriLogWriter::reopen`). Returning synchronously guarantees output
2275+
// written after this RPC lands in the rotated file rather than racing
2276+
// the supervisor. Clone the notify handles out of the lock so we never
2277+
// hold it across the await.
2278+
let handles = {
2279+
let reopens = self.log_reopens.read().await;
2280+
reopens
2281+
.get(container_id)
2282+
.map(|handle| (handle.request.clone(), handle.done.clone()))
2283+
};
2284+
if let Some((request, done)) = handles {
2285+
// Register the done future BEFORE signalling so a fast supervisor
2286+
// cannot complete the reopen before we start waiting (notify_one
2287+
// also stores a permit, so there is no lost-wakeup either way).
2288+
let done = done.notified();
2289+
request.notify_one();
2290+
if tokio::time::timeout(std::time::Duration::from_secs(5), done)
2291+
.await
2292+
.is_err()
2293+
{
2294+
tracing::warn!(
2295+
container_id = %container_id,
2296+
"ReopenContainerLog timed out waiting for the supervisor to reopen the log"
2297+
);
2298+
}
22622299
}
22632300

22642301
Ok(Response::new(ReopenContainerLogResponse {}))

src/cri/src/runtime_service/supervisor.rs

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -54,6 +54,7 @@ pub(super) struct ContainerExitSupervisor {
5454
pub(super) attach_tx: AttachStreamSender,
5555
pub(super) stop_rx: oneshot::Receiver<()>,
5656
pub(super) log_reopen: Arc<Notify>,
57+
pub(super) log_reopen_done: Arc<Notify>,
5758
pub(super) workload: SupervisedWorkload,
5859
}
5960

@@ -72,6 +73,7 @@ pub(super) fn spawn_container_exit_supervisor(supervisor: ContainerExitSuperviso
7273
attach_tx,
7374
stop_rx,
7475
log_reopen,
76+
log_reopen_done,
7577
workload,
7678
} = supervisor;
7779
let mut workload = workload;
@@ -113,6 +115,9 @@ pub(super) fn spawn_container_exit_supervisor(supervisor: ContainerExitSuperviso
113115
log_writer = CriLogWriter::open(&log_path).await.ok().flatten();
114116
}
115117
}
118+
// Acknowledge so a synchronous ReopenContainerLog can return
119+
// only now that the new log file is in place.
120+
log_reopen_done.notify_one();
116121
}
117122
stop = &mut stop_rx, if !stop_requested => {
118123
stop_requested = true;

src/cri/src/runtime_service/tests.rs

Lines changed: 18 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -3191,25 +3191,33 @@ async fn test_reopen_container_log_signals_supervisor() {
31913191
let svc = make_test_service();
31923192
svc.store.containers.add(test_container("c-1", "sb-1")).await;
31933193

3194-
// Register a reopen signal as StartContainer does for a running container.
3194+
// Register a reopen handle as StartContainer does for a running container.
31953195
// The actual file reopen happens in the exit supervisor (integration-tested
3196-
// via critest); here we verify the RPC fires the per-container signal.
3197-
let signal = std::sync::Arc::new(tokio::sync::Notify::new());
3198-
svc.log_reopens
3199-
.write()
3200-
.await
3201-
.insert("c-1".to_string(), signal.clone());
3196+
// via critest); here we verify the RPC fires the per-container request and
3197+
// returns once the supervisor acks. Pre-arm `done` so the now-synchronous
3198+
// RPC does not block waiting for a supervisor that isn't running here.
3199+
let request = std::sync::Arc::new(tokio::sync::Notify::new());
3200+
let done = std::sync::Arc::new(tokio::sync::Notify::new());
3201+
done.notify_one();
3202+
svc.log_reopens.write().await.insert(
3203+
"c-1".to_string(),
3204+
super::LogReopenHandle {
3205+
request: request.clone(),
3206+
done: done.clone(),
3207+
},
3208+
);
32023209

32033210
svc.reopen_container_log(Request::new(ReopenContainerLogRequest {
32043211
container_id: "c-1".to_string(),
32053212
}))
32063213
.await
32073214
.unwrap();
32083215

3209-
// notify_one() stores a permit, so notified() resolves immediately.
3210-
tokio::time::timeout(std::time::Duration::from_secs(1), signal.notified())
3216+
// The RPC fired the per-container reopen request (notify_one stores a
3217+
// permit, so notified() resolves immediately).
3218+
tokio::time::timeout(std::time::Duration::from_secs(1), request.notified())
32113219
.await
3212-
.expect("ReopenContainerLog should signal the container's reopen notify");
3220+
.expect("ReopenContainerLog should signal the container's reopen request");
32133221
}
32143222

32153223
// ── Stop/Remove Pod Sandbox (store-only, no VM) ──────────────────

0 commit comments

Comments
 (0)