diff --git a/scripts/cosmic/atuq-en-imagen.py b/scripts/cosmic/atuq-en-imagen.py index 1705c74c..07c46191 100755 --- a/scripts/cosmic/atuq-en-imagen.py +++ b/scripts/cosmic/atuq-en-imagen.py @@ -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' '" - "

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 + "

ATUQ PINTA

' > /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: diff --git a/scripts/vigia-imagen.py b/scripts/vigia-imagen.py index cef8c4f4..b43bcc3e 100644 --- a/scripts/vigia-imagen.py +++ b/scripts/vigia-imagen.py @@ -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"