95b0b77c13
The stage 5 smoke test failure was a locked config section, but not one of the two the installer unlocks. A diagnostic collected from the server returned: HTTP 500.52 - URL Rewrite Module Error Module RewriteModule, Handler httpplatformhandler Error Code 0x80070021 Config Error: This configuration section cannot be used at this path. Config File: \\?\C:\shopdb-flask\web.config handlers and httpPlatform were both overrideMode Allow and locked false, so the unlock had worked. The section at fault was a third one, system.webServer/rewrite/allowedServerVariables, which ships overrideModeDefault="Deny". web.config declared <allowedServerVariables> locally for the X-Forwarded-For rule, and IIS rejects that declaration outright, failing the entire configuration before httpPlatformHandler ran. python was therefore never launched and C:\shopdb-flask\logs stayed empty, which reads as a dead application or a permissions fault and is neither. Unlocking the section would let every site on the machine declare arbitrary server variables. The installer now adds the single variable to the server-level allow list, checking first because a duplicate add is an error, and web.config no longer declares it. The rewrite rule is unchanged. Verified by applying the installer's own uncommenting to the template and parsing the result: one rewrite element, no allowedServerVariables, the rule still setting HTTP_X_FORWARDED_FOR from REMOTE_ADDR. shopdb-diagnose.py checked only the two sections the installer unlocks, so it could not have named this one; the IIS error page did. It now reports the lock state of the rewrite sections as well.
423 lines
18 KiB
Python
423 lines
18 KiB
Python
"""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.
|
|
#
|
|
# allowedServerVariables is in this list because it caused a 500.52 that
|
|
# the first two sections could not explain: it is Deny by default, so an
|
|
# <allowedServerVariables> block in the app's web.config is rejected
|
|
# before httpPlatformHandler runs. Checking only the sections we unlock
|
|
# would have missed the one we do not.
|
|
for section in ('system.webServer/handlers',
|
|
'system.webServer/httpPlatform',
|
|
'system.webServer/rewrite/allowedServerVariables',
|
|
'system.webServer/rewrite/rules'):
|
|
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())
|