Add a stage 5 diagnostic collector
The stage 5 smoke test failing tells us only that IIS did not return 200. The cause is in one of four places, and finding out which has taken a round trip per guess. This gathers all four in one pass and writes a single report. It records what IIS actually answers on localhost, 127.0.0.1, ::1 and the machine name, including the status code and the parsed text of the IIS error page; the site, application, pool and module state from appcmd, plus the override state of the two config sections httpPlatformHandler needs; the contents of web.config and the resolved httpPlatform processPath; whether the venv can import shopdb and call create_app; the application logs, separating a missing log from an empty one; the ACLs the pool identity depends on; and recent HttpPlatform, WAS and W3SVC event log entries. Secrets never reach the report. Values are read from .env first, then scrubbed from every section before the file is written, which covers command output and tracebacks that might quote them. A password embedded in any connection URL is also masked whether or not it came from .env. Standard library only, so it runs on the bundled runtime or any system Python. Verified end to end on a Windows VM: it correctly reported a 404 with the IIS error code for an absent application, and that localhost resolves to ::1 first.
This commit is contained in:
cproudlock
413
deploy/windows/shopdb-diagnose.py
Normal file
413
deploy/windows/shopdb-diagnose.py
Normal file
@@ -0,0 +1,413 @@
|
||||
"""Collect everything needed to diagnose a ShopDB-Flask stage 5 failure.
|
||||
|
||||
Stage 5 is the smoke test: the installer asks IIS for the site and expects 200.
|
||||
When it does not get one, the cause is always in one of four places, and this
|
||||
script reads all four in one pass so the answer arrives in a single round trip:
|
||||
|
||||
1. What IIS actually answers, and with which status code and error page.
|
||||
2. Whether the config sections httpPlatformHandler needs are unlocked.
|
||||
3. Whether the app-pool identity can read the app and run its venv.
|
||||
4. Whether the app itself imports and starts.
|
||||
|
||||
Run it ON THE SERVER, as Administrator:
|
||||
|
||||
C:\\Python314\\python.exe shopdb-diagnose.py
|
||||
|
||||
It writes shopdb-diagnose-<timestamp>.txt next to itself and prints the path.
|
||||
Send that file back.
|
||||
|
||||
SECRETS: the report never contains them. Values from .env (database password,
|
||||
SECRET_KEY, JWT_SECRET_KEY) are read first, then scrubbed out of every section
|
||||
of the report before it is written, including command output and tracebacks
|
||||
that might quote them.
|
||||
|
||||
Standard library only, so it runs on the bundled runtime or any system Python.
|
||||
"""
|
||||
|
||||
import os
|
||||
import re
|
||||
import socket
|
||||
import subprocess
|
||||
import sys
|
||||
import time
|
||||
from datetime import datetime
|
||||
|
||||
APP_ROOT = os.environ.get('SHOPDB_APPROOT', r'C:\shopdb-flask')
|
||||
ALIAS = 'shopdb'
|
||||
TIMEOUT = 25
|
||||
|
||||
# Filled from .env, then scrubbed from the whole report.
|
||||
SECRETS = []
|
||||
|
||||
WINDIR = os.environ.get('WINDIR', r'C:\Windows')
|
||||
# Sysnative gives a 32-bit process the real 64-bit System32. Harmless on 64-bit.
|
||||
APPCMD_CANDIDATES = [
|
||||
os.path.join(WINDIR, 'Sysnative', 'inetsrv', 'appcmd.exe'),
|
||||
os.path.join(WINDIR, 'System32', 'inetsrv', 'appcmd.exe'),
|
||||
]
|
||||
|
||||
|
||||
def find_appcmd():
|
||||
for path in APPCMD_CANDIDATES:
|
||||
if os.path.isfile(path):
|
||||
return path
|
||||
return None
|
||||
|
||||
|
||||
class Report(object):
|
||||
def __init__(self):
|
||||
self.chunks = []
|
||||
|
||||
def head(self, title):
|
||||
self.chunks.append('\n' + '=' * 72 + '\n' + title + '\n' + '=' * 72)
|
||||
|
||||
def line(self, text=''):
|
||||
self.chunks.append(str(text))
|
||||
|
||||
def block(self, title, body):
|
||||
self.chunks.append('\n--- %s ---' % title)
|
||||
if body is None or str(body).strip() == '':
|
||||
self.chunks.append('(no output)')
|
||||
else:
|
||||
self.chunks.append(str(body).rstrip())
|
||||
|
||||
def text(self):
|
||||
return '\n'.join(self.chunks) + '\n'
|
||||
|
||||
|
||||
def run(cmd, timeout=60):
|
||||
"""Run a command, return combined output. Never raises."""
|
||||
try:
|
||||
proc = subprocess.Popen(cmd, stdout=subprocess.PIPE,
|
||||
stderr=subprocess.STDOUT, shell=False)
|
||||
out, _ = proc.communicate(timeout=timeout)
|
||||
text = out.decode('utf-8', 'replace') if out else ''
|
||||
return '[exit %s]\n%s' % (proc.returncode, text)
|
||||
except subprocess.TimeoutExpired:
|
||||
try:
|
||||
proc.kill()
|
||||
except Exception:
|
||||
pass
|
||||
return '[TIMED OUT after %ss]' % timeout
|
||||
except Exception as exc:
|
||||
return '[could not run: %s]' % exc
|
||||
|
||||
|
||||
def powershell(script, timeout=90):
|
||||
exe = os.path.join(WINDIR, 'Sysnative', 'WindowsPowerShell', 'v1.0', 'powershell.exe')
|
||||
if not os.path.isfile(exe):
|
||||
exe = 'powershell.exe'
|
||||
return run([exe, '-NoProfile', '-ExecutionPolicy', 'Bypass', '-Command', script],
|
||||
timeout=timeout)
|
||||
|
||||
|
||||
def load_secrets():
|
||||
"""Read .env so its secret VALUES can be scrubbed from the report."""
|
||||
env_path = os.path.join(APP_ROOT, '.env')
|
||||
found = {}
|
||||
if not os.path.isfile(env_path):
|
||||
return found, None
|
||||
try:
|
||||
with open(env_path, 'r', encoding='utf-8', errors='replace') as handle:
|
||||
raw = handle.read()
|
||||
except Exception as exc:
|
||||
return found, '[could not read .env: %s]' % exc
|
||||
|
||||
for line in raw.splitlines():
|
||||
line = line.strip()
|
||||
if not line or line.startswith('#') or '=' not in line:
|
||||
continue
|
||||
key, value = line.split('=', 1)
|
||||
key, value = key.strip(), value.strip().strip('"').strip("'")
|
||||
found[key] = value
|
||||
if not value:
|
||||
continue
|
||||
upper = key.upper()
|
||||
if 'SECRET' in upper or 'PASSWORD' in upper or 'TOKEN' in upper or 'KEY' in upper:
|
||||
SECRETS.append(value)
|
||||
if upper == 'DATABASE_URL':
|
||||
# mysql+pymysql://user:PASSWORD@host/db -- the password only.
|
||||
match = re.match(r'^[^:]+://([^:@/]+):([^@]+)@', value)
|
||||
if match:
|
||||
SECRETS.append(match.group(2))
|
||||
return found, raw
|
||||
|
||||
|
||||
def scrub(text):
|
||||
"""Remove every known secret value from the report."""
|
||||
for secret in SECRETS:
|
||||
if secret and len(secret) >= 4:
|
||||
text = text.replace(secret, '<REDACTED>')
|
||||
# Catch a password inside any URL that did not come from .env.
|
||||
text = re.sub(r'(://[^:@/\s]+:)[^@\s]+(@)', r'\1<REDACTED>\2', text)
|
||||
return text
|
||||
|
||||
|
||||
def http_probe(url):
|
||||
"""Fetch a URL, returning status, headers and body even for an error page."""
|
||||
import urllib.error
|
||||
import urllib.request
|
||||
|
||||
started = time.time()
|
||||
try:
|
||||
request = urllib.request.Request(url, headers={'User-Agent': 'shopdb-diagnose'})
|
||||
with urllib.request.urlopen(request, timeout=TIMEOUT) as response:
|
||||
body = response.read(4000).decode('utf-8', 'replace')
|
||||
return {'status': response.status, 'reason': response.reason,
|
||||
'headers': dict(response.headers), 'body': body,
|
||||
'seconds': time.time() - started}
|
||||
except urllib.error.HTTPError as exc:
|
||||
body = ''
|
||||
try:
|
||||
body = exc.read(4000).decode('utf-8', 'replace')
|
||||
except Exception:
|
||||
pass
|
||||
return {'status': exc.code, 'reason': exc.reason,
|
||||
'headers': dict(exc.headers or {}), 'body': body,
|
||||
'seconds': time.time() - started}
|
||||
except Exception as exc:
|
||||
return {'status': None, 'reason': '%s: %s' % (type(exc).__name__, exc),
|
||||
'headers': {}, 'body': '', 'seconds': time.time() - started}
|
||||
|
||||
|
||||
def summarise_iis_error(body):
|
||||
"""Pull the meaningful bits out of an IIS error page."""
|
||||
if not body:
|
||||
return None
|
||||
import html
|
||||
|
||||
# style and script blocks first: their contents survive plain tag stripping
|
||||
# and drag CSS into the summary.
|
||||
flat = re.sub(r'(?is)<(script|style)[^>]*>.*?</\1>', ' ', body)
|
||||
flat = re.sub(r'(?s)<!--.*?-->', ' ', flat)
|
||||
flat = re.sub(r'(?s)<[^>]*>', ' ', flat)
|
||||
# Any unterminated tag left by the 4000-byte body truncation.
|
||||
flat = re.sub(r'(?s)<[^>]*$', ' ', flat)
|
||||
flat = html.unescape(flat)
|
||||
flat = re.sub(r'\s+', ' ', flat).strip()
|
||||
|
||||
hints = []
|
||||
for pattern in (r'\b\d{3}\.\d+\b', r'0x[0-9a-fA-F]{8}',
|
||||
r'Error Code[^.]{0,80}', r'Config (?:Error|File)[^.]{0,120}',
|
||||
r'Requested URL[^.]{0,120}', r'Physical Path[^.]{0,120}'):
|
||||
for match in re.findall(pattern, flat):
|
||||
cleaned = re.sub(r'\s+', ' ', match).strip(' :-')
|
||||
if cleaned and cleaned not in hints:
|
||||
hints.append(cleaned)
|
||||
return {'flat': flat[:1200], 'hints': hints}
|
||||
|
||||
|
||||
def main():
|
||||
report = Report()
|
||||
stamp = datetime.now().strftime('%Y%m%d-%H%M%S')
|
||||
|
||||
env_values, env_raw = load_secrets()
|
||||
|
||||
report.line('ShopDB-Flask stage 5 diagnostic')
|
||||
report.line('generated %s' % datetime.now().strftime('%Y-%m-%d %H:%M:%S'))
|
||||
report.line('host %s' % socket.gethostname())
|
||||
report.line('app root %s' % APP_ROOT)
|
||||
report.line('python %s' % sys.version.replace('\n', ' '))
|
||||
report.line('process is %d-bit' % (64 if sys.maxsize > 2 ** 32 else 32))
|
||||
|
||||
# ---------------------------------------------------------------- 1. HTTP
|
||||
report.head('1. WHAT IIS ANSWERS')
|
||||
report.line('This is the single most important section. The status code names')
|
||||
report.line('the fault: 500.19 = config locked, 502.3/503 = the app did not')
|
||||
report.line('start, 404 = application or handler mapping missing.')
|
||||
|
||||
hostname = socket.gethostname()
|
||||
targets = [
|
||||
'http://localhost/%s/' % ALIAS,
|
||||
'http://127.0.0.1/%s/' % ALIAS,
|
||||
'http://[::1]/%s/' % ALIAS,
|
||||
'http://%s/%s/' % (hostname, ALIAS),
|
||||
'http://localhost/',
|
||||
]
|
||||
for url in targets:
|
||||
result = http_probe(url)
|
||||
report.line('\n%s' % url)
|
||||
report.line(' status : %s %s' % (result['status'], result['reason']))
|
||||
report.line(' time : %.1fs' % result['seconds'])
|
||||
server = result['headers'].get('Server')
|
||||
if server:
|
||||
report.line(' server : %s' % server)
|
||||
summary = summarise_iis_error(result['body'])
|
||||
if summary and summary['hints']:
|
||||
report.line(' hints : %s' % ' | '.join(summary['hints'][:8]))
|
||||
if summary and summary['flat']:
|
||||
report.line(' body : %s' % summary['flat'][:600])
|
||||
|
||||
# localhost resolving to ::1 first has bitten this install before.
|
||||
report.block('name resolution for localhost', run(
|
||||
['nslookup', 'localhost'], timeout=20))
|
||||
|
||||
# ------------------------------------------------------------- 2. IIS state
|
||||
report.head('2. IIS STATE')
|
||||
appcmd = find_appcmd()
|
||||
if not appcmd:
|
||||
report.line('appcmd.exe NOT FOUND - is the IIS role installed?')
|
||||
else:
|
||||
report.line('appcmd: %s' % appcmd)
|
||||
report.block('sites', run([appcmd, 'list', 'sites']))
|
||||
report.block('applications', run([appcmd, 'list', 'apps']))
|
||||
report.block('app pools', run([appcmd, 'list', 'apppools']))
|
||||
report.block('worker processes (empty means nothing is running)',
|
||||
run([appcmd, 'list', 'wp']))
|
||||
report.block('modules: httpPlatformHandler present?',
|
||||
run([appcmd, 'list', 'modules']))
|
||||
# overrideMode tells us whether the unlock actually took effect.
|
||||
for section in ('system.webServer/handlers', 'system.webServer/httpPlatform'):
|
||||
report.block('lock state of %s' % section,
|
||||
run([appcmd, 'list', 'config', '/section:%s' % section,
|
||||
'/text:*']))
|
||||
|
||||
report.block('W3SVC / WAS services', powershell(
|
||||
"Get-Service W3SVC,WAS | Format-Table Name,Status,StartType -AutoSize | Out-String"))
|
||||
report.block('listeners on port 80', powershell(
|
||||
"Get-NetTCPConnection -LocalPort 80 -State Listen -EA SilentlyContinue | "
|
||||
"Format-Table LocalAddress,LocalPort,OwningProcess -AutoSize | Out-String"))
|
||||
report.block('app pool detail', powershell(
|
||||
"Import-Module WebAdministration -EA SilentlyContinue; "
|
||||
"Get-Item IIS:\\AppPools\\shopdbflask -EA SilentlyContinue | "
|
||||
"Select-Object name,state,managedRuntimeVersion,enable32BitAppOnWin64,"
|
||||
"@{n='identity';e={$_.processModel.identityType}} | Format-List | Out-String"))
|
||||
|
||||
# --------------------------------------------------------- 3. app + config
|
||||
report.head('3. APPLICATION AND CONFIG')
|
||||
|
||||
web_config = os.path.join(APP_ROOT, 'web.config')
|
||||
if os.path.isfile(web_config):
|
||||
try:
|
||||
with open(web_config, 'r', encoding='utf-8', errors='replace') as handle:
|
||||
report.block('web.config', handle.read())
|
||||
except Exception as exc:
|
||||
report.block('web.config', '[could not read: %s]' % exc)
|
||||
else:
|
||||
report.block('web.config', 'MISSING at %s' % web_config)
|
||||
|
||||
if env_raw is None:
|
||||
report.block('.env', 'MISSING at %s' % os.path.join(APP_ROOT, '.env'))
|
||||
else:
|
||||
# Keys and non-secret values only. Secret values are scrubbed anyway.
|
||||
lines = []
|
||||
for key in sorted(env_values):
|
||||
upper = key.upper()
|
||||
secretish = ('SECRET' in upper or 'PASSWORD' in upper
|
||||
or 'TOKEN' in upper or 'KEY' in upper
|
||||
or upper == 'DATABASE_URL')
|
||||
if secretish:
|
||||
lines.append('%s = <set, %d chars>' % (key, len(env_values[key])))
|
||||
else:
|
||||
lines.append('%s = %s' % (key, env_values[key]))
|
||||
report.block('.env (secret values withheld)', '\n'.join(lines))
|
||||
|
||||
venv_python = os.path.join(APP_ROOT, 'venv', 'Scripts', 'python.exe')
|
||||
report.line('\nvenv python exists: %s' % os.path.isfile(venv_python))
|
||||
if os.path.isfile(venv_python):
|
||||
# The exact failure stage 3 used to hit. Proves the app imports.
|
||||
report.block('venv: import shopdb', run(
|
||||
[venv_python, '-c',
|
||||
'import shopdb; print("import OK"); '
|
||||
'app = shopdb.create_app(); print("create_app OK")'], timeout=120))
|
||||
report.block('venv: waitress present', run(
|
||||
[venv_python, '-c', 'import waitress; print(waitress.__version__)'],
|
||||
timeout=60))
|
||||
|
||||
# What httpPlatformHandler is told to launch, and whether it exists.
|
||||
if os.path.isfile(web_config):
|
||||
try:
|
||||
with open(web_config, 'r', encoding='utf-8', errors='replace') as handle:
|
||||
raw = handle.read()
|
||||
match = re.search(r'processPath\s*=\s*"([^"]+)"', raw)
|
||||
args = re.search(r'arguments\s*=\s*"([^"]*)"', raw)
|
||||
if match:
|
||||
path = os.path.expandvars(match.group(1))
|
||||
report.line('\nhttpPlatform processPath : %s' % match.group(1))
|
||||
report.line(' resolved : %s' % path)
|
||||
report.line(' exists : %s' % os.path.isfile(path))
|
||||
if args:
|
||||
report.line('httpPlatform arguments : %s' % args.group(1))
|
||||
except Exception as exc:
|
||||
report.line('[could not parse web.config: %s]' % exc)
|
||||
|
||||
# ------------------------------------------------------------- 4. app logs
|
||||
report.head('4. APPLICATION LOGS')
|
||||
log_dir = os.path.join(APP_ROOT, 'logs')
|
||||
if not os.path.isdir(log_dir):
|
||||
report.line('MISSING: %s' % log_dir)
|
||||
else:
|
||||
entries = []
|
||||
for name in sorted(os.listdir(log_dir)):
|
||||
full = os.path.join(log_dir, name)
|
||||
try:
|
||||
entries.append((os.path.getmtime(full), full, name,
|
||||
os.path.getsize(full)))
|
||||
except OSError:
|
||||
pass
|
||||
if not entries:
|
||||
report.line('%s is EMPTY.' % log_dir)
|
||||
report.line('No stdout log at all means httpPlatformHandler never')
|
||||
report.line('launched python - look at the pool identity and ACLs.')
|
||||
for _, full, name, size in sorted(entries, reverse=True)[:5]:
|
||||
if size == 0:
|
||||
report.block('%s (0 bytes)' % name,
|
||||
'EMPTY - python was launched but wrote nothing.')
|
||||
continue
|
||||
try:
|
||||
with open(full, 'r', encoding='utf-8', errors='replace') as handle:
|
||||
tail = handle.readlines()[-60:]
|
||||
report.block('%s (%d bytes, last 60 lines)' % (name, size),
|
||||
''.join(tail))
|
||||
except Exception as exc:
|
||||
report.block(name, '[could not read: %s]' % exc)
|
||||
|
||||
# ---------------------------------------------------------------- 5. ACLs
|
||||
report.head('5. PERMISSIONS')
|
||||
report.line('The pool runs as "IIS AppPool\\shopdbflask". It needs RX on the')
|
||||
report.line('tree, Modify on logs and instance, and Read on .env.')
|
||||
for target in (APP_ROOT, log_dir, os.path.join(APP_ROOT, '.env'),
|
||||
os.path.join(APP_ROOT, 'venv', 'Scripts')):
|
||||
if os.path.exists(target):
|
||||
report.block('icacls %s' % target, run(['icacls', target], timeout=40))
|
||||
|
||||
# ------------------------------------------------------------ 6. event log
|
||||
report.head('6. EVENT LOG')
|
||||
report.block('recent application errors', powershell(
|
||||
"Get-WinEvent -FilterHashtable @{LogName='Application';"
|
||||
"StartTime=(Get-Date).AddHours(-6)} -EA SilentlyContinue | "
|
||||
"Where-Object { $_.ProviderName -match 'HttpPlatform|IIS|W3SVC|WAS|\\.NET' "
|
||||
"-or $_.LevelDisplayName -eq 'Error' } | Select-Object -First 25 "
|
||||
"TimeCreated,ProviderName,LevelDisplayName,Message | Format-List | Out-String",
|
||||
timeout=180))
|
||||
report.block('system log: WAS / W3SVC', powershell(
|
||||
"Get-WinEvent -FilterHashtable @{LogName='System';"
|
||||
"StartTime=(Get-Date).AddHours(-6)} -EA SilentlyContinue | "
|
||||
"Where-Object { $_.ProviderName -match 'WAS|W3SVC|HTTP' } | "
|
||||
"Select-Object -First 20 TimeCreated,ProviderName,LevelDisplayName,Message | "
|
||||
"Format-List | Out-String", timeout=180))
|
||||
|
||||
# ------------------------------------------------------------------ write
|
||||
body = scrub(report.text())
|
||||
out_path = os.path.join(os.path.dirname(os.path.abspath(__file__)),
|
||||
'shopdb-diagnose-%s.txt' % stamp)
|
||||
try:
|
||||
with open(out_path, 'w', encoding='utf-8') as handle:
|
||||
handle.write(body)
|
||||
except Exception:
|
||||
out_path = os.path.join(os.environ.get('TEMP', r'C:\Windows\Temp'),
|
||||
'shopdb-diagnose-%s.txt' % stamp)
|
||||
with open(out_path, 'w', encoding='utf-8') as handle:
|
||||
handle.write(body)
|
||||
|
||||
print('')
|
||||
print('Report written to:')
|
||||
print(' %s' % out_path)
|
||||
print('')
|
||||
print('%d secret value(s) were scrubbed from it.' % len(SECRETS))
|
||||
print('Send that file back.')
|
||||
return 0
|
||||
|
||||
|
||||
if __name__ == '__main__':
|
||||
sys.exit(main())
|
||||
Reference in New Issue
Block a user