El test pasaba con el fallo puesto

La 0.9.2 arregla una molestia vieja. Cuando la herramienta termina de rastrear tu sitio, todavía le queda comprobar el estado de los enlaces que salen de él, y eso va a la velocidad del servidor más lento de otra persona, con una sola petición en vuelo por cada host ajeno, por educación. Durante esa espera, la línea de progreso decía algo así:

5,865 crawled · 1,204 queued · 65 URL/s · 2,834 findings

Mil doscientas URLs en cola que no eran tuyas: eran sondas a sitios ajenos, sumadas al mismo contador sin ninguna etiqueta. Y como del sitio ya no quedaba nada por rastrear, el número dejaba de bajar durante minutos. Un proceso vivo, con la CPU parada, sin decir a qué espera. Cualquiera lo mata, y matarlo a destiempo es como se pierde el volcado del diario de SQLite.

Ahora las sondas viajan en su propio contador y la línea lo dice:

5,865 crawled · checking external links · 1,204 left · 2,834 findings

Mientras el sitio avanza, las sondas quedan como un apunte al margen. El arreglo es pequeño y la versión también, un 0.9.2: no cambia ni un dato del rastreo ni el comportamiento de ninguna regla.

Y aun así hay dos cosas que aprendí escribiéndolo.

El contador que se habría quedado colgado

Para separar las dos cuentas hace falta saber cuántas peticiones en vuelo son sondas, y eso no lo sabe el pool: dentro conviven las dos clases. Se lleva a mano, sumando uno al despachar una sonda y restando uno al recibir su respuesta.

Puse el decremento donde parecía natural, en el brazo que maneja la respuesta de una sonda. Al releerlo vi que hay dos brazos que la manejan: el general, y uno anterior para el caso en que el nombre resolvió a una dirección que el perímetro rechaza. Ese segundo caso también consume una sonda en vuelo, y con el decremento solo en el primero, el contador se habría quedado alto para siempre en cuanto apareciera un enlace a una dirección prohibida. La barra habría dicho «quedan 3 sondas» hasta el final del rastreo.

Se arregla moviéndolo antes del reparto por casos, donde vale para todos. No lo encontró ningún test; lo encontró releer lo que acababa de escribir con la pregunta de «¿hay otro sitio por donde pase esto?».

El test que no protegía de nada

Aquí está lo que de verdad merece el post. Escribí un test del emisor de progreso: se le pasan unos números, se comprueba que la instantánea que entrega trae la cola del sitio por un lado y las sondas por otro. En verde a la primera.

En este proyecto hay una regla de la casa: un test que no has visto fallar no protege de nada. Así que reverté el arreglo del motor —volví a sumar las sondas al contador del sitio, que era el fallo original— y ejecuté el test esperando el rojo.

Siguió verde.

El motivo, una vez visto, es evidente. El emisor nunca estuvo roto: hace lo que le mandan con los números que le dan. Lo que estaba mal era quién le pasa esos números, en el bucle del rastreo, que sumaba dos cosas distintas antes de entregarlas. Mi test le daba los números ya separados y comprobaba que los entregaba separados. Comprobaba que dos más dos son cuatro.

El test bueno tuvo que mirar el rastreo entero: un servidor de pruebas haciendo de host ajeno que responde a 300 milisegundos, dos enlaces externos, y un observador de progreso apuntando el máximo de cada contador. Con eso, revertir el cableado sí da rojo, y el mensaje dice por qué: «alguna instantánea tuvo que enseñar sondas pendientes».

Los 300 milisegundos tampoco son arbitrarios, y esa fue la tercera lección de la tarde. Con un retardo de 120 el test falló, y no por el fallo: el emisor muestrea cada 150 milisegundos, el rastreo entero duraba menos que eso y solo llegaba a emitir la instantánea inicial, con los contadores a cero. Un test de tiempos que no respeta los tiempos del sistema que prueba mide otra cosa.

Por qué esto pasa más de lo que parece

Es la tercera vez este mes que un test de este proyecto pasa con su fallo puesto, y las tres veces el patrón ha sido el mismo: el test apunta a la pieza que está bien y no a la costura entre dos piezas. Es fácil de entender —la pieza es lo que acabas de escribir y la tienes en la cabeza— y la costura es justo donde se rompen las cosas.

De ahí que la comprobación no sea «¿pasa el test?» sino «¿lo he visto fallar por el fallo que digo que cubre?». Son treinta segundos y es la diferencia entre un test y un adorno. En la entrada de ayer ese mismo hábito destapó un fallo del planificador que llevaba semanas ahí.

El resto del balance de la 0.9.2: 1.036 pruebas en verde, el análisis estático sin quejas y la regresión de rendimiento compilada con optimizaciones en 107.702 elementos por segundo con 30,1 MB de memoria máxima. Los dos tests nuevos se quedan, el del emisor incluido: comprueba poco, pero lo que comprueba es cierto y cuesta microsegundos.