sergio/takana
> Una distribución Linux construida con un laboratorio funcional y hermético en el > sótano, y una terminal mutable, clásica y anárquica en el piso de arriba — diseñada > desde el suelo para que una IA programadora entienda, modifique y co…
⎇ e7369efe824aed48bb1b0752bd128d37c9b7b791
scripts/cosmic/atuq-en-imagen.py
History
Who touched what
raw
atuq: la tasa con perfil sano es +97 y +98 s — y PINTAR NO ES TERMINAR el arranque
1#!/usr/bin/env python3
2"""atuq-en-imagen.py — arranca la IMAGEN DE DISCO con COSMIC y le pide al navegador que pinte.
3
4 scripts/cosmic/atuq-en-imagen.py # lanza atuq y fotografía la pantalla
5 scripts/cosmic/atuq-en-imagen.py --only-cosmic # control: NO lanza atuq (línea de base)
6
7── POR QUÉ ────────────────────────────────────────────────────────────────────────────────────
8El §6.10.ter del SDD 26 dejó esto medido y sin explicar: en la imagen arrancada `atuq` corre —sus
9extensiones sondean, WebRender inicializa— y la ventana NO APARECE, mientras que bajo `sway` headless
10el mismo artefacto pinta. `scripts/cosmic/atuq-en-cosmic.sh` ya sacó una variable de encima:
11**con cosmic-comp NESTEADO (backend winit, GL por software) el navegador pinta**, o sea que no es el
12compositor por sí mismo. Lo que queda es el arranque de verdad: kms/DRM sobre virtio-gpu, el PID1 de
13arje, el seat. Eso sólo se mide acá adentro.
14
15La corrida anterior fue A MANO por el serial y no dejó ni un log que se pueda releer. Este guion
16hace lo mismo pero REPETIBLE y con la evidencia guardada: maneja el serial, lanza el navegador con
17`MOZ_LOG` del widget de Wayland, pide capturas por QMP y saca los logs por el serial.
18
19── CÓMO HABLA CON LA VM ───────────────────────────────────────────────────────────────────────
20`console-getty` corre `cosmic-start`, que tras su ventana de observación (3 min) hace `exec /bin/sh`
21CON EL ENTORNO DE LA SESIÓN puesto (WAYLAND_DISPLAY, DBUS_SESSION_BUS_ADDRESS). O sea que el shell
22del serial es exactamente desde donde un usuario lanzaría una app — y por eso no hace falta
23reconstruir el entorno a mano, que es como se inventan diferencias que después se confunden con la
24causa.
25"""
26import argparse, json, os, re, shutil, socket, subprocess, sys, time
27
28# Sin esto la salida sale por tandas cuando se redirige a un fichero, y una corrida de 20 minutos se
29# lee como si estuviera colgada.
30sys.stdout.reconfigure(line_buffering=True)
31
32RAIZ = os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
33IMG = os.environ.get("IMG", "/mnt/cosecha/takana-cosmic-qemu.img")
34OVMF_CODE = os.environ.get("OVMF_CODE", "/usr/share/edk2/x64/OVMF_CODE.4m.fd")
35OVMF_VARS = os.environ.get("OVMF_VARS", "/usr/share/edk2/x64/OVMF_VARS.4m.fd")
36MEM = os.environ.get("MEM", "2560")
37SMP = os.environ.get("SMP", "2")
38
39# ⚠ `VGA=1` reproduce el arranque del §6.10.ter, y la diferencia NO es cosmética: sin `-vga none`,
40# QEMU agrega una VGA estándar ADEMÁS del virtio-gpu, OVMF pinta su GOP ahí y el kernel levanta
41# `simpledrm` encima ⇒ el guest ve DOS dispositivos DRM. En el serial se lee tal cual:
42#
43# == cosmic :: kernel 6.16.12 · drm: card0 card1 renderD128 (corrida del §6.10.ter)
44# == cosmic :: kernel 6.16.12 · drm: card0 renderD128 (con -vga none)
45#
46# Un compositor con dos tarjetas puede componer en la que el `screendump` NO muestra. Por eso el
47# default acá es UNA sola (-vga none) y la reproducción del caso original es una opción explícita:
48# son dos mediciones distintas y hay que poder pedir cada una por su nombre.
49# Las dos pantallas van con ID EXPLÍCITO (`vga0`, `gpu0`) y no por el `-vga std` implícito, porque
50# `screendump` de QMP fotografía UN dispositivo y hay que poder pedir cada uno por su nombre: con dos
51# salidas, el compositor puede poner la ventana en la que la captura por defecto NO muestra, y eso se
52# ve exactamente igual que «la ventana no aparece».
53DOS_PANTALLAS = os.environ.get("VGA") == "1"
54VGA_ARGS = (["-vga", "none", "-device", "VGA,id=vga0"] if DOS_PANTALLAS else ["-vga", "none"])
55PANTALLAS = ["gpu0", "vga0"] if DOS_PANTALLAS else ["gpu0"]
56
57
58class Serial:
59 """El serial de la VM. Todo lo que entra queda en el .log crudo, pase lo que pase."""
60
61 def __init__(self, ruta, log):
62 self.log = open(log, "ab", buffering=0)
63 for _ in range(120):
64 try:
65 self.s = socket.socket(socket.AF_UNIX); self.s.connect(ruta); break
66 except OSError:
67 time.sleep(0.5)
68 else:
69 raise SystemExit(f"no pude conectarme al serial {ruta}")
70 self.s.settimeout(1.0)
71 self.buf = b""
72
73 def leer(self, segundos):
74 fin = time.time() + segundos
75 while time.time() < fin:
76 try:
77 d = self.s.recv(65536)
78 except socket.timeout:
79 continue
80 if not d:
81 break
82 self.buf += d; self.log.write(d)
83 return self.buf
84
85 def esperar(self, marca, segundos, nombre=""):
86 """Lee hasta ver `marca`. Devuelve lo leído desde la llamada anterior."""
87 vistos = len(self.buf)
88 fin = time.time() + segundos
89 while time.time() < fin:
90 try:
91 d = self.s.recv(65536)
92 except socket.timeout:
93 continue
94 if d:
95 self.buf += d; self.log.write(d)
96 if marca.encode() in self.buf[vistos:]:
97 return self.buf[vistos:].decode("utf-8", "replace")
98 print(f" ⚠ nunca llegó «{marca}» {nombre} en {segundos}s", flush=True)
99 return self.buf[vistos:].decode("utf-8", "replace")
100
101 def cmd(self, orden, segundos=30, fondo=False):
102 """Manda una orden y devuelve su salida (delimitada por una marca propia).
103
104 ⚠ DOS TRAMPAS MEDIDAS, las dos hacen que la orden NO CORRA y el guion siga como si nada:
105
106 · **el terminal hace ECO de lo que se le escribe**, así que una marca escrita literal en la
107 línea aparece en el serial ANTES de que el shell ejecute nada: el `esperar` la ve en el eco
108 y vuelve al instante, y las órdenes se pisan unas a otras. Por eso la marca se ARMA EN EL
109 GUEST partida en dos (`'FIN''-123'`): el eco muestra las comillas y sólo la salida trae la
110 marca entera.
111 · **`cmd & ; echo …` es un error de sintaxis** en ash: pegarle un `;` a un `&` no lanza nada
112 y el shell contesta «syntax error». Lo de fondo va en su propia línea (`fondo=True`).
113 """
114 n = int(time.time() * 1000) % 100000
115 marca = f"FIN-{n}"
116 if fondo:
117 self.s.sendall(f"{orden}\n".encode()); time.sleep(0.5)
118 self.s.sendall(f"echo 'FIN''-{n}'\n".encode())
119 else:
120 self.s.sendall(f"{orden}; echo 'FIN''-{n}'\n".encode())
121 return self.esperar(marca, segundos, nombre=f"de «{orden[:40]}»")
122
123
124def capturar(ruta_qmp, out, nombre):
125 """Fotografía CADA pantalla del guest y devuelve {pantalla: fichero}.
126
127 Con dos salidas hay que mirar las dos: la ventana puede estar viva y dibujando en la que no se
128 fotografía, y eso es indistinguible de «no pinta» si sólo se mira una.
129 """
130 ficheros = {p: os.path.join(out, f"{nombre}-{p}.ppm") for p in PANTALLAS}
131 qmp(ruta_qmp, [{"execute": "screendump", "arguments": {"filename": f, "device": p}}
132 for p, f in ficheros.items()])
133 return ficheros
134
135
136def pintado(ppm):
137 """¿Cuántos píxeles de la pantalla son la página de prueba?
138
139 Se cuenta el magenta con TOLERANCIA, no por color exacto, y la razón está medida: a los ~+590 s
140 sin una sola entrada `cosmic-idle` ATENÚA la pantalla y los 703 766 px de `(255,0,255)` pasan a
141 703 779 px de `(117,0,117)` —la misma ventana al 46 % de brillo—. Un contador por color exacto
142 lee eso como «desapareció la ventana», que es justo el error que este guion existe para no
143 cometer.
144 """
145 try:
146 from PIL import Image
147 except Exception:
148 return None
149 im = Image.open(ppm).convert("RGB")
150 return sum(n for n, (r, g, b) in im.getcolors(1 << 24) if r > 90 and b > 90 and g < 40)
151
152
153def leer_contador_de_caidas(texto):
154 """Saca el valor de `toolkit.startup.recent_crashes` de un volcado de `prefs.js`.
155
156 Devuelve `None` si el pref NO ESTÁ, que no es lo mismo que un 0 puesto a mano: «no está» es el
157 estado de un perfil cuyo arranque terminó bien —y es también lo que deja Gecko DESPUÉS de
158 mostrar el diálogo de Modo de resolución de problemas, que es la razón por la que la corrida
159 siguiente «se arregla sola» y la anterior parece intermitente.
160
161 Filtra por `user_pref` a propósito: el serial hace eco de la propia orden `grep`, y esa línea
162 contiene el nombre del pref sin su valor.
163 """
164 for linea in texto.splitlines():
165 if "user_pref" in linea and "toolkit.startup.recent_crashes" in linea:
166 m = re.search(r"recent_crashes\"?\s*,\s*(-?\d+)", linea)
167 if m:
168 return int(m.group(1))
169 return None
170
171
172def anotar_medicion(segundos, a, pantalla=None, extra=None):
173 """Deja el tiempo de primera pintura en `docs/state/primera-pintura.json`.
174
175 Va al estado del repo y no a un log porque quien pregunta «¿esta imagen se puede usar?» es
176 `scripts/vigia-imagen.py`, que mira artefactos y no arranca ninguna VM: el número tiene que
177 llegarle por escrito o no le llega. Se guarda TODO lo que lo hace comparable —cómo se lanzó, con
178 qué vídeo, con cuánta RAM y cuántos cores— porque el tiempo depende de eso y de la carga de la
179 máquina anfitriona; un número sin sus condiciones invita a leerlo como si fuera del producto.
180 """
181 dato = {
182 "medido": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()),
183 "imagen": IMG,
184 "segundos_primera_pintura": segundos, # None = no pintó dentro de la ventana
185 "pantalla": pantalla, # EN CUÁL de las salidas apareció (medido 2026-09-14:
186 # con dos, la ventana cae en cualquiera de las dos)
187 "pantallas_fotografiadas": len(PANTALLAS), # con 1 y dos salidas, un ✗ NO es concluyente
188 "presupuesto_s": a.budget,
189 "ventana_s": a.wait,
190 "cadencia_s": a.cadence, # la RESOLUCIÓN del número: ±cadencia
191 "lanzamiento": "perfil del usuario" if a.as_user else "perfil nuevo en tmpfs",
192 "video": "vga+virtio-gpu (dos DRM)" if DOS_PANTALLAS else "virtio-gpu solo (-vga none)",
193 "mem_mb": int(MEM), "vcpus": int(SMP), "acel": "tcg",
194 "guion": "scripts/cosmic/atuq-en-imagen.py",
195 }
196 # ⚠ EL CONTADOR DE CAÍDAS DEL PERFIL VIAJA CON LA MEDICIÓN, y es lo que hace legible la serie:
197 # con `toolkit.startup.recent_crashes` por encima de 3 el sujeto de la corrida NO es el
198 # navegador sino el diálogo de Modo de resolución de problemas (§6.10.terdecies), así que un ✗
199 # de esas corridas no dice nada del producto. Sin este campo, una tasa cierta se lee como si
200 # fuera del navegador — que es exactamente lo que pasó con «3 de 13» y «2 de 10».
201 dato.update(extra or {})
202 # ⚠ SE ACUMULAN, NO SE PISAN. Medido el 2026-09-14: dos corridas IDÉNTICAS (mismo comando,
203 # misma imagen) dieron «+204 s» y «no pintó en 900 s». Un fichero de UNA medición convierte un
204 # fenómeno intermitente en el número que le tocó a la última corrida, que es la forma más cara
205 # de mentir con datos ciertos.
206 destino = os.path.join(RAIZ, "docs/state/primera-pintura.json")
207 try:
208 historia = {"corridas": []}
209 if os.path.exists(destino):
210 with open(destino) as f:
211 historia = json.load(f)
212 historia.setdefault("corridas", []).append(dato)
213 historia["corridas"] = historia["corridas"][-30:]
214 os.makedirs(os.path.dirname(destino), exist_ok=True)
215 with open(destino, "w") as f:
216 json.dump(historia, f, indent=2, ensure_ascii=False)
217 f.write("\n")
218 pintaron = [c for c in historia["corridas"] if c.get("segundos_primera_pintura") is not None]
219 print(" anotada en docs/state/primera-pintura.json — %d de %d corridas pintaron"
220 % (len(pintaron), len(historia["corridas"])))
221 except (OSError, ValueError) as e:
222 print(f" ⚠ no pude anotar la medición: {e}")
223
224
225def qmp(ruta, ordenes):
226 s = socket.socket(socket.AF_UNIX); s.settimeout(30); s.connect(ruta)
227 f = s.makefile("rwb", buffering=0)
228 f.readline() # greeting
229 f.write(b'{"execute":"qmp_capabilities"}\n'); f.readline()
230 salidas = []
231 for o in ordenes:
232 f.write(json.dumps(o).encode() + b"\n"); salidas.append(f.readline())
233 s.close()
234 return salidas
235
236
237def main():
238 ap = argparse.ArgumentParser()
239 ap.add_argument("--only-cosmic", action="store_true", help="control: no lanza el navegador")
240 ap.add_argument("--as-user", action="store_true",
241 help="lanza `atuq` a secas —perfil por defecto, sin MOZ_ENABLE_WAYLAND— como se hizo a mano en el §6.10.ter")
242 ap.add_argument("--wait", type=int, default=600, help="segundos de observación como máximo")
243 ap.add_argument("--cadence", type=int, default=30, help="segundos entre capturas (la resolución de la medida)")
244 ap.add_argument("--budget", type=int, default=420,
245 help="segundos que puede tardar la primera pintura antes de dar ✗")
246 ap.add_argument("--until-paint", action="store_true",
247 help="cortar la observación en cuanto la página aparezca (más barato para medir el tiempo)")
248 ap.add_argument("--wayland-debug", action="store_true",
249 help="lanza el navegador con WAYLAND_DEBUG=1: registra CADA mensaje del "
250 "protocolo en los dos sentidos. Es la única forma de ver qué MANDA el "
251 "compositor sin recompilarlo (sus macros de debug están compiladas fuera)")
252 ap.add_argument("--set-rust-log", metavar="VALOR",
253 help="escribe RUST_LOG en /etc/cosmic-mode de la IMAGEN y apaga; "
254 "cadena vacía = lo quita. El compositor lo lee en el arranque SIGUIENTE, "
255 "que es la única forma de subirle el nivel de log sin recompilar")
256 ap.add_argument("--crashes", type=int, metavar="N",
257 help="fija `toolkit.startup.recent_crashes` del perfil del usuario antes de "
258 "lanzar: 0 lo limpia, 4 o más reproduce el diálogo de Modo de resolución "
259 "de problemas (medido: con 3 guardado todavía pinta, porque el arranque "
260 "suma ANTES de comparar). Sólo tiene efecto con --as-user. ⚠ 0 es el valor "
261 "por DEFECTO y un pref igual al default no se persiste: si lo que querés "
262 "medir es quién limpia el contador, NO lo pinnees")
263 ap.add_argument("--xulstore", metavar="ANCHOxALTO",
264 help="agrega una SEGUNDA fase en el mismo arranque con `xulstore.json` sembrado "
265 "(p. ej. 1152x720): la ventana arranca con un tamaño YA PERSISTIDO. Es el "
266 "control del 117x70 — si con semilla sale grande, lo que falla es que nadie "
267 "le da tamaño en el primer arranque")
268 ap.add_argument("--repeat", type=int, metavar="N",
269 help="corre N fases IDÉNTICAS en el mismo arranque. Con `--wait` corto (60 s, o "
270 "sea antes de que pinte) mide el contador de caídas: cada fase lee "
271 "`recent_crashes` ANTES de lanzar, así que la serie 0,1,2… dice cuánto suma "
272 "un arranque interrumpido — y si no sube, el envenenamiento vino de otro lado")
273 ap.add_argument("--out", default=os.path.join(RAIZ, "work/atuq-imagen"))
274 a = ap.parse_args()
275
276 rc = [0] # lista para poder tocarlo desde dentro del try/finally
277 out = a.out; os.makedirs(out, exist_ok=True)
278 vars_fd = os.path.join(out, "OVMF_VARS.fd")
279 shutil.copy(OVMF_VARS, vars_fd)
280 ser_sock, qmp_sock = os.path.join(out, "serial.sock"), os.path.join(out, "qmp.sock")
281 for p in (ser_sock, qmp_sock):
282 if os.path.exists(p):
283 os.unlink(p)
284
285 qemu = [
286 "nice", "-n", "10", "qemu-system-x86_64",
287 "-machine", "q35", "-accel", "tcg", "-cpu", "max", "-m", MEM, "-smp", SMP,
288 *VGA_ARGS, "-device", "virtio-gpu-pci,id=gpu0", "-display", "none", "-nic", "none",
289 "-drive", f"if=pflash,format=raw,unit=0,file={OVMF_CODE},readonly=on",
290 "-drive", f"if=pflash,format=raw,unit=1,file={vars_fd}",
291 "-drive", f"file={IMG},format=raw,if=virtio",
292 "-serial", f"unix:{ser_sock},server,nowait",
293 "-qmp", f"unix:{qmp_sock},server,nowait",
294 "-no-reboot",
295 ]
296 print("== arrancando la imagen (TCG, sin KVM — paciencia)")
297
298 def primero_en_la_fila():
299 # El repo es COMPARTIDO y casi siempre hay una tanda de la granja compilando en esta misma
300 # máquina (4 cores, 7,6 G). Si la RAM se acaba, el que tiene que morir es ESTA VM y no el
301 # build de otro agente: `oom_score_adj` alto es la única forma de decirlo por adelantado.
302 with open("/proc/self/oom_score_adj", "w") as f:
303 f.write("900")
304
305 vm = subprocess.Popen(qemu, stdout=open(os.path.join(out, "qemu.log"), "wb"),
306 stderr=subprocess.STDOUT, preexec_fn=primero_en_la_fila)
307 # ⚠ QEMU TOMA UN LOCK DE ESCRITURA SOBRE LA IMAGEN, y sin esta comprobación el arnés espera
308 # 600 s una marca del serial que no va a llegar NUNCA: el socket queda creado, el `connect()`
309 # funciona y no falla nada — el error es UNA línea en `qemu.log` que nadie mira. Medido el
310 # 2026-09-15 al lanzar el control negativo con la corrida anterior todavía viva:
311 # Failed to get "write" lock. Is another process using the image [...]?
312 # Las corridas sobre la misma imagen van EN SERIE; esto lo dice en el primer segundo.
313 time.sleep(2)
314 if vm.poll() is not None:
315 raise SystemExit("✗ QEMU no arrancó:\n " +
316 open(os.path.join(out, "qemu.log")).read().strip())
317
318 try:
319 ser = Serial(ser_sock, os.path.join(out, "serial.log"))
320 print("== esperando a COSMIC…", flush=True)
321 ser.esperar("compositor OK", 600, nombre="(arranque de cosmic-comp)")
322 print(" compositor arriba; esperando el shell del serial (ventana de observación)", flush=True)
323 # 420 s alcanzaban con el anfitrión ocioso y NO con carga ~13: la VM llegaba a «+15s» y el
324 # arnés se rendía antes de que `cosmic-start` soltara el shell. El margen es de espera, no de
325 # medida: subirlo no cambia ningún número, sólo deja de tirar corridas por carga ajena.
326 ser.esperar("fin de la ventana de observación", 780, nombre="(fin de observación)")
327 time.sleep(3)
328 ser.s.sendall(b"\n")
329 print(ser.cmd("echo ENTORNO: WD=$WAYLAND_DISPLAY XDG=$XDG_RUNTIME_DIR DBUS=$DBUS_SESSION_BUS_ADDRESS").strip())
330 print(ser.cmd("ls -l $XDG_RUNTIME_DIR; ls /usr/lib/dri").strip())
331
332 if a.set_rust_log is not None:
333 # `cosmic-start` hace `. /etc/cosmic-mode` ANTES de `export RUST_LOG="${RUST_LOG:-info}"`,
334 # así que el fichero es la perilla. Se escribe y se apaga: quien la usa es el arranque
335 # siguiente — el compositor de ESTA sesión ya arrancó y no se lo puede reconfigurar.
336 ser.cmd("grep -v '^RUST_LOG=' /etc/cosmic-mode > /tmp/cm 2>/dev/null; true")
337 if a.set_rust_log:
338 ser.cmd("printf '%%s\\n' \"RUST_LOG=%s\" >> /tmp/cm" % a.set_rust_log)
339 ser.cmd("cp /tmp/cm /etc/cosmic-mode && sync")
340 print("== /etc/cosmic-mode ahora dice:")
341 print(ser.cmd("cat /etc/cosmic-mode").strip())
342 return
343
344 capturar(qmp_sock, out, "antes")
345 print("== captura ANTES (%s)" % ", ".join(PANTALLAS), flush=True)
346
347 if a.only_cosmic:
348 print("== CONTROL: no se lanza el navegador")
349 else:
350 # Una página de un color imposible de confundir con el escritorio.
351 ser.cmd("mkdir -p /var/log/cosmic")
352 # La página además DICE, por `dump()`, qué tamaño cree que tiene la ventana y qué
353 # pantalla ve el navegador. Con `screen=` y `outer=` en el log se sabe si el navegador
354 # ve la pantalla o no — y desde el §6.10.terdecies sabemos que SÍ la ve, así que lo que
355 # queda por contar es el otro lado: qué tamaño cree tener la VENTANA. Sin comillas
356 # simples: va dentro de un `printf '%s' '...'`.
357 ser.cmd("printf '%s' '<!doctype html><body style=\"margin:0;background:#ff00ff\">"
358 "<h1 style=\"font:40px monospace\">ATUQ PINTA</h1><script>"
359 "function diag(t){dump(\"ATUQ-DIAG \"+t+\" screen=\"+screen.width+\"x\"+screen.height"
360 "+\" avail=\"+screen.availWidth+\"x\"+screen.availHeight"
361 "+\" outer=\"+outerWidth+\"x\"+outerHeight"
362 "+\" inner=\"+innerWidth+\"x\"+innerHeight"
363 "+\" dpr=\"+devicePixelRatio+\"\\n\");}"
364 "addEventListener(\"load\",function(){diag(\"load\");"
365 "setTimeout(function(){diag(\"t10\");},10000);"
366 "setTimeout(function(){diag(\"t60\");},60000);});"
367 "</script>' > /tmp/pagina.html")
368
369 # ⚠ LO QUE DEJÓ LA CORRIDA ANTERIOR, ANTES DE PISARLO. El disco de esta VM es
370 # PERSISTENTE (`-drive` sin `snapshot=on`) ⇒ `/var/log/cosmic/` todavía tiene el
371 # arranque anterior, y el lanzamiento de esta corrida lo trunca. Ahí es donde salen los
372 # errores de JS del chrome, y NUNCA se habían mirado: se leía `tail -25`, que con
373 # `WAYLAND_DEBUG` son 25 líneas de protocolo y nada más. Copiarlo primero cuesta nada.
374 ser.cmd("rm -rf /var/log/cosmic-anterior; cp -a /var/log/cosmic /var/log/cosmic-anterior "
375 "2>/dev/null; true", 120)
376 print("---- corrida ANTERIOR: cómo terminó y qué se quejó ----")
377 print(ser.cmd("grep -a -h -E 'ATUQ-EXIT|JavaScript error|Uncaught|NS_ERROR|"
378 "###!!!|\\[Parent\\].*ERROR' /var/log/cosmic-anterior/atuq*.log "
379 "2>/dev/null | head -20", 120))
380 # DÓNDE VIVE EL PERFIL, SIN ADIVINARLO. El `find` anterior miraba sólo `/root` y esta
381 # imagen lo desmintió en silencio: dijo «no encontré el perfil» y la sonda salió muda.
382 # `$HOME` lo decide todo y el shell del serial lo hereda de `cosmic-start`, así que se
383 # IMPRIME; y el `find` va sobre la raíz entera con `-xdev` (que deja fuera /proc y /sys).
384 print("== HOME del shell de la sesión y perfiles que ya existen en el disco:")
385 print(ser.cmd("echo HOME=$HOME; find / -xdev -maxdepth 7 -name prefs.js 2>/dev/null | head -5", 180))
386
387 def perfil_de_la_fase(semilla):
388 """Deja el perfil listo para la fase y devuelve su directorio (o None).
389
390 Las dos formas de lanzar NO son el mismo experimento y por eso conviven: el modo por
391 defecto usa un perfil NUEVO en tmpfs —primer arranque de verdad, que es el caso que
392 sale 117×70— y `--as-user` reproduce lo que se tecleó a mano en el §6.10.ter, con el
393 perfil del usuario y sin variables de entorno.
394 """
395 if a.as_user:
396 hallado = ser.cmd("find / -xdev -maxdepth 7 -name prefs.js 2>/dev/null | head -3", 180)
397 perfil = next((l.strip() for l in hallado.splitlines()
398 if l.strip().endswith("prefs.js") and l.strip().startswith("/")), None)
399 if not perfil:
400 print(" ⚠ no encontré el perfil del usuario: la sonda ATUQ-DIAG va a salir muda")
401 return None
402 d = os.path.dirname(perfil)
403 print("== perfil del usuario:", d)
404 # ⚠⚠ EL CONTADOR DE CAÍDAS DEL PERFIL, SIEMPRE A LA VISTA. Con
405 # `toolkit.startup.recent_crashes` por encima de `max_resumed_crashes` (3 por
406 # defecto) el navegador NO abre el navegador: abre el diálogo de Modo de
407 # resolución de problemas. Y este arnés mata la VM con el navegador vivo, así
408 # que CADA corrida fallida puede sumar uno: el instrumento degrada el sujeto y
409 # la tasa medida deja de ser del producto. Sin este número impreso, una corrida
410 # no se puede interpretar.
411 # ⚠ `last_success` VA EN EL MISMO VOLCADO. Es la otra mitad del cálculo: sin
412 # él, un `recent_crashes` que no se movió es ambiguo entre «no subió» y «subió y
413 # lo limpió el gancho de cierre», que son conclusiones opuestas sobre la misma
414 # cifra.
415 volcado = ser.cmd("grep -E 'toolkit.startup.(recent_crashes|max_resumed|"
416 "last_success)|browser.sessionstore.max_resumed' %s/prefs.js" % d, 60)
417 print(volcado.strip())
418 estado["recent_crashes_antes"] = leer_contador_de_caidas(volcado)
419 # ⚠ EL AVISO QUE FALTABA. Medido el 2026-09-15: el arranque que encuentra el
420 # anterior sin terminar SUMA UNO y compara DESPUÉS, así que con 3 guardado esta
421 # corrida abre el diálogo de Modo de resolución de problemas y no el navegador —
422 # y como el arnés mata la VM antes del gancho de cierre, CADA corrida suma.
423 # Una serie se rompe sola a la cuarta; por eso se dice acá y no en el post-mortem.
424 previo = estado["recent_crashes_antes"]
425 if previo is not None and previo >= 3 and a.crashes is None:
426 print(" ⚠⚠ contador en %d: ESTA corrida va a abrir el DIÁLOGO, no el "
427 "navegador. Para medir la pintura, pasá --crashes 0" % previo)
428 else:
429 d = "/tmp/perfil"
430 ser.cmd("rm -rf /tmp/perfil && mkdir -p /tmp/perfil")
431 ujs = ['user_pref("browser.dom.window.dump.enabled", true);',
432 'user_pref("browser.shell.checkDefaultBrowser", false);']
433 if a.crashes is not None:
434 # El mismo mando en los DOS sentidos: 0 limpia el contador (¿pinta?) y un
435 # número alto lo reproduce a propósito (¿se rompe?). `user.js` gana sobre
436 # `prefs.js` en cada arranque, así que fija el valor de la corrida.
437 ujs.append('user_pref("toolkit.startup.recent_crashes", %d);' % a.crashes)
438 print("== recent_crashes FIJADO a %d para esta corrida" % a.crashes)
439 ser.cmd("rm -f %s/user.js" % d)
440 for linea in ujs:
441 ser.cmd("printf '%%s\\n' '%s' >> %s/user.js" % (linea, d))
442 if semilla:
443 # EL CONTROL. `browser-init.js` —el que trae el propio artefacto, leído del
444 # `omni.ja` sellado— fija el tamaño de arranque UNA sola vez:
445 #
446 # } else if (!document.documentElement.hasAttribute("width")) {
447 # let width = Math.min(screen.availWidth * 0.9, 1280);
448 # let height = Math.min(screen.availHeight * 0.9, 1040);
449 #
450 # y ese atributo, en un perfil ya usado, lo rellena el `xulstore.json`. Sembrarlo
451 # a mano separa las dos explicaciones posibles del 117×70 en UNA corrida: si con
452 # semilla la ventana sale grande, el fallo es «nadie le dio tamaño» (ese `if` no
453 # corrió); si sale igual de chica, el tamaño no es lo que falla.
454 w, h = semilla.lower().split("x")
455 doc = {"chrome://browser/content/browser.xhtml":
456 {"main-window": {"screenX": "0", "screenY": "0",
457 "width": w, "height": h, "sizemode": "normal"}}}
458 ser.cmd("printf '%%s' '%s' > %s/xulstore.json" % (json.dumps(doc), d))
459 elif not a.as_user:
460 # Sólo en el perfil DESECHABLE de tmpfs. ⚠ En `--as-user` el `xulstore.json` es
461 # el estado del usuario —el tamaño que la ventana RECUERDA— y borrarlo cambiaría
462 # el experimento sin decirlo: la corrida siguiente ya no sería «como lo abre el
463 # usuario» sino un primer arranque disfrazado.
464 ser.cmd("rm -f %s/xulstore.json" % d)
465 ser.cmd("sync")
466 print("== el perfil, ANTES de lanzar (user.js y el tamaño que RECUERDA):")
467 print(ser.cmd("cat %s/user.js; echo ---; cat %s/xulstore.json 2>/dev/null || "
468 "echo '(sin xulstore.json: la ventana no recuerda ningún tamaño)'"
469 % (d, d), 60).strip())
470 return d
471
472 def matar_al_navegador():
473 """Deja la sesión sin ningún `atuq` vivo antes de la fase siguiente.
474
475 Por PID leído de `/proc/*/comm`, no por `pkill -f atuq`: el patrón engancha la propia
476 línea de orden del shell del serial y ahí se mata la sesión entera (medido en el hub,
477 sale 144 y lo que sigue no corre).
478 """
479 # ⚠ `-9` A PROPÓSITO. Un `kill` a secas le da a Gecko su apagado ordenado, y un
480 # apagado ordenado es EXACTAMENTE la variable bajo prueba: lo que hace este arnés al
481 # terminar es matar la VM entera, que no avisa. Con `-KILL` la fase siguiente
482 # encuentra el mismo estado que encontraría tras una corrida matada de verdad.
483 ser.cmd("for p in /proc/[0-9]*; do grep -q atuq $p/comm 2>/dev/null && "
484 "kill -9 ${p#/proc/}; done; true", 60)
485 time.sleep(8)
486 salida = ser.cmd("for c in /proc/[0-9]*/comm; do cat $c 2>/dev/null; done | grep -c atuq")
487 # El serial hace ECO de la orden, así que la respuesta es la ÚLTIMA línea que sea un
488 # número y no la primera que aparezca: leer la primera devuelve un trozo del eco.
489 cuenta = next((l.strip() for l in reversed(salida.splitlines()) if l.strip().isdigit()), "?")
490 print(" navegadores vivos tras el kill: " + cuenta)
491
492 # LAS FASES. Una sola es la medición de siempre; con `--xulstore` se agrega una SEGUNDA
493 # en el MISMO arranque, que es un A/B de verdad: mismo compositor, misma sesión, misma
494 # carga del anfitrión. Dos arranques distintos no lo serían — y cada arranque cuesta
495 # cinco minutos de TCG.
496 # El estado del perfil que hay que ADJUNTAR a la medición: el contador de caídas antes
497 # y después. Vive acá afuera porque lo escribe la preparación de la fase y lo lee la
498 # anotación, y porque con `--crashes` fijado hay que poder distinguir el valor que
499 # PUSIMOS del que el perfil traía.
500 estado = {"recent_crashes_fijado": a.crashes}
501
502 fases = [("base", None)]
503 if a.xulstore:
504 fases.append(("semilla-%s" % a.xulstore, a.xulstore))
505 if a.repeat:
506 # N fases iguales: lo que varía entre ellas no es la configuración sino el ESTADO que
507 # deja la anterior en el perfil, que es justo lo que se quiere medir.
508 fases = [("k%d" % i, None) for i in range(1, a.repeat + 1)]
509
510 for fase, semilla in fases:
511 print("\n===== FASE «%s» =====" % fase, flush=True)
512 if fase != fases[0][0]:
513 matar_al_navegador()
514 perfil_d = perfil_de_la_fase(semilla)
515 log_atuq = "/var/log/cosmic/atuq-%s.log" % fase
516 log_moz = "/var/log/cosmic/moz-%s" % fase
517 capturar(qmp_sock, out, "%s-antes" % fase)
518 print("== captura ANTES de la fase (%s)" % ", ".join(PANTALLAS), flush=True)
519
520 wd = "WAYLAND_DEBUG=1 " if a.wayland_debug else ""
521 moz = ("MOZ_LOG='Widget:5,WidgetWayland:5,WaylandBackend:5,WidgetScreen:5,timestamp' "
522 "MOZ_LOG_FILE=%s " % log_moz)
523 if a.as_user:
524 orden = wd + moz + "/usr/bin/atuq file:///tmp/pagina.html"
525 else:
526 orden = (wd + "MOZ_ENABLE_WAYLAND=1 GDK_BACKEND=wayland " + moz +
527 "/usr/bin/atuq --no-remote --profile /tmp/perfil file:///tmp/pagina.html")
528 # ⚠ EL NAVEGADOR SE MURIÓ Y NADIE LO SUPO (medido 2026-09-15, 17:12): el shell
529 # imprimió «[1]+ Done» a los ~25 s y la corrida siguió 420 s fotografiando un
530 # escritorio sin navegador, para terminar diciendo «no pintó». Un proceso que sale
531 # deja un CÓDIGO, y ese código es la diferencia entre «se cayó» y «se fue solo»; va
532 # al log, en el subshell, para que quede escrito aunque el arnés muera después.
533 print(ser.cmd("( %s; echo ATUQ-EXIT=$? ) > %s 2>&1 &" % (orden, log_atuq), fondo=True).strip())
534 print(f"== navegador lanzado; observando {a.wait}s", flush=True)
535 t0 = time.time(); n = 0
536 primera = None # segundos hasta la PRIMERA captura con la página en pantalla
537 donde = None
538 while time.time() - t0 < a.wait:
539 time.sleep(a.cadence); n += 1
540 tomas = capturar(qmp_sock, out, f"{fase}-durante-{n}")
541 t = int(time.time() - t0)
542 medidas = {p: pintado(f) for p, f in tomas.items()}
543 px = max((v for v in medidas.values() if v is not None), default=None)
544 donde = next((p for p, v in medidas.items() if v and v > 100_000), None)
545 if primera is None and px and px > 100_000:
546 primera = t
547 print(f" +{t}s ██ PRIMERA PINTURA — {px} px de la página EN {donde}", flush=True)
548 if a.until_paint:
549 break
550 else:
551 vivos = ser.cmd("for c in /proc/[0-9]*/comm; do cat $c 2>/dev/null; done | grep -c atuq")
552 v = vivos.splitlines()[1].strip() if len(vivos.splitlines()) > 1 else "?"
553 detalle = " ".join(f"{p}={medidas[p]}" for p in PANTALLAS)
554 print(f" +{t}s px de la página: {detalle} procesos atuq: {v}", flush=True)
555
556 capturar(qmp_sock, out, "%s-despues" % fase)
557 print("== captura DESPUES de la fase", flush=True)
558
559 # EL NÚMERO. No «pinta / no pinta»: CUÁNTO TARDA. Medido el 2026-09-14 sobre esta
560 # misma imagen, la primera pintura cae entre +137 s y +204 s con el perfil por
561 # defecto y ~+134 s con uno nuevo en tmpfs — y con la máquina anfitriona cargada pasa
562 # de los +300 s. Por eso el presupuesto es HOLGADO y se dice el número siempre: un
563 # guardián que sólo contestara «no pintó» a los 5 min habría firmado el error del
564 # §6.10.ter.
565 if primera is None:
566 print(f"✗ el navegador NO pintó en {a.wait}s — mirá {out}/{fase}-despues.png y el MOZ_LOG:")
567 print(" `mapped 1` + «marked as visible & has buffer» + WaylandBufferSHM ⇒ estaba pintando"
568 " y la captura llegó antes; sin eso, es un fallo de verdad")
569 rc[0] = 1
570 else:
571 print(f"✓ primera pintura: +{primera}s (presupuesto {a.budget}s)")
572 if primera > a.budget:
573 print(f"✗ tardó {primera - a.budget}s MÁS que el presupuesto")
574 rc[0] = 1
575
576 if perfil_d and a.as_user:
577 # ⚠ EL ESTADO FINAL ES PARTE DE LA PRUEBA: el número cambia DENTRO de la
578 # corrida —lo escribe el ARRANQUE al encontrar el anterior sin terminar, no el
579 # kill— así que sin el «después» no se puede encadenar una corrida con la
580 # siguiente, que es lo que convierte esto en una serie legible (medido:
581 # 2 → 3 → 4 en tres fases de un mismo arranque). Se lee con el navegador
582 # todavía vivo, o sea que refleja el último volcado de prefs de Gecko.
583 volcado = ser.cmd("grep -E 'toolkit.startup.recent_crashes' %s/prefs.js || "
584 "echo '(el pref no está: arranque sin caídas pendientes)'"
585 % perfil_d, 60)
586 estado["recent_crashes_despues"] = leer_contador_de_caidas(volcado)
587 print("---- el contador de caídas, DESPUÉS ----")
588 print(volcado.strip())
589 # ⚠ SÓLO LA FASE BASE SE ANOTA. La serie de `primera-pintura.json` es una TASA del
590 # producto tal como se entrega; una fase con el tamaño de ventana sembrado a mano es
591 # otro experimento, y mezclarlos haría que el denominador dejara de significar nada.
592 if semilla is None:
593 anotar_medicion(primera, a, donde if primera is not None else None, estado)
594 else:
595 print(" (fase con semilla: NO se anota en la serie de la tasa)")
596
597 # La evidencia que no se puede leer de una captura: cómo terminó el proceso, qué se
598 # quejó el chrome, y qué hizo el widget de Wayland.
599 # QUÉ QUEDÓ PERSISTIDO. `browser.xhtml` lleva `persist="… width height sizemode"`,
600 # así que el tamaño con el que terminó la ventana se ESCRIBE en el perfil y lo hereda
601 # la corrida siguiente: si una corrida sale de 117×70 y lo guarda, el fallo se
602 # aprende. Sin este volcado, «intermitente» y «contagiado» se ven igual.
603 if perfil_d:
604 print("---- el perfil, DESPUÉS: qué tamaño quedó recordado ----")
605 print(ser.cmd("cat %s/xulstore.json 2>/dev/null || echo '(no escribió xulstore.json)'"
606 % perfil_d, 60))
607 print("---- cómo terminó, y de qué se quejó el chrome ----")
608 print(ser.cmd("grep -a -E 'ATUQ-EXIT|JavaScript error|Uncaught|NS_ERROR|###!!!' "
609 "%s | head -25" % log_atuq, 120))
610 print("---- atuq.log (cabeza) ----")
611 print(ser.cmd("head -20 %s" % log_atuq, 60))
612 print("---- atuq.log (cola) ----")
613 print(ser.cmd("tail -20 %s" % log_atuq, 60))
614 print("---- MOZ_LOG: creación de la ventana ----")
615 print(ser.cmd("grep -a -m 40 -E 'nsWindow::Create|CreateNative|Map|configure|Show|frame callback|Buffer' "
616 "%s.moz_log | head -40" % log_moz, 120))
617 # QUÉ PANTALLA VE GECKO — contestado el 2026-09-15 y por eso se queda: la sonda que
618 # ya contestó es la que avisa cuando la respuesta cambia. `New monitor 0 size
619 # [0,0 -> 1280 x 800]` ANTES de `Initial resize to 1 x 1` ⇒ la geometría de la salida
620 # NO es lo que falta.
621 print("---- MOZ_LOG: pantallas que ve Gecko y tamaños del nsWindow ----")
622 print(ser.cmd("grep -a -E 'WidgetScreen|Screen\\[|AddScreen|nsWindow::Resize|Initial resize|"
623 "SetSizeMode|OnConfigure|SizeAllocate|LockAspect' "
624 "%s.moz_log | head -50" % log_moz, 180))
625 # Y lo que dice el propio navegador, desde la página, por `dump()`: `screen=` es lo
626 # que el contenido ve de la pantalla y `outer=` el tamaño de la ventana. Dos fuentes
627 # independientes para el mismo número; si se contradicen, eso también es un dato.
628 print("---- la página: ATUQ-DIAG ----")
629 print(ser.cmd("grep -a ATUQ-DIAG %s | head -10" % log_atuq, 120))
630 print("---- MOZ_LOG: últimas líneas ----")
631 print(ser.cmd("tail -25 %s.moz_log" % log_moz, 60))
632 # El otro lado de la conversación. Gecko commitea a ciegas cuando nadie le devuelve
633 # frame callbacks (§6.10.nonies), y eso lo decide el COMPOSITOR: sin su log, «no
634 # pinta» sólo se puede mirar desde el cliente, que es la mitad que ya sabemos miente.
635 if a.wayland_debug:
636 # ⚠ EN `WAYLAND_DEBUG` LA FLECHA ES DEL CLIENTE. `-> obj.metodo()` es un PEDIDO
637 # que manda el navegador; los EVENTOS del compositor son las líneas SIN flecha.
638 # Filtrar por `->` es leer otra vez al cliente. Y los nombres llevan `@id` en el
639 # medio, así que `wl_surface.commit` no engancha: hay que anclar en el método.
640 # QUIÉN ELIGE EL TAMAÑO: `attach` no lo dice —el tamaño del buffer está en
641 # `create_buffer(…, W, H, stride, fmt)`— y lo que el cliente DECLARA querer está
642 # en `set_window_geometry`. Puestos en orden y en los DOS sentidos se ve quién
643 # propone (contestado en el §6.10.duodecies: lo propone el cliente).
644 print("---- protocolo: el tamaño, en orden (→ = pedido del cliente) ----")
645 # ⚠ El filtro EXCLUYE `mode(0,`: QEMU anuncia ~60 modos no-actuales y con ellos
646 # dentro el `head` cortaba ANTES del `set_window_geometry` — la lista que existe
647 # para ordenar dos cosas se quedaba sin una de las dos.
648 print(ser.cmd("grep -a -n -E 'create_buffer|set_window_geometry|configure|ack_configure|"
649 "get_toplevel|set_min_size|set_max_size|set_title|set_app_id|\\.attach|"
650 "wl_output|\\.mode\\(|\\.geometry\\(|\\.done\\(\\)' "
651 "%s | grep -av 'mode(0,' | head -80" % log_atuq, 240))
652 print("---- protocolo: EVENTOS del compositor (sin flecha) ----")
653 print(ser.cmd("grep -av ' -> ' %s | "
654 "grep -a -E 'xdg_surface|xdg_toplevel|wl_callback|wl_output|wl_surface' | "
655 "tail -40" % log_atuq, 180))
656 print("---- cosmic-comp: superficies, salidas y foco ----")
657 print(ser.cmd("grep -a -i -E 'output|workspace|focus|toplevel|surface|xdg|map' "
658 "/var/log/cosmic/cosmic-session.log | tail -40", 120))
659 print("---- tamaño de los logs ----")
660 print(ser.cmd("wc -l /var/log/cosmic/atuq-*.log /var/log/cosmic/moz-*.moz_log "
661 "/var/log/cosmic/cosmic-session.log /var/log/cosmic/cosmic-start.log", 30))
662 finally:
663 try:
664 qmp(qmp_sock, [{"execute": "quit"}])
665 except Exception:
666 pass
667 time.sleep(2); vm.terminate()
668 try:
669 vm.wait(20)
670 except Exception:
671 vm.kill()
672
673 # Las capturas salen en PPM (lo único que sabe QMP); a PNG para poder mirarlas.
674 try:
675 from PIL import Image
676 for f in sorted(os.listdir(out)):
677 if f.endswith(".ppm"):
678 Image.open(os.path.join(out, f)).save(os.path.join(out, f[:-4] + ".png"))
679 print("== capturas convertidas a PNG en", out)
680 except Exception as e:
681 print(" ⚠ sin conversión a PNG:", e)
682 return rc[0]
683
684
685if __name__ == "__main__":
686 sys.exit(main())