From dcb6fa17218c16b2d296670a6a17c782d0e98bc2 Mon Sep 17 00:00:00 2001 From: Timo Steuerwald Date: Mon, 31 Aug 2026 17:40:49 +0200 Subject: [PATCH 1/6] Reintroduce original commit e92504d --- .../details/process_info_node.cpp | 26 ++++++--- .../details/process_info_node_UT.cpp | 54 +++++++++++++++++++ 2 files changed, 72 insertions(+), 8 deletions(-) diff --git a/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp b/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp index ab943feecf..a5d8d7c86d 100644 --- a/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp +++ b/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp @@ -49,15 +49,23 @@ ProcessInfoNode::ProcessInfoNode(configuration::ComponentConfig&& config, Proces IComponent::RequestResult ProcessInfoNode::tryReportCompletion(score::mw::lifecycle::ProcessState new_state) { + if (new_state == ProcessState::kFailed) + { + // Didn't reach running or startup + return tryReportError(ComponentError::kErrorBeforeReady); + } + ProcessState desired_state; + bool has_process_state_condition = false; const auto& ready_condition = config_.component_properties.ready_condition; std::visit( - [&desired_state](auto&& arg) { + [&desired_state, &has_process_state_condition](auto&& arg) { using ReadyCondT = std::decay_t; if constexpr (std::is_same_v) { + has_process_state_condition = true; switch (arg) { case configuration::ProcessState::Running: @@ -75,12 +83,9 @@ IComponent::RequestResult ProcessInfoNode::tryReportCompletion(score::mw::lifecy }, ready_condition); - if (new_state == ProcessState::kFailed) - { - // Didn't reach running or startup - return tryReportError(ComponentError::kErrorBeforeReady); - } - if (new_state == desired_state) + // Reaching the desired state or beyond satisfies the ready condition: a self-terminating process + // may already have exited (kTerminated) by the time completion is reported. + if (has_process_state_condition && new_state >= desired_state) { return tryReportSuccess(); } @@ -281,7 +286,12 @@ IComponent::RequestResult ProcessInfoNode::startProcess(score::cpp::stop_token s } setState(ProcessState::kRunning); // Can fail if we've terminated already - return tryReportCompletion(ProcessState::kRunning); + + // A self-terminating process may already have exited before startup completed. tryHandleTermination() + // leaves such a node waiting for the startup thread, so report against the state actually reached. + const ProcessState reached_state = + (getState() == ProcessState::kTerminated) ? ProcessState::kTerminated : ProcessState::kRunning; + return tryReportCompletion(reached_state); } void ProcessInfoNode::setupControlClientChannel() diff --git a/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node_UT.cpp b/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node_UT.cpp index 0e38a596a3..c93e6257f2 100644 --- a/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node_UT.cpp +++ b/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node_UT.cpp @@ -268,6 +268,60 @@ TEST_F(ProcessInfoNodeStartupTest, SelfTerminating_ExitsBeforeMapInsert_ReturnsS ASSERT_THAT(node->getState(), Eq(score::mw::lifecycle::ProcessState::kTerminated)); } +TEST_F(ProcessInfoNodeStartupTest, SelfTerminating_TerminatedReadyCondition_ExitsBeforeMapInsert_ReturnsSuccess) +{ + RecordProperty( + "Description", + "A self-terminating process whose ready condition is Terminated and that exits with status 0 before the map " + "insertion completes reports success from activate() instead of waiting forever."); + + auto node = createProcessInfoNode( + configuration::ApplicationType::Native, 0U, true, configuration::ProcessState::Terminated); + // Simulate the process exiting before the map insertion happens. + EXPECT_CALL(mock_processIf_, startProcess(_, _, _)) + .WillOnce(DoAll( + InvokeWithoutArgs([node = node.get()] { + static_cast(node->tryHandleTermination(0)); + }), + Return(osal::OsalReturnType::kSuccess))); + EXPECT_CALL(*process_map_, insertIfNotTerminated(_, _)) + .WillOnce(Return(score::mw::lifecycle::internal::SafeProcessMapReturnType::kYield)); + + auto result = node->activate(score::cpp::stop_token{}); + + ASSERT_THAT(result.has_value(), IsTrue()); + ASSERT_THAT(result.value(), Eq(IComponent::RequestState::kSuccess)); + ASSERT_THAT(node->getState(), Eq(score::mw::lifecycle::ProcessState::kTerminated)); +} + +TEST_F(ProcessInfoNodeStartupTest, SelfTerminating_TerminatedReadyCondition_ReapedWhileWaitingForkRunning_ReturnsSuccess) +{ + RecordProperty( + "Description", + "A self-terminating reporting process whose ready condition is Terminated and that is reaped while the startup " + "thread is still waiting for kRunning reports success instead of losing its completion."); + + auto node = createProcessInfoNode( + configuration::ApplicationType::Reporting, 0U, true, configuration::ProcessState::Terminated); + expectSuccessfulProcessLaunch(); + // Simulate the OS handler reaping the process while the startup thread is blocked in waitForkRunning, + // i.e. before it could set kRunning. This is the race behind the flaky sandbox_options test (#503). + EXPECT_CALL(mock_processIf_, waitForkRunning(_, _)) + .WillOnce(DoAll( + InvokeWithoutArgs([node = node.get()] { + static_cast(node->tryHandleTermination(0)); + }), + Return(osal::OsalReturnType::kSuccess))); + EXPECT_CALL(mock_publisher_, reportActivation); + + auto result = node->activate(score::cpp::stop_token{}); + + ASSERT_THAT(result.has_value(), IsTrue()); + ASSERT_THAT(result.value(), Eq(IComponent::RequestState::kSuccess)); + ASSERT_THAT(node->active(), IsTrue()); + ASSERT_THAT(node->getState(), Eq(score::mw::lifecycle::ProcessState::kTerminated)); +} + TEST_F(ProcessInfoNodeStartupTest, ActivateAlreadyActiveNode_ReturnsSuccess) { RecordProperty( From 6a51485b016e0834e44fd071362f47bb8c2cd39b Mon Sep 17 00:00:00 2001 From: Timo Steuerwald Date: Mon, 31 Aug 2026 17:46:19 +0200 Subject: [PATCH 2/6] Adjust scheduling priorities Just to have different numbers tested --- tests/integration/sandbox_options/sandbox_options.json | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/integration/sandbox_options/sandbox_options.json b/tests/integration/sandbox_options/sandbox_options.json index 5005139d84..93cc9852aa 100644 --- a/tests/integration/sandbox_options/sandbox_options.json +++ b/tests/integration/sandbox_options/sandbox_options.json @@ -86,7 +86,7 @@ "--uid=0", "--gid=0", "--scheduling-policy=SCHED_RR", - "--scheduling-priority=10" + "--scheduling-priority=15" ], "ready_condition": { "process_state": "Terminated" @@ -101,7 +101,7 @@ "gid": 0, "supplementary_group_ids": [], "scheduling_policy": "SCHED_RR", - "scheduling_priority": 10 + "scheduling_priority": 20 } } }, From e156294126099a2d54d03d148d429bef16ffe88a Mon Sep 17 00:00:00 2001 From: Timo Steuerwald Date: Mon, 31 Aug 2026 17:47:00 +0200 Subject: [PATCH 3/6] Commit claude code analysis for now Needs to be reverted of cause. --- SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md | 113 ++++++++++++++++++++++++++++ 1 file changed, 113 insertions(+) create mode 100644 SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md diff --git a/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md b/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md new file mode 100644 index 0000000000..363d078f97 --- /dev/null +++ b/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md @@ -0,0 +1,113 @@ +# Root-cause analysis & fix: flaky `sandbox_options` integration test + +- **Issue:** [eclipse-score/lifecycle#503](https://github.com/eclipse-score/lifecycle/issues/503) — `//tests/integration/sandbox_options:sandbox_options` is flaky +- **Related:** [eclipse-score/lifecycle#554](https://github.com/eclipse-score/lifecycle/issues/554) — the launch-manager fix (reverted commit reintroduced via patch) +- **Branch:** `bugfix/stabilize-sandbox-options-test` + +## TL;DR + +The flake is **not** a test bug and **not** a scheduling bug. It is a genuine race in the +launch manager that real-time (`SCHED_FIFO`/`SCHED_RR`) scheduling merely *triggers* on +CPU-constrained hosts. The `NOTE: Cancellation timed out` log line is a **downstream +symptom** of that race, not an independent problem. + +The fix is the launch-manager change from issue #554 (it applies cleanly to current `main` +— it is **not** outdated), plus an added regression unit test for the exact #503 code path +and distinct scheduling priorities in the test config. + +## Answer: is "NOTE: Cancellation timed out" caused by scheduling? + +Not independent, but not a scheduling defect either — it is a symptom of an LM +activation-completion race that RT scheduling triggers. Evidence (all reproduced under a +single-core container pin, `cpuset_cpus="0"`): + +| Config | Before fix | After fix | +| -------------------------- | --------------------------- | ---------------- | +| FIFO/RR **prio 10** | fails | — | +| FIFO/RR **prio 1 & 2** | fails 1/60 (*same rate*) | — | +| **all SCHED_OTHER** | 0/60 (never fails) | — | +| FIFO 10 / RR 20 | (the flake) | **200/200 pass** | + +The identical failure rate at prio 1 vs prio 10 proves priority tuning **cannot** fix it: +any RT priority preempts the launch manager's `SCHED_OTHER` worker and reaper threads +equally. That is why the real fix had to be in the launch manager, not the test config. + +## Root cause (the race) + +For a self-terminating, `Reporting` process whose `ready_condition` is `Terminated` +(processes a/b/c in this test): + +1. A worker thread runs `startProcess()` → `setState(kStarting)` → forks the child → blocks + in `handleProcessStillStarting` / `waitForkRunning`. +2. The child completes its `report_running` handshake, then exits. +3. The `OsHandler` reaping thread reaps it and calls `tryHandleTermination()`. Because the + worker has **not yet** reached `setState(kRunning)`, `getState() < kRunning`, so it takes + the *"Defer to the startup thread"* branch — which sets `kTerminated` and reports **no + completion**. +4. The worker unblocks, finishes `startProcess()`, and calls `setState(kRunning)` — which + **fails** (state is already `kTerminated`, and `setState` only advances `new > old`). It + then reported `tryReportCompletion(kRunning)`, which **never matches** a `Terminated` + ready condition → returns `kWaiting`. + +Result: neither thread reports success. `jobs_in_progress_` never reaches 0 → the graph +never completes the transition → `verification_component` never runs → `test_end` is never +written → `run_until_file_deployed` raises `TimeoutError`. On the subsequent `SIGTERM`, the +cancel path waits on the stuck in-flight job and logs `NOTE: Cancellation timed out`. + +Key insight: ready-condition success is reported by **different threads** depending on the +condition — `ready=Running` is reported by the worker (at `kRunning`); `ready=Terminated` is +reported by `tryHandleTermination`. The "defer" branch wrongly assumed the worker would +report, but the worker only ever reported `kRunning`. + +### Log evidence (a reproduced failure, process_c) + +``` +...terminated with status 0 <- OsHandler reaps process_c +Got kRunning for pid 79 process 2 <- worker sets kRunning AFTER the reap +startProcess for process 2 done + <- "Component 2 finished activation successfully" NEVER appears +NOTE: Cancellation timed out <- downstream symptom +TimeoutError: File '/tmp/tests/test_end' did not appear within 3.0s +``` + +Processes a and b (whose workers won the race) logged `Got kRunning` *before* their +termination and both reported `finished activation successfully`. + +## The fix + +Launch manager (`process_info_node.cpp`, from #554): + +- `startProcess()` reports completion against the state **actually reached** — `kTerminated` + if the process already exited during startup — instead of blindly reporting `kRunning`. +- `tryReportCompletion()` treats `new_state >= desired_state` as success, so a `kTerminated` + report satisfies both `ready=Terminated` and a self-terminated `ready=Running` process. + +Unit tests (`process_info_node_UT.cpp`): + +- The #554 patch adds a test for the **Native / exits-before-map-insert** (`kYield`) path. +- Added `SelfTerminating_TerminatedReadyCondition_ReapedWhileWaitingForkRunning_ReturnsSuccess` + for the **Reporting / reaped-during-`waitForkRunning`** path — the exact #503 scenario the + integration test exercises. + +Test config (`tests/integration/sandbox_options/sandbox_options.json`): + +- `sandbox_options_process_b` (`SCHED_RR`) priority changed `10 → 20` so the three processes + use **distinct** priorities: `SCHED_FIFO=10`, `SCHED_RR=20`, `SCHED_OTHER=0`. All three + `scheduling_policy` values remain verified. + +## Verification + +- `//score/launch_manager/src/daemon/src/process_group_manager/details:process_info_node_UT` + — passes (patch test + new #503 regression test). +- `//score/launch_manager/...` — 30/30 tests pass. +- Integration test under the single-core repro pin — **200/200 pass** (was 1/60 failing). +- Official command — **200/200 pass**: + +``` +bazel test //tests/integration/sandbox_options:sandbox_options \ + --config=x86_64-linux --verbose_failures --nocache_test_results --runs_per_test=200 +``` + +> Note: the flake only reproduces under CPU contention. On a multi-core host the official +> command passes regardless of the fix; meaningful reproduction requires pinning the +> container to a single core (`cpuset_cpus="0"`) during investigation. From bb719bd79cbdb8ab18cd8e785fad71b9c9c8fc9c Mon Sep 17 00:00:00 2001 From: Timo Steuerwald Date: Tue, 1 Sep 2026 09:54:39 +0200 Subject: [PATCH 4/6] Adapt fix after rebase --- SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md | 56 ++++++++++++++++++- .../details/process_info_node.cpp | 9 +-- .../sandbox_options/sandbox_options.json | 2 +- 3 files changed, 61 insertions(+), 6 deletions(-) diff --git a/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md b/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md index 363d078f97..40f7b5d6ef 100644 --- a/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md +++ b/SANDBOX_OPTIONS_FLAKE_ROOT_CAUSE.md @@ -99,7 +99,7 @@ Test config (`tests/integration/sandbox_options/sandbox_options.json`): - `//score/launch_manager/src/daemon/src/process_group_manager/details:process_info_node_UT` — passes (patch test + new #503 regression test). -- `//score/launch_manager/...` — 30/30 tests pass. +- `//score/launch_manager/...` — all tests pass. - Integration test under the single-core repro pin — **200/200 pass** (was 1/60 failing). - Official command — **200/200 pass**: @@ -111,3 +111,57 @@ bazel test //tests/integration/sandbox_options:sandbox_options \ > Note: the flake only reproduces under CPU contention. On a multi-core host the official > command passes regardless of the fix; meaningful reproduction requires pinning the > container to a single core (`cpuset_cpus="0"`) during investigation. + +## Post-rebase follow-up (rebase onto `main`) + +After rebasing the fix branch onto `main`, the test suite broke again — for **two reasons +unrelated to the LM race**, both introduced by the rebase interacting with new `main` +commits (#500 "wait-for [file] ready condition", #523 "Use idhash as index", +#565 "Log process startup time"). Both are now fixed. + +### Issue 1 — `tryReportCompletion` conflict with the new `FileState` ready condition + +`main` #500 added a `FileState` alternative to the ready-condition variant, mapping it to +`desired_state = kRunning`. The #554 fix had gated success on a boolean +`has_process_state_condition` that was only set in the `ProcessState` branch. After the +rebase, a `FileState` ready condition therefore never set the flag, so +`tryReportCompletion` always returned `kWaiting` — success was never reported for +file-based ready conditions. + +Symptom: `ProcessInfoNodeFileStateTest` unit tests failed +(`ConditionAlreadyMet_ReturnsSuccess`, `NotExistingCondition_ReturnsSuccess`, +`NativeApplication_DoesNotIgnoreRunning_ReturnsSuccess`) with `reportActivation` never +called / `activate()` returning `kWaiting`. + +Fix: the guard represents "the ready condition maps to a comparable target state," which is +true for both `ProcessState` and `FileState`. Renamed it to `has_state_based_condition` and +set it in **both** branches of the `std::visit`. + +### Issue 2 — inconsistent `scheduling_priority` for process_b after conflict resolution + +The rebase conflict resolution left `sandbox_options_process_b` with **mismatched** priority +fields: + +- `process_arguments`: `--scheduling-priority=15` — the value the process *asserts* against +- `sandbox.scheduling_priority`: `20` — the value the launch manager *applies* + +The process reads its expected priority from `--scheduling-priority` and checks it against +its actual OS scheduling. The LM correctly applied `20`, but the process expected `15`, so +it failed its own gtest assertion and exited with code 256. That crashed the managed +process before `test_end` was written → `TimeoutError`, and the SIGTERM cancel then logged +`NOTE: Cancellation timed out` again — a good illustration that this log line is a **generic +"a job did not complete" symptom**, not specific to the LM race. + +Fix: set process_b's `--scheduling-priority` back to `20` so both fields match (the exact +config verified 200/200 before the rebase). Final config: `SCHED_FIFO=10` (a), +`SCHED_RR=20` (b), `SCHED_OTHER=0` (c) — three distinct priorities, all policies verified. + +> Note: a bazel JVM server crash (`error code: 14`, likely WSL2 memory pressure at 200 +> concurrent runs) truncated one retry, but the process_b mismatch was the real cause of the +> observed failure, independent of the crash. + +### Post-rebase verification + +- `//score/launch_manager/...` — **31/31 tests pass** (incl. the `FileState` tests and both + ProcessState race regression tests). +- Official command — **200/200 pass**. diff --git a/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp b/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp index a5d8d7c86d..02bca430cb 100644 --- a/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp +++ b/score/launch_manager/src/daemon/src/process_group_manager/details/process_info_node.cpp @@ -56,16 +56,16 @@ IComponent::RequestResult ProcessInfoNode::tryReportCompletion(score::mw::lifecy } ProcessState desired_state; - bool has_process_state_condition = false; + bool has_state_based_condition = false; const auto& ready_condition = config_.component_properties.ready_condition; std::visit( - [&desired_state, &has_process_state_condition](auto&& arg) { + [&desired_state, &has_state_based_condition](auto&& arg) { using ReadyCondT = std::decay_t; if constexpr (std::is_same_v) { - has_process_state_condition = true; + has_state_based_condition = true; switch (arg) { case configuration::ProcessState::Running: @@ -78,6 +78,7 @@ IComponent::RequestResult ProcessInfoNode::tryReportCompletion(score::mw::lifecy } else if constexpr (std::is_same_v) { + has_state_based_condition = true; desired_state = ProcessState::kRunning; } }, @@ -85,7 +86,7 @@ IComponent::RequestResult ProcessInfoNode::tryReportCompletion(score::mw::lifecy // Reaching the desired state or beyond satisfies the ready condition: a self-terminating process // may already have exited (kTerminated) by the time completion is reported. - if (has_process_state_condition && new_state >= desired_state) + if (has_state_based_condition && new_state >= desired_state) { return tryReportSuccess(); } diff --git a/tests/integration/sandbox_options/sandbox_options.json b/tests/integration/sandbox_options/sandbox_options.json index 93cc9852aa..eacc650af3 100644 --- a/tests/integration/sandbox_options/sandbox_options.json +++ b/tests/integration/sandbox_options/sandbox_options.json @@ -86,7 +86,7 @@ "--uid=0", "--gid=0", "--scheduling-policy=SCHED_RR", - "--scheduling-priority=15" + "--scheduling-priority=20" ], "ready_condition": { "process_state": "Terminated" From bcbfab28637934ffdb046e3e0c17f9a0040631b6 Mon Sep 17 00:00:00 2001 From: Timo Steuerwald Date: Tue, 1 Sep 2026 10:01:17 +0200 Subject: [PATCH 5/6] Force to execute sandbox_options test 200 times --- .github/workflows/on-pr.yml | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/.github/workflows/on-pr.yml b/.github/workflows/on-pr.yml index c7fa60f356..7e38e0f135 100644 --- a/.github/workflows/on-pr.yml +++ b/.github/workflows/on-pr.yml @@ -81,10 +81,7 @@ jobs: bazel test \ --lockfile_mode=error \ ${{ matrix.bazel-args }} \ - //examples/... \ - //score/... \ - //scripts/... \ - //tests/... + //tests/integration/sandbox_options --verbose_failures --nocache_test_results --runs_per_test=200 - name: Upload test logs if: always() From 3b541bc1a124ee400be366c5ce53379b3248e98a Mon Sep 17 00:00:00 2001 From: Timo Steuerwald Date: Tue, 1 Sep 2026 12:20:10 +0200 Subject: [PATCH 6/6] Increase test runs to 500 --- .github/workflows/on-pr.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/on-pr.yml b/.github/workflows/on-pr.yml index 7e38e0f135..39993844ed 100644 --- a/.github/workflows/on-pr.yml +++ b/.github/workflows/on-pr.yml @@ -81,7 +81,7 @@ jobs: bazel test \ --lockfile_mode=error \ ${{ matrix.bazel-args }} \ - //tests/integration/sandbox_options --verbose_failures --nocache_test_results --runs_per_test=200 + //tests/integration/sandbox_options --verbose_failures --nocache_test_results --runs_per_test=500 - name: Upload test logs if: always()