test(harness): resident CEF reuse proof for startup measurements (#416)
* feat(cef): integrate residency lifecycle with quiescence * fix(cef): address senior review blockers on residency * test(harness): prove resident CEF reuse across second windows Fix isolated-env rendering (JSON log config, absolute Wayland display, display var passthrough), capture the relay owner log with first-presentation readiness, count owner CEF inits per sample, scope the relay socket search to XDG_STATE, and add --idle-timeout-ms so reopen-window can exercise the residency knob. Only summary and run JSON files are shareable; owner logs stay machine-local. * test(harness): report spawn-to-first-document latency per sample Wall-clock log times are second-precision and process milestones fire once, so neither can time a resident second window. Export first_document_observation_ms measured on the harness monotonic clock (spawn to first fixture document request) as the honest second-window latency until page beacons are delivered. * test(harness): enforce residency validity per senior review Separate fixture completeness from residency validity: require clean launcher handoff (exit 0, no launcher CEF init) to a live unchanged owner with exactly one CEF init, plus settled close and same process for reopen. Resident samples wait for the correlated document past launcher exit until a bounded navigation deadline. Document routes validate run/nav tokens and handler state is per-sample. Rename the second-window aggregate to spawn-to-first-document, restrict it to valid samples, and escape all TOML control characters. * test(harness): drop duplicated bad-runs block from idle-timeout test Copilot review on PR #416: the trailing subprocess block repeated the existing bad --runs coverage without exercising --idle-timeout-ms. The flag is covered by the parametrized loop above; bad --runs stays in test_rejects_bad_runs.
- commit
- 5fc5c8e741b7152b7f5060c64d20e1ab6bd10e24
- author
- bnema · · 2026-09-08 11:59 UTC
- committer
- GitHub · · 2026-09-08 11:59 UTC
- parent
- 58268c8
- signature
- GPG Unverified
B5690EEEBB952194The key is unknown
2 files · +658 -34
M scripts/measure_cef_startup.py +325 -33
| @@ -13,6 +13,18 @@ Scenarios: | |||
| 13 | 13 | through the relay; verifies the same owner process serves | |
| 14 | 14 | the reopen without a second CEF initialization | |
| 15 | 15 | ||
| 16 | + | Second-window contract (relay-window, reopen-window): the owner captures | |
| 17 | + | its own log, readiness is its first presentation (never a fixed sleep), | |
| 18 | + | and every sample records owner_cef_init_count, which must stay at 1. | |
| 19 | + | Cold-process numbers (process-warm, profile-fresh) and resident-reopen | |
| 20 | + | observations are reported separately and never averaged together. | |
| 21 | + | --idle-timeout-ms forwards the product residency knob into generated | |
| 22 | + | configs (default 0 = exit with last window; reopen-window only reuses | |
| 23 | + | the same process with a nonzero timeout). Second-window latency is | |
| 24 | + | first_document_observation_ms (spawn to first fixture document request | |
| 25 | + | on the harness clock); paint-level timing stays open until page | |
| 26 | + | beacons are delivered. | |
| 27 | + | ||
| 16 | 28 | Fixtures (loopback only): static, delayed, redirect, cache. | |
| 17 | 29 | ||
| 18 | 30 | Protocol: fixture pages report PerformanceObserver results through a | |
| @@ -67,6 +79,46 @@ def post_nav_cutoff_seconds(): | |||
| 67 | 79 | return min(30.0, max(0.1, value)) | |
| 68 | 80 | ||
| 69 | 81 | ||
| 82 | + | def navigation_deadline_seconds(): | |
| 83 | + | # Bounded wait for the correlated document after spawn when no | |
| 84 | + | # document has arrived yet. Overridable for fast unit tests. | |
| 85 | + | try: | |
| 86 | + | value = float(os.environ.get("DUMBER_MEASURE_NAV_DEADLINE_SECONDS", "")) | |
| 87 | + | if value > 0: | |
| 88 | + | return min(60.0, value) | |
| 89 | + | except ValueError: | |
| 90 | + | pass | |
| 91 | + | return post_nav_cutoff_seconds() + 5.0 | |
| 92 | + | ||
| 93 | + | ||
| 94 | + | def is_residency_valid(result, scenario): | |
| 95 | + | # Fixture completeness (document count, beacons) is not residency | |
| 96 | + | # validity. A resident sample is valid only when the launcher handed | |
| 97 | + | # off cleanly to a live, unchanged owner that initialized CEF exactly | |
| 98 | + | # once, the launcher itself never initialized CEF (a fallback cold | |
| 99 | + | # start would hide in the dead owner's log), and a reopen additionally | |
| 100 | + | # completed its close. Returns True/False, or None outside resident | |
| 101 | + | # scenarios. | |
| 102 | + | if scenario not in ("relay-window", "reopen-window"): | |
| 103 | + | return None | |
| 104 | + | if result.get("fallback_spawn") or not result.get("relayed"): | |
| 105 | + | return False | |
| 106 | + | if result.get("launcher_returncode") != 0: | |
| 107 | + | return False | |
| 108 | + | if result.get("owner_cef_init_count") != 1: | |
| 109 | + | return False | |
| 110 | + | if result.get("launcher_cef_init_count", 0) != 0: | |
| 111 | + | return False | |
| 112 | + | if scenario == "reopen-window": | |
| 113 | + | reopen = result.get("reopen") or {} | |
| 114 | + | if not (reopen.get("close_acknowledged") | |
| 115 | + | and reopen.get("quiescence_settled", False) | |
| 116 | + | and reopen.get("same_process") | |
| 117 | + | and reopen.get("owner_alive_after")): | |
| 118 | + | return False | |
| 119 | + | return True | |
| 120 | + | ||
| 121 | + | ||
| 70 | 122 | class FixtureState: | |
| 71 | 123 | def __init__(self): | |
| 72 | 124 | self.lock = threading.Lock() | |
| @@ -147,14 +199,37 @@ class Handler(BaseHTTPRequestHandler): | |||
| 147 | 199 | else: | |
| 148 | 200 | self.state.subresource_requests.append(entry) | |
| 149 | 201 | ||
| 202 | + | def _document_tokens_valid(self, parsed): | |
| 203 | + | # Document routes carry the sample tokens by construction; an | |
| 204 | + | # uncorrelated request (stale tab, foreign client, port reuse) | |
| 205 | + | # must neither establish the first-document timestamp nor be | |
| 206 | + | # served the current sample's tokens. | |
| 207 | + | query = parse_qs(parsed.query) | |
| 208 | + | run = query.get("run", [None])[0] | |
| 209 | + | nav = query.get("nav", [None])[0] | |
| 210 | + | return ( | |
| 211 | + | isinstance(run, str) and TOKEN_RE.fullmatch(run) and run == self.run_token | |
| 212 | + | and isinstance(nav, str) and NAV_RE.fullmatch(nav) and nav == self.nav_token | |
| 213 | + | ) | |
| 214 | + | ||
| 150 | 215 | def do_GET(self): | |
| 151 | 216 | parsed = urlparse(self.path) | |
| 152 | 217 | path = parsed.path | |
| 153 | 218 | if path == "/__beacon": | |
| 154 | 219 | self._handle_beacon(parsed) | |
| 155 | 220 | return | |
| 156 | - | if path in ("/", "/index.html", "/target"): | |
| 221 | + | if path in ("/", "/index.html", "/target", "/redirect"): | |
| 222 | + | if not self._document_tokens_valid(parsed): | |
| 223 | + | self.send_response(404) | |
| 224 | + | self.end_headers() | |
| 225 | + | return | |
| 157 | 226 | self._record(True) | |
| 227 | + | if path == "/redirect": | |
| 228 | + | target = "/target?run=%s&nav=%s" % (self.run_token, self.nav_token) | |
| 229 | + | self.send_response(302) | |
| 230 | + | self.send_header("Location", target) | |
| 231 | + | self.end_headers() | |
| 232 | + | return | |
| 158 | 233 | if self.fixture == "delayed" and path == "/": | |
| 159 | 234 | time.sleep(self.delay_seconds) | |
| 160 | 235 | body = build_fixture_html( | |
| @@ -168,13 +243,6 @@ class Handler(BaseHTTPRequestHandler): | |||
| 168 | 243 | self.end_headers() | |
| 169 | 244 | self.wfile.write(body) | |
| 170 | 245 | return | |
| 171 | - | if path == "/redirect": | |
| 172 | - | self._record(True) | |
| 173 | - | target = "/target?run=%s&nav=%s" % (self.run_token, self.nav_token) | |
| 174 | - | self.send_response(302) | |
| 175 | - | self.send_header("Location", target) | |
| 176 | - | self.end_headers() | |
| 177 | - | return | |
| 178 | 246 | if path in ("/app.css", "/pixel.png", "/cacheable.js", "/cacheable.png"): | |
| 179 | 247 | self._record(False) | |
| 180 | 248 | if path.endswith(".png"): | |
| @@ -230,6 +298,18 @@ class Handler(BaseHTTPRequestHandler): | |||
| 230 | 298 | self.end_headers() | |
| 231 | 299 | ||
| 232 | 300 | ||
| 301 | + | def make_sample_handler(state, fixture, run_token, nav_token): | |
| 302 | + | # Per-sample handler state: the base Handler only carries defaults. | |
| 303 | + | # Binding state on a fresh subclass per sample keeps surviving request | |
| 304 | + | # threads of a previous sample from adopting a later sample's tokens. | |
| 305 | + | return type("SampleHandler", (Handler,), { | |
| 306 | + | "state": state, | |
| 307 | + | "fixture": fixture, | |
| 308 | + | "run_token": run_token, | |
| 309 | + | "nav_token": nav_token, | |
| 310 | + | }) | |
| 311 | + | ||
| 312 | + | ||
| 233 | 313 | def parse_child_output(lines): | |
| 234 | 314 | milestones = [] | |
| 235 | 315 | for line in lines: | |
| @@ -242,7 +322,121 @@ def parse_child_output(lines): | |||
| 242 | 322 | return milestones | |
| 243 | 323 | ||
| 244 | 324 | ||
| 245 | - | def scenario_env(cef_dir, dirs, extra=None): | |
| 325 | + | DISPLAY_PASSTHROUGH_VARS = ("DBUS_SESSION_BUS_ADDRESS", "XAUTHORITY") | |
| 326 | + | ||
| 327 | + | ||
| 328 | + | def _escape_toml_basic(value): | |
| 329 | + | # Full TOML basic-string escaping: backslash, quote, and every | |
| 330 | + | # control character (raw newlines/tabs/other C0 controls are invalid | |
| 331 | + | # in basic strings). Paths with such characters stay representable | |
| 332 | + | # instead of producing broken configuration. | |
| 333 | + | out = [] | |
| 334 | + | for char in value: | |
| 335 | + | code = ord(char) | |
| 336 | + | if char == "\\": | |
| 337 | + | out.append("\\\\") | |
| 338 | + | elif char == '"': | |
| 339 | + | out.append('\\"') | |
| 340 | + | elif char == "\n": | |
| 341 | + | out.append("\\n") | |
| 342 | + | elif char == "\t": | |
| 343 | + | out.append("\\t") | |
| 344 | + | elif char == "\r": | |
| 345 | + | out.append("\\r") | |
| 346 | + | elif char == "\b": | |
| 347 | + | out.append("\\b") | |
| 348 | + | elif char == "\f": | |
| 349 | + | out.append("\\f") | |
| 350 | + | elif code < 0x20 or code == 0x7F: | |
| 351 | + | out.append("\\u%04X" % code) | |
| 352 | + | else: | |
| 353 | + | out.append(char) | |
| 354 | + | return "".join(out) | |
| 355 | + | ||
| 356 | + | ||
| 357 | + | def write_child_config(config_home, cef_dir, idle_timeout_ms=0): | |
| 358 | + | """Force JSON debug logging so milestone parsing works. | |
| 359 | + | ||
| 360 | + | Without this, isolated XDG homes fall back to text logs and | |
| 361 | + | parse_child_output finds zero milestones. Idempotent: relay owners | |
| 362 | + | share one config across samples. idle_timeout_ms selects the product | |
| 363 | + | residency knob (0 = product default, exit with last window).""" | |
| 364 | + | config_dir = os.path.join(config_home, "dumber") | |
| 365 | + | os.makedirs(config_dir, exist_ok=True) | |
| 366 | + | path = os.path.join(config_dir, "config.toml") | |
| 367 | + | content = ( | |
| 368 | + | '[logging]\nlevel = "debug"\nformat = "json"\n' | |
| 369 | + | 'enable_file_log = false\n\n[engine.cef]\ncef_dir = "%s"\n' | |
| 370 | + | 'idle_runtime_timeout_ms = %d\n' | |
| 371 | + | % (_escape_toml_basic(cef_dir), idle_timeout_ms) | |
| 372 | + | ) | |
| 373 | + | with open(path, "w") as handle: | |
| 374 | + | handle.write(content) | |
| 375 | + | return path | |
| 376 | + | ||
| 377 | + | ||
| 378 | + | def ensure_wayland_socket(runtime_dir, env): | |
| 379 | + | """Point a relative Wayland display at the real compositor socket. | |
| 380 | + | ||
| 381 | + | Isolating XDG_RUNTIME_DIR breaks relative WAYLAND_DISPLAY values | |
| 382 | + | (the compositor socket lives in the real runtime dir). Symlinking the | |
| 383 | + | socket into the isolated dir is not an option: isolated test paths | |
| 384 | + | easily exceed the 108-byte unix-socket limit and CEF aborts with | |
| 385 | + | "File name too long". Instead, when the display is a relative name | |
| 386 | + | whose socket exists in the real runtime dir, override WAYLAND_DISPLAY | |
| 387 | + | with its absolute path, which Wayland clients use as-is. The isolated | |
| 388 | + | runtime dir stays untouched. Returns True when rendering connectivity | |
| 389 | + | is preserved or Wayland is not in use.""" | |
| 390 | + | display = env.get("WAYLAND_DISPLAY", "") | |
| 391 | + | if not display or "/" in display: | |
| 392 | + | return True | |
| 393 | + | os.makedirs(runtime_dir, exist_ok=True) | |
| 394 | + | real_runtime = os.environ.get("XDG_RUNTIME_DIR", "/run/user/%d" % os.getuid()) | |
| 395 | + | source = os.path.join(real_runtime, display) | |
| 396 | + | if os.path.exists(source): | |
| 397 | + | env["WAYLAND_DISPLAY"] = source | |
| 398 | + | return True | |
| 399 | + | return False | |
| 400 | + | ||
| 401 | + | ||
| 402 | + | def count_cef_inits(lines): | |
| 403 | + | """Count CEF initialization completions in child output lines. | |
| 404 | + | ||
| 405 | + | Each process initializes CEF at most once: a resident owner serving | |
| 406 | + | N second windows must still show exactly one cef_initialized | |
| 407 | + | milestone. Only the milestone event counts; the InitWithApp log line | |
| 408 | + | describes the same init and is ignored.""" | |
| 409 | + | count = 0 | |
| 410 | + | for line in lines: | |
| 411 | + | try: | |
| 412 | + | event = json.loads(line) | |
| 413 | + | except (json.JSONDecodeError, ValueError): | |
| 414 | + | continue | |
| 415 | + | if ( | |
| 416 | + | isinstance(event, dict) | |
| 417 | + | and event.get("message") == "startup_trace: milestone" | |
| 418 | + | and event.get("milestone") == "cef_initialized" | |
| 419 | + | ): | |
| 420 | + | count += 1 | |
| 421 | + | return count | |
| 422 | + | ||
| 423 | + | ||
| 424 | + | def wait_for_owner_log_line(log_path, needle, timeout_seconds=30.0): | |
| 425 | + | """Wait until the owner log contains needle. Bounded; False on timeout.""" | |
| 426 | + | end = time.monotonic() + timeout_seconds | |
| 427 | + | while time.monotonic() < end: | |
| 428 | + | try: | |
| 429 | + | with open(log_path, errors="replace") as handle: | |
| 430 | + | for line in handle: | |
| 431 | + | if needle in line: | |
| 432 | + | return True | |
| 433 | + | except OSError: | |
| 434 | + | pass | |
| 435 | + | time.sleep(0.2) | |
| 436 | + | return False | |
| 437 | + | ||
| 438 | + | ||
| 439 | + | def scenario_env(cef_dir, dirs, extra=None, idle_timeout_ms=0): | |
| 246 | 440 | env = { | |
| 247 | 441 | "HOME": os.environ.get("HOME", ""), | |
| 248 | 442 | "PATH": os.environ.get("PATH", ""), | |
| @@ -260,16 +454,27 @@ def scenario_env(cef_dir, dirs, extra=None): | |||
| 260 | 454 | } | |
| 261 | 455 | if extra: | |
| 262 | 456 | env.update(extra) | |
| 457 | + | for name in DISPLAY_PASSTHROUGH_VARS: | |
| 458 | + | value = os.environ.get(name) | |
| 459 | + | if value: | |
| 460 | + | env[name] = value | |
| 263 | 461 | for key in ("config", "data", "state", "cache", "runtime"): | |
| 264 | 462 | os.makedirs(dirs[key], exist_ok=True) | |
| 265 | 463 | os.makedirs(dirs["root_cache"], exist_ok=True) | |
| 464 | + | write_child_config(dirs["config"], cef_dir, idle_timeout_ms) | |
| 465 | + | ensure_wayland_socket(dirs["runtime"], env) | |
| 266 | 466 | return env | |
| 267 | 467 | ||
| 268 | 468 | ||
| 269 | - | def wait_for_relay_socket(runtime_dir, timeout_seconds=30.0): | |
| 469 | + | def wait_for_relay_socket(search_root, timeout_seconds=30.0): | |
| 470 | + | # The relay socket lives under XDG_STATE_HOME | |
| 471 | + | # (<state>/[dumber/]runtime/<engine>/browser-launch.sock), not the | |
| 472 | + | # XDG_RUNTIME dir: walk the state tree. Keep scenario outputs shallow: | |
| 473 | + | # unix-socket paths are limited to 108 bytes and deep evidence dirs | |
| 474 | + | # make the relay unreachable. | |
| 270 | 475 | end = time.monotonic() + timeout_seconds | |
| 271 | 476 | while time.monotonic() < end: | |
| 272 | - | for root, _, files in os.walk(runtime_dir): | |
| 477 | + | for root, _, files in os.walk(search_root): | |
| 273 | 478 | if "browser-launch.sock" in files: | |
| 274 | 479 | path = os.path.join(root, "browser-launch.sock") | |
| 275 | 480 | sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) | |
| @@ -285,7 +490,8 @@ def wait_for_relay_socket(runtime_dir, timeout_seconds=30.0): | |||
| 285 | 490 | return None | |
| 286 | 491 | ||
| 287 | 492 | ||
| 288 | - | def start_relay_owner(binary, cef_dir, scenario_dir, diagnostic_close=False): | |
| 493 | + | def start_relay_owner(binary, cef_dir, scenario_dir, diagnostic_close=False, | |
| 494 | + | idle_timeout_ms=0): | |
| 289 | 495 | dirs = { | |
| 290 | 496 | "config": os.path.join(scenario_dir, "owner-config"), | |
| 291 | 497 | "data": os.path.join(scenario_dir, "owner-data"), | |
| @@ -293,27 +499,42 @@ def start_relay_owner(binary, cef_dir, scenario_dir, diagnostic_close=False): | |||
| 293 | 499 | "cache": os.path.join(scenario_dir, "owner-cache"), | |
| 294 | 500 | "runtime": os.path.join(scenario_dir, "owner-runtime"), | |
| 295 | 501 | "root_cache": os.path.join(scenario_dir, "shared-profile"), | |
| 502 | + | "owner_log": os.path.join(scenario_dir, "owner.log"), | |
| 296 | 503 | } | |
| 297 | - | env = scenario_env(cef_dir, dirs) | |
| 504 | + | # scenario_env only reads the six XDG/root-cache keys; owner_log | |
| 505 | + | # rides along for CEF-init counting without affecting the child env. | |
| 506 | + | env = scenario_env(cef_dir, dirs, idle_timeout_ms=idle_timeout_ms) | |
| 298 | 507 | if diagnostic_close: | |
| 299 | 508 | # Owned window-close mechanism for the reopen scenario only: the | |
| 300 | 509 | # relay honors it solely in processes carrying this variable. It is | |
| 301 | 510 | # never a general unauthenticated shutdown command. | |
| 302 | 511 | env = dict(env) | |
| 303 | 512 | env["DUMBER_DIAGNOSTIC_WINDOW_CLOSE"] = "1" | |
| 513 | + | log_file = open(dirs["owner_log"], "w") | |
| 304 | 514 | try: | |
| 305 | 515 | proc = subprocess.Popen( | |
| 306 | 516 | [binary, "browse", "about:blank"], | |
| 307 | - | stdout=subprocess.DEVNULL, | |
| 308 | - | stderr=subprocess.DEVNULL, | |
| 517 | + | stdout=log_file, | |
| 518 | + | stderr=subprocess.STDOUT, | |
| 519 | + | text=True, | |
| 520 | + | bufsize=1, | |
| 309 | 521 | env=env, | |
| 310 | 522 | ) | |
| 311 | 523 | except OSError: | |
| 524 | + | log_file.close() | |
| 312 | 525 | return None, None, None | |
| 313 | - | time.sleep(0.5) | |
| 314 | 526 | if proc.poll() is not None: | |
| 527 | + | log_file.close() | |
| 528 | + | return None, None, None | |
| 529 | + | # Readiness is the owner's first presentation, not a fixed sleep: | |
| 530 | + | # only then is the relay guaranteed to serve second windows. | |
| 531 | + | ready = wait_for_owner_log_line( | |
| 532 | + | dirs["owner_log"], "startup_trace: first presentation") | |
| 533 | + | log_file.close() | |
| 534 | + | if not ready or proc.poll() is not None: | |
| 535 | + | stop_proc(proc) | |
| 315 | 536 | return None, None, None | |
| 316 | - | socket_path = wait_for_relay_socket(dirs["runtime"]) | |
| 537 | + | socket_path = wait_for_relay_socket(dirs["state"]) | |
| 317 | 538 | if socket_path is None: | |
| 318 | 539 | proc.terminate() | |
| 319 | 540 | try: | |
| @@ -398,7 +619,11 @@ def wait_for_child_quiescence(owner_pid, settle_seconds=2.0, timeout_seconds=15. | |||
| 398 | 619 | """Wait until the owner's child count is stable across settle_seconds. | |
| 399 | 620 | Window close is asynchronous: the relay acknowledgement only means the | |
| 400 | 621 | request was accepted, so reopening must wait for an observable steady | |
| 401 | - | state instead of a fixed sleep. Returns the stable child count.""" | |
| 622 | + | state instead of a fixed sleep. Returns (stable_count, settled): | |
| 623 | + | settled is False on timeout, and a timeout must fail the reopen, not | |
| 624 | + | silently pass. Child counts stay diagnostics only: CEF process | |
| 625 | + | topology does not map one-to-one to windows, so stability alone never | |
| 626 | + | proves zero windows or resident-idle entry.""" | |
| 402 | 627 | end = time.monotonic() + timeout_seconds | |
| 403 | 628 | last_change = time.monotonic() | |
| 404 | 629 | last_count = len(child_pids(owner_pid)) | |
| @@ -409,8 +634,8 @@ def wait_for_child_quiescence(owner_pid, settle_seconds=2.0, timeout_seconds=15. | |||
| 409 | 634 | last_count = count | |
| 410 | 635 | last_change = time.monotonic() | |
| 411 | 636 | elif time.monotonic() - last_change >= settle_seconds: | |
| 412 | - | return count | |
| 413 | - | return len(child_pids(owner_pid)) | |
| 637 | + | return count, True | |
| 638 | + | return len(child_pids(owner_pid)), False | |
| 414 | 639 | ||
| 415 | 640 | ||
| 416 | 641 | def proc_rss_kb(pid): | |
| @@ -426,16 +651,13 @@ def proc_rss_kb(pid): | |||
| 426 | 651 | ||
| 427 | 652 | ||
| 428 | 653 | def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_dirs=None, | |
| 429 | - | shared_root_cache=None, owner_socket=None): | |
| 654 | + | shared_root_cache=None, owner_socket=None, idle_timeout_ms=0): | |
| 430 | 655 | run_token = secrets.token_hex(8) | |
| 431 | 656 | nav_token = secrets.token_hex(8) | |
| 432 | 657 | cutoff = post_nav_cutoff_seconds() | |
| 433 | 658 | state = FixtureState() | |
| 434 | - | Handler.state = state | |
| 435 | - | Handler.fixture = fixture | |
| 436 | - | Handler.run_token = run_token | |
| 437 | - | Handler.nav_token = nav_token | |
| 438 | - | server = ThreadingHTTPServer(("127.0.0.1", 0), Handler) | |
| 659 | + | server = ThreadingHTTPServer(("127.0.0.1", 0), | |
| 660 | + | make_sample_handler(state, fixture, run_token, nav_token)) | |
| 439 | 661 | port = server.server_address[1] | |
| 440 | 662 | thread = threading.Thread(target=server.serve_forever, kwargs={"poll_interval": 0.05}) | |
| 441 | 663 | thread.daemon = True | |
| @@ -459,7 +681,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 459 | 681 | "root_cache": shared_root_cache or os.path.join(run_dir, "cef-root-cache"), | |
| 460 | 682 | } | |
| 461 | 683 | extra = {} | |
| 462 | - | env = scenario_env(cef_dir, dirs, extra) | |
| 684 | + | env = scenario_env(cef_dir, dirs, extra, idle_timeout_ms) | |
| 463 | 685 | owner_alive_at_start = owner is not None and owner.poll() is None | |
| 464 | 686 | reopen = None | |
| 465 | 687 | if scenario == "reopen-window" and owner is not None and owner_socket: | |
| @@ -470,11 +692,13 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 470 | 692 | acknowledged = send_diagnostic_close(owner_socket) | |
| 471 | 693 | # The acknowledgement only means accepted: wait for an | |
| 472 | 694 | # observable steady state before measuring the reopen. | |
| 473 | - | quiescent_children = wait_for_child_quiescence(owner_pid) | |
| 695 | + | # An unsettled timeout fails the reopen via quiescence_settled. | |
| 696 | + | quiescent_children, settled = wait_for_child_quiescence(owner_pid) | |
| 474 | 697 | reopen = { | |
| 475 | 698 | "owner_pid": owner_pid, | |
| 476 | 699 | "owner_starttime": owner_start, | |
| 477 | 700 | "close_acknowledged": acknowledged, | |
| 701 | + | "quiescence_settled": settled, | |
| 478 | 702 | "browser_child_count_before": len(children_before), | |
| 479 | 703 | "browser_child_count_quiescent": quiescent_children, | |
| 480 | 704 | "owner_rss_kb_before": rss_before, | |
| @@ -500,6 +724,13 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 500 | 724 | pump_thread = threading.Thread(target=pump) | |
| 501 | 725 | pump_thread.daemon = True | |
| 502 | 726 | pump_thread.start() | |
| 727 | + | nav_deadline = navigation_deadline_seconds() | |
| 728 | + | # A live owner serves the navigation after the launcher exits: | |
| 729 | + | # in that case launcher exit must not end collection before the | |
| 730 | + | # correlated document arrives. Without a live owner the sample | |
| 731 | + | # is its own browser and exit ends it. | |
| 732 | + | defers_to_owner = bool(owner_alive_at_start and owner_dirs is not None | |
| 733 | + | and scenario in ("relay-window", "reopen-window")) | |
| 503 | 734 | hard_end = spawn_ts + cutoff + 25.0 | |
| 504 | 735 | while True: | |
| 505 | 736 | now = time.monotonic() | |
| @@ -514,7 +745,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 514 | 745 | break | |
| 515 | 746 | if now >= navigated_at + cutoff + 5.0: | |
| 516 | 747 | break | |
| 517 | - | elif now >= spawn_ts + cutoff + 5.0 or exited: | |
| 748 | + | elif now >= spawn_ts + nav_deadline or (exited and not defers_to_owner): | |
| 518 | 749 | break | |
| 519 | 750 | if now >= hard_end: | |
| 520 | 751 | break | |
| @@ -527,6 +758,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 527 | 758 | except subprocess.TimeoutExpired: | |
| 528 | 759 | proc.kill() | |
| 529 | 760 | proc.wait(timeout=5) | |
| 761 | + | launcher_returncode = proc.returncode | |
| 530 | 762 | pump_thread.join(timeout=5) | |
| 531 | 763 | try: | |
| 532 | 764 | proc.stdout.close() | |
| @@ -538,6 +770,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 538 | 770 | beacons = list(state.beacons) | |
| 539 | 771 | document_count = len(state.document_requests) | |
| 540 | 772 | subresource_count = len(state.subresource_requests) | |
| 773 | + | first_document_at = state.first_document_monotonic | |
| 541 | 774 | fcp = [b for b in beacons if b["event"] == "first-contentful-paint"] | |
| 542 | 775 | lcp = [b for b in beacons if b["event"] == "largest-contentful-paint"] | |
| 543 | 776 | if fcp: | |
| @@ -564,10 +797,26 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 564 | 797 | "target_fcp_ms": fcp[0]["value_ms"] if fcp else None, | |
| 565 | 798 | "target_lcp_through_cutoff_ms": lcp[-1]["value_ms"] if lcp else None, | |
| 566 | 799 | "startup_milestones": len(milestones), | |
| 800 | + | "launcher_returncode": launcher_returncode, | |
| 801 | + | "launcher_cef_init_count": count_cef_inits([line for _, line in arrivals]), | |
| 802 | + | "first_document_observation_ms": ( | |
| 803 | + | int((first_document_at - spawn_ts) * 1000) | |
| 804 | + | if first_document_at is not None and first_document_at >= spawn_ts | |
| 805 | + | else None | |
| 806 | + | ), | |
| 567 | 807 | "complete": complete, | |
| 568 | 808 | "relayed": relayed, | |
| 569 | 809 | "fallback_spawn": scenario in ("relay-window", "reopen-window") and not relayed, | |
| 570 | 810 | } | |
| 811 | + | if scenario in ("relay-window", "reopen-window") and owner_dirs is not None: | |
| 812 | + | # Residency proof: the owner must initialize CEF exactly once | |
| 813 | + | # no matter how many second windows it serves. A second init | |
| 814 | + | # here means the sample paid a full cold start, not a reopen. | |
| 815 | + | try: | |
| 816 | + | with open(owner_dirs.get("owner_log", ""), errors="replace") as owner_log: | |
| 817 | + | result["owner_cef_init_count"] = count_cef_inits(owner_log) | |
| 818 | + | except OSError: | |
| 819 | + | result["owner_cef_init_count"] = None | |
| 571 | 820 | if reopen is not None: | |
| 572 | 821 | # Owner identity is verified independently of the Popen handle: | |
| 573 | 822 | # the same pid with a different start time is a recycled pid, | |
| @@ -584,6 +833,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||
| 584 | 833 | reopen["browser_child_count_after"] = len(child_pids(owner.pid)) if owner_alive else 0 | |
| 585 | 834 | reopen["owner_rss_kb_after"] = proc_rss_kb(owner.pid) if owner_alive else None | |
| 586 | 835 | result["reopen"] = reopen | |
| 836 | + | result["residency_valid"] = is_residency_valid(result, scenario) | |
| 587 | 837 | return result | |
| 588 | 838 | finally: | |
| 589 | 839 | server.shutdown() | |
| @@ -608,8 +858,15 @@ def main(): | |||
| 608 | 858 | ) | |
| 609 | 859 | parser.add_argument("--runs", type=int, default=30) | |
| 610 | 860 | parser.add_argument("--output", required=True) | |
| 861 | + | parser.add_argument("--idle-timeout-ms", type=int, default=0, | |
| 862 | + | help="resident CEF idle timeout for generated configs " | |
| 863 | + | "(0..300000, 0 is the product default)") | |
| 611 | 864 | args = parser.parse_args() | |
| 612 | 865 | ||
| 866 | + | if args.idle_timeout_ms < 0 or args.idle_timeout_ms > 300000: | |
| 867 | + | print("measure: --idle-timeout-ms must be 0..300000", file=sys.stderr) | |
| 868 | + | raise SystemExit(2) | |
| 869 | + | ||
| 613 | 870 | if args.runs < 1 or args.runs > 100: | |
| 614 | 871 | print("measure: --runs must be 1..100", file=sys.stderr) | |
| 615 | 872 | raise SystemExit(2) | |
| @@ -635,6 +892,10 @@ def main(): | |||
| 635 | 892 | binary_sha256 = digest.hexdigest() | |
| 636 | 893 | ||
| 637 | 894 | os.makedirs(args.output) | |
| 895 | + | # Privacy: only summary.json and run-*.json are safe to share (timings, | |
| 896 | + | # counts, hashes). owner.log and generated configs are machine-local: | |
| 897 | + | # raw child logs and the selected --cef-dir path may contain local | |
| 898 | + | # usernames or paths. Never publish the whole directory. | |
| 638 | 899 | owner = None | |
| 639 | 900 | owner_dirs = None | |
| 640 | 901 | owner_socket = None | |
| @@ -646,12 +907,15 @@ def main(): | |||
| 646 | 907 | if args.scenario == "relay-window": | |
| 647 | 908 | scenario_dir = os.path.join(args.output, "relay-scenario") | |
| 648 | 909 | os.makedirs(scenario_dir) | |
| 649 | - | owner, owner_dirs, owner_socket = start_relay_owner(args.binary, args.cef_dir, scenario_dir) | |
| 910 | + | owner, owner_dirs, owner_socket = start_relay_owner( | |
| 911 | + | args.binary, args.cef_dir, scenario_dir, | |
| 912 | + | idle_timeout_ms=args.idle_timeout_ms) | |
| 650 | 913 | if args.scenario == "reopen-window": | |
| 651 | 914 | scenario_dir = os.path.join(args.output, "reopen-scenario") | |
| 652 | 915 | os.makedirs(scenario_dir) | |
| 653 | 916 | owner, owner_dirs, owner_socket = start_relay_owner( | |
| 654 | - | args.binary, args.cef_dir, scenario_dir, diagnostic_close=True) | |
| 917 | + | args.binary, args.cef_dir, scenario_dir, diagnostic_close=True, | |
| 918 | + | idle_timeout_ms=args.idle_timeout_ms) | |
| 655 | 919 | ||
| 656 | 920 | results = [] | |
| 657 | 921 | try: | |
| @@ -661,7 +925,8 @@ def main(): | |||
| 661 | 925 | # warm-up aborts the scenario: later runs must never use an | |
| 662 | 926 | # uninitialized profile. | |
| 663 | 927 | warmup = run_sample(args.binary, args.cef_dir, args.scenario, args.fixture, | |
| 664 | - | 0, shared_root_cache=shared_root_cache) | |
| 928 | + | 0, shared_root_cache=shared_root_cache, | |
| 929 | + | idle_timeout_ms=args.idle_timeout_ms) | |
| 665 | 930 | if not warmup["complete"]: | |
| 666 | 931 | print("measure: process-warm warm-up was incomplete", file=sys.stderr) | |
| 667 | 932 | raise SystemExit(1) | |
| @@ -670,7 +935,7 @@ def main(): | |||
| 670 | 935 | result = run_sample( | |
| 671 | 936 | args.binary, args.cef_dir, args.scenario, args.fixture, index, | |
| 672 | 937 | owner=owner, owner_dirs=owner_dirs, shared_root_cache=shared_root_cache, | |
| 673 | - | owner_socket=owner_socket, | |
| 938 | + | owner_socket=owner_socket, idle_timeout_ms=args.idle_timeout_ms, | |
| 674 | 939 | ) | |
| 675 | 940 | results.append(result) | |
| 676 | 941 | with open(os.path.join(args.output, "run-%02d.json" % index), "w") as handle: | |
| @@ -692,7 +957,34 @@ def main(): | |||
| 692 | 957 | ), | |
| 693 | 958 | "warmup_discarded": warmup_discarded, | |
| 694 | 959 | "relay_owner_ready": owner is not None, | |
| 960 | + | "idle_timeout_ms": args.idle_timeout_ms, | |
| 695 | 961 | } | |
| 962 | + | if args.scenario in ("relay-window", "reopen-window") and owner_dirs is not None: | |
| 963 | + | # Second-window contract, kept separate from cold-process numbers: | |
| 964 | + | # one owner CEF init total, plus the request-to-FCP distribution | |
| 965 | + | # of resident reopens. Missing FCP stays missing, never averaged in. | |
| 966 | + | try: | |
| 967 | + | with open(owner_dirs.get("owner_log", ""), errors="replace") as owner_log: | |
| 968 | + | summary["owner_cef_init_count"] = count_cef_inits(owner_log) | |
| 969 | + | except OSError: | |
| 970 | + | summary["owner_cef_init_count"] = None | |
| 971 | + | fcp_observations = sorted( | |
| 972 | + | r["first_document_observation_ms"] | |
| 973 | + | for r in results | |
| 974 | + | if r.get("residency_valid") and r["first_document_observation_ms"] is not None | |
| 975 | + | ) | |
| 976 | + | summary["resident_valid_runs"] = sum(1 for r in results if r.get("residency_valid")) | |
| 977 | + | summary["resident_invalid_runs"] = sum(1 for r in results if r.get("residency_valid") is False) | |
| 978 | + | summary["second_window_complete_runs"] = len(fcp_observations) | |
| 979 | + | if fcp_observations: | |
| 980 | + | # Spawn to first document request, same harness clock. This is | |
| 981 | + | # request arrival, not document completion or paint; for the | |
| 982 | + | # redirect fixture it measures the initial redirect request. | |
| 983 | + | summary["second_window_spawn_to_first_document_observation_ms"] = { | |
| 984 | + | "min": fcp_observations[0], | |
| 985 | + | "median": fcp_observations[len(fcp_observations) // 2], | |
| 986 | + | "max": fcp_observations[-1], | |
| 987 | + | } | |
| 696 | 988 | with open(os.path.join(args.output, "summary.json"), "w") as handle: | |
| 697 | 989 | json.dump(summary, handle, indent=2, sort_keys=True) | |
| 698 | 990 | print("measure artifacts: %s" % args.output) | |
| @@ -13,6 +13,18 @@ Scenarios: | |||||
| 13 | through the relay; verifies the same owner process serves | 13 | through the relay; verifies the same owner process serves | ||
| 14 | the reopen without a second CEF initialization | 14 | the reopen without a second CEF initialization | ||
| 15 | 15 | ||||
| 16 | + | Second-window contract (relay-window, reopen-window): the owner captures | |||
| 17 | + | its own log, readiness is its first presentation (never a fixed sleep), | |||
| 18 | + | and every sample records owner_cef_init_count, which must stay at 1. | |||
| 19 | + | Cold-process numbers (process-warm, profile-fresh) and resident-reopen | |||
| 20 | + | observations are reported separately and never averaged together. | |||
| 21 | + | --idle-timeout-ms forwards the product residency knob into generated | |||
| 22 | + | configs (default 0 = exit with last window; reopen-window only reuses | |||
| 23 | + | the same process with a nonzero timeout). Second-window latency is | |||
| 24 | + | first_document_observation_ms (spawn to first fixture document request | |||
| 25 | + | on the harness clock); paint-level timing stays open until page | |||
| 26 | + | beacons are delivered. | |||
| 27 | + | ||||
| 16 | Fixtures (loopback only): static, delayed, redirect, cache. | 28 | Fixtures (loopback only): static, delayed, redirect, cache. | ||
| 17 | 29 | ||||
| 18 | Protocol: fixture pages report PerformanceObserver results through a | 30 | Protocol: fixture pages report PerformanceObserver results through a | ||
| @@ -67,6 +79,46 @@ def post_nav_cutoff_seconds(): | |||||
| 67 | return min(30.0, max(0.1, value)) | 79 | return min(30.0, max(0.1, value)) | ||
| 68 | 80 | ||||
| 69 | 81 | ||||
| 82 | + | def navigation_deadline_seconds(): | |||
| 83 | + | # Bounded wait for the correlated document after spawn when no | |||
| 84 | + | # document has arrived yet. Overridable for fast unit tests. | |||
| 85 | + | try: | |||
| 86 | + | value = float(os.environ.get("DUMBER_MEASURE_NAV_DEADLINE_SECONDS", "")) | |||
| 87 | + | if value > 0: | |||
| 88 | + | return min(60.0, value) | |||
| 89 | + | except ValueError: | |||
| 90 | + | pass | |||
| 91 | + | return post_nav_cutoff_seconds() + 5.0 | |||
| 92 | + | ||||
| 93 | + | ||||
| 94 | + | def is_residency_valid(result, scenario): | |||
| 95 | + | # Fixture completeness (document count, beacons) is not residency | |||
| 96 | + | # validity. A resident sample is valid only when the launcher handed | |||
| 97 | + | # off cleanly to a live, unchanged owner that initialized CEF exactly | |||
| 98 | + | # once, the launcher itself never initialized CEF (a fallback cold | |||
| 99 | + | # start would hide in the dead owner's log), and a reopen additionally | |||
| 100 | + | # completed its close. Returns True/False, or None outside resident | |||
| 101 | + | # scenarios. | |||
| 102 | + | if scenario not in ("relay-window", "reopen-window"): | |||
| 103 | + | return None | |||
| 104 | + | if result.get("fallback_spawn") or not result.get("relayed"): | |||
| 105 | + | return False | |||
| 106 | + | if result.get("launcher_returncode") != 0: | |||
| 107 | + | return False | |||
| 108 | + | if result.get("owner_cef_init_count") != 1: | |||
| 109 | + | return False | |||
| 110 | + | if result.get("launcher_cef_init_count", 0) != 0: | |||
| 111 | + | return False | |||
| 112 | + | if scenario == "reopen-window": | |||
| 113 | + | reopen = result.get("reopen") or {} | |||
| 114 | + | if not (reopen.get("close_acknowledged") | |||
| 115 | + | and reopen.get("quiescence_settled", False) | |||
| 116 | + | and reopen.get("same_process") | |||
| 117 | + | and reopen.get("owner_alive_after")): | |||
| 118 | + | return False | |||
| 119 | + | return True | |||
| 120 | + | ||||
| 121 | + | ||||
| 70 | class FixtureState: | 122 | class FixtureState: | ||
| 71 | def __init__(self): | 123 | def __init__(self): | ||
| 72 | self.lock = threading.Lock() | 124 | self.lock = threading.Lock() | ||
| @@ -147,14 +199,37 @@ class Handler(BaseHTTPRequestHandler): | |||||
| 147 | else: | 199 | else: | ||
| 148 | self.state.subresource_requests.append(entry) | 200 | self.state.subresource_requests.append(entry) | ||
| 149 | 201 | ||||
| 202 | + | def _document_tokens_valid(self, parsed): | |||
| 203 | + | # Document routes carry the sample tokens by construction; an | |||
| 204 | + | # uncorrelated request (stale tab, foreign client, port reuse) | |||
| 205 | + | # must neither establish the first-document timestamp nor be | |||
| 206 | + | # served the current sample's tokens. | |||
| 207 | + | query = parse_qs(parsed.query) | |||
| 208 | + | run = query.get("run", [None])[0] | |||
| 209 | + | nav = query.get("nav", [None])[0] | |||
| 210 | + | return ( | |||
| 211 | + | isinstance(run, str) and TOKEN_RE.fullmatch(run) and run == self.run_token | |||
| 212 | + | and isinstance(nav, str) and NAV_RE.fullmatch(nav) and nav == self.nav_token | |||
| 213 | + | ) | |||
| 214 | + | ||||
| 150 | def do_GET(self): | 215 | def do_GET(self): | ||
| 151 | parsed = urlparse(self.path) | 216 | parsed = urlparse(self.path) | ||
| 152 | path = parsed.path | 217 | path = parsed.path | ||
| 153 | if path == "/__beacon": | 218 | if path == "/__beacon": | ||
| 154 | self._handle_beacon(parsed) | 219 | self._handle_beacon(parsed) | ||
| 155 | return | 220 | return | ||
| 156 | - | if path in ("/", "/index.html", "/target"): | 221 | + | if path in ("/", "/index.html", "/target", "/redirect"): |
| 222 | + | if not self._document_tokens_valid(parsed): | |||
| 223 | + | self.send_response(404) | |||
| 224 | + | self.end_headers() | |||
| 225 | + | return | |||
| 157 | self._record(True) | 226 | self._record(True) | ||
| 227 | + | if path == "/redirect": | |||
| 228 | + | target = "/target?run=%s&nav=%s" % (self.run_token, self.nav_token) | |||
| 229 | + | self.send_response(302) | |||
| 230 | + | self.send_header("Location", target) | |||
| 231 | + | self.end_headers() | |||
| 232 | + | return | |||
| 158 | if self.fixture == "delayed" and path == "/": | 233 | if self.fixture == "delayed" and path == "/": | ||
| 159 | time.sleep(self.delay_seconds) | 234 | time.sleep(self.delay_seconds) | ||
| 160 | body = build_fixture_html( | 235 | body = build_fixture_html( | ||
| @@ -168,13 +243,6 @@ class Handler(BaseHTTPRequestHandler): | |||||
| 168 | self.end_headers() | 243 | self.end_headers() | ||
| 169 | self.wfile.write(body) | 244 | self.wfile.write(body) | ||
| 170 | return | 245 | return | ||
| 171 | - | if path == "/redirect": | |||
| 172 | - | self._record(True) | |||
| 173 | - | target = "/target?run=%s&nav=%s" % (self.run_token, self.nav_token) | |||
| 174 | - | self.send_response(302) | |||
| 175 | - | self.send_header("Location", target) | |||
| 176 | - | self.end_headers() | |||
| 177 | - | return | |||
| 178 | if path in ("/app.css", "/pixel.png", "/cacheable.js", "/cacheable.png"): | 246 | if path in ("/app.css", "/pixel.png", "/cacheable.js", "/cacheable.png"): | ||
| 179 | self._record(False) | 247 | self._record(False) | ||
| 180 | if path.endswith(".png"): | 248 | if path.endswith(".png"): | ||
| @@ -230,6 +298,18 @@ class Handler(BaseHTTPRequestHandler): | |||||
| 230 | self.end_headers() | 298 | self.end_headers() | ||
| 231 | 299 | ||||
| 232 | 300 | ||||
| 301 | + | def make_sample_handler(state, fixture, run_token, nav_token): | |||
| 302 | + | # Per-sample handler state: the base Handler only carries defaults. | |||
| 303 | + | # Binding state on a fresh subclass per sample keeps surviving request | |||
| 304 | + | # threads of a previous sample from adopting a later sample's tokens. | |||
| 305 | + | return type("SampleHandler", (Handler,), { | |||
| 306 | + | "state": state, | |||
| 307 | + | "fixture": fixture, | |||
| 308 | + | "run_token": run_token, | |||
| 309 | + | "nav_token": nav_token, | |||
| 310 | + | }) | |||
| 311 | + | ||||
| 312 | + | ||||
| 233 | def parse_child_output(lines): | 313 | def parse_child_output(lines): | ||
| 234 | milestones = [] | 314 | milestones = [] | ||
| 235 | for line in lines: | 315 | for line in lines: | ||
| @@ -242,7 +322,121 @@ def parse_child_output(lines): | |||||
| 242 | return milestones | 322 | return milestones | ||
| 243 | 323 | ||||
| 244 | 324 | ||||
| 245 | - | def scenario_env(cef_dir, dirs, extra=None): | 325 | + | DISPLAY_PASSTHROUGH_VARS = ("DBUS_SESSION_BUS_ADDRESS", "XAUTHORITY") |
| 326 | + | ||||
| 327 | + | ||||
| 328 | + | def _escape_toml_basic(value): | |||
| 329 | + | # Full TOML basic-string escaping: backslash, quote, and every | |||
| 330 | + | # control character (raw newlines/tabs/other C0 controls are invalid | |||
| 331 | + | # in basic strings). Paths with such characters stay representable | |||
| 332 | + | # instead of producing broken configuration. | |||
| 333 | + | out = [] | |||
| 334 | + | for char in value: | |||
| 335 | + | code = ord(char) | |||
| 336 | + | if char == "\\": | |||
| 337 | + | out.append("\\\\") | |||
| 338 | + | elif char == '"': | |||
| 339 | + | out.append('\\"') | |||
| 340 | + | elif char == "\n": | |||
| 341 | + | out.append("\\n") | |||
| 342 | + | elif char == "\t": | |||
| 343 | + | out.append("\\t") | |||
| 344 | + | elif char == "\r": | |||
| 345 | + | out.append("\\r") | |||
| 346 | + | elif char == "\b": | |||
| 347 | + | out.append("\\b") | |||
| 348 | + | elif char == "\f": | |||
| 349 | + | out.append("\\f") | |||
| 350 | + | elif code < 0x20 or code == 0x7F: | |||
| 351 | + | out.append("\\u%04X" % code) | |||
| 352 | + | else: | |||
| 353 | + | out.append(char) | |||
| 354 | + | return "".join(out) | |||
| 355 | + | ||||
| 356 | + | ||||
| 357 | + | def write_child_config(config_home, cef_dir, idle_timeout_ms=0): | |||
| 358 | + | """Force JSON debug logging so milestone parsing works. | |||
| 359 | + | ||||
| 360 | + | Without this, isolated XDG homes fall back to text logs and | |||
| 361 | + | parse_child_output finds zero milestones. Idempotent: relay owners | |||
| 362 | + | share one config across samples. idle_timeout_ms selects the product | |||
| 363 | + | residency knob (0 = product default, exit with last window).""" | |||
| 364 | + | config_dir = os.path.join(config_home, "dumber") | |||
| 365 | + | os.makedirs(config_dir, exist_ok=True) | |||
| 366 | + | path = os.path.join(config_dir, "config.toml") | |||
| 367 | + | content = ( | |||
| 368 | + | '[logging]\nlevel = "debug"\nformat = "json"\n' | |||
| 369 | + | 'enable_file_log = false\n\n[engine.cef]\ncef_dir = "%s"\n' | |||
| 370 | + | 'idle_runtime_timeout_ms = %d\n' | |||
| 371 | + | % (_escape_toml_basic(cef_dir), idle_timeout_ms) | |||
| 372 | + | ) | |||
| 373 | + | with open(path, "w") as handle: | |||
| 374 | + | handle.write(content) | |||
| 375 | + | return path | |||
| 376 | + | ||||
| 377 | + | ||||
| 378 | + | def ensure_wayland_socket(runtime_dir, env): | |||
| 379 | + | """Point a relative Wayland display at the real compositor socket. | |||
| 380 | + | ||||
| 381 | + | Isolating XDG_RUNTIME_DIR breaks relative WAYLAND_DISPLAY values | |||
| 382 | + | (the compositor socket lives in the real runtime dir). Symlinking the | |||
| 383 | + | socket into the isolated dir is not an option: isolated test paths | |||
| 384 | + | easily exceed the 108-byte unix-socket limit and CEF aborts with | |||
| 385 | + | "File name too long". Instead, when the display is a relative name | |||
| 386 | + | whose socket exists in the real runtime dir, override WAYLAND_DISPLAY | |||
| 387 | + | with its absolute path, which Wayland clients use as-is. The isolated | |||
| 388 | + | runtime dir stays untouched. Returns True when rendering connectivity | |||
| 389 | + | is preserved or Wayland is not in use.""" | |||
| 390 | + | display = env.get("WAYLAND_DISPLAY", "") | |||
| 391 | + | if not display or "/" in display: | |||
| 392 | + | return True | |||
| 393 | + | os.makedirs(runtime_dir, exist_ok=True) | |||
| 394 | + | real_runtime = os.environ.get("XDG_RUNTIME_DIR", "/run/user/%d" % os.getuid()) | |||
| 395 | + | source = os.path.join(real_runtime, display) | |||
| 396 | + | if os.path.exists(source): | |||
| 397 | + | env["WAYLAND_DISPLAY"] = source | |||
| 398 | + | return True | |||
| 399 | + | return False | |||
| 400 | + | ||||
| 401 | + | ||||
| 402 | + | def count_cef_inits(lines): | |||
| 403 | + | """Count CEF initialization completions in child output lines. | |||
| 404 | + | ||||
| 405 | + | Each process initializes CEF at most once: a resident owner serving | |||
| 406 | + | N second windows must still show exactly one cef_initialized | |||
| 407 | + | milestone. Only the milestone event counts; the InitWithApp log line | |||
| 408 | + | describes the same init and is ignored.""" | |||
| 409 | + | count = 0 | |||
| 410 | + | for line in lines: | |||
| 411 | + | try: | |||
| 412 | + | event = json.loads(line) | |||
| 413 | + | except (json.JSONDecodeError, ValueError): | |||
| 414 | + | continue | |||
| 415 | + | if ( | |||
| 416 | + | isinstance(event, dict) | |||
| 417 | + | and event.get("message") == "startup_trace: milestone" | |||
| 418 | + | and event.get("milestone") == "cef_initialized" | |||
| 419 | + | ): | |||
| 420 | + | count += 1 | |||
| 421 | + | return count | |||
| 422 | + | ||||
| 423 | + | ||||
| 424 | + | def wait_for_owner_log_line(log_path, needle, timeout_seconds=30.0): | |||
| 425 | + | """Wait until the owner log contains needle. Bounded; False on timeout.""" | |||
| 426 | + | end = time.monotonic() + timeout_seconds | |||
| 427 | + | while time.monotonic() < end: | |||
| 428 | + | try: | |||
| 429 | + | with open(log_path, errors="replace") as handle: | |||
| 430 | + | for line in handle: | |||
| 431 | + | if needle in line: | |||
| 432 | + | return True | |||
| 433 | + | except OSError: | |||
| 434 | + | pass | |||
| 435 | + | time.sleep(0.2) | |||
| 436 | + | return False | |||
| 437 | + | ||||
| 438 | + | ||||
| 439 | + | def scenario_env(cef_dir, dirs, extra=None, idle_timeout_ms=0): | |||
| 246 | env = { | 440 | env = { | ||
| 247 | "HOME": os.environ.get("HOME", ""), | 441 | "HOME": os.environ.get("HOME", ""), | ||
| 248 | "PATH": os.environ.get("PATH", ""), | 442 | "PATH": os.environ.get("PATH", ""), | ||
| @@ -260,16 +454,27 @@ def scenario_env(cef_dir, dirs, extra=None): | |||||
| 260 | } | 454 | } | ||
| 261 | if extra: | 455 | if extra: | ||
| 262 | env.update(extra) | 456 | env.update(extra) | ||
| 457 | + | for name in DISPLAY_PASSTHROUGH_VARS: | |||
| 458 | + | value = os.environ.get(name) | |||
| 459 | + | if value: | |||
| 460 | + | env[name] = value | |||
| 263 | for key in ("config", "data", "state", "cache", "runtime"): | 461 | for key in ("config", "data", "state", "cache", "runtime"): | ||
| 264 | os.makedirs(dirs[key], exist_ok=True) | 462 | os.makedirs(dirs[key], exist_ok=True) | ||
| 265 | os.makedirs(dirs["root_cache"], exist_ok=True) | 463 | os.makedirs(dirs["root_cache"], exist_ok=True) | ||
| 464 | + | write_child_config(dirs["config"], cef_dir, idle_timeout_ms) | |||
| 465 | + | ensure_wayland_socket(dirs["runtime"], env) | |||
| 266 | return env | 466 | return env | ||
| 267 | 467 | ||||
| 268 | 468 | ||||
| 269 | - | def wait_for_relay_socket(runtime_dir, timeout_seconds=30.0): | 469 | + | def wait_for_relay_socket(search_root, timeout_seconds=30.0): |
| 470 | + | # The relay socket lives under XDG_STATE_HOME | |||
| 471 | + | # (<state>/[dumber/]runtime/<engine>/browser-launch.sock), not the | |||
| 472 | + | # XDG_RUNTIME dir: walk the state tree. Keep scenario outputs shallow: | |||
| 473 | + | # unix-socket paths are limited to 108 bytes and deep evidence dirs | |||
| 474 | + | # make the relay unreachable. | |||
| 270 | end = time.monotonic() + timeout_seconds | 475 | end = time.monotonic() + timeout_seconds | ||
| 271 | while time.monotonic() < end: | 476 | while time.monotonic() < end: | ||
| 272 | - | for root, _, files in os.walk(runtime_dir): | 477 | + | for root, _, files in os.walk(search_root): |
| 273 | if "browser-launch.sock" in files: | 478 | if "browser-launch.sock" in files: | ||
| 274 | path = os.path.join(root, "browser-launch.sock") | 479 | path = os.path.join(root, "browser-launch.sock") | ||
| 275 | sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) | 480 | sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) | ||
| @@ -285,7 +490,8 @@ def wait_for_relay_socket(runtime_dir, timeout_seconds=30.0): | |||||
| 285 | return None | 490 | return None | ||
| 286 | 491 | ||||
| 287 | 492 | ||||
| 288 | - | def start_relay_owner(binary, cef_dir, scenario_dir, diagnostic_close=False): | 493 | + | def start_relay_owner(binary, cef_dir, scenario_dir, diagnostic_close=False, |
| 494 | + | idle_timeout_ms=0): | |||
| 289 | dirs = { | 495 | dirs = { | ||
| 290 | "config": os.path.join(scenario_dir, "owner-config"), | 496 | "config": os.path.join(scenario_dir, "owner-config"), | ||
| 291 | "data": os.path.join(scenario_dir, "owner-data"), | 497 | "data": os.path.join(scenario_dir, "owner-data"), | ||
| @@ -293,27 +499,42 @@ def start_relay_owner(binary, cef_dir, scenario_dir, diagnostic_close=False): | |||||
| 293 | "cache": os.path.join(scenario_dir, "owner-cache"), | 499 | "cache": os.path.join(scenario_dir, "owner-cache"), | ||
| 294 | "runtime": os.path.join(scenario_dir, "owner-runtime"), | 500 | "runtime": os.path.join(scenario_dir, "owner-runtime"), | ||
| 295 | "root_cache": os.path.join(scenario_dir, "shared-profile"), | 501 | "root_cache": os.path.join(scenario_dir, "shared-profile"), | ||
| 502 | + | "owner_log": os.path.join(scenario_dir, "owner.log"), | |||
| 296 | } | 503 | } | ||
| 297 | - | env = scenario_env(cef_dir, dirs) | 504 | + | # scenario_env only reads the six XDG/root-cache keys; owner_log |
| 505 | + | # rides along for CEF-init counting without affecting the child env. | |||
| 506 | + | env = scenario_env(cef_dir, dirs, idle_timeout_ms=idle_timeout_ms) | |||
| 298 | if diagnostic_close: | 507 | if diagnostic_close: | ||
| 299 | # Owned window-close mechanism for the reopen scenario only: the | 508 | # Owned window-close mechanism for the reopen scenario only: the | ||
| 300 | # relay honors it solely in processes carrying this variable. It is | 509 | # relay honors it solely in processes carrying this variable. It is | ||
| 301 | # never a general unauthenticated shutdown command. | 510 | # never a general unauthenticated shutdown command. | ||
| 302 | env = dict(env) | 511 | env = dict(env) | ||
| 303 | env["DUMBER_DIAGNOSTIC_WINDOW_CLOSE"] = "1" | 512 | env["DUMBER_DIAGNOSTIC_WINDOW_CLOSE"] = "1" | ||
| 513 | + | log_file = open(dirs["owner_log"], "w") | |||
| 304 | try: | 514 | try: | ||
| 305 | proc = subprocess.Popen( | 515 | proc = subprocess.Popen( | ||
| 306 | [binary, "browse", "about:blank"], | 516 | [binary, "browse", "about:blank"], | ||
| 307 | - | stdout=subprocess.DEVNULL, | 517 | + | stdout=log_file, |
| 308 | - | stderr=subprocess.DEVNULL, | 518 | + | stderr=subprocess.STDOUT, |
| 519 | + | text=True, | |||
| 520 | + | bufsize=1, | |||
| 309 | env=env, | 521 | env=env, | ||
| 310 | ) | 522 | ) | ||
| 311 | except OSError: | 523 | except OSError: | ||
| 524 | + | log_file.close() | |||
| 312 | return None, None, None | 525 | return None, None, None | ||
| 313 | - | time.sleep(0.5) | |||
| 314 | if proc.poll() is not None: | 526 | if proc.poll() is not None: | ||
| 527 | + | log_file.close() | |||
| 528 | + | return None, None, None | |||
| 529 | + | # Readiness is the owner's first presentation, not a fixed sleep: | |||
| 530 | + | # only then is the relay guaranteed to serve second windows. | |||
| 531 | + | ready = wait_for_owner_log_line( | |||
| 532 | + | dirs["owner_log"], "startup_trace: first presentation") | |||
| 533 | + | log_file.close() | |||
| 534 | + | if not ready or proc.poll() is not None: | |||
| 535 | + | stop_proc(proc) | |||
| 315 | return None, None, None | 536 | return None, None, None | ||
| 316 | - | socket_path = wait_for_relay_socket(dirs["runtime"]) | 537 | + | socket_path = wait_for_relay_socket(dirs["state"]) |
| 317 | if socket_path is None: | 538 | if socket_path is None: | ||
| 318 | proc.terminate() | 539 | proc.terminate() | ||
| 319 | try: | 540 | try: | ||
| @@ -398,7 +619,11 @@ def wait_for_child_quiescence(owner_pid, settle_seconds=2.0, timeout_seconds=15. | |||||
| 398 | """Wait until the owner's child count is stable across settle_seconds. | 619 | """Wait until the owner's child count is stable across settle_seconds. | ||
| 399 | Window close is asynchronous: the relay acknowledgement only means the | 620 | Window close is asynchronous: the relay acknowledgement only means the | ||
| 400 | request was accepted, so reopening must wait for an observable steady | 621 | request was accepted, so reopening must wait for an observable steady | ||
| 401 | - | state instead of a fixed sleep. Returns the stable child count.""" | 622 | + | state instead of a fixed sleep. Returns (stable_count, settled): |
| 623 | + | settled is False on timeout, and a timeout must fail the reopen, not | |||
| 624 | + | silently pass. Child counts stay diagnostics only: CEF process | |||
| 625 | + | topology does not map one-to-one to windows, so stability alone never | |||
| 626 | + | proves zero windows or resident-idle entry.""" | |||
| 402 | end = time.monotonic() + timeout_seconds | 627 | end = time.monotonic() + timeout_seconds | ||
| 403 | last_change = time.monotonic() | 628 | last_change = time.monotonic() | ||
| 404 | last_count = len(child_pids(owner_pid)) | 629 | last_count = len(child_pids(owner_pid)) | ||
| @@ -409,8 +634,8 @@ def wait_for_child_quiescence(owner_pid, settle_seconds=2.0, timeout_seconds=15. | |||||
| 409 | last_count = count | 634 | last_count = count | ||
| 410 | last_change = time.monotonic() | 635 | last_change = time.monotonic() | ||
| 411 | elif time.monotonic() - last_change >= settle_seconds: | 636 | elif time.monotonic() - last_change >= settle_seconds: | ||
| 412 | - | return count | 637 | + | return count, True |
| 413 | - | return len(child_pids(owner_pid)) | 638 | + | return len(child_pids(owner_pid)), False |
| 414 | 639 | ||||
| 415 | 640 | ||||
| 416 | def proc_rss_kb(pid): | 641 | def proc_rss_kb(pid): | ||
| @@ -426,16 +651,13 @@ def proc_rss_kb(pid): | |||||
| 426 | 651 | ||||
| 427 | 652 | ||||
| 428 | def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_dirs=None, | 653 | def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_dirs=None, | ||
| 429 | - | shared_root_cache=None, owner_socket=None): | 654 | + | shared_root_cache=None, owner_socket=None, idle_timeout_ms=0): |
| 430 | run_token = secrets.token_hex(8) | 655 | run_token = secrets.token_hex(8) | ||
| 431 | nav_token = secrets.token_hex(8) | 656 | nav_token = secrets.token_hex(8) | ||
| 432 | cutoff = post_nav_cutoff_seconds() | 657 | cutoff = post_nav_cutoff_seconds() | ||
| 433 | state = FixtureState() | 658 | state = FixtureState() | ||
| 434 | - | Handler.state = state | 659 | + | server = ThreadingHTTPServer(("127.0.0.1", 0), |
| 435 | - | Handler.fixture = fixture | 660 | + | make_sample_handler(state, fixture, run_token, nav_token)) |
| 436 | - | Handler.run_token = run_token | |||
| 437 | - | Handler.nav_token = nav_token | |||
| 438 | - | server = ThreadingHTTPServer(("127.0.0.1", 0), Handler) | |||
| 439 | port = server.server_address[1] | 661 | port = server.server_address[1] | ||
| 440 | thread = threading.Thread(target=server.serve_forever, kwargs={"poll_interval": 0.05}) | 662 | thread = threading.Thread(target=server.serve_forever, kwargs={"poll_interval": 0.05}) | ||
| 441 | thread.daemon = True | 663 | thread.daemon = True | ||
| @@ -459,7 +681,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 459 | "root_cache": shared_root_cache or os.path.join(run_dir, "cef-root-cache"), | 681 | "root_cache": shared_root_cache or os.path.join(run_dir, "cef-root-cache"), | ||
| 460 | } | 682 | } | ||
| 461 | extra = {} | 683 | extra = {} | ||
| 462 | - | env = scenario_env(cef_dir, dirs, extra) | 684 | + | env = scenario_env(cef_dir, dirs, extra, idle_timeout_ms) |
| 463 | owner_alive_at_start = owner is not None and owner.poll() is None | 685 | owner_alive_at_start = owner is not None and owner.poll() is None | ||
| 464 | reopen = None | 686 | reopen = None | ||
| 465 | if scenario == "reopen-window" and owner is not None and owner_socket: | 687 | if scenario == "reopen-window" and owner is not None and owner_socket: | ||
| @@ -470,11 +692,13 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 470 | acknowledged = send_diagnostic_close(owner_socket) | 692 | acknowledged = send_diagnostic_close(owner_socket) | ||
| 471 | # The acknowledgement only means accepted: wait for an | 693 | # The acknowledgement only means accepted: wait for an | ||
| 472 | # observable steady state before measuring the reopen. | 694 | # observable steady state before measuring the reopen. | ||
| 473 | - | quiescent_children = wait_for_child_quiescence(owner_pid) | 695 | + | # An unsettled timeout fails the reopen via quiescence_settled. |
| 696 | + | quiescent_children, settled = wait_for_child_quiescence(owner_pid) | |||
| 474 | reopen = { | 697 | reopen = { | ||
| 475 | "owner_pid": owner_pid, | 698 | "owner_pid": owner_pid, | ||
| 476 | "owner_starttime": owner_start, | 699 | "owner_starttime": owner_start, | ||
| 477 | "close_acknowledged": acknowledged, | 700 | "close_acknowledged": acknowledged, | ||
| 701 | + | "quiescence_settled": settled, | |||
| 478 | "browser_child_count_before": len(children_before), | 702 | "browser_child_count_before": len(children_before), | ||
| 479 | "browser_child_count_quiescent": quiescent_children, | 703 | "browser_child_count_quiescent": quiescent_children, | ||
| 480 | "owner_rss_kb_before": rss_before, | 704 | "owner_rss_kb_before": rss_before, | ||
| @@ -500,6 +724,13 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 500 | pump_thread = threading.Thread(target=pump) | 724 | pump_thread = threading.Thread(target=pump) | ||
| 501 | pump_thread.daemon = True | 725 | pump_thread.daemon = True | ||
| 502 | pump_thread.start() | 726 | pump_thread.start() | ||
| 727 | + | nav_deadline = navigation_deadline_seconds() | |||
| 728 | + | # A live owner serves the navigation after the launcher exits: | |||
| 729 | + | # in that case launcher exit must not end collection before the | |||
| 730 | + | # correlated document arrives. Without a live owner the sample | |||
| 731 | + | # is its own browser and exit ends it. | |||
| 732 | + | defers_to_owner = bool(owner_alive_at_start and owner_dirs is not None | |||
| 733 | + | and scenario in ("relay-window", "reopen-window")) | |||
| 503 | hard_end = spawn_ts + cutoff + 25.0 | 734 | hard_end = spawn_ts + cutoff + 25.0 | ||
| 504 | while True: | 735 | while True: | ||
| 505 | now = time.monotonic() | 736 | now = time.monotonic() | ||
| @@ -514,7 +745,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 514 | break | 745 | break | ||
| 515 | if now >= navigated_at + cutoff + 5.0: | 746 | if now >= navigated_at + cutoff + 5.0: | ||
| 516 | break | 747 | break | ||
| 517 | - | elif now >= spawn_ts + cutoff + 5.0 or exited: | 748 | + | elif now >= spawn_ts + nav_deadline or (exited and not defers_to_owner): |
| 518 | break | 749 | break | ||
| 519 | if now >= hard_end: | 750 | if now >= hard_end: | ||
| 520 | break | 751 | break | ||
| @@ -527,6 +758,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 527 | except subprocess.TimeoutExpired: | 758 | except subprocess.TimeoutExpired: | ||
| 528 | proc.kill() | 759 | proc.kill() | ||
| 529 | proc.wait(timeout=5) | 760 | proc.wait(timeout=5) | ||
| 761 | + | launcher_returncode = proc.returncode | |||
| 530 | pump_thread.join(timeout=5) | 762 | pump_thread.join(timeout=5) | ||
| 531 | try: | 763 | try: | ||
| 532 | proc.stdout.close() | 764 | proc.stdout.close() | ||
| @@ -538,6 +770,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 538 | beacons = list(state.beacons) | 770 | beacons = list(state.beacons) | ||
| 539 | document_count = len(state.document_requests) | 771 | document_count = len(state.document_requests) | ||
| 540 | subresource_count = len(state.subresource_requests) | 772 | subresource_count = len(state.subresource_requests) | ||
| 773 | + | first_document_at = state.first_document_monotonic | |||
| 541 | fcp = [b for b in beacons if b["event"] == "first-contentful-paint"] | 774 | fcp = [b for b in beacons if b["event"] == "first-contentful-paint"] | ||
| 542 | lcp = [b for b in beacons if b["event"] == "largest-contentful-paint"] | 775 | lcp = [b for b in beacons if b["event"] == "largest-contentful-paint"] | ||
| 543 | if fcp: | 776 | if fcp: | ||
| @@ -564,10 +797,26 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 564 | "target_fcp_ms": fcp[0]["value_ms"] if fcp else None, | 797 | "target_fcp_ms": fcp[0]["value_ms"] if fcp else None, | ||
| 565 | "target_lcp_through_cutoff_ms": lcp[-1]["value_ms"] if lcp else None, | 798 | "target_lcp_through_cutoff_ms": lcp[-1]["value_ms"] if lcp else None, | ||
| 566 | "startup_milestones": len(milestones), | 799 | "startup_milestones": len(milestones), | ||
| 800 | + | "launcher_returncode": launcher_returncode, | |||
| 801 | + | "launcher_cef_init_count": count_cef_inits([line for _, line in arrivals]), | |||
| 802 | + | "first_document_observation_ms": ( | |||
| 803 | + | int((first_document_at - spawn_ts) * 1000) | |||
| 804 | + | if first_document_at is not None and first_document_at >= spawn_ts | |||
| 805 | + | else None | |||
| 806 | + | ), | |||
| 567 | "complete": complete, | 807 | "complete": complete, | ||
| 568 | "relayed": relayed, | 808 | "relayed": relayed, | ||
| 569 | "fallback_spawn": scenario in ("relay-window", "reopen-window") and not relayed, | 809 | "fallback_spawn": scenario in ("relay-window", "reopen-window") and not relayed, | ||
| 570 | } | 810 | } | ||
| 811 | + | if scenario in ("relay-window", "reopen-window") and owner_dirs is not None: | |||
| 812 | + | # Residency proof: the owner must initialize CEF exactly once | |||
| 813 | + | # no matter how many second windows it serves. A second init | |||
| 814 | + | # here means the sample paid a full cold start, not a reopen. | |||
| 815 | + | try: | |||
| 816 | + | with open(owner_dirs.get("owner_log", ""), errors="replace") as owner_log: | |||
| 817 | + | result["owner_cef_init_count"] = count_cef_inits(owner_log) | |||
| 818 | + | except OSError: | |||
| 819 | + | result["owner_cef_init_count"] = None | |||
| 571 | if reopen is not None: | 820 | if reopen is not None: | ||
| 572 | # Owner identity is verified independently of the Popen handle: | 821 | # Owner identity is verified independently of the Popen handle: | ||
| 573 | # the same pid with a different start time is a recycled pid, | 822 | # the same pid with a different start time is a recycled pid, | ||
| @@ -584,6 +833,7 @@ def run_sample(binary, cef_dir, scenario, fixture, run_index, owner=None, owner_ | |||||
| 584 | reopen["browser_child_count_after"] = len(child_pids(owner.pid)) if owner_alive else 0 | 833 | reopen["browser_child_count_after"] = len(child_pids(owner.pid)) if owner_alive else 0 | ||
| 585 | reopen["owner_rss_kb_after"] = proc_rss_kb(owner.pid) if owner_alive else None | 834 | reopen["owner_rss_kb_after"] = proc_rss_kb(owner.pid) if owner_alive else None | ||
| 586 | result["reopen"] = reopen | 835 | result["reopen"] = reopen | ||
| 836 | + | result["residency_valid"] = is_residency_valid(result, scenario) | |||
| 587 | return result | 837 | return result | ||
| 588 | finally: | 838 | finally: | ||
| 589 | server.shutdown() | 839 | server.shutdown() | ||
| @@ -608,8 +858,15 @@ def main(): | |||||
| 608 | ) | 858 | ) | ||
| 609 | parser.add_argument("--runs", type=int, default=30) | 859 | parser.add_argument("--runs", type=int, default=30) | ||
| 610 | parser.add_argument("--output", required=True) | 860 | parser.add_argument("--output", required=True) | ||
| 861 | + | parser.add_argument("--idle-timeout-ms", type=int, default=0, | |||
| 862 | + | help="resident CEF idle timeout for generated configs " | |||
| 863 | + | "(0..300000, 0 is the product default)") | |||
| 611 | args = parser.parse_args() | 864 | args = parser.parse_args() | ||
| 612 | 865 | ||||
| 866 | + | if args.idle_timeout_ms < 0 or args.idle_timeout_ms > 300000: | |||
| 867 | + | print("measure: --idle-timeout-ms must be 0..300000", file=sys.stderr) | |||
| 868 | + | raise SystemExit(2) | |||
| 869 | + | ||||
| 613 | if args.runs < 1 or args.runs > 100: | 870 | if args.runs < 1 or args.runs > 100: | ||
| 614 | print("measure: --runs must be 1..100", file=sys.stderr) | 871 | print("measure: --runs must be 1..100", file=sys.stderr) | ||
| 615 | raise SystemExit(2) | 872 | raise SystemExit(2) | ||
| @@ -635,6 +892,10 @@ def main(): | |||||
| 635 | binary_sha256 = digest.hexdigest() | 892 | binary_sha256 = digest.hexdigest() | ||
| 636 | 893 | ||||
| 637 | os.makedirs(args.output) | 894 | os.makedirs(args.output) | ||
| 895 | + | # Privacy: only summary.json and run-*.json are safe to share (timings, | |||
| 896 | + | # counts, hashes). owner.log and generated configs are machine-local: | |||
| 897 | + | # raw child logs and the selected --cef-dir path may contain local | |||
| 898 | + | # usernames or paths. Never publish the whole directory. | |||
| 638 | owner = None | 899 | owner = None | ||
| 639 | owner_dirs = None | 900 | owner_dirs = None | ||
| 640 | owner_socket = None | 901 | owner_socket = None | ||
| @@ -646,12 +907,15 @@ def main(): | |||||
| 646 | if args.scenario == "relay-window": | 907 | if args.scenario == "relay-window": | ||
| 647 | scenario_dir = os.path.join(args.output, "relay-scenario") | 908 | scenario_dir = os.path.join(args.output, "relay-scenario") | ||
| 648 | os.makedirs(scenario_dir) | 909 | os.makedirs(scenario_dir) | ||
| 649 | - | owner, owner_dirs, owner_socket = start_relay_owner(args.binary, args.cef_dir, scenario_dir) | 910 | + | owner, owner_dirs, owner_socket = start_relay_owner( |
| 911 | + | args.binary, args.cef_dir, scenario_dir, | |||
| 912 | + | idle_timeout_ms=args.idle_timeout_ms) | |||
| 650 | if args.scenario == "reopen-window": | 913 | if args.scenario == "reopen-window": | ||
| 651 | scenario_dir = os.path.join(args.output, "reopen-scenario") | 914 | scenario_dir = os.path.join(args.output, "reopen-scenario") | ||
| 652 | os.makedirs(scenario_dir) | 915 | os.makedirs(scenario_dir) | ||
| 653 | owner, owner_dirs, owner_socket = start_relay_owner( | 916 | owner, owner_dirs, owner_socket = start_relay_owner( | ||
| 654 | - | args.binary, args.cef_dir, scenario_dir, diagnostic_close=True) | 917 | + | args.binary, args.cef_dir, scenario_dir, diagnostic_close=True, |
| 918 | + | idle_timeout_ms=args.idle_timeout_ms) | |||
| 655 | 919 | ||||
| 656 | results = [] | 920 | results = [] | ||
| 657 | try: | 921 | try: | ||
| @@ -661,7 +925,8 @@ def main(): | |||||
| 661 | # warm-up aborts the scenario: later runs must never use an | 925 | # warm-up aborts the scenario: later runs must never use an | ||
| 662 | # uninitialized profile. | 926 | # uninitialized profile. | ||
| 663 | warmup = run_sample(args.binary, args.cef_dir, args.scenario, args.fixture, | 927 | warmup = run_sample(args.binary, args.cef_dir, args.scenario, args.fixture, | ||
| 664 | - | 0, shared_root_cache=shared_root_cache) | 928 | + | 0, shared_root_cache=shared_root_cache, |
| 929 | + | idle_timeout_ms=args.idle_timeout_ms) | |||
| 665 | if not warmup["complete"]: | 930 | if not warmup["complete"]: | ||
| 666 | print("measure: process-warm warm-up was incomplete", file=sys.stderr) | 931 | print("measure: process-warm warm-up was incomplete", file=sys.stderr) | ||
| 667 | raise SystemExit(1) | 932 | raise SystemExit(1) | ||
| @@ -670,7 +935,7 @@ def main(): | |||||
| 670 | result = run_sample( | 935 | result = run_sample( | ||
| 671 | args.binary, args.cef_dir, args.scenario, args.fixture, index, | 936 | args.binary, args.cef_dir, args.scenario, args.fixture, index, | ||
| 672 | owner=owner, owner_dirs=owner_dirs, shared_root_cache=shared_root_cache, | 937 | owner=owner, owner_dirs=owner_dirs, shared_root_cache=shared_root_cache, | ||
| 673 | - | owner_socket=owner_socket, | 938 | + | owner_socket=owner_socket, idle_timeout_ms=args.idle_timeout_ms, |
| 674 | ) | 939 | ) | ||
| 675 | results.append(result) | 940 | results.append(result) | ||
| 676 | with open(os.path.join(args.output, "run-%02d.json" % index), "w") as handle: | 941 | with open(os.path.join(args.output, "run-%02d.json" % index), "w") as handle: | ||
| @@ -692,7 +957,34 @@ def main(): | |||||
| 692 | ), | 957 | ), | ||
| 693 | "warmup_discarded": warmup_discarded, | 958 | "warmup_discarded": warmup_discarded, | ||
| 694 | "relay_owner_ready": owner is not None, | 959 | "relay_owner_ready": owner is not None, | ||
| 960 | + | "idle_timeout_ms": args.idle_timeout_ms, | |||
| 695 | } | 961 | } | ||
| 962 | + | if args.scenario in ("relay-window", "reopen-window") and owner_dirs is not None: | |||
| 963 | + | # Second-window contract, kept separate from cold-process numbers: | |||
| 964 | + | # one owner CEF init total, plus the request-to-FCP distribution | |||
| 965 | + | # of resident reopens. Missing FCP stays missing, never averaged in. | |||
| 966 | + | try: | |||
| 967 | + | with open(owner_dirs.get("owner_log", ""), errors="replace") as owner_log: | |||
| 968 | + | summary["owner_cef_init_count"] = count_cef_inits(owner_log) | |||
| 969 | + | except OSError: | |||
| 970 | + | summary["owner_cef_init_count"] = None | |||
| 971 | + | fcp_observations = sorted( | |||
| 972 | + | r["first_document_observation_ms"] | |||
| 973 | + | for r in results | |||
| 974 | + | if r.get("residency_valid") and r["first_document_observation_ms"] is not None | |||
| 975 | + | ) | |||
| 976 | + | summary["resident_valid_runs"] = sum(1 for r in results if r.get("residency_valid")) | |||
| 977 | + | summary["resident_invalid_runs"] = sum(1 for r in results if r.get("residency_valid") is False) | |||
| 978 | + | summary["second_window_complete_runs"] = len(fcp_observations) | |||
| 979 | + | if fcp_observations: | |||
| 980 | + | # Spawn to first document request, same harness clock. This is | |||
| 981 | + | # request arrival, not document completion or paint; for the | |||
| 982 | + | # redirect fixture it measures the initial redirect request. | |||
| 983 | + | summary["second_window_spawn_to_first_document_observation_ms"] = { | |||
| 984 | + | "min": fcp_observations[0], | |||
| 985 | + | "median": fcp_observations[len(fcp_observations) // 2], | |||
| 986 | + | "max": fcp_observations[-1], | |||
| 987 | + | } | |||
| 696 | with open(os.path.join(args.output, "summary.json"), "w") as handle: | 988 | with open(os.path.join(args.output, "summary.json"), "w") as handle: | ||
| 697 | json.dump(summary, handle, indent=2, sort_keys=True) | 989 | json.dump(summary, handle, indent=2, sort_keys=True) | ||
| 698 | print("measure artifacts: %s" % args.output) | 990 | print("measure artifacts: %s" % args.output) | ||
M scripts/test_measure_cef_startup.py +333 -1
| @@ -140,6 +140,17 @@ class CliValidationTest(unittest.TestCase): | |||
| 140 | 140 | capture_output=True, text=True) | |
| 141 | 141 | self.assertNotEqual(result.returncode, 0) | |
| 142 | 142 | ||
| 143 | + | def test_rejects_bad_idle_timeout(self): | |
| 144 | + | for bad in ("-1", "300001"): | |
| 145 | + | result = subprocess.run( | |
| 146 | + | [sys.executable, self.script, "--binary", self.binary, "--cef-dir", self.cef_dir, | |
| 147 | + | "--scenario", "profile-fresh", "--fixture", "static", | |
| 148 | + | "--runs", "1", "--idle-timeout-ms", bad, | |
| 149 | + | "--output", os.path.join(self.temp, "out-idle-" + bad)], | |
| 150 | + | capture_output=True, text=True) | |
| 151 | + | self.assertNotEqual(result.returncode, 0) | |
| 152 | + | self.assertIn("idle-timeout-ms", result.stderr) | |
| 153 | + | ||
| 143 | 154 | ||
| 144 | 155 | class FakeBinaryLifetimeTest(unittest.TestCase): | |
| 145 | 156 | def setUp(self): | |
| @@ -179,6 +190,15 @@ class FakeBinaryLifetimeTest(unittest.TestCase): | |||
| 179 | 190 | self.assertEqual(result["document_requests"], 1) | |
| 180 | 191 | self.assertIsNone(result["target_fcp_ms"]) | |
| 181 | 192 | self.assertFalse(result["complete"]) | |
| 193 | + | # Same-clock spawn-to-request latency is still reported. | |
| 194 | + | self.assertIsNotNone(result["first_document_observation_ms"]) | |
| 195 | + | self.assertGreaterEqual(result["first_document_observation_ms"], 0) | |
| 196 | + | ||
| 197 | + | def test_no_navigation_means_no_document_observation(self): | |
| 198 | + | binary = self.make_binary("exit 0") | |
| 199 | + | result = harness.run_sample(binary, self.cef_dir, "profile-fresh", "static", 1) | |
| 200 | + | self.assertEqual(result["document_requests"], 0) | |
| 201 | + | self.assertIsNone(result["first_document_observation_ms"]) | |
| 182 | 202 | ||
| 183 | 203 | def test_relay_fallback_recorded_without_owner(self): | |
| 184 | 204 | binary = self.make_binary("exit 0") | |
| @@ -211,6 +231,311 @@ class FakeBinaryLifetimeTest(unittest.TestCase): | |||
| 211 | 231 | self.assertLess(result["observation_spawn_to_summary_ms"], 15000) | |
| 212 | 232 | ||
| 213 | 233 | ||
| 234 | + | class ResidencyContractTest(unittest.TestCase): | |
| 235 | + | def setUp(self): | |
| 236 | + | self.temp = tempfile.mkdtemp() | |
| 237 | + | self.cef_dir = os.path.join(self.temp, "cef") | |
| 238 | + | os.makedirs(self.cef_dir) | |
| 239 | + | self.dirs = { | |
| 240 | + | "config": os.path.join(self.temp, "config"), | |
| 241 | + | "data": os.path.join(self.temp, "data"), | |
| 242 | + | "state": os.path.join(self.temp, "state"), | |
| 243 | + | "cache": os.path.join(self.temp, "cache"), | |
| 244 | + | "runtime": os.path.join(self.temp, "runtime"), | |
| 245 | + | "root_cache": os.path.join(self.temp, "cef-root-cache"), | |
| 246 | + | } | |
| 247 | + | ||
| 248 | + | def test_scenario_env_forces_json_debug_config(self): | |
| 249 | + | env = harness.scenario_env(self.cef_dir, self.dirs, idle_timeout_ms=120000) | |
| 250 | + | self.assertEqual(env["DUMBER_CEF_DIR"], self.cef_dir) | |
| 251 | + | with open(os.path.join(self.dirs["config"], "dumber", "config.toml")) as handle: | |
| 252 | + | content = handle.read() | |
| 253 | + | self.assertIn('format = "json"', content) | |
| 254 | + | self.assertIn('level = "debug"', content) | |
| 255 | + | self.assertIn(self.cef_dir, content) | |
| 256 | + | self.assertIn("idle_runtime_timeout_ms = 120000", content) | |
| 257 | + | ||
| 258 | + | def test_scenario_env_defaults_to_no_residency(self): | |
| 259 | + | harness.scenario_env(self.cef_dir, self.dirs) | |
| 260 | + | with open(os.path.join(self.dirs["config"], "dumber", "config.toml")) as handle: | |
| 261 | + | content = handle.read() | |
| 262 | + | self.assertIn("idle_runtime_timeout_ms = 0", content) | |
| 263 | + | ||
| 264 | + | def test_scenario_env_passes_display_vars_only(self): | |
| 265 | + | os.environ["DUMBER_MEASURE_TEST_MARKER"] = "must-not-propagate" | |
| 266 | + | try: | |
| 267 | + | env = harness.scenario_env(self.cef_dir, self.dirs) | |
| 268 | + | finally: | |
| 269 | + | del os.environ["DUMBER_MEASURE_TEST_MARKER"] | |
| 270 | + | self.assertNotIn("DUMBER_MEASURE_TEST_MARKER", env) | |
| 271 | + | for name in harness.DISPLAY_PASSTHROUGH_VARS: | |
| 272 | + | if os.environ.get(name): | |
| 273 | + | self.assertEqual(env[name], os.environ[name]) | |
| 274 | + | ||
| 275 | + | def test_wayland_absolute_display_needs_nothing(self): | |
| 276 | + | previous = os.environ.get("WAYLAND_DISPLAY") | |
| 277 | + | runtime = os.environ.get("XDG_RUNTIME_DIR", "/run/user/%d" % os.getuid()) | |
| 278 | + | display = previous or "wayland-1" | |
| 279 | + | absolute = display if "/" in display else os.path.join(runtime, os.path.basename(display)) | |
| 280 | + | env = {"WAYLAND_DISPLAY": absolute} | |
| 281 | + | os.makedirs(self.dirs["runtime"], exist_ok=True) | |
| 282 | + | self.assertTrue(harness.ensure_wayland_socket(self.dirs["runtime"], env)) | |
| 283 | + | self.assertEqual(env["WAYLAND_DISPLAY"], absolute) | |
| 284 | + | self.assertEqual(os.listdir(self.dirs["runtime"]), []) | |
| 285 | + | ||
| 286 | + | def test_wayland_relative_display_resolves_to_absolute(self): | |
| 287 | + | import socket as stdlib_socket | |
| 288 | + | fake_runtime = os.path.join(self.temp, "real-runtime") | |
| 289 | + | os.makedirs(fake_runtime) | |
| 290 | + | sock = stdlib_socket.socket(stdlib_socket.AF_UNIX, stdlib_socket.SOCK_STREAM) | |
| 291 | + | sock.bind(os.path.join(fake_runtime, "wayland-99")) | |
| 292 | + | previous_runtime = os.environ.get("XDG_RUNTIME_DIR") | |
| 293 | + | os.environ["XDG_RUNTIME_DIR"] = fake_runtime | |
| 294 | + | env = {"WAYLAND_DISPLAY": "wayland-99"} | |
| 295 | + | try: | |
| 296 | + | self.assertTrue(harness.ensure_wayland_socket(self.dirs["runtime"], env)) | |
| 297 | + | self.assertEqual(env["WAYLAND_DISPLAY"], | |
| 298 | + | os.path.join(fake_runtime, "wayland-99")) | |
| 299 | + | # No symlink: deep isolated paths exceed the unix-socket limit. | |
| 300 | + | self.assertNotIn("wayland-99", os.listdir(self.dirs["runtime"])) | |
| 301 | + | finally: | |
| 302 | + | if previous_runtime is None: | |
| 303 | + | os.environ.pop("XDG_RUNTIME_DIR", None) | |
| 304 | + | else: | |
| 305 | + | os.environ["XDG_RUNTIME_DIR"] = previous_runtime | |
| 306 | + | sock.close() | |
| 307 | + | ||
| 308 | + | def test_wayland_missing_socket_reports_false(self): | |
| 309 | + | previous_runtime = os.environ.get("XDG_RUNTIME_DIR") | |
| 310 | + | os.environ["XDG_RUNTIME_DIR"] = os.path.join(self.temp, "empty-runtime") | |
| 311 | + | env = {"WAYLAND_DISPLAY": "wayland-does-not-exist"} | |
| 312 | + | try: | |
| 313 | + | self.assertFalse(harness.ensure_wayland_socket(self.dirs["runtime"], env)) | |
| 314 | + | finally: | |
| 315 | + | if previous_runtime is None: | |
| 316 | + | os.environ.pop("XDG_RUNTIME_DIR", None) | |
| 317 | + | else: | |
| 318 | + | os.environ["XDG_RUNTIME_DIR"] = previous_runtime | |
| 319 | + | self.assertEqual(env["WAYLAND_DISPLAY"], "wayland-does-not-exist") | |
| 320 | + | ||
| 321 | + | def test_count_cef_inits(self): | |
| 322 | + | init = '{"message":"startup_trace: milestone","milestone":"cef_initialized"}' | |
| 323 | + | other = '{"message":"startup_trace: milestone","milestone":"process_entry"}' | |
| 324 | + | noise = '{"message":"cef: InitWithApp returned OK"}' | |
| 325 | + | self.assertEqual(harness.count_cef_inits([]), 0) | |
| 326 | + | self.assertEqual(harness.count_cef_inits([other, "not json"]), 0) | |
| 327 | + | self.assertEqual(harness.count_cef_inits([other, init]), 1) | |
| 328 | + | self.assertEqual(harness.count_cef_inits([init, noise, init]), 2) | |
| 329 | + | ||
| 330 | + | def test_second_window_records_owner_init_count(self): | |
| 331 | + | binary = os.path.join(self.temp, "fakebin") | |
| 332 | + | with open(binary, "w") as handle: | |
| 333 | + | handle.write("#!/bin/sh\nexit 0\n") | |
| 334 | + | os.chmod(binary, 0o755) | |
| 335 | + | log_path = os.path.join(self.temp, "owner.log") | |
| 336 | + | with open(log_path, "w") as handle: | |
| 337 | + | handle.write('{"message":"startup_trace: milestone","milestone":"cef_initialized"}\n') | |
| 338 | + | owner_dirs = dict(self.dirs) | |
| 339 | + | owner_dirs["owner_log"] = log_path | |
| 340 | + | result = harness.run_sample(binary, self.cef_dir, "relay-window", "static", 1, | |
| 341 | + | owner=None, owner_dirs=owner_dirs, owner_socket=None) | |
| 342 | + | self.assertTrue(result["fallback_spawn"]) | |
| 343 | + | self.assertEqual(result["owner_cef_init_count"], 1) | |
| 344 | + | ||
| 345 | + | def test_second_window_missing_owner_log_is_none(self): | |
| 346 | + | binary = os.path.join(self.temp, "fakebin") | |
| 347 | + | with open(binary, "w") as handle: | |
| 348 | + | handle.write("#!/bin/sh\nexit 0\n") | |
| 349 | + | os.chmod(binary, 0o755) | |
| 350 | + | owner_dirs = dict(self.dirs) | |
| 351 | + | owner_dirs["owner_log"] = os.path.join(self.temp, "absent.log") | |
| 352 | + | result = harness.run_sample(binary, self.cef_dir, "relay-window", "static", 1, | |
| 353 | + | owner=None, owner_dirs=owner_dirs, owner_socket=None) | |
| 354 | + | self.assertIsNone(result["owner_cef_init_count"]) | |
| 355 | + | ||
| 356 | + | ||
| 357 | + | class DocumentTokenTest(unittest.TestCase): | |
| 358 | + | # Document routes must only record and serve correlated requests; | |
| 359 | + | # beacons already validate tokens, subresources stay ungated. | |
| 360 | + | def setUp(self): | |
| 361 | + | self.state = harness.FixtureState() | |
| 362 | + | cls = harness.make_sample_handler(self.state, "static", "a" * 16, "b" * 16) | |
| 363 | + | self.server = ThreadingHTTPServer(("127.0.0.1", 0), cls) | |
| 364 | + | self.port = self.server.server_address[1] | |
| 365 | + | self.thread = threading.Thread(target=self.server.serve_forever, kwargs={"poll_interval": 0.05}) | |
| 366 | + | self.thread.daemon = True | |
| 367 | + | self.thread.start() | |
| 368 | + | ||
| 369 | + | def tearDown(self): | |
| 370 | + | self.server.shutdown() | |
| 371 | + | self.server.server_close() | |
| 372 | + | self.thread.join(timeout=5) | |
| 373 | + | ||
| 374 | + | def get(self, path): | |
| 375 | + | url = "http://127.0.0.1:%d%s" % (self.port, path) | |
| 376 | + | try: | |
| 377 | + | with urllib.request.urlopen(url, timeout=5) as response: | |
| 378 | + | return response.status, response.read() | |
| 379 | + | except urllib.error.HTTPError as exc: | |
| 380 | + | exc.read() | |
| 381 | + | return exc.code, b"" | |
| 382 | + | ||
| 383 | + | def test_correlated_document_recorded_and_served(self): | |
| 384 | + | status, body = self.get("/?run=%s&nav=%s" % ("a" * 16, "b" * 16)) | |
| 385 | + | self.assertEqual(status, 200) | |
| 386 | + | self.assertIn(b"static", body) | |
| 387 | + | self.assertEqual(len(self.state.document_requests), 1) | |
| 388 | + | self.assertIsNotNone(self.state.first_document_monotonic) | |
| 389 | + | ||
| 390 | + | def test_wrong_tokens_rejected_without_recording(self): | |
| 391 | + | status, _ = self.get("/?run=%s&nav=%s" % ("c" * 16, "d" * 16)) | |
| 392 | + | self.assertEqual(status, 404) | |
| 393 | + | self.assertEqual(self.state.document_requests, []) | |
| 394 | + | self.assertIsNone(self.state.first_document_monotonic) | |
| 395 | + | ||
| 396 | + | def test_missing_tokens_rejected_without_recording(self): | |
| 397 | + | status, _ = self.get("/") | |
| 398 | + | self.assertEqual(status, 404) | |
| 399 | + | self.assertEqual(self.state.document_requests, []) | |
| 400 | + | ||
| 401 | + | def test_redirect_with_bad_tokens_rejected(self): | |
| 402 | + | status, _ = self.get("/redirect?run=%s&nav=%s" % ("c" * 16, "d" * 16)) | |
| 403 | + | self.assertEqual(status, 404) | |
| 404 | + | self.assertEqual(self.state.document_requests, []) | |
| 405 | + | ||
| 406 | + | def test_redirect_with_tokens_redirects_once(self): | |
| 407 | + | opener = urllib.request.build_opener(NoRedirect()) | |
| 408 | + | url = "http://127.0.0.1:%d/redirect?run=%s&nav=%s" % (self.port, "a" * 16, "b" * 16) | |
| 409 | + | try: | |
| 410 | + | opener.open(url, timeout=5) | |
| 411 | + | self.fail("expected redirect") | |
| 412 | + | except Redirected as exc: | |
| 413 | + | self.assertEqual(exc.code, 302) | |
| 414 | + | self.assertIn("/target?run=%s" % ("a" * 16), exc.headers["Location"]) | |
| 415 | + | self.assertEqual(len(self.state.document_requests), 1) | |
| 416 | + | ||
| 417 | + | def test_handler_state_is_per_sample(self): | |
| 418 | + | other_state = harness.FixtureState() | |
| 419 | + | other_cls = harness.make_sample_handler(other_state, "static", "c" * 16, "d" * 16) | |
| 420 | + | self.assertIsNot(other_cls.state, self.state) | |
| 421 | + | self.assertNotEqual(other_cls.run_token, "a" * 16) | |
| 422 | + | ||
| 423 | + | ||
| 424 | + | class NoRedirect(urllib.request.HTTPRedirectHandler): | |
| 425 | + | def redirect_request(self, req, fp, code, msg, headers, newurl): | |
| 426 | + | raise Redirected(code, headers) | |
| 427 | + | ||
| 428 | + | ||
| 429 | + | class Redirected(Exception): | |
| 430 | + | def __init__(self, code, headers): | |
| 431 | + | super().__init__(code) | |
| 432 | + | self.code = code | |
| 433 | + | self.headers = headers | |
| 434 | + | ||
| 435 | + | ||
| 436 | + | class ResidencyValidityTest(unittest.TestCase): | |
| 437 | + | def base_result(self): | |
| 438 | + | return {"relayed": True, "fallback_spawn": False, "launcher_returncode": 0, | |
| 439 | + | "owner_cef_init_count": 1, "launcher_cef_init_count": 0} | |
| 440 | + | ||
| 441 | + | def test_non_resident_scenario_is_none(self): | |
| 442 | + | self.assertIsNone(harness.is_residency_valid(self.base_result(), "profile-fresh")) | |
| 443 | + | ||
| 444 | + | def test_valid_relay(self): | |
| 445 | + | self.assertTrue(harness.is_residency_valid(self.base_result(), "relay-window")) | |
| 446 | + | ||
| 447 | + | def test_fallback_is_invalid(self): | |
| 448 | + | result = self.base_result() | |
| 449 | + | result.update({"relayed": False, "fallback_spawn": True}) | |
| 450 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |
| 451 | + | ||
| 452 | + | def test_launcher_failure_is_invalid(self): | |
| 453 | + | result = self.base_result() | |
| 454 | + | result["launcher_returncode"] = 1 | |
| 455 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |
| 456 | + | ||
| 457 | + | def test_launcher_cold_start_is_invalid(self): | |
| 458 | + | result = self.base_result() | |
| 459 | + | result["launcher_cef_init_count"] = 1 | |
| 460 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |
| 461 | + | ||
| 462 | + | def test_missing_owner_init_is_invalid(self): | |
| 463 | + | result = self.base_result() | |
| 464 | + | result["owner_cef_init_count"] = None | |
| 465 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |
| 466 | + | ||
| 467 | + | def test_reopen_requires_settled_close_and_same_process(self): | |
| 468 | + | valid = self.base_result() | |
| 469 | + | valid["reopen"] = {"close_acknowledged": True, "quiescence_settled": True, | |
| 470 | + | "same_process": True, "owner_alive_after": True} | |
| 471 | + | self.assertTrue(harness.is_residency_valid(valid, "reopen-window")) | |
| 472 | + | for key in ("close_acknowledged", "quiescence_settled", "same_process", "owner_alive_after"): | |
| 473 | + | broken = self.base_result() | |
| 474 | + | reopen = {"close_acknowledged": True, "quiescence_settled": True, | |
| 475 | + | "same_process": True, "owner_alive_after": True} | |
| 476 | + | reopen[key] = False | |
| 477 | + | broken["reopen"] = reopen | |
| 478 | + | self.assertFalse(harness.is_residency_valid(broken, "reopen-window"), key) | |
| 479 | + | self.assertFalse(harness.is_residency_valid(self.base_result(), "reopen-window")) | |
| 480 | + | ||
| 481 | + | def test_toml_escaping_round_trips(self): | |
| 482 | + | try: | |
| 483 | + | import tomllib | |
| 484 | + | except ImportError: | |
| 485 | + | self.skipTest("tomllib unavailable") | |
| 486 | + | nasty = "C:\\we\"ird\npath\twith\x01controls\x7f" | |
| 487 | + | escaped = harness._escape_toml_basic(nasty) | |
| 488 | + | parsed = tomllib.loads('key = "%s"' % escaped) | |
| 489 | + | self.assertEqual(parsed["key"], nasty) | |
| 490 | + | ||
| 491 | + | ||
| 492 | + | class LateOwnerRequestTest(unittest.TestCase): | |
| 493 | + | # Finding 2: a relay launcher may exit right after forwarding while | |
| 494 | + | # the owner requests the document later. Collection must survive the | |
| 495 | + | # launcher exit until the bounded navigation deadline. | |
| 496 | + | def setUp(self): | |
| 497 | + | self.temp = tempfile.mkdtemp() | |
| 498 | + | self.cef_dir = os.path.join(self.temp, "cef") | |
| 499 | + | os.makedirs(self.cef_dir) | |
| 500 | + | self.saved = {key: os.environ.get(key) for key in | |
| 501 | + | ("DUMBER_MEASURE_CUTOFF_SECONDS", "DUMBER_MEASURE_NAV_DEADLINE_SECONDS")} | |
| 502 | + | os.environ["DUMBER_MEASURE_CUTOFF_SECONDS"] = "0.2" | |
| 503 | + | os.environ["DUMBER_MEASURE_NAV_DEADLINE_SECONDS"] = "4" | |
| 504 | + | self.owner = subprocess.Popen(["sleep", "30"]) | |
| 505 | + | self.addCleanup(self.owner.kill) | |
| 506 | + | ||
| 507 | + | def tearDown(self): | |
| 508 | + | for key, value in self.saved.items(): | |
| 509 | + | if value is None: | |
| 510 | + | os.environ.pop(key, None) | |
| 511 | + | else: | |
| 512 | + | os.environ[key] = value | |
| 513 | + | try: | |
| 514 | + | self.owner.wait(timeout=5) | |
| 515 | + | except subprocess.TimeoutExpired: | |
| 516 | + | pass | |
| 517 | + | ||
| 518 | + | def test_late_document_survives_launcher_exit(self): | |
| 519 | + | binary = os.path.join(self.temp, "late-launcher") | |
| 520 | + | with open(binary, "w") as handle: | |
| 521 | + | handle.write("#!/bin/sh\n" | |
| 522 | + | 'url="$2"\n' | |
| 523 | + | '(sleep 1; python3 -c "import sys,urllib.request;' | |
| 524 | + | ' urllib.request.urlopen(sys.argv[1], timeout=10).read()" "$url") >/dev/null 2>&1 &\n' | |
| 525 | + | "exit 0\n") | |
| 526 | + | os.chmod(binary, 0o755) | |
| 527 | + | owner_dirs = {key: os.path.join(self.temp, key) | |
| 528 | + | for key in ("config", "data", "state", "cache", "runtime", "root_cache")} | |
| 529 | + | owner_dirs["owner_log"] = os.path.join(self.temp, "owner.log") | |
| 530 | + | with open(owner_dirs["owner_log"], "w") as handle: | |
| 531 | + | handle.write('{"message":"startup_trace: milestone","milestone":"cef_initialized"}\n') | |
| 532 | + | result = harness.run_sample(binary, self.cef_dir, "relay-window", "static", 1, | |
| 533 | + | owner=self.owner, owner_dirs=owner_dirs, owner_socket=None) | |
| 534 | + | self.assertEqual(result["document_requests"], 1) | |
| 535 | + | self.assertIsNotNone(result["first_document_observation_ms"]) | |
| 536 | + | self.assertGreaterEqual(result["first_document_observation_ms"], 900) | |
| 537 | + | ||
| 538 | + | ||
| 214 | 539 | class ReopenWindowTest(unittest.TestCase): | |
| 215 | 540 | def setUp(self): | |
| 216 | 541 | self.temp = tempfile.mkdtemp() | |
| @@ -268,9 +593,16 @@ class ReopenWindowTest(unittest.TestCase): | |||
| 268 | 593 | self.assertIsNone(harness.proc_starttime(2 ** 30)) | |
| 269 | 594 | ||
| 270 | 595 | def test_child_quiescence_returns_stable_count(self): | |
| 271 | - | count = harness.wait_for_child_quiescence(os.getpid(), settle_seconds=0.2, timeout_seconds=5.0) | |
| 596 | + | count, settled = harness.wait_for_child_quiescence(os.getpid(), settle_seconds=0.2, timeout_seconds=5.0) | |
| 272 | 597 | self.assertIsInstance(count, int) | |
| 273 | 598 | self.assertGreaterEqual(count, 0) | |
| 599 | + | self.assertTrue(settled) | |
| 600 | + | ||
| 601 | + | def test_child_quiescence_timeout_reports_unsettled(self): | |
| 602 | + | count, settled = harness.wait_for_child_quiescence( | |
| 603 | + | os.getpid(), settle_seconds=60.0, timeout_seconds=0.0) | |
| 604 | + | self.assertIsInstance(count, int) | |
| 605 | + | self.assertFalse(settled) | |
| 274 | 606 | ||
| 275 | 607 | def test_reopen_without_owner_falls_back(self): | |
| 276 | 608 | binary = os.path.join(self.temp, "fakebin") | |
| @@ -140,6 +140,17 @@ class CliValidationTest(unittest.TestCase): | |||||
| 140 | capture_output=True, text=True) | 140 | capture_output=True, text=True) | ||
| 141 | self.assertNotEqual(result.returncode, 0) | 141 | self.assertNotEqual(result.returncode, 0) | ||
| 142 | 142 | ||||
| 143 | + | def test_rejects_bad_idle_timeout(self): | |||
| 144 | + | for bad in ("-1", "300001"): | |||
| 145 | + | result = subprocess.run( | |||
| 146 | + | [sys.executable, self.script, "--binary", self.binary, "--cef-dir", self.cef_dir, | |||
| 147 | + | "--scenario", "profile-fresh", "--fixture", "static", | |||
| 148 | + | "--runs", "1", "--idle-timeout-ms", bad, | |||
| 149 | + | "--output", os.path.join(self.temp, "out-idle-" + bad)], | |||
| 150 | + | capture_output=True, text=True) | |||
| 151 | + | self.assertNotEqual(result.returncode, 0) | |||
| 152 | + | self.assertIn("idle-timeout-ms", result.stderr) | |||
| 153 | + | ||||
| 143 | 154 | ||||
| 144 | class FakeBinaryLifetimeTest(unittest.TestCase): | 155 | class FakeBinaryLifetimeTest(unittest.TestCase): | ||
| 145 | def setUp(self): | 156 | def setUp(self): | ||
| @@ -179,6 +190,15 @@ class FakeBinaryLifetimeTest(unittest.TestCase): | |||||
| 179 | self.assertEqual(result["document_requests"], 1) | 190 | self.assertEqual(result["document_requests"], 1) | ||
| 180 | self.assertIsNone(result["target_fcp_ms"]) | 191 | self.assertIsNone(result["target_fcp_ms"]) | ||
| 181 | self.assertFalse(result["complete"]) | 192 | self.assertFalse(result["complete"]) | ||
| 193 | + | # Same-clock spawn-to-request latency is still reported. | |||
| 194 | + | self.assertIsNotNone(result["first_document_observation_ms"]) | |||
| 195 | + | self.assertGreaterEqual(result["first_document_observation_ms"], 0) | |||
| 196 | + | ||||
| 197 | + | def test_no_navigation_means_no_document_observation(self): | |||
| 198 | + | binary = self.make_binary("exit 0") | |||
| 199 | + | result = harness.run_sample(binary, self.cef_dir, "profile-fresh", "static", 1) | |||
| 200 | + | self.assertEqual(result["document_requests"], 0) | |||
| 201 | + | self.assertIsNone(result["first_document_observation_ms"]) | |||
| 182 | 202 | ||||
| 183 | def test_relay_fallback_recorded_without_owner(self): | 203 | def test_relay_fallback_recorded_without_owner(self): | ||
| 184 | binary = self.make_binary("exit 0") | 204 | binary = self.make_binary("exit 0") | ||
| @@ -211,6 +231,311 @@ class FakeBinaryLifetimeTest(unittest.TestCase): | |||||
| 211 | self.assertLess(result["observation_spawn_to_summary_ms"], 15000) | 231 | self.assertLess(result["observation_spawn_to_summary_ms"], 15000) | ||
| 212 | 232 | ||||
| 213 | 233 | ||||
| 234 | + | class ResidencyContractTest(unittest.TestCase): | |||
| 235 | + | def setUp(self): | |||
| 236 | + | self.temp = tempfile.mkdtemp() | |||
| 237 | + | self.cef_dir = os.path.join(self.temp, "cef") | |||
| 238 | + | os.makedirs(self.cef_dir) | |||
| 239 | + | self.dirs = { | |||
| 240 | + | "config": os.path.join(self.temp, "config"), | |||
| 241 | + | "data": os.path.join(self.temp, "data"), | |||
| 242 | + | "state": os.path.join(self.temp, "state"), | |||
| 243 | + | "cache": os.path.join(self.temp, "cache"), | |||
| 244 | + | "runtime": os.path.join(self.temp, "runtime"), | |||
| 245 | + | "root_cache": os.path.join(self.temp, "cef-root-cache"), | |||
| 246 | + | } | |||
| 247 | + | ||||
| 248 | + | def test_scenario_env_forces_json_debug_config(self): | |||
| 249 | + | env = harness.scenario_env(self.cef_dir, self.dirs, idle_timeout_ms=120000) | |||
| 250 | + | self.assertEqual(env["DUMBER_CEF_DIR"], self.cef_dir) | |||
| 251 | + | with open(os.path.join(self.dirs["config"], "dumber", "config.toml")) as handle: | |||
| 252 | + | content = handle.read() | |||
| 253 | + | self.assertIn('format = "json"', content) | |||
| 254 | + | self.assertIn('level = "debug"', content) | |||
| 255 | + | self.assertIn(self.cef_dir, content) | |||
| 256 | + | self.assertIn("idle_runtime_timeout_ms = 120000", content) | |||
| 257 | + | ||||
| 258 | + | def test_scenario_env_defaults_to_no_residency(self): | |||
| 259 | + | harness.scenario_env(self.cef_dir, self.dirs) | |||
| 260 | + | with open(os.path.join(self.dirs["config"], "dumber", "config.toml")) as handle: | |||
| 261 | + | content = handle.read() | |||
| 262 | + | self.assertIn("idle_runtime_timeout_ms = 0", content) | |||
| 263 | + | ||||
| 264 | + | def test_scenario_env_passes_display_vars_only(self): | |||
| 265 | + | os.environ["DUMBER_MEASURE_TEST_MARKER"] = "must-not-propagate" | |||
| 266 | + | try: | |||
| 267 | + | env = harness.scenario_env(self.cef_dir, self.dirs) | |||
| 268 | + | finally: | |||
| 269 | + | del os.environ["DUMBER_MEASURE_TEST_MARKER"] | |||
| 270 | + | self.assertNotIn("DUMBER_MEASURE_TEST_MARKER", env) | |||
| 271 | + | for name in harness.DISPLAY_PASSTHROUGH_VARS: | |||
| 272 | + | if os.environ.get(name): | |||
| 273 | + | self.assertEqual(env[name], os.environ[name]) | |||
| 274 | + | ||||
| 275 | + | def test_wayland_absolute_display_needs_nothing(self): | |||
| 276 | + | previous = os.environ.get("WAYLAND_DISPLAY") | |||
| 277 | + | runtime = os.environ.get("XDG_RUNTIME_DIR", "/run/user/%d" % os.getuid()) | |||
| 278 | + | display = previous or "wayland-1" | |||
| 279 | + | absolute = display if "/" in display else os.path.join(runtime, os.path.basename(display)) | |||
| 280 | + | env = {"WAYLAND_DISPLAY": absolute} | |||
| 281 | + | os.makedirs(self.dirs["runtime"], exist_ok=True) | |||
| 282 | + | self.assertTrue(harness.ensure_wayland_socket(self.dirs["runtime"], env)) | |||
| 283 | + | self.assertEqual(env["WAYLAND_DISPLAY"], absolute) | |||
| 284 | + | self.assertEqual(os.listdir(self.dirs["runtime"]), []) | |||
| 285 | + | ||||
| 286 | + | def test_wayland_relative_display_resolves_to_absolute(self): | |||
| 287 | + | import socket as stdlib_socket | |||
| 288 | + | fake_runtime = os.path.join(self.temp, "real-runtime") | |||
| 289 | + | os.makedirs(fake_runtime) | |||
| 290 | + | sock = stdlib_socket.socket(stdlib_socket.AF_UNIX, stdlib_socket.SOCK_STREAM) | |||
| 291 | + | sock.bind(os.path.join(fake_runtime, "wayland-99")) | |||
| 292 | + | previous_runtime = os.environ.get("XDG_RUNTIME_DIR") | |||
| 293 | + | os.environ["XDG_RUNTIME_DIR"] = fake_runtime | |||
| 294 | + | env = {"WAYLAND_DISPLAY": "wayland-99"} | |||
| 295 | + | try: | |||
| 296 | + | self.assertTrue(harness.ensure_wayland_socket(self.dirs["runtime"], env)) | |||
| 297 | + | self.assertEqual(env["WAYLAND_DISPLAY"], | |||
| 298 | + | os.path.join(fake_runtime, "wayland-99")) | |||
| 299 | + | # No symlink: deep isolated paths exceed the unix-socket limit. | |||
| 300 | + | self.assertNotIn("wayland-99", os.listdir(self.dirs["runtime"])) | |||
| 301 | + | finally: | |||
| 302 | + | if previous_runtime is None: | |||
| 303 | + | os.environ.pop("XDG_RUNTIME_DIR", None) | |||
| 304 | + | else: | |||
| 305 | + | os.environ["XDG_RUNTIME_DIR"] = previous_runtime | |||
| 306 | + | sock.close() | |||
| 307 | + | ||||
| 308 | + | def test_wayland_missing_socket_reports_false(self): | |||
| 309 | + | previous_runtime = os.environ.get("XDG_RUNTIME_DIR") | |||
| 310 | + | os.environ["XDG_RUNTIME_DIR"] = os.path.join(self.temp, "empty-runtime") | |||
| 311 | + | env = {"WAYLAND_DISPLAY": "wayland-does-not-exist"} | |||
| 312 | + | try: | |||
| 313 | + | self.assertFalse(harness.ensure_wayland_socket(self.dirs["runtime"], env)) | |||
| 314 | + | finally: | |||
| 315 | + | if previous_runtime is None: | |||
| 316 | + | os.environ.pop("XDG_RUNTIME_DIR", None) | |||
| 317 | + | else: | |||
| 318 | + | os.environ["XDG_RUNTIME_DIR"] = previous_runtime | |||
| 319 | + | self.assertEqual(env["WAYLAND_DISPLAY"], "wayland-does-not-exist") | |||
| 320 | + | ||||
| 321 | + | def test_count_cef_inits(self): | |||
| 322 | + | init = '{"message":"startup_trace: milestone","milestone":"cef_initialized"}' | |||
| 323 | + | other = '{"message":"startup_trace: milestone","milestone":"process_entry"}' | |||
| 324 | + | noise = '{"message":"cef: InitWithApp returned OK"}' | |||
| 325 | + | self.assertEqual(harness.count_cef_inits([]), 0) | |||
| 326 | + | self.assertEqual(harness.count_cef_inits([other, "not json"]), 0) | |||
| 327 | + | self.assertEqual(harness.count_cef_inits([other, init]), 1) | |||
| 328 | + | self.assertEqual(harness.count_cef_inits([init, noise, init]), 2) | |||
| 329 | + | ||||
| 330 | + | def test_second_window_records_owner_init_count(self): | |||
| 331 | + | binary = os.path.join(self.temp, "fakebin") | |||
| 332 | + | with open(binary, "w") as handle: | |||
| 333 | + | handle.write("#!/bin/sh\nexit 0\n") | |||
| 334 | + | os.chmod(binary, 0o755) | |||
| 335 | + | log_path = os.path.join(self.temp, "owner.log") | |||
| 336 | + | with open(log_path, "w") as handle: | |||
| 337 | + | handle.write('{"message":"startup_trace: milestone","milestone":"cef_initialized"}\n') | |||
| 338 | + | owner_dirs = dict(self.dirs) | |||
| 339 | + | owner_dirs["owner_log"] = log_path | |||
| 340 | + | result = harness.run_sample(binary, self.cef_dir, "relay-window", "static", 1, | |||
| 341 | + | owner=None, owner_dirs=owner_dirs, owner_socket=None) | |||
| 342 | + | self.assertTrue(result["fallback_spawn"]) | |||
| 343 | + | self.assertEqual(result["owner_cef_init_count"], 1) | |||
| 344 | + | ||||
| 345 | + | def test_second_window_missing_owner_log_is_none(self): | |||
| 346 | + | binary = os.path.join(self.temp, "fakebin") | |||
| 347 | + | with open(binary, "w") as handle: | |||
| 348 | + | handle.write("#!/bin/sh\nexit 0\n") | |||
| 349 | + | os.chmod(binary, 0o755) | |||
| 350 | + | owner_dirs = dict(self.dirs) | |||
| 351 | + | owner_dirs["owner_log"] = os.path.join(self.temp, "absent.log") | |||
| 352 | + | result = harness.run_sample(binary, self.cef_dir, "relay-window", "static", 1, | |||
| 353 | + | owner=None, owner_dirs=owner_dirs, owner_socket=None) | |||
| 354 | + | self.assertIsNone(result["owner_cef_init_count"]) | |||
| 355 | + | ||||
| 356 | + | ||||
| 357 | + | class DocumentTokenTest(unittest.TestCase): | |||
| 358 | + | # Document routes must only record and serve correlated requests; | |||
| 359 | + | # beacons already validate tokens, subresources stay ungated. | |||
| 360 | + | def setUp(self): | |||
| 361 | + | self.state = harness.FixtureState() | |||
| 362 | + | cls = harness.make_sample_handler(self.state, "static", "a" * 16, "b" * 16) | |||
| 363 | + | self.server = ThreadingHTTPServer(("127.0.0.1", 0), cls) | |||
| 364 | + | self.port = self.server.server_address[1] | |||
| 365 | + | self.thread = threading.Thread(target=self.server.serve_forever, kwargs={"poll_interval": 0.05}) | |||
| 366 | + | self.thread.daemon = True | |||
| 367 | + | self.thread.start() | |||
| 368 | + | ||||
| 369 | + | def tearDown(self): | |||
| 370 | + | self.server.shutdown() | |||
| 371 | + | self.server.server_close() | |||
| 372 | + | self.thread.join(timeout=5) | |||
| 373 | + | ||||
| 374 | + | def get(self, path): | |||
| 375 | + | url = "http://127.0.0.1:%d%s" % (self.port, path) | |||
| 376 | + | try: | |||
| 377 | + | with urllib.request.urlopen(url, timeout=5) as response: | |||
| 378 | + | return response.status, response.read() | |||
| 379 | + | except urllib.error.HTTPError as exc: | |||
| 380 | + | exc.read() | |||
| 381 | + | return exc.code, b"" | |||
| 382 | + | ||||
| 383 | + | def test_correlated_document_recorded_and_served(self): | |||
| 384 | + | status, body = self.get("/?run=%s&nav=%s" % ("a" * 16, "b" * 16)) | |||
| 385 | + | self.assertEqual(status, 200) | |||
| 386 | + | self.assertIn(b"static", body) | |||
| 387 | + | self.assertEqual(len(self.state.document_requests), 1) | |||
| 388 | + | self.assertIsNotNone(self.state.first_document_monotonic) | |||
| 389 | + | ||||
| 390 | + | def test_wrong_tokens_rejected_without_recording(self): | |||
| 391 | + | status, _ = self.get("/?run=%s&nav=%s" % ("c" * 16, "d" * 16)) | |||
| 392 | + | self.assertEqual(status, 404) | |||
| 393 | + | self.assertEqual(self.state.document_requests, []) | |||
| 394 | + | self.assertIsNone(self.state.first_document_monotonic) | |||
| 395 | + | ||||
| 396 | + | def test_missing_tokens_rejected_without_recording(self): | |||
| 397 | + | status, _ = self.get("/") | |||
| 398 | + | self.assertEqual(status, 404) | |||
| 399 | + | self.assertEqual(self.state.document_requests, []) | |||
| 400 | + | ||||
| 401 | + | def test_redirect_with_bad_tokens_rejected(self): | |||
| 402 | + | status, _ = self.get("/redirect?run=%s&nav=%s" % ("c" * 16, "d" * 16)) | |||
| 403 | + | self.assertEqual(status, 404) | |||
| 404 | + | self.assertEqual(self.state.document_requests, []) | |||
| 405 | + | ||||
| 406 | + | def test_redirect_with_tokens_redirects_once(self): | |||
| 407 | + | opener = urllib.request.build_opener(NoRedirect()) | |||
| 408 | + | url = "http://127.0.0.1:%d/redirect?run=%s&nav=%s" % (self.port, "a" * 16, "b" * 16) | |||
| 409 | + | try: | |||
| 410 | + | opener.open(url, timeout=5) | |||
| 411 | + | self.fail("expected redirect") | |||
| 412 | + | except Redirected as exc: | |||
| 413 | + | self.assertEqual(exc.code, 302) | |||
| 414 | + | self.assertIn("/target?run=%s" % ("a" * 16), exc.headers["Location"]) | |||
| 415 | + | self.assertEqual(len(self.state.document_requests), 1) | |||
| 416 | + | ||||
| 417 | + | def test_handler_state_is_per_sample(self): | |||
| 418 | + | other_state = harness.FixtureState() | |||
| 419 | + | other_cls = harness.make_sample_handler(other_state, "static", "c" * 16, "d" * 16) | |||
| 420 | + | self.assertIsNot(other_cls.state, self.state) | |||
| 421 | + | self.assertNotEqual(other_cls.run_token, "a" * 16) | |||
| 422 | + | ||||
| 423 | + | ||||
| 424 | + | class NoRedirect(urllib.request.HTTPRedirectHandler): | |||
| 425 | + | def redirect_request(self, req, fp, code, msg, headers, newurl): | |||
| 426 | + | raise Redirected(code, headers) | |||
| 427 | + | ||||
| 428 | + | ||||
| 429 | + | class Redirected(Exception): | |||
| 430 | + | def __init__(self, code, headers): | |||
| 431 | + | super().__init__(code) | |||
| 432 | + | self.code = code | |||
| 433 | + | self.headers = headers | |||
| 434 | + | ||||
| 435 | + | ||||
| 436 | + | class ResidencyValidityTest(unittest.TestCase): | |||
| 437 | + | def base_result(self): | |||
| 438 | + | return {"relayed": True, "fallback_spawn": False, "launcher_returncode": 0, | |||
| 439 | + | "owner_cef_init_count": 1, "launcher_cef_init_count": 0} | |||
| 440 | + | ||||
| 441 | + | def test_non_resident_scenario_is_none(self): | |||
| 442 | + | self.assertIsNone(harness.is_residency_valid(self.base_result(), "profile-fresh")) | |||
| 443 | + | ||||
| 444 | + | def test_valid_relay(self): | |||
| 445 | + | self.assertTrue(harness.is_residency_valid(self.base_result(), "relay-window")) | |||
| 446 | + | ||||
| 447 | + | def test_fallback_is_invalid(self): | |||
| 448 | + | result = self.base_result() | |||
| 449 | + | result.update({"relayed": False, "fallback_spawn": True}) | |||
| 450 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |||
| 451 | + | ||||
| 452 | + | def test_launcher_failure_is_invalid(self): | |||
| 453 | + | result = self.base_result() | |||
| 454 | + | result["launcher_returncode"] = 1 | |||
| 455 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |||
| 456 | + | ||||
| 457 | + | def test_launcher_cold_start_is_invalid(self): | |||
| 458 | + | result = self.base_result() | |||
| 459 | + | result["launcher_cef_init_count"] = 1 | |||
| 460 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |||
| 461 | + | ||||
| 462 | + | def test_missing_owner_init_is_invalid(self): | |||
| 463 | + | result = self.base_result() | |||
| 464 | + | result["owner_cef_init_count"] = None | |||
| 465 | + | self.assertFalse(harness.is_residency_valid(result, "relay-window")) | |||
| 466 | + | ||||
| 467 | + | def test_reopen_requires_settled_close_and_same_process(self): | |||
| 468 | + | valid = self.base_result() | |||
| 469 | + | valid["reopen"] = {"close_acknowledged": True, "quiescence_settled": True, | |||
| 470 | + | "same_process": True, "owner_alive_after": True} | |||
| 471 | + | self.assertTrue(harness.is_residency_valid(valid, "reopen-window")) | |||
| 472 | + | for key in ("close_acknowledged", "quiescence_settled", "same_process", "owner_alive_after"): | |||
| 473 | + | broken = self.base_result() | |||
| 474 | + | reopen = {"close_acknowledged": True, "quiescence_settled": True, | |||
| 475 | + | "same_process": True, "owner_alive_after": True} | |||
| 476 | + | reopen[key] = False | |||
| 477 | + | broken["reopen"] = reopen | |||
| 478 | + | self.assertFalse(harness.is_residency_valid(broken, "reopen-window"), key) | |||
| 479 | + | self.assertFalse(harness.is_residency_valid(self.base_result(), "reopen-window")) | |||
| 480 | + | ||||
| 481 | + | def test_toml_escaping_round_trips(self): | |||
| 482 | + | try: | |||
| 483 | + | import tomllib | |||
| 484 | + | except ImportError: | |||
| 485 | + | self.skipTest("tomllib unavailable") | |||
| 486 | + | nasty = "C:\\we\"ird\npath\twith\x01controls\x7f" | |||
| 487 | + | escaped = harness._escape_toml_basic(nasty) | |||
| 488 | + | parsed = tomllib.loads('key = "%s"' % escaped) | |||
| 489 | + | self.assertEqual(parsed["key"], nasty) | |||
| 490 | + | ||||
| 491 | + | ||||
| 492 | + | class LateOwnerRequestTest(unittest.TestCase): | |||
| 493 | + | # Finding 2: a relay launcher may exit right after forwarding while | |||
| 494 | + | # the owner requests the document later. Collection must survive the | |||
| 495 | + | # launcher exit until the bounded navigation deadline. | |||
| 496 | + | def setUp(self): | |||
| 497 | + | self.temp = tempfile.mkdtemp() | |||
| 498 | + | self.cef_dir = os.path.join(self.temp, "cef") | |||
| 499 | + | os.makedirs(self.cef_dir) | |||
| 500 | + | self.saved = {key: os.environ.get(key) for key in | |||
| 501 | + | ("DUMBER_MEASURE_CUTOFF_SECONDS", "DUMBER_MEASURE_NAV_DEADLINE_SECONDS")} | |||
| 502 | + | os.environ["DUMBER_MEASURE_CUTOFF_SECONDS"] = "0.2" | |||
| 503 | + | os.environ["DUMBER_MEASURE_NAV_DEADLINE_SECONDS"] = "4" | |||
| 504 | + | self.owner = subprocess.Popen(["sleep", "30"]) | |||
| 505 | + | self.addCleanup(self.owner.kill) | |||
| 506 | + | ||||
| 507 | + | def tearDown(self): | |||
| 508 | + | for key, value in self.saved.items(): | |||
| 509 | + | if value is None: | |||
| 510 | + | os.environ.pop(key, None) | |||
| 511 | + | else: | |||
| 512 | + | os.environ[key] = value | |||
| 513 | + | try: | |||
| 514 | + | self.owner.wait(timeout=5) | |||
| 515 | + | except subprocess.TimeoutExpired: | |||
| 516 | + | pass | |||
| 517 | + | ||||
| 518 | + | def test_late_document_survives_launcher_exit(self): | |||
| 519 | + | binary = os.path.join(self.temp, "late-launcher") | |||
| 520 | + | with open(binary, "w") as handle: | |||
| 521 | + | handle.write("#!/bin/sh\n" | |||
| 522 | + | 'url="$2"\n' | |||
| 523 | + | '(sleep 1; python3 -c "import sys,urllib.request;' | |||
| 524 | + | ' urllib.request.urlopen(sys.argv[1], timeout=10).read()" "$url") >/dev/null 2>&1 &\n' | |||
| 525 | + | "exit 0\n") | |||
| 526 | + | os.chmod(binary, 0o755) | |||
| 527 | + | owner_dirs = {key: os.path.join(self.temp, key) | |||
| 528 | + | for key in ("config", "data", "state", "cache", "runtime", "root_cache")} | |||
| 529 | + | owner_dirs["owner_log"] = os.path.join(self.temp, "owner.log") | |||
| 530 | + | with open(owner_dirs["owner_log"], "w") as handle: | |||
| 531 | + | handle.write('{"message":"startup_trace: milestone","milestone":"cef_initialized"}\n') | |||
| 532 | + | result = harness.run_sample(binary, self.cef_dir, "relay-window", "static", 1, | |||
| 533 | + | owner=self.owner, owner_dirs=owner_dirs, owner_socket=None) | |||
| 534 | + | self.assertEqual(result["document_requests"], 1) | |||
| 535 | + | self.assertIsNotNone(result["first_document_observation_ms"]) | |||
| 536 | + | self.assertGreaterEqual(result["first_document_observation_ms"], 900) | |||
| 537 | + | ||||
| 538 | + | ||||
| 214 | class ReopenWindowTest(unittest.TestCase): | 539 | class ReopenWindowTest(unittest.TestCase): | ||
| 215 | def setUp(self): | 540 | def setUp(self): | ||
| 216 | self.temp = tempfile.mkdtemp() | 541 | self.temp = tempfile.mkdtemp() | ||
| @@ -268,9 +593,16 @@ class ReopenWindowTest(unittest.TestCase): | |||||
| 268 | self.assertIsNone(harness.proc_starttime(2 ** 30)) | 593 | self.assertIsNone(harness.proc_starttime(2 ** 30)) | ||
| 269 | 594 | ||||
| 270 | def test_child_quiescence_returns_stable_count(self): | 595 | def test_child_quiescence_returns_stable_count(self): | ||
| 271 | - | count = harness.wait_for_child_quiescence(os.getpid(), settle_seconds=0.2, timeout_seconds=5.0) | 596 | + | count, settled = harness.wait_for_child_quiescence(os.getpid(), settle_seconds=0.2, timeout_seconds=5.0) |
| 272 | self.assertIsInstance(count, int) | 597 | self.assertIsInstance(count, int) | ||
| 273 | self.assertGreaterEqual(count, 0) | 598 | self.assertGreaterEqual(count, 0) | ||
| 599 | + | self.assertTrue(settled) | |||
| 600 | + | ||||
| 601 | + | def test_child_quiescence_timeout_reports_unsettled(self): | |||
| 602 | + | count, settled = harness.wait_for_child_quiescence( | |||
| 603 | + | os.getpid(), settle_seconds=60.0, timeout_seconds=0.0) | |||
| 604 | + | self.assertIsInstance(count, int) | |||
| 605 | + | self.assertFalse(settled) | |||
| 274 | 606 | ||||
| 275 | def test_reopen_without_owner_falls_back(self): | 607 | def test_reopen_without_owner_falls_back(self): | ||
| 276 | binary = os.path.join(self.temp, "fakebin") | 608 | binary = os.path.join(self.temp, "fakebin") | ||