From 6f7df5a476500d9380f6b5de9cfefc907eb399db Mon Sep 17 00:00:00 2001 From: twangboy Date: Tue, 11 Aug 2026 15:00:47 -0600 Subject: [PATCH] Widen retry window for salt-minion service re-registration race The NSIS stress tests still hit intermittent installer Abort (exit code 2) after the previous retry fix, on both 3006.x and 3007.x. Timing recovered from the CI logs shows the SCM held the salt-minion service key for 25s+ before the uninstall side's own wait_svc_deleted loop and the test harness's post-uninstall wait both gave up, leaving only ~10s of retry budget on the install side before it aborted -- not enough headroom for the observed delay. Wait for the salt-minion service registry key to disappear before even attempting "ssm install" (CreateService), instead of only reacting after CreateService fails. This is a no-op on a normal install, since the key was never present. Also widen the existing retry budgets: the install-side CreateService retry from 5x2s to 10x2s, and the uninstall-side wait_svc_deleted from 10s to 15s. Add diagnostics so future occurrences don't require a fresh repro: print the tail of the relevant %TEMP%\SaltInstaller\*.log directly into the pytest failure output on any non-zero exit or timeout, and upload the full log directory as a CI artifact from both the Logic Tests and Stress Tests jobs. --- .github/workflows/nsis-tests.yml | 36 +++++++++++++++++ .../nsis/installer/Salt-Minion-Setup.nsi | 39 +++++++++++++++---- pkg/windows/nsis/tests/conftest.py | 37 ++++++++++++++++++ 3 files changed, 105 insertions(+), 7 deletions(-) diff --git a/.github/workflows/nsis-tests.yml b/.github/workflows/nsis-tests.yml index 5fecd1e6bc94..cd4fe306b0fb 100644 --- a/.github/workflows/nsis-tests.yml +++ b/.github/workflows/nsis-tests.yml @@ -47,6 +47,24 @@ jobs: run: .\pkg\windows\nsis\tests\test.cmd -CICD .\config_tests shell: cmd + - name: Collect NSIS Installer Logs + if: always() + shell: pwsh + run: | + $dest = "$env:GITHUB_WORKSPACE\nsis-install-logs" + New-Item -ItemType Directory -Force -Path $dest | Out-Null + if (Test-Path "$env:TEMP\SaltInstaller") { + Copy-Item "$env:TEMP\SaltInstaller\*" $dest -Recurse -Force + } + + - name: Upload NSIS Installer Logs + if: always() + uses: actions/upload-artifact@ea165f8d65b6e75b540449e92b4886f43607fa02 # v4 + with: + name: nsis-logic-test-logs + path: nsis-install-logs + if-no-files-found: ignore + Test-NSIS-Stress: name: Stress Tests runs-on: @@ -74,3 +92,21 @@ jobs: - name: Run Stress Test run: .\pkg\windows\nsis\tests\test.cmd -CICD .\stress_tests shell: cmd + + - name: Collect NSIS Installer Logs + if: always() + shell: pwsh + run: | + $dest = "$env:GITHUB_WORKSPACE\nsis-install-logs" + New-Item -ItemType Directory -Force -Path $dest | Out-Null + if (Test-Path "$env:TEMP\SaltInstaller") { + Copy-Item "$env:TEMP\SaltInstaller\*" $dest -Recurse -Force + } + + - name: Upload NSIS Installer Logs + if: always() + uses: actions/upload-artifact@ea165f8d65b6e75b540449e92b4886f43607fa02 # v4 + with: + name: nsis-stress-test-logs + path: nsis-install-logs + if-no-files-found: ignore diff --git a/pkg/windows/nsis/installer/Salt-Minion-Setup.nsi b/pkg/windows/nsis/installer/Salt-Minion-Setup.nsi index 67cf43e3904b..5f066bdbd35c 100644 --- a/pkg/windows/nsis/installer/Salt-Minion-Setup.nsi +++ b/pkg/windows/nsis/installer/Salt-Minion-Setup.nsi @@ -1090,9 +1090,34 @@ Section -Post # races that pending delete and fails, which used to Abort the install # (NSIS error level 2 -- the intermittent installer failure). # - # The condition is self-clearing within a second or two once the handles - # close, so retry a handful of times before giving up rather than aborting - # on the first failure. + # CI stress runs have measured this pending-delete window taking well + # over 10 seconds under load -- both the uninstaller's own + # wait_svc_deleted loop and the test harness's post-uninstall wait have + # been observed to exhaust their budgets while the service key was still + # present, which then burned through the retry loop below and Aborted. + # So, before even attempting CreateService, wait for the service registry + # key to disappear. This costs 0s on a normal install (the key was never + # present, so ReadRegDWORD errors immediately) and only spends time in + # the race case this is meant to cover. + ${LogMsg} "Checking for a pending salt-minion service deletion" + StrCpy $R0 0 + wait_svc_deleted_before_install: + ClearErrors + ReadRegDWORD $R1 HKLM "SYSTEM\CurrentControlSet\Services\salt-minion" "Type" + ${If} ${Errors} + ${LogMsg} "No pending service deletion detected" + ${ElseIf} $R0 < 30 + IntOp $R0 $R0 + 1 + Sleep 500 + Goto wait_svc_deleted_before_install + ${Else} + ${LogMsg} "Service key still present after 15s -- proceeding anyway" + ${EndIf} + + # The condition is also self-clearing within a couple of seconds once the + # SCM finishes closing out the old service's handles, so retry + # CreateService itself a number of times before giving up rather than + # aborting on the first failure. ${LogMsg} "Registering the salt-minion service" StrCpy $SvcInstallTries 0 retry_svc_install: @@ -1100,10 +1125,10 @@ Section -Post pop $0 # ExitCode pop $1 # StdOut ${If} $0 != 0 - ${AndIf} $SvcInstallTries < 5 + ${AndIf} $SvcInstallTries < 10 IntOp $SvcInstallTries $SvcInstallTries + 1 ${LogMsg} "Service registration failed (ExitCode: $0). \ - Retry $SvcInstallTries/5 in 2s (SCM delete may still be pending)" + Retry $SvcInstallTries/10 in 2s (SCM delete may still be pending)" ${LogMsg} "StdOut: $1" Sleep 2000 Goto retry_svc_install @@ -1362,12 +1387,12 @@ Function ${un}uninstallSalt ReadRegDWORD $R1 HKLM "SYSTEM\CurrentControlSet\Services\salt-minion" "Type" ${If} ${Errors} ${LogMsg} "Service key removed" - ${ElseIf} $R0 < 20 + ${ElseIf} $R0 < 30 IntOp $R0 $R0 + 1 Sleep 500 Goto wait_svc_deleted ${Else} - ${LogMsg} "Service key still present after 10s — continuing anyway" + ${LogMsg} "Service key still present after 15s — continuing anyway" ${EndIf} ${Else} diff --git a/pkg/windows/nsis/tests/conftest.py b/pkg/windows/nsis/tests/conftest.py index b404ec2402ae..c37488b72bfe 100644 --- a/pkg/windows/nsis/tests/conftest.py +++ b/pkg/windows/nsis/tests/conftest.py @@ -349,6 +349,41 @@ def install_salt(args): pass +SALT_INSTALLER_LOG_DIR = os.path.join(os.environ.get("TEMP", ""), "SaltInstaller") + + +def _print_latest_installer_log(tail_lines=100): + """ + Print the tail of the most recently modified NSIS install/uninstall log. + + ${LogMsg} in the NSIS script writes a timestamped log for every + install/uninstall run to %TEMP%\\SaltInstaller. Surfacing the tail here + means a failure (e.g. an Abort during service registration) shows the + NSIS-side detail -- including ssm.exe's exit code and stdout -- directly + in the pytest failure output, without needing to dig through CI + artifacts or reproduce locally. + """ + if not os.path.isdir(SALT_INSTALLER_LOG_DIR): + return + try: + logs = [ + os.path.join(SALT_INSTALLER_LOG_DIR, name) + for name in os.listdir(SALT_INSTALLER_LOG_DIR) + if name.endswith(".log") + ] + if not logs: + return + latest = max(logs, key=os.path.getmtime) + with open(latest, encoding="utf-8", errors="replace") as fp: + lines = fp.readlines() + print(f"\n----- tail of {latest} -----") + for line in lines[-tail_lines:]: + print(line.rstrip()) + print("----- end of log -----") + except OSError as exc: + print(f"\nWARNING: could not read installer log: {exc}") + + def is_file_locked(path): """ Try to see if a file is locked @@ -418,6 +453,7 @@ def run_command(cmd_args, timeout=60): print( f"\nWARNING: process exited with code {proc.returncode}: {cmd_args[:120]}" ) + _print_latest_installer_log() return False return True except subprocess.TimeoutExpired: @@ -426,5 +462,6 @@ def run_command(cmd_args, timeout=60): print( f"\nWARNING: process timed out after {timeout}s — force-killing: {cmd_args[:120]}" ) + _print_latest_installer_log() _kill_process_tree(proc) return False