From 2f7af7b820c376d6b28ddb86811c235505812cd4 Mon Sep 17 00:00:00 2001 From: Stamatis Katsaounis Date: Mon, 7 Sep 2026 09:36:16 +0000 Subject: [PATCH] fix: ensure boot order is properly set before deployment reboot (#567) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit On BMCs where MAAS controls the boot order (`can_set_boot_order`, notably IBM Z DPM), deployment could fail two ways: - The firmware can't fall through from netboot to local disk. If the guest rebooted before MAAS flipped the boot device, it network-IPLed into an empty config and hung (No value found for kernel, IPL failed 110). - IBM Z rejects writes with 409,2 busy while another partition op is in flight (fire-and-forget start/stop settling, post-install re-IPL), causing power/boot activities to fail intermittently. - `deploy.py`: MAAS-driven boot switch. For `can_set_boot_order` machines, replace the bare "set boot order + rely on installer reboot" with an explicit sequence in `_switch_to_local_boot`: power off → set boot order to disk → power on → _confirm_powered_on. The confirm step polls power state (bounded) and persists it, de-bouncing transient BMC/HMC readings (state must repeat on two consecutive polls before it's persisted). - `hmcz.py`: busy handling. New `_retry_on_busy` helper wraps all HMC writes (power on/off, boot-order updates), retrying only on 409,2 and re-raising everything else. `set_boot_order` also waits out transitional states before writing and now accepts `paused`/`terminated`/`degraded` (not just `stopped`/`active`) so it doesn't hang the full 120s. Retry budget is deliberately capped (8×15s ≈ 105s) to stay well under the 300s Temporal activity timeout it shares with `wait_for_status`. Resolves: LP:2158318 --------- Co-authored-by: fheimes (cherry picked from commit d6747ef33047ce2a6c1d8f660586db2a9be11646) --- src/maastemporalworker/workflow/deploy.py | 89 +++++++++- src/provisioningserver/drivers/power/hmcz.py | 121 ++++++++++++-- .../drivers/power/tests/test_hmcz.py | 98 ++++++++++- .../workflow/test_deploy.py | 152 +++++++++++++++++- 4 files changed, 438 insertions(+), 22 deletions(-) diff --git a/src/maastemporalworker/workflow/deploy.py b/src/maastemporalworker/workflow/deploy.py index 9ac57a09af..527cb8d987 100644 --- a/src/maastemporalworker/workflow/deploy.py +++ b/src/maastemporalworker/workflow/deploy.py @@ -46,6 +46,7 @@ from maastemporalworker.workflow.power import ( POWER_ACTION_ACTIVITY_TIMEOUT, POWER_CYCLE_ACTIVITY_NAME, + POWER_OFF_ACTIVITY_NAME, POWER_ON_ACTIVITY_NAME, POWER_QUERY_ACTIVITY_NAME, SET_POWER_STATE_ACTIVITY_NAME, @@ -61,6 +62,12 @@ DEFAULT_DEPLOY_ACTIVITY_TIMEOUT = timedelta(seconds=30) DEFAULT_DEPLOY_RETRY_TIMEOUT = timedelta(seconds=60) +# _switch_to_local_boot()'s power-on is fire-and-forget, so poll afterwards +# to persist the real state. Some drivers (e.g. IBM Z HMC/DPM) can take +# minutes to settle. +CONFIRM_POWERED_ON_POLL_INTERVAL = timedelta(seconds=15) +CONFIRM_POWERED_ON_MAX_ATTEMPTS = 20 # ~5 minutes total + # Activities names GET_BOOT_ORDER_ACTIVITY_NAME = "get-boot-order" SET_NODE_STATUS_ACTIVITY_NAME = "set-node-status" @@ -490,6 +497,86 @@ async def _set_boot_order( else: raise InvalidMachineStateException("no boot order found") + async def _power(self, params: DeployParam, activity_name: str) -> None: + """Run a power activity (on/off) on the agent for this machine.""" + await workflow.execute_activity( + activity_name, + params.power_params, + task_queue=params.power_params.task_queue, + start_to_close_timeout=POWER_ACTION_ACTIVITY_TIMEOUT, + retry_policy=RetryPolicy(maximum_attempts=3), + ) + + async def _confirm_powered_on(self, params: DeployParam) -> None: + """Poll and persist the node's power state until it reads "on". + + The preceding power-on is fire-and-forget, so query the state on a + bounded poll and persist changes as they settle, reusing the + query-then-persist pattern from _start_deployment(). A reading is + only acted on once seen on two consecutive polls, to ignore + transient flaky reports from the BMC/HMC. + """ + persisted_state = None + candidate_state = None + for _ in range(CONFIRM_POWERED_ON_MAX_ATTEMPTS): + result = await workflow.execute_activity( + POWER_QUERY_ACTIVITY_NAME, + PowerQueryParam( + system_id=params.power_params.system_id, + driver_type=params.power_params.driver_type, + driver_opts=params.power_params.driver_opts, + task_queue=params.power_params.task_queue, + is_dpu=params.power_params.is_dpu, + ), + task_queue=params.power_params.task_queue, + start_to_close_timeout=POWER_ACTION_ACTIVITY_TIMEOUT, + retry_policy=RetryPolicy(maximum_attempts=3), + ) + state = PowerState(result["state"]) + if state != candidate_state: + candidate_state = state + elif state != persisted_state: + await workflow.execute_activity( + SET_POWER_STATE_ACTIVITY_NAME, + SetPowerStateParam( + system_id=params.power_params.system_id, + state=state, + ), + task_queue="region", + start_to_close_timeout=DEFAULT_DEPLOY_ACTIVITY_TIMEOUT, + retry_policy=RetryPolicy( + maximum_interval=DEFAULT_DEPLOY_RETRY_TIMEOUT, + ), + ) + persisted_state = state + if persisted_state == PowerState.ON: + return + await asyncio.sleep( + CONFIRM_POWERED_ON_POLL_INTERVAL.total_seconds() + ) + + async def _switch_to_local_boot(self, params: DeployParam) -> None: + """Point a boot-order-capable machine at its local disk to boot. + + MAAS drives the power transition itself (power off -> confirm off -> + set boot order to disk -> power on) instead of relying on the + in-installer reboot. + + This avoids a race specific to BMCs that MAAS controls the boot order + for (``can_set_boot_order``) and whose firmware cannot fall through + from a netboot config to the local disk -- notably IBM Z DPM. Once the + installer finishes, MAAS stops serving a netboot kernel; if the guest + reboots before the boot device is flipped to disk, the machine + network-IPLs into an empty config and hangs ("No value found for + kernel", IPL failed 110). Powering off and confirming the machine is + actually down before the flip closes that window (and also sidesteps + the transient HMC "busy" state seen while an operation is in flight). + """ + await self._power(params, POWER_OFF_ACTIVITY_NAME) + await self._set_boot_order(params, netboot=False) + await self._power(params, POWER_ON_ACTIVITY_NAME) + await self._confirm_powered_on(params) + @workflow_run_with_context async def run(self, params: DeployParam) -> DeployResult: # Arm network boot before powering on so the machine PXE boots into @@ -504,7 +591,7 @@ async def run(self, params: DeployParam) -> DeployResult: await workflow.wait_condition(lambda: self._has_netbooted) if params.can_set_boot_order: - await self._set_boot_order(params, netboot=False) + await self._switch_to_local_boot(params) await workflow.wait_condition(lambda: self._deployed_os_ready) diff --git a/src/provisioningserver/drivers/power/hmcz.py b/src/provisioningserver/drivers/power/hmcz.py index 42a0acdecc..a32cf1b06f 100644 --- a/src/provisioningserver/drivers/power/hmcz.py +++ b/src/provisioningserver/drivers/power/hmcz.py @@ -10,6 +10,7 @@ """ import contextlib +import time from twisted.internet.defer import inlineCallbacks @@ -31,7 +32,7 @@ from provisioningserver.utils.twisted import asynchronous, threadDeferred try: - from zhmcclient import Client, NotFound, Session, StatusTimeout + from zhmcclient import Client, HTTPError, NotFound, Session, StatusTimeout except ImportError: no_zhmcclient = True else: @@ -39,11 +40,76 @@ maaslog = get_maas_logger("drivers.power.hmcz") + +def _retry_on_busy( + func, + *args, + op_desc, + system_id, + max_attempts=12, + retry_delay=5, + **kwargs, +): + """Run a zhmcclient call, retrying while the partition is 409,2 busy. + + IBM Z rejects a write against a partition with HTTP 409 reason 2 while + another operation is in flight on that partition -- e.g. a fire-and-forget + start/stop still settling on the HMC, or a guest re-IPL after the install. + That busy window is transient and is not reflected in the partition status, + so retry the call for a bounded time before giving up. Any other error is + re-raised immediately. + + These power/boot operations run inside the short-lived maas.power CLI under + a Temporal power activity whose start_to_close timeout is 5 minutes, so the + ~60s budget here stays comfortably under that. + """ + for attempt in range(1, max_attempts + 1): + try: + return func(*args, **kwargs) + except HTTPError as exc: + if not (exc.http_status == 409 and exc.reason == 2): + raise + if attempt >= max_attempts: + maaslog.error( + "%s: %s still 409,2 busy after %d attempts; giving up. " + "HMC error: %s [%s %s]", + system_id, + op_desc, + attempt, + exc.message, + exc.request_method, + exc.request_uri, + ) + raise + maaslog.warning( + "%s: %s got 409,2 busy (attempt %d/%d); retrying in %ds. " + "HMC error: %s [%s %s]", + system_id, + op_desc, + attempt, + max_attempts, + retry_delay, + exc.message, + exc.request_method, + exc.request_uri, + ) + time.sleep(retry_delay) + + VERIFY_SSL_YES = "y" VERIFY_SSL_NO = "n" VERIFY_SSL_CHOICES = [[VERIFY_SSL_NO, "No"], [VERIFY_SSL_YES, "Yes"]] +# set_boot_order shares the single 5 minute (300s) Temporal power activity +# budget with an upfront partition.wait_for_status() that can block up to 120s. +# Keep the busy-retry budget small enough that 120s + retries + the HMC session +# setup still finish well under 300s; otherwise Temporal aborts and retries the +# activity while this Twisted thread keeps writing to the HMC in the background. +# 8 attempts => 7 x 15s = 105s of retries, so ~225s worst case (120s + 105s). +SET_BOOT_ORDER_RETRY_MAX_ATTEMPTS = 8 +SET_BOOT_ORDER_RETRY_DELAY = 15 + class HMCZPowerDriver(PowerDriver): name = "hmcz" @@ -122,7 +188,12 @@ def power_on(self, system_id: str, context: dict): # the stop action completes. This holds the thread in MAAS for ~30s. # IBM is aware this isn't optimal for us so they are looking into # modifying IBM Z to go into a stopped state. - partition.stop(wait_for_completion=True) + _retry_on_busy( + partition.stop, + wait_for_completion=True, + op_desc="power_on pre-start stop", + system_id=system_id, + ) elif status == "stopping": # The HMC does not allow a machine to be powered on if its # currently stopping. Wait 120s for it which should be more @@ -138,7 +209,12 @@ def power_on(self, system_id: str, context: dict): f"{partition.get_property('status')} state!" ) - partition.start(wait_for_completion=False) + _retry_on_busy( + partition.start, + wait_for_completion=False, + op_desc="power_on start", + system_id=system_id, + ) @asynchronous @threadDeferred @@ -160,7 +236,12 @@ def power_off(self, system_id: str, context: dict): "Partition is stuck in a " f"{partition.get_property('status')} state!" ) - partition.stop(wait_for_completion=False) + _retry_on_busy( + partition.stop, + wait_for_completion=False, + op_desc="power_off stop", + system_id=system_id, + ) @asynchronous @threadDeferred @@ -206,9 +287,17 @@ def set_boot_order(self, system_id: str, context: dict, order: list): if status in {"starting", "stopping"}: # The HMC does not allow a machine's boot order to be reconfigured - # while in a transitional state. Wait for it to complete. If this - # times out allow it to be raised so the region can log it. - partition.wait_for_status(["stopped", "active"], 120) + # while in a transitional (starting/stopping) state. Wait for it to + # settle. Accept any non-transitional state -- including "paused", + # which IBM Z can land in (e.g. after `shutdown -h now` or a quick + # release/redeploy) and which never resolves to stopped/active on + # its own. Waiting only for ["stopped", "active"] would then hang + # the full 120s and raise StatusTimeout. If it times out anyway, + # allow it to be raised so the region can log it. + partition.wait_for_status( + ["stopped", "active", "degraded", "paused", "terminated"], + 120, + ) # You can only specify one boot device on IBM Z boot_device = order[0] @@ -216,11 +305,16 @@ def set_boot_order(self, system_id: str, context: dict, order: list): nic = partition.nics.find( **{"mac-address": boot_device["mac_address"]} ) - partition.update_properties( + _retry_on_busy( + partition.update_properties, { "boot-device": "network-adapter", "boot-network-device": nic.uri, - } + }, + op_desc="set_boot_order network-adapter", + system_id=system_id, + max_attempts=SET_BOOT_ORDER_RETRY_MAX_ATTEMPTS, + retry_delay=SET_BOOT_ORDER_RETRY_DELAY, ) else: for storage_group in partition.list_attached_storage_groups(): @@ -233,11 +327,16 @@ def set_boot_order(self, system_id: str, context: dict, order: list): vol.properties.get("uuid", "").strip(), vol.properties.get("serial-number", "").strip(), ]: - partition.update_properties( + _retry_on_busy( + partition.update_properties, { "boot-device": "storage-volume", "boot-storage-volume": vol.uri, - } + }, + op_desc="set_boot_order storage-volume", + system_id=system_id, + max_attempts=SET_BOOT_ORDER_RETRY_MAX_ATTEMPTS, + retry_delay=SET_BOOT_ORDER_RETRY_DELAY, ) return diff --git a/src/provisioningserver/drivers/power/tests/test_hmcz.py b/src/provisioningserver/drivers/power/tests/test_hmcz.py index 8b9e170ed6..6c42da1ace 100644 --- a/src/provisioningserver/drivers/power/tests/test_hmcz.py +++ b/src/provisioningserver/drivers/power/tests/test_hmcz.py @@ -11,7 +11,7 @@ import pytest from twisted.internet.defer import inlineCallbacks, succeed -from zhmcclient import StatusTimeout +from zhmcclient import HTTPError, StatusTimeout from zhmcclient_mock import FakedSession from maastesting import get_testing_timeout @@ -562,7 +562,7 @@ def test_set_boot_order_waits_for_starting_state(self): ) mock_get_partition.return_value.wait_for_status.assert_called_once_with( - ["stopped", "active"], 120 + ["stopped", "active", "degraded", "paused", "terminated"], 120 ) @inlineCallbacks @@ -579,10 +579,102 @@ def test_set_boot_order_waits_for_stopping_state(self): ) mock_get_partition.return_value.wait_for_status.assert_called_once_with( - ["stopped", "active"], 120 + ["stopped", "active", "degraded", "paused", "terminated"], 120 ) +class TestRetryOnBusy(MAASTestCase): + """Tests for `hmcz._retry_on_busy`.""" + + def make_busy_error(self): + return HTTPError( + { + "http-status": 409, + "reason": 2, + "message": "object is busy with another operation", + "request-method": "POST", + "request-uri": "/api/partitions/abc", + } + ) + + def test_returns_result_without_retrying_on_success(self): + mock_sleep = self.patch(hmcz_module.time, "sleep") + func = Mock(return_value="ok") + + result = hmcz_module._retry_on_busy( + func, "arg", op_desc="op", system_id="sys", kw=1 + ) + + self.assertEqual(result, "ok") + func.assert_called_once_with("arg", kw=1) + mock_sleep.assert_not_called() + + def test_retries_while_409_2_busy_then_succeeds(self): + mock_sleep = self.patch(hmcz_module.time, "sleep") + func = Mock( + side_effect=[ + self.make_busy_error(), + self.make_busy_error(), + "ok", + ] + ) + + result = hmcz_module._retry_on_busy( + func, op_desc="op", system_id="sys", retry_delay=5 + ) + + self.assertEqual(result, "ok") + self.assertEqual(func.call_count, 3) + self.assertEqual(mock_sleep.call_count, 2) + mock_sleep.assert_called_with(5) + + def test_reraises_other_http_errors_immediately(self): + mock_sleep = self.patch(hmcz_module.time, "sleep") + other = HTTPError({"http-status": 500, "reason": 1}) + func = Mock(side_effect=other) + + self.assertRaises( + HTTPError, + hmcz_module._retry_on_busy, + func, + op_desc="op", + system_id="sys", + ) + func.assert_called_once() + mock_sleep.assert_not_called() + + def test_reraises_409_with_other_reason_immediately(self): + mock_sleep = self.patch(hmcz_module.time, "sleep") + other = HTTPError({"http-status": 409, "reason": 1}) + func = Mock(side_effect=other) + + self.assertRaises( + HTTPError, + hmcz_module._retry_on_busy, + func, + op_desc="op", + system_id="sys", + ) + func.assert_called_once() + mock_sleep.assert_not_called() + + def test_gives_up_and_reraises_after_max_attempts(self): + mock_sleep = self.patch(hmcz_module.time, "sleep") + func = Mock(side_effect=self.make_busy_error()) + + self.assertRaises( + HTTPError, + hmcz_module._retry_on_busy, + func, + op_desc="op", + system_id="sys", + max_attempts=3, + ) + self.assertEqual(func.call_count, 3) + # No sleep after the final (failing) attempt. + self.assertEqual(mock_sleep.call_count, 2) + + @dataclass class FakeNode: architecture: str diff --git a/src/tests/maastemporalworker/workflow/test_deploy.py b/src/tests/maastemporalworker/workflow/test_deploy.py index 9b44c6691e..cbfb2ec46f 100644 --- a/src/tests/maastemporalworker/workflow/test_deploy.py +++ b/src/tests/maastemporalworker/workflow/test_deploy.py @@ -1,7 +1,7 @@ from collections import defaultdict from datetime import datetime, timedelta from typing import Any -from unittest.mock import Mock +from unittest.mock import AsyncMock, Mock import uuid import pytest @@ -17,6 +17,7 @@ from maascommon.constants import NODE_TIMEOUT from maascommon.enums.node import NodeStatus +from maascommon.enums.power import PowerState from maascommon.workflows.deploy import ( DEPLOY_MANY_WORKFLOW_NAME, DEPLOY_WORKFLOW_NAME, @@ -34,6 +35,7 @@ from maasservicelayer.models.nodes import Node from maasservicelayer.services import CacheForServices from maastemporalworker.workflow.deploy import ( + CONFIRM_POWERED_ON_MAX_ATTEMPTS, DeployActivity, DeployManyParam, DeployManyWorkflow, @@ -807,10 +809,24 @@ async def set_power_state(params: SetPowerStateParam) -> None: assert len(calls["set_node_status"]) == 3 assert len(calls["get_boot_order"]) == 2 - assert len(calls["power_query"]) == 3 - assert len(calls["power_on"]) == 3 + # 3 deploy-start queries + CONFIRM_POWERED_ON_MAX_ATTEMPTS + # confirm polls for the single can_set_boot_order machine + # after its switch-to-local-boot power-on. The mocked query + # never reports "on", so the confirm loop runs to exhaustion; + # its settle/debounce logic is covered in TestConfirmPoweredOn. + assert ( + len(calls["power_query"]) + == 3 + CONFIRM_POWERED_ON_MAX_ATTEMPTS + ) + # 3 initial deploy power-ons + 1 extra power-on for the single + # can_set_boot_order machine, which MAAS power-cycles to switch + # its boot device to disk (power off -> set boot order -> + # power on). + assert len(calls["power_on"]) == 4 + assert len(calls["power_off"]) == 1 assert len(calls["power_cycle"]) == 0 - assert len(calls["set_power_state"]) == 3 + # 3 deploy-start persists + one confirm-loop persist. + assert len(calls["set_power_state"]) == 4 assert len(calls["power_reset"]) == 0 async def test_one_ephemeral( @@ -1510,10 +1526,23 @@ async def set_power_state(params: SetPowerStateParam) -> None: assert len(calls["set_node_status"]) == 0 assert len(calls["get_boot_order"]) == 2 assert len(calls["set_boot_order"]) == 2 - assert len(calls["power_query"]) == 1 - assert len(calls["power_on"]) == 1 + # 1 deploy-start query + CONFIRM_POWERED_ON_MAX_ATTEMPTS + # confirm polls after the switch-to-local-boot power-on. The + # mocked query never reports "on", so the confirm loop runs to + # exhaustion; its settle/debounce logic is covered in + # TestConfirmPoweredOn. + assert ( + len(calls["power_query"]) + == 1 + CONFIRM_POWERED_ON_MAX_ATTEMPTS + ) + # Two power-ons: the initial deploy start, plus the + # MAAS-driven power-on after switching the boot device to + # disk (power off -> set boot order -> power on). + assert len(calls["power_on"]) == 2 + assert len(calls["power_off"]) == 1 assert len(calls["power_cycle"]) == 0 - assert len(calls["set_power_state"]) == 1 + # deploy-start persist + one confirm-loop persist. + assert len(calls["set_power_state"]) == 2 assert len(calls["power_reset"]) == 0 async def test_deploy_workflow_ephemeral_sets_network_boot_order( @@ -1736,3 +1765,112 @@ async def set_power_state(params: SetPowerStateParam) -> None: await wf.result() temporal_calls.assert_activity_calls([]) + + +@pytest.mark.asyncio +class TestConfirmPoweredOn: + """Unit tests for `DeployWorkflow._confirm_powered_on`. + + Drives the method directly with `workflow.execute_activity` and + `asyncio.sleep` mocked, so the query sequence (and thus the settle and + debounce behavior) can be scripted deterministically without a Temporal + server. + """ + + def _params(self) -> DeployParam: + return DeployParam( + system_id="abc", + ephemeral_deploy=False, + can_set_boot_order=True, + task_queue="agent:1", + power_params=PowerParam( + system_id="abc", + driver_type="hmcz", + driver_opts={}, + task_queue="agent:1", + is_dpu=False, + ), + ) + + async def _drive( + self, mocker: MockerFixture, query_states: list[str] + ) -> tuple[int, list[PowerState], AsyncMock]: + """Run `_confirm_powered_on` against a scripted query sequence. + + Returns the number of power-query calls, the list of states persisted + via SET_POWER_STATE, and the patched sleep mock. Once `query_states` + is exhausted the last value is repeated, so callers can pad to + `CONFIRM_POWERED_ON_MAX_ATTEMPTS` or let a terminal state persist. + """ + states = iter(query_states) + last = None + query_calls = 0 + persisted: list[PowerState] = [] + + def execute_activity(name, *args, **kwargs): + nonlocal query_calls, last + if name == POWER_QUERY_ACTIVITY_NAME: + query_calls += 1 + try: + last = next(states) + except StopIteration: + pass + return {"state": last} + if name == SET_POWER_STATE_ACTIVITY_NAME: + persisted.append(args[0].state) + return None + raise AssertionError(f"unexpected activity: {name}") + + mocker.patch( + "maastemporalworker.workflow.deploy.workflow.execute_activity", + AsyncMock(side_effect=execute_activity), + ) + sleep = AsyncMock() + mocker.patch("maastemporalworker.workflow.deploy.asyncio.sleep", sleep) + + await DeployWorkflow()._confirm_powered_on(self._params()) + return query_calls, persisted, sleep + + async def test_settles_after_two_consecutive_on_readings( + self, mocker: MockerFixture + ) -> None: + query_calls, persisted, sleep = await self._drive(mocker, ["on", "on"]) + + assert query_calls == 2 + assert persisted == [PowerState.ON] + assert sleep.await_count == 1 + + async def test_persists_each_state_as_it_settles( + self, mocker: MockerFixture + ) -> None: + query_calls, persisted, _ = await self._drive( + mocker, ["off", "off", "unknown", "unknown", "on", "on"] + ) + + assert query_calls == 6 + assert persisted == [ + PowerState.OFF, + PowerState.UNKNOWN, + PowerState.ON, + ] + + async def test_gives_up_after_max_attempts_when_never_on( + self, mocker: MockerFixture + ) -> None: + query_calls, persisted, sleep = await self._drive(mocker, ["off"]) + + assert query_calls == CONFIRM_POWERED_ON_MAX_ATTEMPTS + assert persisted == [PowerState.OFF] + assert sleep.await_count == CONFIRM_POWERED_ON_MAX_ATTEMPTS + + async def test_ignores_single_flaky_reading( + self, mocker: MockerFixture + ) -> None: + # A one-off "on" seen on a single poll (not confirmed on the next) + # must never be persisted. + _, persisted, _ = await self._drive( + mocker, ["off", "off", "on", "off"] + ) + + assert PowerState.ON not in persisted + assert persisted == [PowerState.OFF]