Install swap: first Move-Item of InstallRoot fails "file in use" right after the stop (host still exiting) #908

Closed
opened 2026-11-13 07:48:58 -05:00 by dohertj2 · 1 comment
Owner

Found in the 2026-11-13 QA deploy of 76e73e7d (record docs/deploy/2026-11-13-vd03-qa-to-76e73e7d.md).

What happened. Invoke-OtOpcUaInstallSwap.ps1 -NoStart, run on QA with the service up, failed at step 3 on both nodes. The first Move-Item E:\ApiInstall\OtOpcUa\app -> app.bak.20261113-pre-76e73e7d threw The process cannot access the file because it is being used by another process.

  • vq04: after the 30 s old-build stop (#906's "before"). WaitForStatus('Stopped') returned at 12:35:57.08Z, and the move failed at the same moment.
  • vq03: after a 1.3 s stop. Stop issued 12:38:58.22Z, the move failed at 12:38:59.56Z.

State after the failure was safe. A directory rename fails as a whole, so app\ was intact, the candidate was still staged, there was no PreviousInstall, and the service was Stopped. A retry went through on both nodes:

  • vq04: a separate retry ~1.5 min later. A scan of every process image and module under app\ found nothing.
  • vq03: an in-call retry. It found no OtOpcUa.Host / ZB.MOM.WW.OtOpcUa.ScriptWorker process 0.5 s after the failure, waited 2 s and re-ran the swap.

So the holder lives less than a second after SCM reports Stopped. The likely cause is the host process (or a worker child) still tearing down after it reported SERVICE_STOPPED. The pre-#905 deploy wrappers waited for the OtOpcUa.Host and worker processes to exit after the stop, so they never hit this. vd03 (single node, flat layout) did not hit it.

Cost. On vq03 the retry re-ran -Scope Outside (~20 s) inside the pair outage. That outage was 36.5 s; the move itself would have taken about 15 s.

Fix. In step 2/3 of Invoke-OtOpcUaInstallSwap.ps1:

  • after WaitForStatus('Stopped'), wait (bounded, e.g. 30 s) for the service's process to exit (Win32_Service.ProcessId, then Wait-Process), and for any ZB.MOM.WW.OtOpcUa.ScriptWorker whose image is under InstallRoot;
  • and/or retry the first Move-Item a few times with a short back-off when it fails with a sharing violation, since nothing has moved yet.

Add a scratch test that holds a handle under InstallRoot for ~1 s after the stop.

Found in the 2026-11-13 QA deploy of `76e73e7d` (record `docs/deploy/2026-11-13-vd03-qa-to-76e73e7d.md`). **What happened.** `Invoke-OtOpcUaInstallSwap.ps1 -NoStart`, run on QA with the service up, failed at step 3 on **both** nodes. The first `Move-Item E:\ApiInstall\OtOpcUa\app -> app.bak.20261113-pre-76e73e7d` threw `The process cannot access the file because it is being used by another process.` - vq04: after the 30 s old-build stop (#906's "before"). `WaitForStatus('Stopped')` returned at 12:35:57.08Z, and the move failed at the same moment. - vq03: after a 1.3 s stop. Stop issued 12:38:58.22Z, the move failed at 12:38:59.56Z. **State after the failure was safe.** A directory rename fails as a whole, so `app\` was intact, the candidate was still staged, there was no `PreviousInstall`, and the service was Stopped. A retry went through on both nodes: - vq04: a separate retry ~1.5 min later. A scan of every process image and module under `app\` found nothing. - vq03: an in-call retry. It found no `OtOpcUa.Host` / `ZB.MOM.WW.OtOpcUa.ScriptWorker` process 0.5 s after the failure, waited 2 s and re-ran the swap. So the holder lives less than a second after SCM reports Stopped. The likely cause is the host process (or a worker child) still tearing down after it reported `SERVICE_STOPPED`. The pre-#905 deploy wrappers waited for the `OtOpcUa.Host` and worker processes to exit after the stop, so they never hit this. vd03 (single node, flat layout) did not hit it. **Cost.** On vq03 the retry re-ran `-Scope Outside` (~20 s) inside the pair outage. That outage was 36.5 s; the move itself would have taken about 15 s. **Fix.** In step 2/3 of `Invoke-OtOpcUaInstallSwap.ps1`: - after `WaitForStatus('Stopped')`, wait (bounded, e.g. 30 s) for the service's process to exit (`Win32_Service.ProcessId`, then `Wait-Process`), and for any `ZB.MOM.WW.OtOpcUa.ScriptWorker` whose image is under InstallRoot; - and/or retry the first `Move-Item` a few times with a short back-off when it fails with a sharing violation, since nothing has moved yet. Add a scratch test that holds a handle under InstallRoot for ~1 s after the stop.
dohertj2 added the type:bugpriority:p3 labels 2026-11-13 07:48:58 -05:00
Author
Owner

Fixed on master in a157b276.

Change (scripts/install/Invoke-OtOpcUaInstallSwap.ps1 + ScriptWorkerIsolation.psm1)

  • After WaitForStatus('Stopped'), the swap now waits for the service's host process to exit (PID from Win32_Service.ProcessId + its start time, both captured before the stop, so a reused PID does not count). It also waits for every process whose image is under InstallRoot (OtOpcUa.Host, the ScriptWorker). The wait is bounded by -ProcessExitTimeoutSeconds (default 60). On a timeout it throws, naming each process (name, PID, path), and nothing is moved. The window line gains an exit N s part.
  • The folder renames now use [IO.Directory]::Move instead of Move-Item. On windev, PowerShell 7's Move-Item handles a rename that fails because a file under the folder is open (IOException 0x80070020, the QA message) by falling back to an item-by-item move. That left a partial PreviousInstall tree behind (app.bak\logs, and on a second try app.bak\app\logs). A retry would then nest into it. Directory.Move is one rename and fails as a whole (IOException 0x80070005, nothing created) on both pwsh 7 and 5.1. So the QA "nothing moved" observation could have been luck, or 5.1.
  • The first rename is retried for at most -MoveRetrySeconds (default 10) while it fails because something under InstallRoot is open. This is a backstop for a holder whose image is outside InstallRoot. Other errors are not retried.
  • -Verify / -Reapply / -Scope behaviour is unchanged. docs/ServiceHosting.md and the 76e73e7d record are updated.

Tests

  • Test-ScriptWorkerIsolation.ps1 (dry run, any OS): 145 passed, 0 failed. New: holder detection from fake process lists (host by PID, also with an unreadable path; worker under app\; the candidate app.new-* and a reused PID are not holders). The wait returns once the holders are gone and times out within its bound, naming them. The sharing-violation detector covers all three windev shapes. The retry covers in use ×2 then success, a non-sharing error, and -MoveRetrySeconds 0. AST checks: PID capture → stop → wait → retried first rename → candidate rename, and no Move-Item in the script. Mutations: pre-fix script gives 4 failures, Move-Item reintroduced gives 3, wait removed gives 1, the wait helper as a no-op gives 3, holder detection ignoring the PID gives 1, and the retry or detector disabled gives 1 and 3.
  • Test-ScriptWorkerIsolation.Windows.ps1 (windev, elevated, scratch tree). The stand-in holder is a copy of powershell.exe under InstallRoot that holds logs\host908.log open. A running image alone does not block the rename; an open file does (checked on windev). Three new cases:
    1. Holder kept, budget 1 s: exit 1, "still in use … OtOpcUa.Host908.exe (PID …)", nothing moved.
    2. Holder released 2 s into the wait, with -MoveRetrySeconds 0: "released after 2.3 s" (pwsh) / "2.6 s" (5.1), swapped and verified.
    3. Holder outside InstallRoot: moved on attempt 6, and the previous install moved whole.
      Results: pwsh 7.6 77/0, Windows PowerShell 5.1 77/0. With the wait removed (mutant), cases 1 and 2 fail: case 2's move fails "in use" exactly as on QA.

Nothing was run on the wonder boxes.

Fixed on `master` in a157b276. **Change (`scripts/install/Invoke-OtOpcUaInstallSwap.ps1` + `ScriptWorkerIsolation.psm1`)** - After `WaitForStatus('Stopped')`, the swap now waits for the service's host process to exit (PID from `Win32_Service.ProcessId` + its start time, both captured before the stop, so a reused PID does not count). It also waits for every process whose image is under `InstallRoot` (OtOpcUa.Host, the ScriptWorker). The wait is bounded by `-ProcessExitTimeoutSeconds` (default 60). On a timeout it throws, naming each process (name, PID, path), and nothing is moved. The window line gains an `exit N s` part. - **The folder renames now use `[IO.Directory]::Move` instead of `Move-Item`.** On windev, PowerShell 7's `Move-Item` handles a rename that fails because a file under the folder is open (IOException 0x80070020, the QA message) by falling back to an item-by-item move. That left a partial `PreviousInstall` tree behind (`app.bak\logs`, and on a second try `app.bak\app\logs`). A retry would then nest into it. `Directory.Move` is one rename and fails as a whole (IOException 0x80070005, nothing created) on both pwsh 7 and 5.1. So the QA "nothing moved" observation could have been luck, or 5.1. - The first rename is retried for at most `-MoveRetrySeconds` (default 10) while it fails because something under `InstallRoot` is open. This is a backstop for a holder whose image is outside `InstallRoot`. Other errors are not retried. - `-Verify` / `-Reapply` / `-Scope` behaviour is unchanged. `docs/ServiceHosting.md` and the 76e73e7d record are updated. **Tests** - `Test-ScriptWorkerIsolation.ps1` (dry run, any OS): **145 passed, 0 failed**. New: holder detection from fake process lists (host by PID, also with an unreadable path; worker under `app\`; the candidate `app.new-*` and a reused PID are not holders). The wait returns once the holders are gone and times out within its bound, naming them. The sharing-violation detector covers all three windev shapes. The retry covers in use ×2 then success, a non-sharing error, and `-MoveRetrySeconds 0`. AST checks: PID capture → stop → wait → retried first rename → candidate rename, and no `Move-Item` in the script. Mutations: pre-fix script gives 4 failures, `Move-Item` reintroduced gives 3, wait removed gives 1, the wait helper as a no-op gives 3, holder detection ignoring the PID gives 1, and the retry or detector disabled gives 1 and 3. - `Test-ScriptWorkerIsolation.Windows.ps1` (windev, elevated, scratch tree). The stand-in holder is a copy of powershell.exe under `InstallRoot` that holds `logs\host908.log` open. A running image alone does not block the rename; an open file does (checked on windev). Three new cases: 1. Holder kept, budget 1 s: exit 1, "still in use … OtOpcUa.Host908.exe (PID …)", nothing moved. 2. Holder released 2 s into the wait, with `-MoveRetrySeconds 0`: "released after 2.3 s" (pwsh) / "2.6 s" (5.1), swapped and verified. 3. Holder outside `InstallRoot`: moved on attempt 6, and the previous install moved whole. **Results: pwsh 7.6 77/0, Windows PowerShell 5.1 77/0.** With the wait removed (mutant), cases 1 and 2 fail: case 2's move fails "in use" exactly as on QA. Nothing was run on the wonder boxes.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: dohertj2/lmxopcua#908