#!/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, 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». 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 anotar_medicion(segundos, a, pantalla=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", } # ⚠ 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("--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) 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 /tmp/perfil /var/log/cosmic") ser.cmd("printf '%s' '" "

ATUQ PINTA

' > /tmp/pagina.html") ser.cmd("printf '%s\\n' 'user_pref(\"browser.dom.window.dump.enabled\", true);' > /tmp/perfil/user.js") ser.cmd("printf '%s\\n' 'user_pref(\"browser.shell.checkDefaultBrowser\", false);' >> /tmp/perfil/user.js") # ⚠ LOS DOS LANZAMIENTOS NO SON EL MISMO EXPERIMENTO. El de por defecto fija el # entorno (perfil nuevo, `MOZ_ENABLE_WAYLAND`) para que la medición no dependa de lo que # haya quedado en el estado del usuario; `--como-usuario` reproduce lo que se tecleó a # mano en el §6.10.ter —`atuq` pelado, con SU perfil y sin variables— que es lo único que # sigue distinto entre aquella corrida y ésta. El `MOZ_LOG` va en los dos: no cambia el # comportamiento, sólo deja rastro. wd = "WAYLAND_DEBUG=1 " if a.wayland_debug else "" if a.as_user: lanz = (wd + "MOZ_LOG='Widget:5,WidgetWayland:5,WaylandBackend:5,timestamp' " "MOZ_LOG_FILE=/var/log/cosmic/moz " "/usr/bin/atuq file:///tmp/pagina.html > /var/log/cosmic/atuq.log 2>&1 &") else: lanz = (wd + "MOZ_ENABLE_WAYLAND=1 GDK_BACKEND=wayland " "MOZ_LOG='Widget:5,WidgetWayland:5,WaylandBackend:5,timestamp' " "MOZ_LOG_FILE=/var/log/cosmic/moz " "/usr/bin/atuq --no-remote --profile /tmp/perfil file:///tmp/pagina.html " "> /var/log/cosmic/atuq.log 2>&1 &") print(ser.cmd(lanz, 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 while time.time() - t0 < a.wait: time.sleep(a.cadence); n += 1 tomas = capturar(qmp_sock, out, f"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) 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}", flush=True) if a.until_paint: break 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}", flush=True) capturar(qmp_sock, out, "despues") print("== captura DESPUES", 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}/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 # El número se PUBLICA donde lo pueda leer el vigía de la imagen, que es estático y no # arranca nada: sin esto el dato vive en el scrollback del que corrió la VM y se pierde, # que es exactamente lo que pasó con la corrida a mano del §6.10.ter. anotar_medicion(primera, a, donde if primera is not None else None) # La evidencia que no se puede leer de una captura: qué hizo el widget de Wayland. print("---- atuq.log (cola) ----") print(ser.cmd("tail -25 /var/log/cosmic/atuq.log", 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' " "/var/log/cosmic/moz.moz_log | head -40", 120)) print("---- MOZ_LOG: últimas líneas ----") print(ser.cmd("tail -25 /var/log/cosmic/moz.moz_log", 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 que miente. if a.wayland_debug: # Lo que INTERESA no es lo que pide el cliente sino lo que llega de vuelta: las # líneas `[ ]` de entrada son eventos DEL COMPOSITOR. Sin `wl_callback.done` no # hay frame callbacks, que es exactamente la hipótesis del §6.10.nonies. # ⚠ 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, que es justo la mitad que ya sabemos que # miente. Y los nombres llevan `@id` en el medio, así que `wl_surface.commit` no # engancha: hay que anclar en el método. print("---- protocolo: EVENTOS del compositor (sin flecha) ----") print(ser.cmd("grep -av ' -> ' /var/log/cosmic/atuq.log | " "grep -a -E 'xdg_surface|xdg_toplevel|wl_callback|wl_output|wl_surface' | " "tail -40", 180)) print("---- protocolo: cuentas (evento = sin flecha) ----") print(ser.cmd("for k in xdg_toplevel# xdg_surface# wl_callback# wl_output#; do " "printf 'EVENTOS %s ' $k; grep -av ' -> ' /var/log/cosmic/atuq.log | " "grep -ac $k; done", 180)) print(ser.cmd("printf 'done() '; grep -av ' -> ' /var/log/cosmic/atuq.log | " "grep -ac 'done('; printf 'configure() '; grep -av ' -> ' " "/var/log/cosmic/atuq.log | grep -ac 'configure('", 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("---- cosmic-comp: últimas líneas ----") print(ser.cmd("tail -30 /var/log/cosmic/cosmic-session.log", 60)) print("---- tamaño de los logs ----") print(ser.cmd("wc -l /var/log/cosmic/moz.moz_log /var/log/cosmic/atuq.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())