Sergio
db24d206dc
Los 180 s de `PISO_SELLO` son de esta máquina (TCG sin KVM y con la carga que tenga el anfitrión, igual que los +97/+120/+137 de la pintura). Con el anfitrión cargado el mismo arranque puede no llegar al gancho que sella el éxito, y entonces la corrida suma al contador de caídas y envenena la siguiente EN SILENCIO — que es exactamente como empezó todo esto. Ahora que `toolkit.startup.last_success` se lee antes y después, eso se puede decir, así que se dice: ✓ el arranque SELLÓ el éxito (last_success X → Y): esta corrida no envenena la siguiente ⚠⚠ el sello NO se movió: este arranque no terminó ⇒ la corrida SUMA al contador. Subí PISO_SELLO Es la diferencia entre un piso confiado y un piso comprobado, y cuesta cuatro líneas porque el dato ya estaba medido y guardado.
766 lines
50 KiB
Python
Executable File
766 lines
50 KiB
Python
Executable File
#!/usr/bin/env python3
|
||
"""atuq-en-imagen.py — arranca la IMAGEN DE DISCO con COSMIC y le pide al navegador que pinte.
|
||
|
||
scripts/cosmic/atuq-en-imagen.py # lanza atuq y fotografía la pantalla
|
||
scripts/cosmic/atuq-en-imagen.py --only-cosmic # control: NO lanza atuq (línea de base)
|
||
|
||
── POR QUÉ ────────────────────────────────────────────────────────────────────────────────────
|
||
El §6.10.ter del SDD 26 dejó esto medido y sin explicar: en la imagen arrancada `atuq` corre —sus
|
||
extensiones sondean, WebRender inicializa— y la ventana NO APARECE, mientras que bajo `sway` headless
|
||
el mismo artefacto pinta. `scripts/cosmic/atuq-en-cosmic.sh` ya sacó una variable de encima:
|
||
**con cosmic-comp NESTEADO (backend winit, GL por software) el navegador pinta**, o sea que no es el
|
||
compositor por sí mismo. Lo que queda es el arranque de verdad: kms/DRM sobre virtio-gpu, el PID1 de
|
||
arje, el seat. Eso sólo se mide acá adentro.
|
||
|
||
La corrida anterior fue A MANO por el serial y no dejó ni un log que se pueda releer. Este guion
|
||
hace lo mismo pero REPETIBLE y con la evidencia guardada: maneja el serial, lanza el navegador con
|
||
`MOZ_LOG` del widget de Wayland, pide capturas por QMP y saca los logs por el serial.
|
||
|
||
── CÓMO HABLA CON LA VM ───────────────────────────────────────────────────────────────────────
|
||
`console-getty` corre `cosmic-start`, que tras su ventana de observación (3 min) hace `exec /bin/sh`
|
||
CON EL ENTORNO DE LA SESIÓN puesto (WAYLAND_DISPLAY, DBUS_SESSION_BUS_ADDRESS). O sea que el shell
|
||
del serial es exactamente desde donde un usuario lanzaría una app — y por eso no hace falta
|
||
reconstruir el entorno a mano, que es como se inventan diferencias que después se confunden con la
|
||
causa.
|
||
"""
|
||
import argparse, json, os, re, shutil, socket, subprocess, sys, time
|
||
|
||
# Sin esto la salida sale por tandas cuando se redirige a un fichero, y una corrida de 20 minutos se
|
||
# lee como si estuviera colgada.
|
||
sys.stdout.reconfigure(line_buffering=True)
|
||
|
||
RAIZ = os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
|
||
IMG = os.environ.get("IMG", "/mnt/cosecha/takana-cosmic-qemu.img")
|
||
OVMF_CODE = os.environ.get("OVMF_CODE", "/usr/share/edk2/x64/OVMF_CODE.4m.fd")
|
||
OVMF_VARS = os.environ.get("OVMF_VARS", "/usr/share/edk2/x64/OVMF_VARS.4m.fd")
|
||
MEM = os.environ.get("MEM", "2560")
|
||
SMP = os.environ.get("SMP", "2")
|
||
|
||
# ⚠ `VGA=1` reproduce el arranque del §6.10.ter, y la diferencia NO es cosmética: sin `-vga none`,
|
||
# QEMU agrega una VGA estándar ADEMÁS del virtio-gpu, OVMF pinta su GOP ahí y el kernel levanta
|
||
# `simpledrm` encima ⇒ el guest ve DOS dispositivos DRM. En el serial se lee tal cual:
|
||
#
|
||
# == cosmic :: kernel 6.16.12 · drm: card0 card1 renderD128 (corrida del §6.10.ter)
|
||
# == cosmic :: kernel 6.16.12 · drm: card0 renderD128 (con -vga none)
|
||
#
|
||
# Un compositor con dos tarjetas puede componer en la que el `screendump` NO muestra. Por eso el
|
||
# default acá es UNA sola (-vga none) y la reproducción del caso original es una opción explícita:
|
||
# son dos mediciones distintas y hay que poder pedir cada una por su nombre.
|
||
# Las dos pantallas van con ID EXPLÍCITO (`vga0`, `gpu0`) y no por el `-vga std` implícito, porque
|
||
# `screendump` de QMP fotografía UN dispositivo y hay que poder pedir cada uno por su nombre: con dos
|
||
# salidas, el compositor puede poner la ventana en la que la captura por defecto NO muestra, y eso se
|
||
# ve exactamente igual que «la ventana no aparece».
|
||
# Segundos desde el lanzamiento del navegador antes de los cuales NO se puede matar la VM sin
|
||
# envenenar el perfil: el sello del arranque (`last_success` + borrado de `recent_crashes`) aparece
|
||
# en disco entre +100 s y +137 s (medido 2026-09-15, `work/cuanto-1.txt`). 180 deja margen sobre la
|
||
# cota alta; es un piso del INSTRUMENTO y no una medida del producto.
|
||
# ⚠ EL PISO DEL SELLO, Y EL NÚMERO QUE LO JUSTIFICA — si esto se lee como elegido, el próximo que
|
||
# lo vea lo baja. Gecko da por bueno un arranque un rato DESPUÉS DEL LANZAMIENTO (no de la primera
|
||
# pintura) y ahí escribe `toolkit.startup.last_success` y limpia `recent_crashes`. Medido el
|
||
# 2026-09-15, leyendo el perfil en cada captura, y acotado por dos corridas independientes:
|
||
#
|
||
# el sello NO estaba a los +100 s (la corrida S1 vivió 100 s desde el lanzamiento y no selló)
|
||
# el sello YA estaba a los +137 s (la corrida `cuanto-1`: last_success pasó a su propia hora)
|
||
#
|
||
# ⇒ el hito cae entre +100 y +137 s, y el 180 es margen sobre la cota alta. Y la consecuencia es
|
||
# contraintuitiva: **cuanto más rápido pinta, MÁS fácil es envenenar el perfil**, porque
|
||
# `--until-paint` corta antes. Una serie sin este piso se rompe sola a la cuarta corrida.
|
||
PISO_SELLO = int(os.environ.get("PISO_SELLO", "180"))
|
||
|
||
DOS_PANTALLAS = os.environ.get("VGA") == "1"
|
||
VGA_ARGS = (["-vga", "none", "-device", "VGA,id=vga0"] if DOS_PANTALLAS else ["-vga", "none"])
|
||
PANTALLAS = ["gpu0", "vga0"] if DOS_PANTALLAS else ["gpu0"]
|
||
|
||
|
||
class Serial:
|
||
"""El serial de la VM. Todo lo que entra queda en el .log crudo, pase lo que pase."""
|
||
|
||
def __init__(self, ruta, log):
|
||
self.log = open(log, "ab", buffering=0)
|
||
for _ in range(120):
|
||
try:
|
||
self.s = socket.socket(socket.AF_UNIX); self.s.connect(ruta); break
|
||
except OSError:
|
||
time.sleep(0.5)
|
||
else:
|
||
raise SystemExit(f"no pude conectarme al serial {ruta}")
|
||
self.s.settimeout(1.0)
|
||
self.buf = b""
|
||
|
||
def leer(self, segundos):
|
||
fin = time.time() + segundos
|
||
while time.time() < fin:
|
||
try:
|
||
d = self.s.recv(65536)
|
||
except socket.timeout:
|
||
continue
|
||
if not d:
|
||
break
|
||
self.buf += d; self.log.write(d)
|
||
return self.buf
|
||
|
||
def esperar(self, marca, segundos, nombre=""):
|
||
"""Lee hasta ver `marca`. Devuelve lo leído desde la llamada anterior."""
|
||
vistos = len(self.buf)
|
||
fin = time.time() + segundos
|
||
while time.time() < fin:
|
||
try:
|
||
d = self.s.recv(65536)
|
||
except socket.timeout:
|
||
continue
|
||
if d:
|
||
self.buf += d; self.log.write(d)
|
||
if marca.encode() in self.buf[vistos:]:
|
||
return self.buf[vistos:].decode("utf-8", "replace")
|
||
print(f" ⚠ nunca llegó «{marca}» {nombre} en {segundos}s", flush=True)
|
||
return self.buf[vistos:].decode("utf-8", "replace")
|
||
|
||
def cmd(self, orden, segundos=30, fondo=False):
|
||
"""Manda una orden y devuelve su salida (delimitada por una marca propia).
|
||
|
||
⚠ DOS TRAMPAS MEDIDAS, las dos hacen que la orden NO CORRA y el guion siga como si nada:
|
||
|
||
· **el terminal hace ECO de lo que se le escribe**, así que una marca escrita literal en la
|
||
línea aparece en el serial ANTES de que el shell ejecute nada: el `esperar` la ve en el eco
|
||
y vuelve al instante, y las órdenes se pisan unas a otras. Por eso la marca se ARMA EN EL
|
||
GUEST partida en dos (`'FIN''-123'`): el eco muestra las comillas y sólo la salida trae la
|
||
marca entera.
|
||
· **`cmd & ; echo …` es un error de sintaxis** en ash: pegarle un `;` a un `&` no lanza nada
|
||
y el shell contesta «syntax error». Lo de fondo va en su propia línea (`fondo=True`).
|
||
"""
|
||
n = int(time.time() * 1000) % 100000
|
||
marca = f"FIN-{n}"
|
||
if fondo:
|
||
self.s.sendall(f"{orden}\n".encode()); time.sleep(0.5)
|
||
self.s.sendall(f"echo 'FIN''-{n}'\n".encode())
|
||
else:
|
||
self.s.sendall(f"{orden}; echo 'FIN''-{n}'\n".encode())
|
||
return self.esperar(marca, segundos, nombre=f"de «{orden[:40]}»")
|
||
|
||
|
||
def capturar(ruta_qmp, out, nombre):
|
||
"""Fotografía CADA pantalla del guest y devuelve {pantalla: fichero}.
|
||
|
||
Con dos salidas hay que mirar las dos: la ventana puede estar viva y dibujando en la que no se
|
||
fotografía, y eso es indistinguible de «no pinta» si sólo se mira una.
|
||
"""
|
||
ficheros = {p: os.path.join(out, f"{nombre}-{p}.ppm") for p in PANTALLAS}
|
||
qmp(ruta_qmp, [{"execute": "screendump", "arguments": {"filename": f, "device": p}}
|
||
for p, f in ficheros.items()])
|
||
return ficheros
|
||
|
||
|
||
def pintado(ppm):
|
||
"""¿Cuántos píxeles de la pantalla son la página de prueba?
|
||
|
||
Se cuenta el magenta con TOLERANCIA, no por color exacto, y la razón está medida: a los ~+590 s
|
||
sin una sola entrada `cosmic-idle` ATENÚA la pantalla y los 703 766 px de `(255,0,255)` pasan a
|
||
703 779 px de `(117,0,117)` —la misma ventana al 46 % de brillo—. Un contador por color exacto
|
||
lee eso como «desapareció la ventana», que es justo el error que este guion existe para no
|
||
cometer.
|
||
"""
|
||
try:
|
||
from PIL import Image
|
||
except Exception:
|
||
return None
|
||
im = Image.open(ppm).convert("RGB")
|
||
return sum(n for n, (r, g, b) in im.getcolors(1 << 24) if r > 90 and b > 90 and g < 40)
|
||
|
||
|
||
def leer_contador_de_caidas(texto):
|
||
"""Saca el valor de `toolkit.startup.recent_crashes` de un volcado de `prefs.js`.
|
||
|
||
Devuelve `None` si el pref NO ESTÁ, que no es lo mismo que un 0 puesto a mano: «no está» es el
|
||
estado de un perfil cuyo arranque terminó bien —y es también lo que deja Gecko DESPUÉS de
|
||
mostrar el diálogo de Modo de resolución de problemas, que es la razón por la que la corrida
|
||
siguiente «se arregla sola» y la anterior parece intermitente.
|
||
|
||
Filtra por `user_pref` a propósito: el serial hace eco de la propia orden `grep`, y esa línea
|
||
contiene el nombre del pref sin su valor.
|
||
"""
|
||
for linea in texto.splitlines():
|
||
if "user_pref" in linea and "toolkit.startup.recent_crashes" in linea:
|
||
m = re.search(r"recent_crashes\"?\s*,\s*(-?\d+)", linea)
|
||
if m:
|
||
return int(m.group(1))
|
||
return None
|
||
|
||
|
||
def leer_sello_de_exito(texto):
|
||
"""Saca `toolkit.startup.last_success` de un volcado de `prefs.js`.
|
||
|
||
Es la OTRA MITAD del cálculo del contador de caídas: el contador sube mientras este sello no se
|
||
mueve, así que un contador que no cambió sólo deja de ser ambiguo —«no subió» contra «subió y se
|
||
limpió»— si se lee junto con el sello. Medido el 2026-09-15: pasó un día entero sin moverse.
|
||
"""
|
||
for linea in texto.splitlines():
|
||
if "user_pref" in linea and "toolkit.startup.last_success" in linea:
|
||
m = re.search(r"last_success\"?\s*,\s*(\d+)", linea)
|
||
if m:
|
||
return int(m.group(1))
|
||
return None
|
||
|
||
|
||
def anotar_medicion(segundos, a, pantalla=None, extra=None):
|
||
"""Deja el tiempo de primera pintura en `docs/state/primera-pintura.json`.
|
||
|
||
Va al estado del repo y no a un log porque quien pregunta «¿esta imagen se puede usar?» es
|
||
`scripts/vigia-imagen.py`, que mira artefactos y no arranca ninguna VM: el número tiene que
|
||
llegarle por escrito o no le llega. Se guarda TODO lo que lo hace comparable —cómo se lanzó, con
|
||
qué vídeo, con cuánta RAM y cuántos cores— porque el tiempo depende de eso y de la carga de la
|
||
máquina anfitriona; un número sin sus condiciones invita a leerlo como si fuera del producto.
|
||
"""
|
||
dato = {
|
||
"medido": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()),
|
||
"imagen": IMG,
|
||
"segundos_primera_pintura": segundos, # None = no pintó dentro de la ventana
|
||
"pantalla": pantalla, # EN CUÁL de las salidas apareció (medido 2026-09-14:
|
||
# con dos, la ventana cae en cualquiera de las dos)
|
||
"pantallas_fotografiadas": len(PANTALLAS), # con 1 y dos salidas, un ✗ NO es concluyente
|
||
"presupuesto_s": a.budget,
|
||
"ventana_s": a.wait,
|
||
"cadencia_s": a.cadence, # la RESOLUCIÓN del número: ±cadencia
|
||
"lanzamiento": "perfil del usuario" if a.as_user else "perfil nuevo en tmpfs",
|
||
"video": "vga+virtio-gpu (dos DRM)" if DOS_PANTALLAS else "virtio-gpu solo (-vga none)",
|
||
"mem_mb": int(MEM), "vcpus": int(SMP), "acel": "tcg",
|
||
"guion": "scripts/cosmic/atuq-en-imagen.py",
|
||
}
|
||
# ⚠ EL CONTADOR DE CAÍDAS DEL PERFIL VIAJA CON LA MEDICIÓN, y es lo que hace legible la serie:
|
||
# con `toolkit.startup.recent_crashes` por encima de 3 el sujeto de la corrida NO es el
|
||
# navegador sino el diálogo de Modo de resolución de problemas (§6.10.terdecies), así que un ✗
|
||
# de esas corridas no dice nada del producto. Sin este campo, una tasa cierta se lee como si
|
||
# fuera del navegador — que es exactamente lo que pasó con «3 de 13» y «2 de 10».
|
||
dato.update(extra or {})
|
||
# ⚠ SE ACUMULAN, NO SE PISAN. Medido el 2026-09-14: dos corridas IDÉNTICAS (mismo comando,
|
||
# misma imagen) dieron «+204 s» y «no pintó en 900 s». Un fichero de UNA medición convierte un
|
||
# fenómeno intermitente en el número que le tocó a la última corrida, que es la forma más cara
|
||
# de mentir con datos ciertos.
|
||
destino = os.path.join(RAIZ, "docs/state/primera-pintura.json")
|
||
try:
|
||
historia = {"corridas": []}
|
||
if os.path.exists(destino):
|
||
with open(destino) as f:
|
||
historia = json.load(f)
|
||
historia.setdefault("corridas", []).append(dato)
|
||
historia["corridas"] = historia["corridas"][-30:]
|
||
os.makedirs(os.path.dirname(destino), exist_ok=True)
|
||
with open(destino, "w") as f:
|
||
json.dump(historia, f, indent=2, ensure_ascii=False)
|
||
f.write("\n")
|
||
pintaron = [c for c in historia["corridas"] if c.get("segundos_primera_pintura") is not None]
|
||
print(" anotada en docs/state/primera-pintura.json — %d de %d corridas pintaron"
|
||
% (len(pintaron), len(historia["corridas"])))
|
||
except (OSError, ValueError) as e:
|
||
print(f" ⚠ no pude anotar la medición: {e}")
|
||
|
||
|
||
def qmp(ruta, ordenes):
|
||
s = socket.socket(socket.AF_UNIX); s.settimeout(30); s.connect(ruta)
|
||
f = s.makefile("rwb", buffering=0)
|
||
f.readline() # greeting
|
||
f.write(b'{"execute":"qmp_capabilities"}\n'); f.readline()
|
||
salidas = []
|
||
for o in ordenes:
|
||
f.write(json.dumps(o).encode() + b"\n"); salidas.append(f.readline())
|
||
s.close()
|
||
return salidas
|
||
|
||
|
||
def main():
|
||
ap = argparse.ArgumentParser()
|
||
ap.add_argument("--only-cosmic", action="store_true", help="control: no lanza el navegador")
|
||
ap.add_argument("--as-user", action="store_true",
|
||
help="lanza `atuq` a secas —perfil por defecto, sin MOZ_ENABLE_WAYLAND— como se hizo a mano en el §6.10.ter")
|
||
ap.add_argument("--wait", type=int, default=600, help="segundos de observación como máximo")
|
||
ap.add_argument("--cadence", type=int, default=30, help="segundos entre capturas (la resolución de la medida)")
|
||
ap.add_argument("--budget", type=int, default=420,
|
||
help="segundos que puede tardar la primera pintura antes de dar ✗")
|
||
ap.add_argument("--until-paint", action="store_true",
|
||
help="cortar la observación en cuanto la página aparezca (más barato para medir el tiempo)")
|
||
ap.add_argument("--wayland-debug", action="store_true",
|
||
help="lanza el navegador con WAYLAND_DEBUG=1: registra CADA mensaje del "
|
||
"protocolo en los dos sentidos. Es la única forma de ver qué MANDA el "
|
||
"compositor sin recompilarlo (sus macros de debug están compiladas fuera)")
|
||
ap.add_argument("--set-rust-log", metavar="VALOR",
|
||
help="escribe RUST_LOG en /etc/cosmic-mode de la IMAGEN y apaga; "
|
||
"cadena vacía = lo quita. El compositor lo lee en el arranque SIGUIENTE, "
|
||
"que es la única forma de subirle el nivel de log sin recompilar")
|
||
ap.add_argument("--crashes", type=int, metavar="N",
|
||
help="fija `toolkit.startup.recent_crashes` del perfil del usuario antes de "
|
||
"lanzar: 0 lo limpia, 4 o más reproduce el diálogo de Modo de resolución "
|
||
"de problemas (medido: con 3 guardado todavía pinta, porque el arranque "
|
||
"suma ANTES de comparar). Sólo tiene efecto con --as-user. ⚠ 0 es el valor "
|
||
"por DEFECTO y un pref igual al default no se persiste: si lo que querés "
|
||
"medir es quién limpia el contador, NO lo pinnees")
|
||
ap.add_argument("--xulstore", metavar="ANCHOxALTO",
|
||
help="agrega una SEGUNDA fase en el mismo arranque con `xulstore.json` sembrado "
|
||
"(p. ej. 1152x720): la ventana arranca con un tamaño YA PERSISTIDO. Es el "
|
||
"control del 117x70 — si con semilla sale grande, lo que falla es que nadie "
|
||
"le da tamaño en el primer arranque")
|
||
ap.add_argument("--watch-prefs", action="store_true",
|
||
help="en CADA captura lee también `recent_crashes` y `last_success` del perfil y "
|
||
"los imprime con el segundo. Es lo que mide CUÁNTO tarda un arranque en "
|
||
"darse por bueno: el valor de `last_success` es la hora de ARRANQUE, no la "
|
||
"de escritura, así que el momento en que cambia sólo se sabe mirándolo "
|
||
"seguido. Ignora `--until-paint`: lo interesante pasa DESPUÉS de pintar")
|
||
ap.add_argument("--repeat", type=int, metavar="N",
|
||
help="corre N fases IDÉNTICAS en el mismo arranque. Con `--wait` corto (60 s, o "
|
||
"sea antes de que pinte) mide el contador de caídas: cada fase lee "
|
||
"`recent_crashes` ANTES de lanzar, así que la serie 0,1,2… dice cuánto suma "
|
||
"un arranque interrumpido — y si no sube, el envenenamiento vino de otro lado")
|
||
ap.add_argument("--out", default=os.path.join(RAIZ, "work/atuq-imagen"))
|
||
a = ap.parse_args()
|
||
|
||
rc = [0] # lista para poder tocarlo desde dentro del try/finally
|
||
out = a.out; os.makedirs(out, exist_ok=True)
|
||
vars_fd = os.path.join(out, "OVMF_VARS.fd")
|
||
shutil.copy(OVMF_VARS, vars_fd)
|
||
ser_sock, qmp_sock = os.path.join(out, "serial.sock"), os.path.join(out, "qmp.sock")
|
||
for p in (ser_sock, qmp_sock):
|
||
if os.path.exists(p):
|
||
os.unlink(p)
|
||
|
||
qemu = [
|
||
"nice", "-n", "10", "qemu-system-x86_64",
|
||
"-machine", "q35", "-accel", "tcg", "-cpu", "max", "-m", MEM, "-smp", SMP,
|
||
*VGA_ARGS, "-device", "virtio-gpu-pci,id=gpu0", "-display", "none", "-nic", "none",
|
||
"-drive", f"if=pflash,format=raw,unit=0,file={OVMF_CODE},readonly=on",
|
||
"-drive", f"if=pflash,format=raw,unit=1,file={vars_fd}",
|
||
"-drive", f"file={IMG},format=raw,if=virtio",
|
||
"-serial", f"unix:{ser_sock},server,nowait",
|
||
"-qmp", f"unix:{qmp_sock},server,nowait",
|
||
"-no-reboot",
|
||
]
|
||
print("== arrancando la imagen (TCG, sin KVM — paciencia)")
|
||
|
||
def primero_en_la_fila():
|
||
# El repo es COMPARTIDO y casi siempre hay una tanda de la granja compilando en esta misma
|
||
# máquina (4 cores, 7,6 G). Si la RAM se acaba, el que tiene que morir es ESTA VM y no el
|
||
# build de otro agente: `oom_score_adj` alto es la única forma de decirlo por adelantado.
|
||
with open("/proc/self/oom_score_adj", "w") as f:
|
||
f.write("900")
|
||
|
||
vm = subprocess.Popen(qemu, stdout=open(os.path.join(out, "qemu.log"), "wb"),
|
||
stderr=subprocess.STDOUT, preexec_fn=primero_en_la_fila)
|
||
# ⚠ QEMU TOMA UN LOCK DE ESCRITURA SOBRE LA IMAGEN, y sin esta comprobación el arnés espera
|
||
# 600 s una marca del serial que no va a llegar NUNCA: el socket queda creado, el `connect()`
|
||
# funciona y no falla nada — el error es UNA línea en `qemu.log` que nadie mira. Medido el
|
||
# 2026-09-15 al lanzar el control negativo con la corrida anterior todavía viva:
|
||
# Failed to get "write" lock. Is another process using the image [...]?
|
||
# Las corridas sobre la misma imagen van EN SERIE; esto lo dice en el primer segundo.
|
||
time.sleep(2)
|
||
if vm.poll() is not None:
|
||
raise SystemExit("✗ QEMU no arrancó:\n " +
|
||
open(os.path.join(out, "qemu.log")).read().strip())
|
||
|
||
try:
|
||
ser = Serial(ser_sock, os.path.join(out, "serial.log"))
|
||
print("== esperando a COSMIC…", flush=True)
|
||
ser.esperar("compositor OK", 600, nombre="(arranque de cosmic-comp)")
|
||
print(" compositor arriba; esperando el shell del serial (ventana de observación)", flush=True)
|
||
# 420 s alcanzaban con el anfitrión ocioso y NO con carga ~13: la VM llegaba a «+15s» y el
|
||
# arnés se rendía antes de que `cosmic-start` soltara el shell. El margen es de espera, no de
|
||
# medida: subirlo no cambia ningún número, sólo deja de tirar corridas por carga ajena.
|
||
ser.esperar("fin de la ventana de observación", 780, nombre="(fin de observación)")
|
||
time.sleep(3)
|
||
ser.s.sendall(b"\n")
|
||
print(ser.cmd("echo ENTORNO: WD=$WAYLAND_DISPLAY XDG=$XDG_RUNTIME_DIR DBUS=$DBUS_SESSION_BUS_ADDRESS").strip())
|
||
print(ser.cmd("ls -l $XDG_RUNTIME_DIR; ls /usr/lib/dri").strip())
|
||
|
||
if a.set_rust_log is not None:
|
||
# `cosmic-start` hace `. /etc/cosmic-mode` ANTES de `export RUST_LOG="${RUST_LOG:-info}"`,
|
||
# así que el fichero es la perilla. Se escribe y se apaga: quien la usa es el arranque
|
||
# siguiente — el compositor de ESTA sesión ya arrancó y no se lo puede reconfigurar.
|
||
ser.cmd("grep -v '^RUST_LOG=' /etc/cosmic-mode > /tmp/cm 2>/dev/null; true")
|
||
if a.set_rust_log:
|
||
ser.cmd("printf '%%s\\n' \"RUST_LOG=%s\" >> /tmp/cm" % a.set_rust_log)
|
||
ser.cmd("cp /tmp/cm /etc/cosmic-mode && sync")
|
||
print("== /etc/cosmic-mode ahora dice:")
|
||
print(ser.cmd("cat /etc/cosmic-mode").strip())
|
||
return
|
||
|
||
capturar(qmp_sock, out, "antes")
|
||
print("== captura ANTES (%s)" % ", ".join(PANTALLAS), flush=True)
|
||
|
||
if a.only_cosmic:
|
||
print("== CONTROL: no se lanza el navegador")
|
||
else:
|
||
# Una página de un color imposible de confundir con el escritorio.
|
||
ser.cmd("mkdir -p /var/log/cosmic")
|
||
# La página además DICE, por `dump()`, qué tamaño cree que tiene la ventana y qué
|
||
# pantalla ve el navegador. Con `screen=` y `outer=` en el log se sabe si el navegador
|
||
# ve la pantalla o no — y desde el §6.10.terdecies sabemos que SÍ la ve, así que lo que
|
||
# queda por contar es el otro lado: qué tamaño cree tener la VENTANA. Sin comillas
|
||
# simples: va dentro de un `printf '%s' '...'`.
|
||
ser.cmd("printf '%s' '<!doctype html><body style=\"margin:0;background:#ff00ff\">"
|
||
"<h1 style=\"font:40px monospace\">ATUQ PINTA</h1><script>"
|
||
"function diag(t){dump(\"ATUQ-DIAG \"+t+\" screen=\"+screen.width+\"x\"+screen.height"
|
||
"+\" avail=\"+screen.availWidth+\"x\"+screen.availHeight"
|
||
"+\" outer=\"+outerWidth+\"x\"+outerHeight"
|
||
"+\" inner=\"+innerWidth+\"x\"+innerHeight"
|
||
"+\" dpr=\"+devicePixelRatio+\"\\n\");}"
|
||
"addEventListener(\"load\",function(){diag(\"load\");"
|
||
"setTimeout(function(){diag(\"t10\");},10000);"
|
||
"setTimeout(function(){diag(\"t60\");},60000);});"
|
||
"</script>' > /tmp/pagina.html")
|
||
|
||
# ⚠ LO QUE DEJÓ LA CORRIDA ANTERIOR, ANTES DE PISARLO. El disco de esta VM es
|
||
# PERSISTENTE (`-drive` sin `snapshot=on`) ⇒ `/var/log/cosmic/` todavía tiene el
|
||
# arranque anterior, y el lanzamiento de esta corrida lo trunca. Ahí es donde salen los
|
||
# errores de JS del chrome, y NUNCA se habían mirado: se leía `tail -25`, que con
|
||
# `WAYLAND_DEBUG` son 25 líneas de protocolo y nada más. Copiarlo primero cuesta nada.
|
||
ser.cmd("rm -rf /var/log/cosmic-anterior; cp -a /var/log/cosmic /var/log/cosmic-anterior "
|
||
"2>/dev/null; true", 120)
|
||
print("---- corrida ANTERIOR: cómo terminó y qué se quejó ----")
|
||
print(ser.cmd("grep -a -h -E 'ATUQ-EXIT|JavaScript error|Uncaught|NS_ERROR|"
|
||
"###!!!|\\[Parent\\].*ERROR' /var/log/cosmic-anterior/atuq*.log "
|
||
"2>/dev/null | head -20", 120))
|
||
# DÓNDE VIVE EL PERFIL, SIN ADIVINARLO. El `find` anterior miraba sólo `/root` y esta
|
||
# imagen lo desmintió en silencio: dijo «no encontré el perfil» y la sonda salió muda.
|
||
# `$HOME` lo decide todo y el shell del serial lo hereda de `cosmic-start`, así que se
|
||
# IMPRIME; y el `find` va sobre la raíz entera con `-xdev` (que deja fuera /proc y /sys).
|
||
print("== HOME del shell de la sesión y perfiles que ya existen en el disco:")
|
||
print(ser.cmd("echo HOME=$HOME; find / -xdev -maxdepth 7 -name prefs.js 2>/dev/null | head -5", 180))
|
||
|
||
def perfil_de_la_fase(semilla):
|
||
"""Deja el perfil listo para la fase y devuelve su directorio (o None).
|
||
|
||
Las dos formas de lanzar NO son el mismo experimento y por eso conviven: el modo por
|
||
defecto usa un perfil NUEVO en tmpfs —primer arranque de verdad, que es el caso que
|
||
sale 117×70— y `--as-user` reproduce lo que se tecleó a mano en el §6.10.ter, con el
|
||
perfil del usuario y sin variables de entorno.
|
||
"""
|
||
if a.as_user:
|
||
hallado = ser.cmd("find / -xdev -maxdepth 7 -name prefs.js 2>/dev/null | head -3", 180)
|
||
perfil = next((l.strip() for l in hallado.splitlines()
|
||
if l.strip().endswith("prefs.js") and l.strip().startswith("/")), None)
|
||
if not perfil:
|
||
print(" ⚠ no encontré el perfil del usuario: la sonda ATUQ-DIAG va a salir muda")
|
||
return None
|
||
d = os.path.dirname(perfil)
|
||
print("== perfil del usuario:", d)
|
||
# ⚠⚠ EL CONTADOR DE CAÍDAS DEL PERFIL, SIEMPRE A LA VISTA. Con
|
||
# `toolkit.startup.recent_crashes` por encima de `max_resumed_crashes` (3 por
|
||
# defecto) el navegador NO abre el navegador: abre el diálogo de Modo de
|
||
# resolución de problemas. Y este arnés mata la VM con el navegador vivo, así
|
||
# que CADA corrida fallida puede sumar uno: el instrumento degrada el sujeto y
|
||
# la tasa medida deja de ser del producto. Sin este número impreso, una corrida
|
||
# no se puede interpretar.
|
||
# ⚠ `last_success` VA EN EL MISMO VOLCADO. Es la otra mitad del cálculo: sin
|
||
# él, un `recent_crashes` que no se movió es ambiguo entre «no subió» y «subió y
|
||
# lo limpió el gancho de cierre», que son conclusiones opuestas sobre la misma
|
||
# cifra.
|
||
volcado = ser.cmd("grep -E 'toolkit.startup.(recent_crashes|max_resumed|"
|
||
"last_success)|browser.sessionstore.max_resumed' %s/prefs.js" % d, 60)
|
||
print(volcado.strip())
|
||
estado["recent_crashes_antes"] = leer_contador_de_caidas(volcado)
|
||
estado["last_success_antes"] = leer_sello_de_exito(volcado)
|
||
# ⚠ EL AVISO QUE FALTABA. Medido el 2026-09-15: el arranque que encuentra el
|
||
# anterior sin terminar SUMA UNO y compara DESPUÉS, así que con 3 guardado esta
|
||
# corrida abre el diálogo de Modo de resolución de problemas y no el navegador —
|
||
# y como el arnés mata la VM antes del gancho de cierre, CADA corrida suma.
|
||
# Una serie se rompe sola a la cuarta; por eso se dice acá y no en el post-mortem.
|
||
previo = estado["recent_crashes_antes"]
|
||
if previo is not None and previo >= 3 and a.crashes is None:
|
||
print(" ⚠⚠ contador en %d: ESTA corrida va a abrir el DIÁLOGO, no el "
|
||
"navegador. Para medir la pintura, pasá --crashes 0" % previo)
|
||
else:
|
||
d = "/tmp/perfil"
|
||
ser.cmd("rm -rf /tmp/perfil && mkdir -p /tmp/perfil")
|
||
ujs = ['user_pref("browser.dom.window.dump.enabled", true);',
|
||
'user_pref("browser.shell.checkDefaultBrowser", false);']
|
||
if a.crashes is not None:
|
||
# El mismo mando en los DOS sentidos: 0 limpia el contador (¿pinta?) y un
|
||
# número alto lo reproduce a propósito (¿se rompe?). `user.js` gana sobre
|
||
# `prefs.js` en cada arranque, así que fija el valor de la corrida.
|
||
ujs.append('user_pref("toolkit.startup.recent_crashes", %d);' % a.crashes)
|
||
print("== recent_crashes FIJADO a %d para esta corrida" % a.crashes)
|
||
ser.cmd("rm -f %s/user.js" % d)
|
||
for linea in ujs:
|
||
ser.cmd("printf '%%s\\n' '%s' >> %s/user.js" % (linea, d))
|
||
if semilla:
|
||
# EL CONTROL. `browser-init.js` —el que trae el propio artefacto, leído del
|
||
# `omni.ja` sellado— fija el tamaño de arranque UNA sola vez:
|
||
#
|
||
# } else if (!document.documentElement.hasAttribute("width")) {
|
||
# let width = Math.min(screen.availWidth * 0.9, 1280);
|
||
# let height = Math.min(screen.availHeight * 0.9, 1040);
|
||
#
|
||
# y ese atributo, en un perfil ya usado, lo rellena el `xulstore.json`. Sembrarlo
|
||
# a mano separa las dos explicaciones posibles del 117×70 en UNA corrida: si con
|
||
# semilla la ventana sale grande, el fallo es «nadie le dio tamaño» (ese `if` no
|
||
# corrió); si sale igual de chica, el tamaño no es lo que falla.
|
||
w, h = semilla.lower().split("x")
|
||
doc = {"chrome://browser/content/browser.xhtml":
|
||
{"main-window": {"screenX": "0", "screenY": "0",
|
||
"width": w, "height": h, "sizemode": "normal"}}}
|
||
ser.cmd("printf '%%s' '%s' > %s/xulstore.json" % (json.dumps(doc), d))
|
||
elif not a.as_user:
|
||
# Sólo en el perfil DESECHABLE de tmpfs. ⚠ En `--as-user` el `xulstore.json` es
|
||
# el estado del usuario —el tamaño que la ventana RECUERDA— y borrarlo cambiaría
|
||
# el experimento sin decirlo: la corrida siguiente ya no sería «como lo abre el
|
||
# usuario» sino un primer arranque disfrazado.
|
||
ser.cmd("rm -f %s/xulstore.json" % d)
|
||
ser.cmd("sync")
|
||
print("== el perfil, ANTES de lanzar (user.js y el tamaño que RECUERDA):")
|
||
print(ser.cmd("cat %s/user.js; echo ---; cat %s/xulstore.json 2>/dev/null || "
|
||
"echo '(sin xulstore.json: la ventana no recuerda ningún tamaño)'"
|
||
% (d, d), 60).strip())
|
||
return d
|
||
|
||
def matar_al_navegador():
|
||
"""Deja la sesión sin ningún `atuq` vivo antes de la fase siguiente.
|
||
|
||
Por PID leído de `/proc/*/comm`, no por `pkill -f atuq`: el patrón engancha la propia
|
||
línea de orden del shell del serial y ahí se mata la sesión entera (medido en el hub,
|
||
sale 144 y lo que sigue no corre).
|
||
"""
|
||
# ⚠ `-9` A PROPÓSITO. Un `kill` a secas le da a Gecko su apagado ordenado, y un
|
||
# apagado ordenado es EXACTAMENTE la variable bajo prueba: lo que hace este arnés al
|
||
# terminar es matar la VM entera, que no avisa. Con `-KILL` la fase siguiente
|
||
# encuentra el mismo estado que encontraría tras una corrida matada de verdad.
|
||
ser.cmd("for p in /proc/[0-9]*; do grep -q atuq $p/comm 2>/dev/null && "
|
||
"kill -9 ${p#/proc/}; done; true", 60)
|
||
time.sleep(8)
|
||
salida = ser.cmd("for c in /proc/[0-9]*/comm; do cat $c 2>/dev/null; done | grep -c atuq")
|
||
# El serial hace ECO de la orden, así que la respuesta es la ÚLTIMA línea que sea un
|
||
# número y no la primera que aparezca: leer la primera devuelve un trozo del eco.
|
||
cuenta = next((l.strip() for l in reversed(salida.splitlines()) if l.strip().isdigit()), "?")
|
||
print(" navegadores vivos tras el kill: " + cuenta)
|
||
|
||
# LAS FASES. Una sola es la medición de siempre; con `--xulstore` se agrega una SEGUNDA
|
||
# en el MISMO arranque, que es un A/B de verdad: mismo compositor, misma sesión, misma
|
||
# carga del anfitrión. Dos arranques distintos no lo serían — y cada arranque cuesta
|
||
# cinco minutos de TCG.
|
||
# El estado del perfil que hay que ADJUNTAR a la medición: el contador de caídas antes
|
||
# y después. Vive acá afuera porque lo escribe la preparación de la fase y lo lee la
|
||
# anotación, y porque con `--crashes` fijado hay que poder distinguir el valor que
|
||
# PUSIMOS del que el perfil traía.
|
||
estado = {"recent_crashes_fijado": a.crashes}
|
||
|
||
fases = [("base", None)]
|
||
if a.xulstore:
|
||
fases.append(("semilla-%s" % a.xulstore, a.xulstore))
|
||
if a.repeat:
|
||
# N fases iguales: lo que varía entre ellas no es la configuración sino el ESTADO que
|
||
# deja la anterior en el perfil, que es justo lo que se quiere medir.
|
||
fases = [("k%d" % i, None) for i in range(1, a.repeat + 1)]
|
||
|
||
for fase, semilla in fases:
|
||
print("\n===== FASE «%s» =====" % fase, flush=True)
|
||
if fase != fases[0][0]:
|
||
matar_al_navegador()
|
||
perfil_d = perfil_de_la_fase(semilla)
|
||
log_atuq = "/var/log/cosmic/atuq-%s.log" % fase
|
||
log_moz = "/var/log/cosmic/moz-%s" % fase
|
||
capturar(qmp_sock, out, "%s-antes" % fase)
|
||
print("== captura ANTES de la fase (%s)" % ", ".join(PANTALLAS), flush=True)
|
||
|
||
wd = "WAYLAND_DEBUG=1 " if a.wayland_debug else ""
|
||
moz = ("MOZ_LOG='Widget:5,WidgetWayland:5,WaylandBackend:5,WidgetScreen:5,timestamp' "
|
||
"MOZ_LOG_FILE=%s " % log_moz)
|
||
if a.as_user:
|
||
orden = wd + moz + "/usr/bin/atuq file:///tmp/pagina.html"
|
||
else:
|
||
orden = (wd + "MOZ_ENABLE_WAYLAND=1 GDK_BACKEND=wayland " + moz +
|
||
"/usr/bin/atuq --no-remote --profile /tmp/perfil file:///tmp/pagina.html")
|
||
# ⚠ EL NAVEGADOR SE MURIÓ Y NADIE LO SUPO (medido 2026-09-15, 17:12): el shell
|
||
# imprimió «[1]+ Done» a los ~25 s y la corrida siguió 420 s fotografiando un
|
||
# escritorio sin navegador, para terminar diciendo «no pintó». Un proceso que sale
|
||
# deja un CÓDIGO, y ese código es la diferencia entre «se cayó» y «se fue solo»; va
|
||
# al log, en el subshell, para que quede escrito aunque el arnés muera después.
|
||
print(ser.cmd("( %s; echo ATUQ-EXIT=$? ) > %s 2>&1 &" % (orden, log_atuq), fondo=True).strip())
|
||
print(f"== navegador lanzado; observando {a.wait}s", flush=True)
|
||
t0 = time.time(); n = 0
|
||
primera = None # segundos hasta la PRIMERA captura con la página en pantalla
|
||
donde = None
|
||
while time.time() - t0 < a.wait:
|
||
time.sleep(a.cadence); n += 1
|
||
tomas = capturar(qmp_sock, out, f"{fase}-durante-{n}")
|
||
t = int(time.time() - t0)
|
||
medidas = {p: pintado(f) for p, f in tomas.items()}
|
||
px = max((v for v in medidas.values() if v is not None), default=None)
|
||
donde = next((p for p, v in medidas.items() if v and v > 100_000), None)
|
||
vigilancia = ""
|
||
if a.watch_prefs and perfil_d:
|
||
# Una sola lectura, corta, por captura. `tr` junta las dos líneas para que
|
||
# entren en el renglón del avance: lo que importa es CUÁNDO cambian.
|
||
vigilancia = " prefs: " + " ".join(
|
||
l.strip() for l in ser.cmd(
|
||
"grep -hE 'toolkit.startup.(recent_crashes|last_success)' "
|
||
"%s/prefs.js | tr -d '\"' | tr '\\n' ' '" % perfil_d, 60).splitlines()
|
||
if "toolkit.startup" in l and "grep" not in l)
|
||
if primera is None and px and px > 100_000:
|
||
primera = t
|
||
print(f" +{t}s ██ PRIMERA PINTURA — {px} px de la página EN {donde}{vigilancia}", flush=True)
|
||
# ⚠ NO SE CORTA ANTES DEL SELLO, Y ESTO ES MEDIDO (2026-09-15). Gecko
|
||
# marca el arranque como bueno —escribe `toolkit.startup.last_success` y
|
||
# BORRA `recent_crashes`— y eso llega al disco entre los +100 s y los +137 s
|
||
# desde el lanzamiento (`work/cuanto-1.txt`, leyendo el perfil en cada
|
||
# captura). El reloj es el del ARRANQUE, no el de la pintura: `cierre-1`
|
||
# pintó a +120 s y selló, y la S1 de la serie pintó a +97 s, se cortó con
|
||
# `--until-paint` y dejó el contador en 1. Cortar en la pintura mata la VM
|
||
# antes del sello, y CADA corrida así suma uno: cuatro y el perfil abre el
|
||
# diálogo en vez del navegador. El piso es la diferencia entre medir el
|
||
# producto y medir el daño que hace el instrumento.
|
||
if a.until_paint and not a.watch_prefs and t >= PISO_SELLO:
|
||
break
|
||
if a.until_paint and t < PISO_SELLO:
|
||
print(f" (sigo hasta +{PISO_SELLO}s: antes de eso el arranque no está "
|
||
f"sellado y matar la VM envenena el perfil)", flush=True)
|
||
else:
|
||
vivos = ser.cmd("for c in /proc/[0-9]*/comm; do cat $c 2>/dev/null; done | grep -c atuq")
|
||
v = vivos.splitlines()[1].strip() if len(vivos.splitlines()) > 1 else "?"
|
||
detalle = " ".join(f"{p}={medidas[p]}" for p in PANTALLAS)
|
||
print(f" +{t}s px de la página: {detalle} procesos atuq: {v}{vigilancia}", flush=True)
|
||
|
||
capturar(qmp_sock, out, "%s-despues" % fase)
|
||
print("== captura DESPUES de la fase", flush=True)
|
||
|
||
# EL NÚMERO. No «pinta / no pinta»: CUÁNTO TARDA. Medido el 2026-09-14 sobre esta
|
||
# misma imagen, la primera pintura cae entre +137 s y +204 s con el perfil por
|
||
# defecto y ~+134 s con uno nuevo en tmpfs — y con la máquina anfitriona cargada pasa
|
||
# de los +300 s. Por eso el presupuesto es HOLGADO y se dice el número siempre: un
|
||
# guardián que sólo contestara «no pintó» a los 5 min habría firmado el error del
|
||
# §6.10.ter.
|
||
if primera is None:
|
||
print(f"✗ el navegador NO pintó en {a.wait}s — mirá {out}/{fase}-despues.png y el MOZ_LOG:")
|
||
print(" `mapped 1` + «marked as visible & has buffer» + WaylandBufferSHM ⇒ estaba pintando"
|
||
" y la captura llegó antes; sin eso, es un fallo de verdad")
|
||
rc[0] = 1
|
||
else:
|
||
print(f"✓ primera pintura: +{primera}s (presupuesto {a.budget}s)")
|
||
if primera > a.budget:
|
||
print(f"✗ tardó {primera - a.budget}s MÁS que el presupuesto")
|
||
rc[0] = 1
|
||
|
||
if perfil_d and a.as_user:
|
||
# ⚠ EL ESTADO FINAL ES PARTE DE LA PRUEBA: el número cambia DENTRO de la
|
||
# corrida —lo escribe el ARRANQUE al encontrar el anterior sin terminar, no el
|
||
# kill— así que sin el «después» no se puede encadenar una corrida con la
|
||
# siguiente, que es lo que convierte esto en una serie legible (medido:
|
||
# 2 → 3 → 4 en tres fases de un mismo arranque). Se lee con el navegador
|
||
# todavía vivo, o sea que refleja el último volcado de prefs de Gecko.
|
||
# ⚠ `last_success` VA EN LOS DOS VOLCADOS. Es la otra mitad del cálculo, y
|
||
# sin él en el «después» una limpieza no dice si el arranque además SELLÓ el
|
||
# éxito: son dos preguntas que se contestan con el mismo grep y una salía muda.
|
||
volcado = ser.cmd("grep -E 'toolkit.startup.(recent_crashes|last_success)' %s/prefs.js || "
|
||
"echo '(el pref no está: arranque sin caídas pendientes)'"
|
||
% perfil_d, 60)
|
||
estado["recent_crashes_despues"] = leer_contador_de_caidas(volcado)
|
||
estado["last_success_despues"] = leer_sello_de_exito(volcado)
|
||
# ⚠ EL PISO SE COMPRUEBA, NO SE CONFÍA. `PISO_SELLO` son 180 s medidos EN ESTA
|
||
# máquina (TCG sin KVM, con la carga que tenga el anfitrión): con el anfitrión
|
||
# cargado el mismo arranque puede no llegar al gancho, y entonces esta corrida
|
||
# SUMA al contador y envenena la siguiente — en silencio, que es como pasó la
|
||
# primera vez. Con el sello leído antes y después, eso se puede DECIR.
|
||
if estado["last_success_despues"] is not None and \
|
||
estado["last_success_despues"] == estado.get("last_success_antes"):
|
||
print(" ⚠⚠ el sello NO se movió (%s): este arranque no terminó ⇒ la corrida "
|
||
"SUMA al contador de caídas. Si usaste --until-paint, subí PISO_SELLO"
|
||
% estado["last_success_despues"])
|
||
elif estado["last_success_despues"] is not None:
|
||
print(" ✓ el arranque SELLÓ el éxito (last_success %s → %s): esta corrida "
|
||
"no envenena la siguiente"
|
||
% (estado.get("last_success_antes"), estado["last_success_despues"]))
|
||
print("---- el contador de caídas, DESPUÉS ----")
|
||
print(volcado.strip())
|
||
# ⚠ SÓLO LA FASE BASE SE ANOTA. La serie de `primera-pintura.json` es una TASA del
|
||
# producto tal como se entrega; una fase con el tamaño de ventana sembrado a mano es
|
||
# otro experimento, y mezclarlos haría que el denominador dejara de significar nada.
|
||
if semilla is None:
|
||
anotar_medicion(primera, a, donde if primera is not None else None, estado)
|
||
else:
|
||
print(" (fase con semilla: NO se anota en la serie de la tasa)")
|
||
|
||
# La evidencia que no se puede leer de una captura: cómo terminó el proceso, qué se
|
||
# quejó el chrome, y qué hizo el widget de Wayland.
|
||
# QUÉ QUEDÓ PERSISTIDO. `browser.xhtml` lleva `persist="… width height sizemode"`,
|
||
# así que el tamaño con el que terminó la ventana se ESCRIBE en el perfil y lo hereda
|
||
# la corrida siguiente: si una corrida sale de 117×70 y lo guarda, el fallo se
|
||
# aprende. Sin este volcado, «intermitente» y «contagiado» se ven igual.
|
||
if perfil_d:
|
||
print("---- el perfil, DESPUÉS: qué tamaño quedó recordado ----")
|
||
print(ser.cmd("cat %s/xulstore.json 2>/dev/null || echo '(no escribió xulstore.json)'"
|
||
% perfil_d, 60))
|
||
print("---- cómo terminó, y de qué se quejó el chrome ----")
|
||
print(ser.cmd("grep -a -E 'ATUQ-EXIT|JavaScript error|Uncaught|NS_ERROR|###!!!' "
|
||
"%s | head -25" % log_atuq, 120))
|
||
print("---- atuq.log (cabeza) ----")
|
||
print(ser.cmd("head -20 %s" % log_atuq, 60))
|
||
print("---- atuq.log (cola) ----")
|
||
print(ser.cmd("tail -20 %s" % log_atuq, 60))
|
||
print("---- MOZ_LOG: creación de la ventana ----")
|
||
print(ser.cmd("grep -a -m 40 -E 'nsWindow::Create|CreateNative|Map|configure|Show|frame callback|Buffer' "
|
||
"%s.moz_log | head -40" % log_moz, 120))
|
||
# QUÉ PANTALLA VE GECKO — contestado el 2026-09-15 y por eso se queda: la sonda que
|
||
# ya contestó es la que avisa cuando la respuesta cambia. `New monitor 0 size
|
||
# [0,0 -> 1280 x 800]` ANTES de `Initial resize to 1 x 1` ⇒ la geometría de la salida
|
||
# NO es lo que falta.
|
||
print("---- MOZ_LOG: pantallas que ve Gecko y tamaños del nsWindow ----")
|
||
print(ser.cmd("grep -a -E 'WidgetScreen|Screen\\[|AddScreen|nsWindow::Resize|Initial resize|"
|
||
"SetSizeMode|OnConfigure|SizeAllocate|LockAspect' "
|
||
"%s.moz_log | head -50" % log_moz, 180))
|
||
# Y lo que dice el propio navegador, desde la página, por `dump()`: `screen=` es lo
|
||
# que el contenido ve de la pantalla y `outer=` el tamaño de la ventana. Dos fuentes
|
||
# independientes para el mismo número; si se contradicen, eso también es un dato.
|
||
print("---- la página: ATUQ-DIAG ----")
|
||
print(ser.cmd("grep -a ATUQ-DIAG %s | head -10" % log_atuq, 120))
|
||
print("---- MOZ_LOG: últimas líneas ----")
|
||
print(ser.cmd("tail -25 %s.moz_log" % log_moz, 60))
|
||
# El otro lado de la conversación. Gecko commitea a ciegas cuando nadie le devuelve
|
||
# frame callbacks (§6.10.nonies), y eso lo decide el COMPOSITOR: sin su log, «no
|
||
# pinta» sólo se puede mirar desde el cliente, que es la mitad que ya sabemos miente.
|
||
if a.wayland_debug:
|
||
# ⚠ EN `WAYLAND_DEBUG` LA FLECHA ES DEL CLIENTE. `-> obj.metodo()` es un PEDIDO
|
||
# que manda el navegador; los EVENTOS del compositor son las líneas SIN flecha.
|
||
# Filtrar por `->` es leer otra vez al cliente. Y los nombres llevan `@id` en el
|
||
# medio, así que `wl_surface.commit` no engancha: hay que anclar en el método.
|
||
# QUIÉN ELIGE EL TAMAÑO: `attach` no lo dice —el tamaño del buffer está en
|
||
# `create_buffer(…, W, H, stride, fmt)`— y lo que el cliente DECLARA querer está
|
||
# en `set_window_geometry`. Puestos en orden y en los DOS sentidos se ve quién
|
||
# propone (contestado en el §6.10.duodecies: lo propone el cliente).
|
||
print("---- protocolo: el tamaño, en orden (→ = pedido del cliente) ----")
|
||
# ⚠ El filtro EXCLUYE `mode(0,`: QEMU anuncia ~60 modos no-actuales y con ellos
|
||
# dentro el `head` cortaba ANTES del `set_window_geometry` — la lista que existe
|
||
# para ordenar dos cosas se quedaba sin una de las dos.
|
||
print(ser.cmd("grep -a -n -E 'create_buffer|set_window_geometry|configure|ack_configure|"
|
||
"get_toplevel|set_min_size|set_max_size|set_title|set_app_id|\\.attach|"
|
||
"wl_output|\\.mode\\(|\\.geometry\\(|\\.done\\(\\)' "
|
||
"%s | grep -av 'mode(0,' | head -80" % log_atuq, 240))
|
||
print("---- protocolo: EVENTOS del compositor (sin flecha) ----")
|
||
print(ser.cmd("grep -av ' -> ' %s | "
|
||
"grep -a -E 'xdg_surface|xdg_toplevel|wl_callback|wl_output|wl_surface' | "
|
||
"tail -40" % log_atuq, 180))
|
||
print("---- cosmic-comp: superficies, salidas y foco ----")
|
||
print(ser.cmd("grep -a -i -E 'output|workspace|focus|toplevel|surface|xdg|map' "
|
||
"/var/log/cosmic/cosmic-session.log | tail -40", 120))
|
||
print("---- tamaño de los logs ----")
|
||
print(ser.cmd("wc -l /var/log/cosmic/atuq-*.log /var/log/cosmic/moz-*.moz_log "
|
||
"/var/log/cosmic/cosmic-session.log /var/log/cosmic/cosmic-start.log", 30))
|
||
finally:
|
||
try:
|
||
qmp(qmp_sock, [{"execute": "quit"}])
|
||
except Exception:
|
||
pass
|
||
time.sleep(2); vm.terminate()
|
||
try:
|
||
vm.wait(20)
|
||
except Exception:
|
||
vm.kill()
|
||
|
||
# Las capturas salen en PPM (lo único que sabe QMP); a PNG para poder mirarlas.
|
||
try:
|
||
from PIL import Image
|
||
for f in sorted(os.listdir(out)):
|
||
if f.endswith(".ppm"):
|
||
Image.open(os.path.join(out, f)).save(os.path.join(out, f[:-4] + ".png"))
|
||
print("== capturas convertidas a PNG en", out)
|
||
except Exception as e:
|
||
print(" ⚠ sin conversión a PNG:", e)
|
||
return rc[0]
|
||
|
||
|
||
if __name__ == "__main__":
|
||
sys.exit(main())
|