sergio/takana
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

arnés de la imagen: el contador de caídas viaja con la medición, y las envenenadas se apartan

Browse Source 
`atuq-en-imagen.py` ahora lee `toolkit.startup.recent_crashes` del perfil ANTES y DESPUÉS de cada
corrida y lo anota junto al tiempo de primera pintura (`recent_crashes_antes` / `_despues` /
`_fijado`). Los dos volcados, no uno: Gecko BORRA el contador al mostrar el diálogo de Modo de
resolución de problemas, así que un perfil envenenado se ve limpio si se lo mira después — y la
corrida siguiente parece arreglarse sola mientras la anterior parece intermitente.

Con eso, `vigia-imagen.py` saca de la tasa las corridas con el contador > 3 (ahí el sujeto no es el
navegador sino un diálogo modal) y para las 21 anteriores al campo dice que NO SE PUEDEN CLASIFICAR
en vez de contarlas como buenas. Un denominador se marca, no se borra.

Mandos y guardas nuevas:

· `--crashes N` fija el contador en el `user.js` del perfil: 0 limpia, >3 reproduce. Es el control en
  los dos sentidos, que es lo único que distingue causa de correlación con suerte;
· `WidgetScreen:5` en el MOZ_LOG y una sonda `ATUQ-DIAG` en la propia página (screen/outer/inner por
  `dump()`), que es lo que refutó la carrera con `wl_output`;
· la lista ordenada del protocolo ya no se ahoga en los ~60 modos que anuncia QEMU —el `head`
  cortaba antes del `set_window_geometry`— y trae `set_title`/`set_app_id`, que es lo que identificó
  la ventana;
· si QEMU no arranca, se dice en el primer segundo leyendo `qemu.log`. El fallo real es «Failed to
  get write lock» con otra VM sobre la misma imagen, y sin esta guarda se veía como diez minutos
  esperando una marca del serial: el socket queda creado y el `connect()` funciona.

Las fases (`--xulstore`), el `ATUQ-EXIT=$?`, la copia del log del arranque anterior y el `find` del
perfil sobre la raíz entera los escribió la otra sesión que trabaja este frente; conviven acá porque
el fichero es compartido.
This commit is contained in:
Sergio
2026-09-15 17:46:30 +00:00
parent 70107b1685
commit 2f90d8eb40
2 changed files with 350 additions and 109 deletions
Download Patch File Download Diff File Expand all files Collapse all files
scripts/cosmic/atuq-en-imagen.py
+324 -109
View File
@@ -23,7 +23,7 @@ del serial es exactamente desde donde un usuario lanzaría una app — y por eso
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
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.
@@ -150,7 +150,26 @@ def pintado(ppm):
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):
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 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
@@ -174,6 +193,12 @@ def anotar_medicion(segundos, a, pantalla=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
@@ -228,6 +253,15 @@ def main():
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, >3 reproduce el diálogo de Modo de resolución de "
"problemas. Sólo tiene efecto con --as-user")
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("--out", default=os.path.join(RAIZ, "work/atuq-imagen"))
a = ap.parse_args()
@@ -262,6 +296,17 @@ def main():
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)
@@ -295,124 +340,294 @@ def main():
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("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>' > /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
"<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.
volcado = ser.cmd("grep -E 'toolkit.startup.(recent_crashes|max_resumed)|"
"browser.sessionstore.max_resumed' %s/prefs.js" % d, 60)
print(volcado.strip())
estado["recent_crashes_antes"] = leer_contador_de_caidas(volcado)
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)
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
capturar(qmp_sock, out, "despues")
print("== captura DESPUES", flush=True)
def matar_al_navegador():
"""Deja la sesión sin ningún `atuq` vivo antes de la fase siguiente.
# 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")
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).
"""
ser.cmd("for p in /proc/[0-9]*; do grep -q atuq $p/comm 2>/dev/null && "
"kill ${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))
for fase, semilla in fases:
print("\n===== FASE «%s» =====" % fase, flush=True)
if semilla:
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)
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, "%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
# 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)
if perfil_d and a.as_user:
# ⚠ EL ESTADO FINAL ES PARTE DE LA PRUEBA. Gecko BORRA el contador después de
# mostrar el diálogo, así que un perfil envenenado se ve limpio en cuanto se
# lo mira DESPUÉS: sin este segundo volcado, la corrida siguiente parece
# «arreglada sola» y la anterior parece intermitente. Se lee con el navegador
# todavía vivo, o sea que refleja el último volcado de prefs de Gecko.
volcado = ser.cmd("grep -E 'toolkit.startup.recent_crashes' %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)
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: 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.
# 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 si el 117×70
# lo propone el cliente (y el compositor lo repite) o lo impone el compositor.
print("---- protocolo: el tamaño, en orden (→ = pedido del cliente) ----")
# Va `wl_output` en la MISMA lista y numerada: la pregunta es si la geometría de
# la salida (`mode`) llega ANTES o DESPUÉS de que el cliente fije su tamaño. Con dos
# greps separados eso no se puede ordenar.
print(ser.cmd("grep -a -n -E 'create_buffer|set_window_geometry|configure|ack_configure|"
"get_toplevel|set_min_size|set_max_size|\\.attach|wl_output|\\.mode\\(|"
"\\.geometry\\(|\\.done\\(\\)' "
"/var/log/cosmic/atuq.log | head -70", 240))
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))
# 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("---- 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 "
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:
scripts/vigia-imagen.py
+26
View File
@@ -286,18 +286,44 @@ def informe_primera_pintura():
and "dos DRM" in (c.get("video") or "")
and c.get("segundos_primera_pintura") is None]
corridas = [c for c in corridas if c not in ciegas]
# ⚠ Y SE SEPARAN LAS CORRIDAS CON EL PERFIL ENVENENADO. Medido el 2026-09-15 (§6.10.terdecies):
# con `toolkit.startup.recent_crashes` por encima de `max_resumed_crashes` —3 por defecto— el
# navegador NO abre una ventana de navegador: abre el diálogo de Modo de resolución de problemas,
# que es modal y mide 117×70. El ✗ de esas corridas es cierto y no dice NADA del producto. Y el
# contador lo subía este mismo andamiaje al matar la VM con el navegador vivo, así que la serie
# vieja está contaminada: las corridas anteriores a que el arnés anotara el campo NO SE PUEDEN
# clasificar, y eso se dice en vez de contarlas como si fueran buenas.
def envenenada(c):
fijado = c.get("recent_crashes_fijado") # lo que PUSO el arnés (user.js gana)
valor = fijado if fijado is not None else c.get("recent_crashes_antes")
return valor is not None and valor > 3
envenenadas = [c for c in corridas if envenenada(c)]
corridas = [c for c in corridas if c not in envenenadas]
sin_clasificar = [c for c in corridas if "recent_crashes_antes" not in c
and c.get("recent_crashes_fijado") is None]
pintaron = [c["segundos_primera_pintura"] for c in corridas
if c.get("segundos_primera_pintura") is not None]
n, m = len(pintaron), len(corridas)
marca = "✓" if n == m else ("✗" if n == 0 else "⚠")
if ciegas:
marca = "⚠" # con corridas ciegas de por medio, un 6/6 no es un ✓: es un «lo que se pudo medir»
if sin_clasificar:
marca = "⚠" # una tasa con corridas de procedencia desconocida adentro no es una tasa
if pintaron:
print(" %s pintaron %d de %d corridas CONCLUYENTES · primera pintura %s"
% (marca, n, m,
("+%ds" % pintaron[0]) if n == 1 else "+%d…+%ds" % (min(pintaron), max(pintaron))))
else:
print(" %s NINGUNA de %d corridas pintó" % (marca, m))
if envenenadas:
print(" ⊘ %d corridas APARTE: el perfil tenía recent_crashes > 3 ⇒ lo que abrió fue el "
"diálogo de Modo de resolución de problemas, no el navegador (SDD 26 §6.10.terdecies)"
% len(envenenadas))
if sin_clasificar:
print(" ⚠ %d de esas %d corridas son de ANTES de que se anotara el contador de caídas: "
"no se puede decir si midieron el navegador o el diálogo" % (len(sin_clasificar), m))
for c in corridas[-6:]:
seg = c.get("segundos_primera_pintura")
print(" %s %-9s %-10s %-22s %-26s %s"