Files
lmxopcua/scripts/validation/opcua-lifecycle-memory/late-slope/analyze.py
T
2026-11-10 17:59:55 -05:00

424 lines
24 KiB
Python
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
#!/usr/bin/env python3
"""Validate a recorded Linux late-slope diagnostic and describe its quiescent samples."""
import argparse
import hashlib
import json
import math
from pathlib import Path
import re
from statistics import median
import sys
import xml.etree.ElementTree as ET
PROTOCOL = "sdk2-late-slope-v1"
DOCKER_LABEL = "org.otopcua.late-slope-run"
MODE = "late-slope"
SECONDS = 7200
MAX_CYCLE_SECONDS = 30
RESTART_SECONDS = 25
SHUTDOWN_SECONDS = 60
CONTAINER_SECONDS = 7440
RUNTIME = "10.0.14"
SDK = "2.0.1+07e62f72500cc0923a2bab940653c8c1116fa286"
APP = "ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests"
TEST_CLASS = APP + ".Sdk2LifecycleSoakTests."
TEST_NAME = TEST_CLASS + "Repeated_lifecycles_return_resources_to_a_steady_baseline"
DESCRIPTOR_TESTS = {
TEST_CLASS + "Descriptor_probe_observes_an_open_PKI_file_through_a_symlink_alias_and_its_close",
TEST_CLASS + "Descriptor_probe_times_out_and_reaps_a_process_that_keeps_both_streams_open",
}
STALL_STATUSES = {"OperationCanceled", "BadTimeout", "BadRequestCancelledByClient", "BadRequestTimeout", "BadRequestInterrupted"}
WINDOWS = ((1800, 2400), (3600, 4200), (6600, 7200))
BUDGETS = {"fdGrowth": 32, "retainedManagedGrowthBytes": 64 << 20, "rssGrowthBytes": 128 << 20}
SETTINGS = {
"protocol": PROTOCOL, "mode": MODE, "requestedSeconds": SECONDS, "rid": "linux-arm64",
"runtimeVersion": RUNTIME, "selfContained": True, "acceptance": False,
"startupTimeoutSeconds": 120, "cycleTimeoutSeconds": MAX_CYCLE_SECONDS,
"cycleDeadlineSeconds": SECONDS + MAX_CYCLE_SECONDS, "restartTimeoutSeconds": RESTART_SECONDS,
"ownerTimeoutSeconds": 20, "shutdownTimeoutSeconds": SHUTDOWN_SECONDS,
"containerTimeoutSeconds": CONTAINER_SECONDS, "certificateLeakTracking": True,
"windowsSeconds": [list(window) for window in WINDOWS], "limits": BUDGETS,
}
CAP_FIELDS = (("Descriptors", "fdGrowth"), ("ManagedBytes", "retainedManagedGrowthBytes"), ("RssBytes", "rssGrowthBytes"))
ZERO_FIELDS = (
"Sessions", "Subscriptions", "Items", "BrowsePoints", "HistoryPoints",
"LiveDataItems", "LiveEventItems", "MonitoredNodes", "PkiDescriptors",
)
STEADY_FIELDS = ("Variables", "Folders", "Conditions", "CachedCertificateStores")
MEASUREMENTS = (
"Descriptors", "ManagedBytes", "RssBytes", "AllocatedBytes", "Gen0", "Gen1", "Gen2",
"GcCommittedBytes", "GcHeapBytes", "GcFragmentedBytes", "PinnedObjects", "PendingFinalizers",
"JitMethods", "JitIlBytes", "ActiveTimers", "Threads",
)
SAMPLE_FIELDS = {"Cycle", "Seconds", *ZERO_FIELDS, *STEADY_FIELDS, *MEASUREMENTS}
EVIDENCE_FILES = (
"launch.json", "container.log", "container-exit-status.txt", "controller-runtime.txt",
"descriptor-controls.log", "test.log", "target-runtime.txt", "resources.jsonl",
"test-exit-status.txt", "results/descriptor-controls.trx", "results/late-slope.trx",
)
TRX = {"t": "http://microsoft.com/schemas/VisualStudio/TeamTest/2010"}
def require(condition, message):
if not condition:
raise ValueError(message)
def local_context(context):
return (type(context) is dict and set(context) == {"name", "endpoint"}
and isinstance(context["name"], str) and re.fullmatch(r"[A-Za-z0-9_.-]+", context["name"])
and isinstance(context["endpoint"], str) and context["endpoint"].startswith("unix:///")
and not any(character in context["endpoint"] for character in "\r\n\0"))
def container_command(root, output, bundle, run_id):
require(all(path.is_absolute() and ":" not in str(path) for path in (root, output)), "Invalid Docker bind paths")
require(local_context(bundle["dockerContext"]), "Expected the reviewed local Unix Docker context")
return ["docker", "--host", bundle["dockerContext"]["endpoint"], "run", "--rm", "--init", "--pull", "never",
"--network", "none", "--platform", "linux/arm64", "--read-only", "--workdir", "/task",
"--name", f"opcua-late-slope-{run_id}",
"--label", f"{DOCKER_LABEL}={run_id}", "-e", "OTOPCUA_SOAK_BUILD_SHA=" + bundle["sourceRevision"],
"-v", f"{root / 'app'}:/app:ro", "-v", f"{root / 'tools'}:/tools:ro", "-v", f"{output}:/task",
bundle["image"], "bash", "/tools/container.sh"]
def digest(path):
with path.open("rb") as stream:
return hashlib.file_digest(stream, "sha256").hexdigest()
def unique_object(pairs):
result = {}
for key, value in pairs:
require(key not in result, f"Duplicate JSON key {key}")
result[key] = value
return result
def reject_constant(value):
raise ValueError(f"Invalid JSON constant {value}")
def json_object(text):
value = json.loads(text, object_pairs_hook=unique_object, parse_constant=reject_constant)
require(type(value) is dict, "Expected a JSON object")
return value
def read_object(path):
return json_object(path.read_text(encoding="utf-8"))
def read_rows(path):
with path.open(encoding="utf-8") as stream:
for line_number, line in enumerate(stream, 1):
require(line.endswith("\n"), f"Truncated JSONL row {line_number}")
try:
yield json_object(line)
except ValueError as error:
raise ValueError(f"Invalid JSONL row {line_number}: {error}") from error
def count(value, label, minimum=0):
require(type(value) is int and minimum <= value <= (1 << 63) - 1, f"Invalid {label}")
return value
def seconds(value, label, minimum=0, maximum=CONTAINER_SECONDS):
require(type(value) in (int, float) and minimum <= value <= maximum, f"Invalid {label}")
return value
def assertion_message(text):
require(isinstance(text, str), "Missing original resource-cap assertion")
message = text.replace("\r", "").split("\n at ", 1)[0].strip()
normalized = re.sub(r"^Shouldly\.ShouldAssertException\s*:\s*", "Shouldly.ShouldAssertException: ", message)
require(normalized.startswith("Shouldly.ShouldAssertException: ") and len(normalized) > 32,
"The recorded failure is not a resource-cap assertion")
return normalized
def sample(row, cycle):
value = row["resources"]
require(type(value) is dict and set(value) == SAMPLE_FIELDS, f"Invalid sample fields at cycle {cycle}")
require(count(value["Cycle"], "sample cycle", 1) == cycle, f"Out-of-order sample cycle {cycle}")
seconds(value["Seconds"], "sample time", maximum=SECONDS + MAX_CYCLE_SECONDS)
for field in SAMPLE_FIELDS - {"Cycle", "Seconds"}:
count(value[field], field)
require(all(value[field] == 0 for field in ZERO_FIELDS), f"Quiescent ownership failure at cycle {cycle}")
return value
def validate_rows(rows, revision):
"""Validate the canonical row order, original budget and fixed-duration outcome."""
rows = iter(rows)
def take(kind):
row = next(rows, {})
require(row.get("kind") == kind, f"Expected {kind}, found {row.get('kind')!r}")
require(row.get("acceptance", False) is False and "satisfiesTwoHourDuration" not in row,
"An ordinary acceptance result is forbidden")
return row
start = take("start")
require(start.get("mode") == MODE and start.get("requestedSeconds") == SECONDS
and type(start["requestedSeconds"]) is int and start.get("minimumFullSeconds") == SECONDS
and start.get("acceptance") is False, "Wrong fixed-duration diagnostic mode")
require(start.get("build") == revision and re.fullmatch(r"[0-9a-f]{40}", revision), "Wrong source revision")
require(start.get("runtime") == RUNTIME and start.get("architecture") == "Arm64" and start.get("sdk") == SDK,
"Wrong Linux ARM64 runtime or SDK version")
count(start.get("processId"), "test process ID", 1)
seconds(start.get("startupSeconds"), "startup duration", maximum=SETTINGS["startupTimeoutSeconds"])
limits = start.get("limits")
require(type(limits) is dict and limits == BUDGETS and all(type(value) is int for value in limits.values()),
"Original cold resource caps changed")
samples = []
first_rejection = None
completions = []
# Buffer only a single row so the actual record order cannot be reconstructed by sorting.
pending = next(rows, {})
while pending.get("kind") == "active":
cycle = len(samples) + 1
require(count(pending.get("cycle"), "active cycle", 1) == cycle, "Missing or duplicate active cycle")
active_counts = tuple(count(pending.get(field), field) for field in ("sessions", "subscriptions", "items"))
require(active_counts == (2, 1, 3), f"Incomplete active session, subscription or item exercise at cycle {cycle}")
for field in ("browsePoints", "historyPoints"):
count(pending.get(field), field, 1)
stall = take("network-stall-recovered")
require(count(stall.get("cycle"), "recovered stall cycle", 1) == cycle, "Missing or duplicate recovered stall")
seconds(stall.get("seconds"), "network stall time", maximum=MAX_CYCLE_SECONDS)
require(isinstance(stall.get("status"), str) and stall["status"] in STALL_STATUSES,
"Unexpected recovered network stall status")
value = sample(take("resource-observation"), cycle)
require(not samples or value["Seconds"] > samples[-1]["Seconds"], "Nonmonotonic or duplicate sample time")
require(not completions or value["Seconds"] > completions[-1]["elapsedSeconds"],
"Sample precedes completion of the previous cycle")
samples.append(value)
if cycle >= 3:
baseline = samples[2]
require(all(value[field] == baseline[field] for field in STEADY_FIELDS),
f"Quiescent model or certificate-store inventory changed at cycle {cycle}")
exceeded = [field for field, cap in CAP_FIELDS if value[field] > baseline[field] + BUDGETS[cap]]
if exceeded and first_rejection is None:
rejection = take("budget-rejected")
require(count(rejection.get("cycle"), "rejection cycle", 1) == cycle
and sample(rejection, cycle) == value
and sample({"resources": rejection.get("baseline")}, 3) == baseline,
"First rejection does not match the failing sample and original cycle-three baseline")
seconds(rejection.get("seconds"), "rejection time", minimum=value["Seconds"],
maximum=SECONDS + MAX_CYCLE_SECONDS)
first_rejection = {**rejection, "exceededFields": exceeded,
"assertionMessage": assertion_message(rejection.get("failure"))}
if cycle >= 26:
retained = [row["ManagedBytes"] for row in samples[-24:]]
require(not (all(a < b for a, b in zip(retained, retained[1:]))
and retained[-1] - retained[0] > (16 << 20)),
f"Managed growth guard failed at cycle {cycle}")
quiescent = take("quiescent-budget-rejected" if first_rejection else "quiescent")
require(sample(quiescent, cycle) == value, "Quiescent sample differs from its pre-assertion observation")
quiescent_seconds = seconds(quiescent.get("cycleSeconds"), "quiescent cycle duration", maximum=MAX_CYCLE_SECONDS)
restart_seconds = 0
if cycle % 4 == 0:
restart = take("restart")
require(count(restart.get("cycles"), "restart cycle", 1) == cycle
and count(restart.get("restarts"), "restart count", 1) == cycle // 4, "Missing or duplicate active restart")
bounded = seconds(restart.get("boundedRestartSeconds"), "bounded restart duration", maximum=RESTART_SECONDS)
restart_seconds = seconds(restart.get("seconds"), "combined restart duration", minimum=bounded, maximum=MAX_CYCLE_SECONDS)
completion = take("late-slope-cycle")
require(count(completion.get("cycle"), "completed cycle", 1) == cycle
and count(completion.get("restarts"), "completed restarts") == cycle // 4, "Invalid completed cycle ledger")
elapsed = seconds(completion.get("elapsedSeconds"), "cycle completion time", minimum=value["Seconds"],
maximum=SECONDS + MAX_CYCLE_SECONDS)
seconds(completion.get("cycleSeconds"), "complete cycle duration", minimum=quiescent_seconds + restart_seconds,
maximum=MAX_CYCLE_SECONDS)
if first_rejection and first_rejection["cycle"] == cycle:
require(first_rejection["seconds"] <= elapsed, "Rejection follows its completed cycle")
require(not completions or completions[-1]["elapsedSeconds"] < SECONDS,
"Another cycle began after the fixed duration")
completions.append(completion)
pending = next(rows, {})
result = pending
require(result.get("kind") == "late-slope-result" and next(rows, None) is None,
"Expected a unique final diagnostic result with no ordinary completion or trailing failure")
require(result.get("mode") == MODE and result.get("acceptance") is False
and "satisfiesTwoHourDuration" not in result and result.get("durationCompleted") is True
and result.get("shutdownVerified") is True and result.get("fatalFailure") is False and result.get("failureTypes") == [],
"Duration, shutdown or diagnostic outcome was incomplete")
cycles = count(result.get("cycles"), "result cycles", 4)
require(cycles == len(samples) and count(result.get("restarts"), "result restarts", 1) == cycles // 4,
"Final cycle or restart count differs from the ledger")
phase = seconds(result.get("cycleSeconds"), "canonical cycle phase", minimum=SECONDS, maximum=SECONDS + MAX_CYCLE_SECONDS)
require(phase >= completions[-1]["elapsedSeconds"] and completions[-1]["elapsedSeconds"] >= SECONDS,
"The final cycle does not cover the fixed duration")
seconds(result.get("shutdownSeconds"), "shutdown duration", maximum=SHUTDOWN_SECONDS)
require(result.get("coldBudgetRejected") is (first_rejection is not None), "The first cold-cap rejection was not preserved")
return start, samples, completions, first_rejection, result
def sample_summary(samples, fields):
times = [value["Seconds"] for value in samples]
summary = {"sampleCount": len(samples), "firstSeconds": times[0], "lastSeconds": times[-1],
"spanSeconds": times[-1] - times[0], "maximumGapSeconds": max((b - a for a, b in zip(times, times[1:])), default=0)}
for field in fields:
values = [value[field] for value in samples]
summary[field] = {"first": values[0], "last": values[-1], "min": min(values), "max": max(values), "median": median(values)}
return summary
def slope(samples, field):
times = [value["Seconds"] for value in samples]
mean = math.fsum(times) / len(times)
mean_value = math.fsum(value[field] for value in samples) / len(samples)
variance = math.fsum((time - mean) ** 2 for time in times)
return 3600 * math.fsum((time - mean) * (value[field] - mean_value)
for time, value in zip(times, samples)) / variance
def describe(samples, completions):
windows = []
for begin, end in WINDOWS:
subset = [value for value in samples if begin <= value["Seconds"] <= end]
require(len(subset) >= 10, f"Insufficient observations in {begin}–{end} seconds")
summary = sample_summary(subset, MEASUREMENTS)
require(summary["firstSeconds"] <= begin + 60 and summary["lastSeconds"] >= end - 60
and summary["spanSeconds"] >= 480 and summary["maximumGapSeconds"] <= 60,
f"Incomplete coverage in {begin}–{end} seconds")
windows.append({"windowSeconds": [begin, end], **summary})
late = [value for value in samples if 1800 <= value["Seconds"] <= SECONDS]
coverage = sample_summary(late, ())
require(coverage["maximumGapSeconds"] <= 60, "An observation gap exceeds 60 seconds across the late phase")
previous = [row for row in completions if row["elapsedSeconds"] <= 1800]
cycles = len(previous)
restarts = previous[-1]["restarts"] if previous else 0
work = {"cycles": cycles, "restarts": restarts, "earlierSaturationWorkloadReached": cycles >= 385 and restarts >= 96}
if not work["earlierSaturationWorkloadReached"]:
work["interpretation"] = "Post-restart-step attribution withheld because the earlier workload counts fell short by 1800 seconds."
return {
"allQuiescent": sample_summary(samples, (*ZERO_FIELDS, *STEADY_FIELDS, *MEASUREMENTS)),
"finalQuiescentSample": samples[-1],
"windows": windows,
"leastSquares": {**coverage, "rangeSeconds": [1800, SECONDS], "units": "bytes/hour",
"rss": slope(late, "RssBytes"), "retainedManaged": slope(late, "ManagedBytes")},
"workCompletedBy1800Seconds": work,
}
def check_trx(path, expected_names, failure=None):
document = ET.parse(path).getroot()
counters = document.findall("./t:ResultSummary/t:Counters", TRX)
require(len(counters) == 1, f"Missing unique counters in {path.name}")
counters = counters[0].attrib
total = len(expected_names)
failed = 1 if failure else 0
expected = {"total": total, "executed": total, "passed": total - failed, "failed": failed,
"error": 0, "timeout": 0, "aborted": 0, "notExecuted": 0}
for key, value in expected.items():
require(counters.get(key) == str(value), f"Unexpected {key} count in {path.name}")
for key in ("inconclusive", "passedButRunAborted", "notRunnable", "disconnected", "inProgress", "pending"):
require(counters.get(key, "0") == "0", f"Unexpected {key} count in {path.name}")
results = document.findall("./t:Results/t:UnitTestResult", TRX)
require(len(results) == total and {row.get("testName") for row in results} == expected_names,
f"Wrong test identities in {path.name}")
require(all(row.get("outcome") == ("Failed" if failure else "Passed") for row in results),
f"Unexpected test outcome in {path.name}")
if failure:
actual = results[0].findtext("./t:Output/t:ErrorInfo/t:Message", namespaces=TRX)
require(assertion_message(actual) == failure, "TRX failure differs from the first cold-cap assertion")
return {"executed": total, "passed": total - failed, "failed": failed, "skipped": 0}
def exit_status(path):
value = path.read_text(encoding="ascii").strip()
require(re.fullmatch(r"0|[1-9][0-9]{0,2}", value) and int(value) <= 255, f"Invalid {path.name}")
return int(value)
def inspect_run(path, provenance, wall_seconds):
"""Check actual run evidence. This function neither launches Docker nor changes the evidence."""
start, samples, completions, rejection, result = validate_rows(read_rows(path / "resources.jsonl"), provenance["sourceRevision"])
wall = seconds(wall_seconds, "container wall time", minimum=SECONDS)
require(start["startupSeconds"] + result["cycleSeconds"] + result["shutdownSeconds"] <= wall,
"Startup, cycle and shutdown phases exceed measured wall time")
test_exit = exit_status(path / "test-exit-status.txt")
container_exit = exit_status(path / "container-exit-status.txt")
require(test_exit == container_exit and ((test_exit != 0) == bool(rejection)), "Original test/container exit was not preserved")
mapping = (path / "target-runtime.txt").read_text(encoding="ascii").splitlines()
require(mapping == [f"targetPid={start['processId']}", f"actualExecutable=/app/{APP}",
"mappedCoreClr=/app/libcoreclr.so", f"coreClrSha256={provenance['coreClrSha256']}"],
"Published Linux apphost or mapped CLR was not verified for the recorded PID")
controls = check_trx(path / "results/descriptor-controls.trx", DESCRIPTOR_TESTS)
workload = check_trx(path / "results/late-slope.trx", {TEST_NAME}, rejection and rejection["assertionMessage"])
return {"diagnosticOutcome": result, "firstColdRejection": rejection, "descriptorTests": controls,
"experimentTests": workload, "testExitStatus": test_exit, "containerExitStatus": container_exit,
**describe(samples, completions)}
def evidence_hashes(path):
result = {}
for name in EVIDENCE_FILES:
file = path / name
require(file.is_file() and file.resolve() == file, f"Missing or linked evidence file {name}")
result[name] = digest(file)
return result
def analyze_run(path, bundle_receipt_path, bundle_hash):
require(re.fullmatch(r"[0-9a-f]{64}", bundle_hash) and digest(bundle_receipt_path) == bundle_hash,
"Reviewed bundle receipt hash differs")
bundle = read_object(bundle_receipt_path)
require(bundle.get("kind") == "bundle" and all(type(bundle.get(key)) is type(value) and bundle[key] == value
for key, value in SETTINGS.items()),
"Invalid immutable bundle protocol")
receipt = read_object(path / "run-receipt.json")
provenance = read_object(path / "launch.json")
require(receipt.get("kind") == "run" and provenance.get("kind") == "launch", "Wrong receipt types")
for record in (receipt, provenance):
require(record.get("protocol") == PROTOCOL and record.get("acceptance") is False
and record.get("bundleReceiptSha256") == bundle_hash, "Wrong diagnostic provenance")
for field in ("runId", "sourceRevision", "image", "coreClrSha256", "dockerContext", "command", "containerTimeoutSeconds"):
require(receipt[field] == provenance[field], f"Launch and run receipts disagree on {field}")
require(receipt["sourceRevision"] == bundle["sourceRevision"] and receipt["image"] == bundle["image"]
and receipt["coreClrSha256"] == bundle["files"]["app/libcoreclr.so"]
and receipt["dockerContext"] == bundle["dockerContext"],
"Recorded source, image or runtime differs from the reviewed bundle")
require(re.fullmatch(r"[0-9a-f]{32}", receipt["runId"])
and re.fullmatch(r"sha256:[0-9a-f]{64}", receipt["image"])
and re.fullmatch(r"[0-9a-f]{64}", receipt["coreClrSha256"]), "Invalid run identity or immutable provenance")
require(receipt.get("diagnosticCompleted") is True and receipt.get("containerRemoved") is True,
"The launcher did not verify duration, shutdown and container cleanup")
require("validationErrors" not in receipt and provenance["containerTimeoutSeconds"] == CONTAINER_SECONDS
and provenance["command"] == container_command(Path(provenance["bundlePath"]), Path(provenance["outputPath"]),
bundle, receipt["runId"]), "The recorded container invocation differs")
require(receipt.get("evidenceSha256") == evidence_hashes(path), "Recorded evidence hashes differ")
report = inspect_run(path, provenance, receipt["wallSeconds"])
for field in ("diagnosticOutcome", "testExitStatus", "containerExitStatus", "descriptorTests", "experimentTests"):
require(receipt[field] == report[field], f"Run receipt differs from the raw {field}")
require(receipt.get("launcherExitStatus") == report["testExitStatus"], "The launcher did not preserve the original exit")
return {"protocol": PROTOCOL, "acceptance": False, "bundleReceiptSha256": bundle_hash,
"sourceRevision": receipt["sourceRevision"], "evidenceSha256": receipt["evidenceSha256"], **report}
def main():
parser = argparse.ArgumentParser(description=__doc__)
parser.add_argument("--run", type=Path, required=True)
parser.add_argument("--bundle-receipt", type=Path, required=True)
parser.add_argument("--bundle-receipt-sha256", required=True)
options = parser.parse_args()
try:
print(json.dumps(analyze_run(options.run.resolve(strict=True), options.bundle_receipt,
options.bundle_receipt_sha256), indent=2, allow_nan=False))
except (OSError, ValueError, KeyError, TypeError, ET.ParseError) as error:
print(f"Incomplete late-slope evidence: {error}", file=sys.stderr)
return 1
return 0
if __name__ == "__main__":
raise SystemExit(main())