From 6c8e52addef092ec0a5ba7e71c8e40f2a96261bf Mon Sep 17 00:00:00 2001 From: Sathish Mathimaran Date: Tue, 4 Aug 2026 10:52:18 +0530 Subject: [PATCH 1/6] Fix auto-assessment systemd startup timeout (Bug #28537460) Keep Type=forking and extend TimeoutStartSec to 10 minutes for slow assessments. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/investigations/28537460/rca-report.md | 59 ++++++++++++++++++++++ src/core/src/core_logic/ServiceManager.py | 9 ++-- src/core/tests/Test_ServiceManager.py | 10 +++- 3 files changed, 73 insertions(+), 5 deletions(-) create mode 100644 docs/investigations/28537460/rca-report.md diff --git a/docs/investigations/28537460/rca-report.md b/docs/investigations/28537460/rca-report.md new file mode 100644 index 00000000..ccc9e778 --- /dev/null +++ b/docs/investigations/28537460/rca-report.md @@ -0,0 +1,59 @@ +# RCA Report - Bug #28537460 + +## Summary + +Linux auto-assessment can remain in progress when a valid assessment exceeds +systemd's default 90-second service start timeout. The initial mitigation keeps +the existing `Type=forking` lifecycle and extends the generated unit's bounded +startup window to 10 minutes. + +## Evidence Collected + +- **Bug metadata**: Bug 28537460 is a high-severity recurring issue affecting + Azure and Arc Linux VMs across multiple distributions. +- **Historical patterns**: Bug 33342595 reports the same + `MsftLinuxPatchAutoAssess.service` timeout signature. Bug 24467908 and PR 203 + introduced `Type=forking` after `Type=notify` caused service failures. +- **Runtime evidence**: GitHub issue 350 demonstrates systemd sending SIGTERM at + approximately 90 seconds while package-manager work is still running. +- **Duration evidence**: A one-day sample of on-demand assessments had P99 near + 215 seconds and P99.9 near 256 seconds. A 10-minute timeout provides + substantial margin while remaining bounded. +- **Source code findings**: `ServiceManager.create_service_unit_file()` does not + emit `TimeoutStartSec`, so systemd applies its manager default. The extension + permits auto-assessment operations to run for up to one hour. + +## Root Cause + +The generated `MsftLinuxPatchAutoAssess.service` uses `Type=forking`. systemd +therefore keeps the unit in its startup phase until it observes the expected +forking lifecycle. If assessment startup and package-manager work exceed the +default `TimeoutStartSec=90s`, systemd terminates the service cgroup before the +extension writes terminal assessment status. Azure Update Manager then retains +the stale `In Progress` state. + +## Competing Hypotheses + +1. **Package-manager work is always hung indefinitely**: Some historical cases + involved unbounded package-manager retries, but the deterministic reproduction + uses an intentionally slow command that eventually completes. The exact + 90-second termination is imposed by systemd rather than the package manager. +2. **The service lifecycle should immediately change to `Type=simple`**: This + matches the foreground wrapper more closely and removes the startup gate, but + email review identified cross-distribution and lifecycle regression testing + as a prerequisite. +3. **The startup timeout is too short for valid assessments**: The observed + duration distribution and exact systemd timeout support this as the safest + first mitigation. + +## Selected Fix + +Keep `Type=forking` and add `TimeoutStartSec=10min` to the generated service +unit. This avoids changing the established lifecycle model while allowing +normal slow assessments to finish. The timeout remains bounded so a process +that never reaches the expected started state is still terminated. + +The validation plan reproduces the 90-second failure on an Azure Linux VM, +copies the modified `ServiceManager.py` into the installed extension, regenerates +the service, and verifies that the same assessment runs beyond 90 seconds and +completes before 10 minutes. diff --git a/src/core/src/core_logic/ServiceManager.py b/src/core/src/core_logic/ServiceManager.py index 9c8dde78..f69344cf 100644 --- a/src/core/src/core_logic/ServiceManager.py +++ b/src/core/src/core_logic/ServiceManager.py @@ -89,17 +89,18 @@ def is_service_enabled(self): # endregion # region - Service Unit Management - def create_service_unit_file(self, exec_start, desc, after="network.target", service_type="forking", wanted_by="multi-user.target"): + def create_service_unit_file(self, exec_start, desc, after="network.target", service_type="forking", timeout_start_sec="10min", wanted_by="multi-user.target"): """ Note: Service type defaults to forking because of sh to py process fork """ service_unit_content_template = "\n[Unit]" + \ "\nDescription={0}" + \ "\nAfter={1}\n" + \ "\n[Service]" + \ "\nType={2}" + \ - "\nExecStart={3}\n" + \ + "\nExecStart={3}" + \ + "\nTimeoutStartSec={4}\n" + \ "\n[Install]" + \ - "\nWantedBy={4}" - service_unit_content = service_unit_content_template.format(desc, after, service_type, exec_start, wanted_by) + "\nWantedBy={5}" + service_unit_content = service_unit_content_template.format(desc, after, service_type, exec_start, timeout_start_sec, wanted_by) service_unit_path = self.__systemd_service_unit_path.format(self.service_name) self.env_layer.file_system.write_with_retry(service_unit_path, service_unit_content) self.env_layer.run_command_output("sudo chmod 644 " + service_unit_path) # 644 = Owner: RW; Group: R; Others: R diff --git a/src/core/tests/Test_ServiceManager.py b/src/core/tests/Test_ServiceManager.py index 0eb406ff..ec4216c2 100644 --- a/src/core/tests/Test_ServiceManager.py +++ b/src/core/tests/Test_ServiceManager.py @@ -28,6 +28,8 @@ def setUp(self): self.service_manager = ServiceManager(self.runtime.env_layer, self.runtime.execution_config, self.runtime.composite_logger, self.runtime.telemetry_writer,ServiceInfo("AutoAssessment", "Auto assessment service", "path")) self.service_manager.service_name = "test_service" self.mock_systemd_service_unit_path = "/etc/systemd/system/{0}.service" + self.written_service_unit_path = None + self.written_service_unit_content = None def tearDown(self): self.runtime.stop() @@ -38,6 +40,8 @@ def mock_run_command_to_set_service_file_permission(self, cmd, no_output=False, return 0, "permissions set" def mock_write_with_retry_valid(self, file_path_or_handle, data, mode='a+'): + self.written_service_unit_path = file_path_or_handle + self.written_service_unit_content = data return def mock_invoke_systemctl(self, command, description): @@ -58,11 +62,15 @@ def mock_invoke_systemctl(self, command, description): elif "is-active" in command: return 0, "Checking if service is active" - def test_create_service_unit_file(self): + def test_create_service_unit_file_sets_ten_minute_start_timeout(self): self.service_manager.env_layer.run_command_output = self.mock_run_command_to_set_service_file_permission self.service_manager.env_layer.file_system.write_with_retry = self.mock_write_with_retry_valid self.service_manager.create_service_unit_file(exec_start="/bin/bash " + self.service_manager.service_exec_path, desc="Microsoft Azure Linux Patch Extension - Auto Assessment") + self.assertEqual("/etc/systemd/system/test_service.service", self.written_service_unit_path) + self.assertIn("\nType=forking\n", self.written_service_unit_content) + self.assertIn("\nTimeoutStartSec=10min\n", self.written_service_unit_content) + def test_start_service(self): # Set method calls self.service_manager.invoke_systemctl_called = False From 51a4d463a51a1a521165a090667090db1ec190e9 Mon Sep 17 00:00:00 2001 From: Sathish Mathimaran Date: Tue, 4 Aug 2026 11:33:54 +0530 Subject: [PATCH 2/6] Document RHEL VM validation for Bug #28537460 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/investigations/28537460/rca-report.md | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/docs/investigations/28537460/rca-report.md b/docs/investigations/28537460/rca-report.md index ccc9e778..f0ece21b 100644 --- a/docs/investigations/28537460/rca-report.md +++ b/docs/investigations/28537460/rca-report.md @@ -57,3 +57,23 @@ The validation plan reproduces the 90-second failure on an Azure Linux VM, copies the modified `ServiceManager.py` into the installed extension, regenerates the service, and verifies that the same assessment runs beyond 90 seconds and completes before 10 minutes. + +## Azure VM Validation + +- **VM**: Azure RHEL 8.9, systemd 239, Linux Patch Extension 1.6.71. +- **Reproduction**: Wrapped `/usr/bin/yum` to delay its first invocation by + 120 seconds and forced auto-assessment to run. +- **Before the fix**: `systemctl start` failed after exactly 90 seconds. + `systemctl show` reported `TimeoutStartUSec=1min 30s`, `Result=timeout`, and + the journal recorded `start operation timed out. Terminating.` +- **Deployment**: Built the extension from this branch, copied the generated + `MsftLinuxPatchCore.py` over the installed extension payload, and reran + `ConfigurePatching` to regenerate the systemd unit. +- **After the fix**: The unit retained `Type=forking` and reported + `TimeoutStartUSec=10min`. The delayed real assessment completed successfully: + the assessment stopwatch reported 136 seconds and systemd reported + `Result=success`. +- **Non-regression**: A subsequent platform-triggered on-demand assessment + completed with status `Succeeded`. +- **Cleanup**: The `yum` wrapper was removed, the original executable was + restored, and the auto-assessment timer was active after validation. From f55f633c7df2efe996869278db521912e95b6154 Mon Sep 17 00:00:00 2001 From: Sathish Mathimaran Date: Tue, 4 Aug 2026 12:57:39 +0530 Subject: [PATCH 3/6] Document Ubuntu and SLES timeout validation Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/investigations/28537460/rca-report.md | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/docs/investigations/28537460/rca-report.md b/docs/investigations/28537460/rca-report.md index f0ece21b..9fcc0967 100644 --- a/docs/investigations/28537460/rca-report.md +++ b/docs/investigations/28537460/rca-report.md @@ -77,3 +77,24 @@ completes before 10 minutes. completed with status `Succeeded`. - **Cleanup**: The `yum` wrapper was removed, the original executable was restored, and the auto-assessment timer was active after validation. + +## Supported Distro Sanity Matrix + +The same test was repeated on Azure VMs using Linux Patch Extension 1.6.71. +Each package-manager wrapper delayed only its first invocation by 120 seconds. + +| Distribution | Delayed command | Before fix | After fix | Platform assessment | +| --- | --- | --- | --- | --- | +| Ubuntu 22.04.5 LTS | `apt-get` | Failed at 90s with `Result=timeout` | Service completed in 157s with `Result=success`; patch assessment completed | `Succeeded` | +| Ubuntu 24.04.4 LTS | `apt-get` | Failed at 90s with `Result=timeout` | Service completed in 136s with `Result=success`; patch assessment completed | `Succeeded` | +| SLES 15 SP5 | `zypper refresh` | Failed at 90s with `Result=timeout` | Service completed in 144s with `Result=success`; assessment stopwatch reported 133.1s | `Succeeded` | + +All three regenerated units retained `Type=forking` and reported +`TimeoutStartUSec=10min`. After each run, the original package-manager +executable was restored and `MsftLinuxPatchAutoAssess.timer` was active. + +On Ubuntu, the intentional delay occurred during the +`ubuntu-advantage-tools` prerequisite step before the assessment stopwatch +started. The full systemd service duration therefore captures the delayed +startup, while the logs separately confirm the subsequent patch assessment +completed successfully. From 3173e7a5988ed8b06ab8412bb79b88c9b8a1fbf7 Mon Sep 17 00:00:00 2001 From: Sathish Mathimaran Date: Tue, 11 Aug 2026 12:16:05 +0530 Subject: [PATCH 4/6] Docs: record 10-minute timeout validation (Bug #28537460) Document the four-distro 600-second boundary test and retained evidence location. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/investigations/28537460/rca-report.md | 26 ++++++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/docs/investigations/28537460/rca-report.md b/docs/investigations/28537460/rca-report.md index 9fcc0967..897a6911 100644 --- a/docs/investigations/28537460/rca-report.md +++ b/docs/investigations/28537460/rca-report.md @@ -98,3 +98,29 @@ On Ubuntu, the intentional delay occurred during the started. The full systemd service duration therefore captures the delayed startup, while the logs separately confirm the subsequent patch assessment completed successfully. + +## Ten-Minute Timeout Boundary Validation + +The fixed unit was retested on new Azure VMs in `westus2` with a 660-second +delay on the first package-manager invocation. This verifies that the service +does not remain indefinitely in `activating` after increasing the startup +timeout. + +| Distribution | Delayed command | Configured timeout | Observed result | +| --- | --- | --- | --- | +| RHEL 8.9 | `yum -q check-update` | 10 minutes | Timed out at exactly 600s | +| Ubuntu 22.04.5 LTS | `apt-get install ubuntu-advantage-tools -y` | 10 minutes | Timed out at exactly 600s | +| Ubuntu 24.04.4 LTS | `apt-get install ubuntu-advantage-tools -y` | 10 minutes | Timed out at exactly 600s | +| SLES 15 SP5 | `zypper refresh` | 10 minutes | Timed out at exactly 600s | + +All units contained `Type=forking` and `TimeoutStartSec=10min`. Each +`systemctl start` returned 1, and the final service state was +`ActiveState=failed`, `SubState=failed`, and `Result=timeout`. The journals +recorded `start operation timed out. Terminating.` at the 600-second boundary. + +After each test, the original package-manager executable was restored and +`MsftLinuxPatchAutoAssess.timer` was active. Complete VM evidence, extracted +logs, archives, checksums, and the per-distribution report are stored locally +under: + +`artifacts\28537460-timeout-validation-20260811` From c4368fb64606aa91e4bc662cbe8e34c92465d65d Mon Sep 17 00:00:00 2001 From: Sathish Mathimaran Date: Thu, 3 Sep 2026 15:30:18 +0530 Subject: [PATCH 5/6] Document package-manager delay wrappers Add reusable APT, YUM, and Zypper delay and cleanup commands for the 90-second reproduction and 10-minute boundary validation. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 91444677-8618-4dc0-8cf1-f415f7cb7185 --- docs/investigations/28537460/rca-report.md | 148 +++++++++++++++++++++ 1 file changed, 148 insertions(+) diff --git a/docs/investigations/28537460/rca-report.md b/docs/investigations/28537460/rca-report.md index 897a6911..f37594d7 100644 --- a/docs/investigations/28537460/rca-report.md +++ b/docs/investigations/28537460/rca-report.md @@ -99,6 +99,154 @@ started. The full systemd service duration therefore captures the delayed startup, while the logs separately confirm the subsequent patch assessment completed successfully. +## Package-Manager Delay Commands + +The validation delayed only the first package-manager invocation. A 120-second +delay reproduces the original 90-second failure while remaining below the +10-minute mitigation. A 660-second delay validates that the mitigation remains +bounded and terminates at 600 seconds. + +> Use these commands only on disposable test VMs. Do not run package-manager +> commands between installing a wrapper and starting auto-assessment, because +> the first invocation consumes the one-time delay. + +### Ubuntu: `apt-get` + +The delayed command observed during validation was +`apt-get install ubuntu-advantage-tools -y`. Use `dpkg-divert` so the original +package-managed binary is preserved safely: + +```bash +DELAY_SECONDS=120 + +sudo test ! -e /usr/bin/apt-get.distrib || { + echo "apt-get diversion already exists; inspect before continuing." + exit 1 +} + +sudo dpkg-divert --local --rename --add /usr/bin/apt-get + +sudo tee /usr/bin/apt-get >/dev/null </dev/null </dev/null < Date: Thu, 3 Sep 2026 15:46:36 +0530 Subject: [PATCH 6/6] Delete report --- docs/investigations/28537460/rca-report.md | 274 --------------------- 1 file changed, 274 deletions(-) delete mode 100644 docs/investigations/28537460/rca-report.md diff --git a/docs/investigations/28537460/rca-report.md b/docs/investigations/28537460/rca-report.md deleted file mode 100644 index f37594d7..00000000 --- a/docs/investigations/28537460/rca-report.md +++ /dev/null @@ -1,274 +0,0 @@ -# RCA Report - Bug #28537460 - -## Summary - -Linux auto-assessment can remain in progress when a valid assessment exceeds -systemd's default 90-second service start timeout. The initial mitigation keeps -the existing `Type=forking` lifecycle and extends the generated unit's bounded -startup window to 10 minutes. - -## Evidence Collected - -- **Bug metadata**: Bug 28537460 is a high-severity recurring issue affecting - Azure and Arc Linux VMs across multiple distributions. -- **Historical patterns**: Bug 33342595 reports the same - `MsftLinuxPatchAutoAssess.service` timeout signature. Bug 24467908 and PR 203 - introduced `Type=forking` after `Type=notify` caused service failures. -- **Runtime evidence**: GitHub issue 350 demonstrates systemd sending SIGTERM at - approximately 90 seconds while package-manager work is still running. -- **Duration evidence**: A one-day sample of on-demand assessments had P99 near - 215 seconds and P99.9 near 256 seconds. A 10-minute timeout provides - substantial margin while remaining bounded. -- **Source code findings**: `ServiceManager.create_service_unit_file()` does not - emit `TimeoutStartSec`, so systemd applies its manager default. The extension - permits auto-assessment operations to run for up to one hour. - -## Root Cause - -The generated `MsftLinuxPatchAutoAssess.service` uses `Type=forking`. systemd -therefore keeps the unit in its startup phase until it observes the expected -forking lifecycle. If assessment startup and package-manager work exceed the -default `TimeoutStartSec=90s`, systemd terminates the service cgroup before the -extension writes terminal assessment status. Azure Update Manager then retains -the stale `In Progress` state. - -## Competing Hypotheses - -1. **Package-manager work is always hung indefinitely**: Some historical cases - involved unbounded package-manager retries, but the deterministic reproduction - uses an intentionally slow command that eventually completes. The exact - 90-second termination is imposed by systemd rather than the package manager. -2. **The service lifecycle should immediately change to `Type=simple`**: This - matches the foreground wrapper more closely and removes the startup gate, but - email review identified cross-distribution and lifecycle regression testing - as a prerequisite. -3. **The startup timeout is too short for valid assessments**: The observed - duration distribution and exact systemd timeout support this as the safest - first mitigation. - -## Selected Fix - -Keep `Type=forking` and add `TimeoutStartSec=10min` to the generated service -unit. This avoids changing the established lifecycle model while allowing -normal slow assessments to finish. The timeout remains bounded so a process -that never reaches the expected started state is still terminated. - -The validation plan reproduces the 90-second failure on an Azure Linux VM, -copies the modified `ServiceManager.py` into the installed extension, regenerates -the service, and verifies that the same assessment runs beyond 90 seconds and -completes before 10 minutes. - -## Azure VM Validation - -- **VM**: Azure RHEL 8.9, systemd 239, Linux Patch Extension 1.6.71. -- **Reproduction**: Wrapped `/usr/bin/yum` to delay its first invocation by - 120 seconds and forced auto-assessment to run. -- **Before the fix**: `systemctl start` failed after exactly 90 seconds. - `systemctl show` reported `TimeoutStartUSec=1min 30s`, `Result=timeout`, and - the journal recorded `start operation timed out. Terminating.` -- **Deployment**: Built the extension from this branch, copied the generated - `MsftLinuxPatchCore.py` over the installed extension payload, and reran - `ConfigurePatching` to regenerate the systemd unit. -- **After the fix**: The unit retained `Type=forking` and reported - `TimeoutStartUSec=10min`. The delayed real assessment completed successfully: - the assessment stopwatch reported 136 seconds and systemd reported - `Result=success`. -- **Non-regression**: A subsequent platform-triggered on-demand assessment - completed with status `Succeeded`. -- **Cleanup**: The `yum` wrapper was removed, the original executable was - restored, and the auto-assessment timer was active after validation. - -## Supported Distro Sanity Matrix - -The same test was repeated on Azure VMs using Linux Patch Extension 1.6.71. -Each package-manager wrapper delayed only its first invocation by 120 seconds. - -| Distribution | Delayed command | Before fix | After fix | Platform assessment | -| --- | --- | --- | --- | --- | -| Ubuntu 22.04.5 LTS | `apt-get` | Failed at 90s with `Result=timeout` | Service completed in 157s with `Result=success`; patch assessment completed | `Succeeded` | -| Ubuntu 24.04.4 LTS | `apt-get` | Failed at 90s with `Result=timeout` | Service completed in 136s with `Result=success`; patch assessment completed | `Succeeded` | -| SLES 15 SP5 | `zypper refresh` | Failed at 90s with `Result=timeout` | Service completed in 144s with `Result=success`; assessment stopwatch reported 133.1s | `Succeeded` | - -All three regenerated units retained `Type=forking` and reported -`TimeoutStartUSec=10min`. After each run, the original package-manager -executable was restored and `MsftLinuxPatchAutoAssess.timer` was active. - -On Ubuntu, the intentional delay occurred during the -`ubuntu-advantage-tools` prerequisite step before the assessment stopwatch -started. The full systemd service duration therefore captures the delayed -startup, while the logs separately confirm the subsequent patch assessment -completed successfully. - -## Package-Manager Delay Commands - -The validation delayed only the first package-manager invocation. A 120-second -delay reproduces the original 90-second failure while remaining below the -10-minute mitigation. A 660-second delay validates that the mitigation remains -bounded and terminates at 600 seconds. - -> Use these commands only on disposable test VMs. Do not run package-manager -> commands between installing a wrapper and starting auto-assessment, because -> the first invocation consumes the one-time delay. - -### Ubuntu: `apt-get` - -The delayed command observed during validation was -`apt-get install ubuntu-advantage-tools -y`. Use `dpkg-divert` so the original -package-managed binary is preserved safely: - -```bash -DELAY_SECONDS=120 - -sudo test ! -e /usr/bin/apt-get.distrib || { - echo "apt-get diversion already exists; inspect before continuing." - exit 1 -} - -sudo dpkg-divert --local --rename --add /usr/bin/apt-get - -sudo tee /usr/bin/apt-get >/dev/null </dev/null </dev/null <