From 97391cdee494ef30720d2b5967168999d1f4583f Mon Sep 17 00:00:00 2001 From: cproudlock Date: Tue, 4 Aug 2026 19:43:30 -0400 Subject: [PATCH] Unlock IIS config after the application exists, and report why the smoke test failed Two defects found in the stage 4 and stage 5 logs from a Windows Server 2019 install. The scoped config unlock ran before the thing it unlocks existed. appcmd resolves its location argument against applicationHost.config, but the unlock was issued from the ACL block, ahead of New-WebApplication. On a first install "Default Web Site/shopdb" is not there yet, so appcmd returned 80070003, "the system cannot find the path specified", and the code fell through to unlocking the section for the entire machine. That fallback exists for servers which refuse the scoped form; it was instead the only path a first install could take, so every install silently granted handler delegation server-wide. Moving the block below site and application creation lets the scoped unlock work. The smoke test discarded the diagnosis. Invoke-WebRequest raises on any non-2xx, and the catch block kept nothing from the exception, so a fault IIS had already identified by status code was reported as "site did not return 200 ... check the logs". It now records the status code and the text of the IIS error page, and prints the tail of the HttpPlatform stdout log, which is where a Python traceback lands. It also distinguishes a missing log from an empty one: the first means the pool never launched python, the second that python started and wrote nothing. A non-200 that did not raise, such as a redirect, skipped the retry delay, so the loop could spend all twelve attempts at once and report a timeout without having waited. --- deploy/windows/installer/shopdb-install.ps1 | 128 ++++++++++++++------ 1 file changed, 94 insertions(+), 34 deletions(-) diff --git a/deploy/windows/installer/shopdb-install.ps1 b/deploy/windows/installer/shopdb-install.ps1 index ba6edb3..c0e80c4 100644 --- a/deploy/windows/installer/shopdb-install.ps1 +++ b/deploy/windows/installer/shopdb-install.ps1 @@ -1755,40 +1755,6 @@ has to come from the bundle either way. Invoke-Native 'icacls.exe' @($EnvFile,'/grant',"${ident}:(R)") 'ACL on .env' } - # Handler sections are locked server-wide by default. Without unlocking, - # IIS returns 500.19 the moment it reads the app's web.config. - # - # `appcmd unlock config /section:X` unlocks it for EVERY site on the machine, - # which on a shared server hands every other application the ability to - # define its own handlers. Delegate to our own location instead, and fall - # back to the server-wide unlock only if that is refused - a 500.19 the - # operator cannot diagnose is worse than a wider delegation, but it should be - # the second choice, not the first. - $ourLocation = if ($MountAlias) { "$ParentSite/$($MountAlias.Trim('/'))" } else { $SiteName } - foreach ($section in @('system.webServer/handlers','system.webServer/httpPlatform')) { - if ($WhatIfOnly) { Write-Log "would unlock $section for $ourLocation"; continue } - Write-Log "unlocking $section for $ourLocation" - # EAP must drop to Continue around these. appcmd writes to stderr on - # ordinary refusals, and '2>&1' with $ErrorActionPreference = 'Stop' - # turns that into a TERMINATING NativeCommandError - so the exit-code - # test and the server-wide fallback below, which is the entire point of - # the block, were unreachable, and stage 4 aborted after Python, the - # venv, the schema and the ACLs had all been changed. - $prevEap = $ErrorActionPreference - $ErrorActionPreference = 'Continue' - try { - $scoped = & $appcmd unlock config "$ourLocation" /section:$section 2>&1 - $scoped | ForEach-Object { Write-Log " $_" } - if ($LASTEXITCODE -ne 0) { - Write-Log " scoped unlock refused; unlocking $section server-wide" 'WARN' - & $appcmd unlock config /section:$section 2>&1 | ForEach-Object { Write-Log " $_" } - if ($LASTEXITCODE -ne 0) { - Write-Log " server-wide unlock also refused - IIS may return 500.19" 'WARN' - } - } - } finally { $ErrorActionPreference = $prevEap } - } - # Switching method must not leave BOTH deployments in place: two entry points # to one directory, one of them serving an SPA built for the wrong base path. # Remove whichever artifact belongs to the method we are NOT using. @@ -1906,6 +1872,49 @@ If not, re-run matching how the application is published today: pass if (-not $WhatIfOnly) { Start-Website -Name $SiteName -ErrorAction SilentlyContinue } } + + # Handler sections are locked server-wide by default. Without unlocking, + # IIS returns 500.19 the moment it reads the app's web.config. + # + # `appcmd unlock config /section:X` unlocks it for EVERY site on the machine, + # which on a shared server hands every other application the ability to + # define its own handlers. Delegate to our own location instead, and fall + # back to the server-wide unlock only if that is refused - a 500.19 the + # operator cannot diagnose is worse than a wider delegation, but it should be + # the second choice, not the first. + # + # MUST run AFTER the site or application exists. appcmd resolves the location + # against applicationHost.config, so unlocking "Default Web Site/shopdb" + # before New-WebApplication created it failed with 80070003 ("the system + # cannot find the path specified") on every first install - and the fallback + # then handed handler delegation to the whole machine, which is exactly the + # outcome the comment above calls the second choice. A first install could + # never take the scoped path. + $ourLocation = if ($MountAlias) { "$ParentSite/$($MountAlias.Trim('/'))" } else { $SiteName } + foreach ($section in @('system.webServer/handlers','system.webServer/httpPlatform')) { + if ($WhatIfOnly) { Write-Log "would unlock $section for $ourLocation"; continue } + Write-Log "unlocking $section for $ourLocation" + # EAP must drop to Continue around these. appcmd writes to stderr on + # ordinary refusals, and '2>&1' with $ErrorActionPreference = 'Stop' + # turns that into a TERMINATING NativeCommandError - so the exit-code + # test and the server-wide fallback below, which is the entire point of + # the block, were unreachable, and stage 4 aborted after Python, the + # venv, the schema and the ACLs had all been changed. + $prevEap = $ErrorActionPreference + $ErrorActionPreference = 'Continue' + try { + $scoped = & $appcmd unlock config "$ourLocation" /section:$section 2>&1 + $scoped | ForEach-Object { Write-Log " $_" } + if ($LASTEXITCODE -ne 0) { + Write-Log " scoped unlock refused; unlocking $section server-wide" 'WARN' + & $appcmd unlock config /section:$section 2>&1 | ForEach-Object { Write-Log " $_" } + if ($LASTEXITCODE -ne 0) { + Write-Log " server-wide unlock also refused - IIS may return 500.19" 'WARN' + } + } + } finally { $ErrorActionPreference = $prevEap } + } + # Stage 2 stops the pool on an upgrade so its files can be replaced. Nothing # else starts it again, so the smoke test would fail against a stopped site # and report it as a broken install. @@ -2004,15 +2013,66 @@ public class ShopdbSmokeTestCertPolicy : ICertificatePolicy { # First request boots the app and connects to MySQL: the runbook records ~15s. Write-Log "requesting $($targets[0]) (first request takes ~15s while the app boots)" $ok = $false + $lastStatus = 'no response' + $lastDetail = '' for ($i = 1; $i -le 12; $i++) { try { $r = Invoke-WebRequest -Uri $targets[0] -UseBasicParsing -TimeoutSec 20 + $lastStatus = "HTTP $($r.StatusCode)" if ($r.StatusCode -eq 200) { $ok = $true; break } + # A non-200 that does NOT throw (a redirect, say) is still not success. + # Without this sleep the loop burned all 12 attempts instantly and + # reported a timeout that never waited for anything. + Start-Sleep -Seconds 5 } catch { + # The status code and the response body ARE the diagnosis, and this + # block used to discard both - leaving a generic "check the logs" for + # a fault IIS had already named. 500.19 = section still locked, + # 502.3/503 = httpPlatform could not start the app, 404 = the + # application or its handler mapping is missing. + $lastStatus = 'no response' + $lastDetail = $_.Exception.Message + try { + $resp = $_.Exception.Response + if ($resp) { + $lastStatus = "HTTP {0} ({1})" -f [int]$resp.StatusCode, $resp.StatusCode + $reader = New-Object System.IO.StreamReader($resp.GetResponseStream()) + $body = $reader.ReadToEnd() + $reader.Close() + if ($body) { + # IIS error pages state the precise cause in their body; + # strip the markup so it fits in the log readably. + $clean = (($body -replace '<[^>]+>', ' ') -replace '\s+', ' ').Trim() + if ($clean) { + if ($clean.Length -gt 500) { $clean = $clean.Substring(0, 500) + ' ...' } + $lastDetail = $clean + } + } + } + } catch { } Start-Sleep -Seconds 5 } } if (-not $ok) { + Write-Log " last response: $lastStatus" 'FAIL' + if ($lastDetail) { Write-Log " $lastDetail" 'FAIL' } + # The HttpPlatform stdout log is where a Python traceback lands. Reading it + # here saves a round trip: whoever is sending this log back already has the + # cause in it, instead of being told which second file to go and open. + try { + $logDir = Join-Path $AppRoot 'logs' + $newest = Get-ChildItem $logDir -Filter '*.log' -ErrorAction SilentlyContinue | + Sort-Object LastWriteTime -Descending | Select-Object -First 1 + if (-not $newest) { + Write-Log " no HttpPlatform log in $logDir - the pool never launched python" 'FAIL' + } elseif ($newest.Length -eq 0) { + Write-Log " $($newest.Name) is empty - python was launched but wrote nothing" 'FAIL' + } else { + Write-Log " tail of $($newest.Name):" 'FAIL' + Get-Content $newest.FullName -Tail 20 -ErrorAction SilentlyContinue | + ForEach-Object { Write-Log " $_" 'FAIL' } + } + } catch { } Fail "site did not return 200 at $($targets[0])" ` "Check $AppRoot\logs. Empty HttpPlatform log usually means the app-pool identity cannot read $AppRoot or run the venv, or .env is missing/invalid." }