¿Qué pasó con Vivaldi Social?

• El 8 de julio de 2023, en la instancia de Mastodon de Vivaldi Social desaparecieron cuentas de usuario antiguas y, finalmente, 198 cuentas terminaron fusionadas en una sola cuenta remota
• La causa no fue una eliminación manual ni un ataque, sino una combinación entre el comportamiento de fusión de cuentas de Mastodon y la configuración de replicación de PostgreSQL basada en Makara en Vivaldi Social, lo que desordenó la secuencia de operaciones
• Aunque las cuentas parecían haber sido borradas, los nombres de usuario volvieron a asignarse y también desaparecieron las imágenes de avatar y cabecera, lo que acotó el problema al funcionamiento interno de la aplicación Mastodon
• El equipo de operaciones preparó un rollback completo de la base de datos, pero al mismo tiempo desarrolló scripts de recuperación selectiva para restaurar cuentas, publicaciones, follows, followers y datos de relaciones
• Mastodon v4.1.5 incluye el bloqueo del uso de Makara en los workers de Sidekiq y una corrección del orden de la fusión de cuentas, por lo que los operadores de servidores que usan bases de datos replicadas deben revisar la ruta de lectura de sus workers

---

El incidente del fin de semana en el que desaparecieron 198 cuentas

• El sábado 8 de julio de 2023, alrededor de las 17:25 CEST, la pestaña de Vivaldi Social volvió a pedir inicio de sesión y, tras entrar, se comprobó que la línea de tiempo de inicio estaba vacía
• El mismo síntoma apareció en otras cuentas de administradores del sistema y, al revisar la base de datos, se vio que las cuentas afectadas estaban siendo eliminadas y luego recreadas como si fueran cuentas nuevas cuando el usuario volvía a iniciar sesión
• Vivaldi Social contaba con un respaldo nocturno del viernes a las 23:00 UTC, y el equipo comenzó a copiar los archivos de backup para confirmar las posibilidades de recuperación
• En una eliminación normal de cuentas en Mastodon, el nombre de usuario queda reservado permanentemente y no se reutiliza, pero en este incidente el mismo nombre volvió a asignarse, así que no se trataba de una eliminación normal

La eliminación seguía en curso

• Al principio, habían desaparecido cuentas antiguas con ID menor a 142, y a las 19:10 ya habían desaparecido cuentas con ID menor a 217, lo que reveló que la eliminación seguía en progreso
• A las 19:18 se pidió ayuda a los desarrolladores de Mastodon, y tras responder Renaud, Claire y Eugen también se sumaron a la investigación
• A las 19:20, al reiniciar las instancias Docker de Mastodon, la eliminación se detuvo y el ID de cuenta más bajo en la base de datos pasó a ser 236
• Durante el incidente, se confirmó que el total de cuentas eliminadas o fusionadas fue finalmente de 198

Se acotó a un comportamiento de la aplicación, no a un ataque

• El equipo de operaciones y los desarrolladores de Mastodon verificaron si UserCleanupScheduler podía haber eliminado cuentas “unconfirmed”, pero se descartó porque los usuarios eliminados no podían cumplir las condiciones de esa consulta
• Como Mastodon se había actualizado a la versión 4.1.3 48 horas antes del incidente, se revisaron los cambios entre v4.1.2 y v4.1.3, así como los cambios publicados por Vivaldi, pero no se encontró una causa relacionada
• En el sistema de archivos también desaparecieron los avatares e imágenes de cabecera de las cuentas eliminadas, lo que confirmó que no fue una eliminación directa en la base de datos, sino una operación de borrado ejecutada por la aplicación Mastodon
• Se buscaron rastros de intrusión o ataque en los logs y en el sistema de archivos, pero no hubo evidencia, y tampoco se confirmó la posibilidad de un exploit relacionado con los parches de seguridad de Mastodon v4.1.3
• La noche del sábado se desplegó un parche para añadir logs sobre las operaciones de eliminación de cuentas y, después de publicar la versión parcheada a las 00:29 CEST, el equipo tomó un descanso

La pista decisiva: publicaciones concentradas en una cuenta remota

• El domingo a las 13:56 se reportó que la página de perfil del experto en seguridad de Vivaldi, Yngve, devolvía un error HTTP 500, y esa cuenta no estaba entre las 198 cuentas eliminadas
• En los logs aparecía repetidamente la misma cuenta de la misma instancia remota de Mastodon, y en el texto se la anonimiza como la cuenta de social.example.com
• La consulta de los status de esa cuenta remota devolvió 17,600 filas
• A las 14:43, al comparar con el backup, se confirmó que todos los status de todas las cuentas eliminadas habían sido reasignados a un solo usuario de social.example.com
• Después de las 15:00, mediante logs de AccountMergingWorker, la consola de Rails y consultas adicionales a la base de datos, tomó fuerza la hipótesis de que el worker de fusión de cuentas estaba fusionando todas las cuentas en una sola cuenta remota

Causa raíz: fusión de cuentas y retraso en la replicación de PostgreSQL

• Vivaldi Social usaba una configuración de replicación de 2 servidores PostgreSQL, y los procesos worker podían leer la base de datos desde el servidor standby mediante Makara
• El escenario del incidente planteado por Claire a las 17:28 fue el siguiente
  • Vivaldi Social recibe una notificación de cambio de nombre de cuenta proveniente de social.example.com
  • Al crearse la nueva cuenta en la base de datos, el campo URI entra con valor null
  • Luego, el URI de la nueva cuenta se actualiza con el valor correcto de la cuenta remota
  • A través de Redis, se programa la ejecución de AccountMergingWorker para fusionar los datos de la cuenta anterior en la nueva
  • Debido al retraso de replicación de la base de datos, el orden entre la asignación del URI y la programación de la ejecución del worker quedó invertido en el momento real de la lectura
• Como todas las cuentas locales de una instancia de Mastodon tienen el valor URI en null, el worker terminó haciendo match con todas las cuentas locales al fusionar cuentas con el mismo URI hacia la nueva cuenta remota
• Los desarrolladores consideraron que esto podía ocurrir con más facilidad cuando la carga de la base de datos aumentaba y el retraso de replicación se prolongaba
• El equipo de operaciones y los desarrolladores de Mastodon concluyeron que esta configuración era, con altísima probabilidad, la causa raíz

Parche y cambios de configuración

• Una vez acotada la causa, el equipo de operaciones se concentró en recuperar los datos, y Claire asumió la tarea de escribir un parche para evitar que volviera a ocurrir
• Hlini se encargó de aplicar el parche y de cambiar la configuración de replicación ya no recomendada
• A las 17:58 surgió un problema durante el despliegue y se produjo el único downtime total de ese fin de semana; a las 18:18 Vivaldi Social volvió a estar en línea
• A las 18:44 se desplegaron con éxito el parche y el cambio de configuración, y se consideró que el mismo incidente ya no volvería a repetirse

Recuperación: restauración selectiva en lugar de rollback completo

• Al principio se consideró un rollback completo de la base de datos, pero por problemas de rendimiento ya conocidos esto requería un procedimiento complejo: convertir el backup .dump a .sql y modificar un archivo de texto de 54 GB
• El equipo llevó en paralelo el procedimiento de restauración completa y la recuperación selectiva
  • Hlini modificó el archivo .sql de 54 GB y avanzó con la preparación de la restauración completa
  • Thomas escribió un script para restaurar las cuentas eliminadas y los datos relacionados
• Mientras se escribía el script, hubo un error al manejar por referencia el binding de parámetros de una consulta PDO, y Ísak lo detectó
• A las 23:04 quedó terminada la primera parte para corregir los registros de user, account e identity de los 198 usuarios afectados
• A las 23:55 quedó terminado el script de recuperación selectiva para devolver status, follows, followers y datos de relaciones al estado previo al incidente

Fin de la recuperación selectiva y correcciones posteriores

• Debido a las restricciones de relaciones en la base de datos, la recuperación se hizo en 2 etapas
  • Primero se restauraron los registros de user/account/identity de las 198 personas
  • Después se restauró el resto de los datos relacionales
• En algunos casos, usuarios que habían vuelto a iniciar sesión después del incidente establecieron follows otra vez, lo que provocó errores de clave duplicada; el script se modificó para eliminar los registros antiguos que no podían restaurarse y conservar los más recientes
• A la 01:27 CEST del lunes terminó la última tarea del script y a la 01:40 se completó la reindexación del feed de inicio
• Como resultado, se restauró el feed de inicio de las 198 cuentas y ya no fue necesario un rollback completo
• El lunes y el martes se corrigieron problemas adicionales
  • problemas de inicio de sesión en 6 cuentas con símbolos en el nombre de usuario
  • pérdida de datos de configuración web en las 198 cuentas
  • errores en contadores de perfil como número de followers y publicaciones
  • 4 cuentas que tenían datos incorrectos

La corrección oficial de Mastodon

• Los desarrolladores de Mastodon alertaron a otros operadores de servidores sobre el riesgo de usar Mastodon con una configuración de replicación basada en Makara
• Se concluyó que este tipo de configuración es poco común, ya que normalmente solo podría considerarse en instancias grandes como Vivaldi Social
• Mastodon v4.1.5 incluye dos correcciones relacionadas con este incidente
  • Evitar el uso de Makara en workers de Sidekiq
  • Corrección para garantizar el orden correcto de operaciones en la fusión de cuentas

Línea de tiempo del incidente en UTC

• Sábado 15:15: desde una instancia externa llega a Vivaldi Social un mensaje de cambio de nombre de cuenta y comienza la fusión errónea de cuentas
• Sábado 15:25: se observa la primera señal del incidente
• Sábado 17:20: tras reiniciar los contenedores Docker, se detiene la fusión de cuentas; entre las 15:15 y las 17:20 se eliminan o fusionan un total de 198 cuentas
• Domingo 13:00: se identifica una posible causa raíz
• Domingo 14:25: se confirma la causa raíz
• Domingo 21:55: comienza la recuperación de datos
• Domingo 23:27: termina la recuperación de datos
• Lunes 10:40: se corrigen 6 cuentas con símbolos en el nombre de usuario
• Lunes 11:05: se restauran los datos perdidos de configuración web
• Martes 15:31: se corrigen valores incorrectos en los contadores
• Martes 16:01: se corrigen 4 cuentas con datos incorrectos

[GN⁺]

Opiniones en Hacker News

• Fue una excelente retrospectiva y, en particular, también reflejó muy bien cuánto influyen los costos humanos, como la falta de sueño, en la resolución de incidentes complejos.
  La parte que más me llamó la atención fue: “se creó una cuenta nueva en la base de datos con un valor null en el campo URI”.
  Cada vez que leo un análisis post mortem relacionado con bases de datos, casi siempre NULL está escondido cerca de la escena del incidente. Aunque NULL no sea el culpable, siempre hay que incluirlo entre los sospechosos.
  Como consejo, no conviene depender de NULL como valor centinela y, si es posible, es mejor no permitirlo directamente en la base de datos. Aunque parezca tener ventajas, años después, cuando cambie el significado del modelo de datos, algún enunciado aparentemente inofensivo esperará NULL o NOT NULL y eso terminará compensándose con un bug difícil de encontrar que produce resultados inesperados.
  En este caso fue una condición de carrera, pero si las cuentas locales y remotas se hubieran distinguido claramente por tipo, el orden de las operaciones quizá no habría importado, y el código de fusión de cuentas también podría haberse limitado a un alcance más acotado.

  • Finalmente me creé una cuenta para responder a esto; espero no sonar demasiado agresivo.
    Null es un valor de datos completamente válido y debe tratarse como tal. Valores por defecto como usar -1 para un booleano o una cadena vacía para un string pueden hacer que un sistema que habría fallado en tiempo de ejecución si fuera NULL parezca funcionar, pero eso no significa que el sistema esté funcionando como se espera; solo queda silencioso.
    Entiendo la tentación de tapar NULL, pero “ausente” es un estado de datos tan válido como “presente”, y por lo general los sistemas deberían escribirse para aceptarlo.
  • ¿La alternativa es una cadena vacía?
    En este caso, creo que el problema no es el NULL de la base de datos, sino el NULL en la capa de aplicación.
    Si NULL fuera un valor que hay que manejar obligatoriamente, como una especie de mónada Maybe, al final lo terminarías manejando y pensando en él. No hay gran diferencia entre una cadena vacía, el string null del lenguaje que uses o un valor marcador especial creado por uno mismo.
  • La fusión automática/eliminación de duplicados es uno de esos problemas muy difíciles en los que, al tratar registros “similares”, debería intervenir una persona tanto como sea posible. Está lleno de casos excepcionales y condiciones de carrera, y en especial los datos consumidos de forma asíncrona deberían transmitirse de la forma más explícita posible, además de pasar por varias comprobaciones para verificar que los hechos reales no hayan cambiado.
    En muchos casos, quien implementa debería empezar pensando en las preocupaciones y requisitos de interacción que exige un conflicto de merge al estilo Git, y desde ese punto de partida definir supuestos simplificadores adecuados al dominio del problema.
    Al mirar el código fuente de Mastodon https://github.com/mastodon/mastodon/blob/main/app/workers/a..., ni siquiera parece haber una lista explícita de “desde qué IDs fusionar” que el lado que inicia la solicitud de fusión le pase al ejecutor asíncrono de la fusión, así que parece que era cuestión de tiempo que ocurriera algo así.
    No es una crítica a Mastodon. Yo mismo escribí lógica de fusión con condiciones de carrera mucho peores y sufrí sus consecuencias. De hecho, que una funcionalidad así exista en un proyecto voluntario como https://opencollective.com/mastodon es sorprendente en sí mismo. Aun así, es un caso para tener presente.
  • Si usas JOIN, NULL es inevitable. Porque así es como funciona JOIN.
    Más en profundidad, NULL es inevitable porque la realidad es desordenada y una base de datos no puede negarse a procesarla solo porque la realidad sea desordenada. Por ejemplo, supongamos que quieres modelar tratamientos honoríficos, títulos antepuestos y títulos pospuestos, y usar esos datos para construir un saludo completo: al menos habrá personas sin título pospuesto. Aunque no guardes NULL, obtendrás NULL como resultado del JOIN que usas para construir el saludo.
    Puedes eliminar ciertos valores NULL, pero no puedes eliminar el hecho de que en la realidad “no aplica” o “desconocido” muchas veces son valores válidos, y la base de datos tiene que lidiar con eso.
  • Aunque exista null, la función de fusión debería haber hecho de alguna manera una comprobación de null o de valor verdadero. Es difícil de creer.

• El flujo con el que me identifico aquí empieza con “tenemos una copia de seguridad completa de la base de datos, así que basta con hacer una restauración completa”, pasa a “una restauración completa es difícil y tiene downtime y efectos secundarios”, luego vuelve a “podríamos restaurar inteligentemente solo los datos faltantes”, después se hace manualmente, aparece un error raro, al final se despliega una restauración selectiva improvisada y, por último, se limpian los cinco datos faltantes finales. Esperando no haber pasado por alto un sexto.
  Cada vez que alguien practica backup/restauración, termina yendo más o menos así. Al final, decidir qué datos recuperar desde una imagen de backup siempre termina siendo algo que debe resolverse a nivel de aplicación.

  • De acuerdo. Hay un dicho: “si no probaste tu backup, no tienes backup”.
    Dicho eso, en este caso no entiendo bien cuál era el problema. Restaurar todo desde el último backup sano haría que desaparecieran algunas publicaciones subidas mientras tanto, lo cual sería lamentable, pero sería una solución inmediata en lugar de trabajo manual e incertidumbre.

• Me llamó la atención la parte donde Renaud, Claire y Eugen del equipo de desarrollo de Mastodon ayudaron más de lo esperado.
  No sé si Vivaldi apoya económicamente a Mastodon, y tampoco encontré su nombre en la página de patrocinadores. Si no lo hace, ojalá este incidente lleve a Vivaldi u otras empresas que usan Mastodon a considerar un patrocinio o contrato de soporte.

  • Actualmente, la organización sin fines de lucro de Mastodon no ofrece contratos de soporte, pero es una buena idea.
    Los patrocinios están abiertos y realmente tienen un gran impacto. Que el proyecto tenga personal de tiempo completo es muy importante, pero actualmente en el área técnica solo están Eugen, el fundador, además de 1 desarrollador de tiempo completo y 1 responsable de DevOps.
  • Como no aparece en https://joinmastodon.org/sponsors, probablemente no sea patrocinador.
  • Aun así, en cierto modo está aportando una instancia bastante grande a la federación de Mastodon y personal que trabaja sobre ella.

• Fue uno de los mejores análisis post mortem que leí en mucho tiempo.

  • Recuerdo que el post mortem de hachyderm también fue bastante bueno. Me alegra que la gente lo publique con transparencia.

• Que los puntos 2 y 3 no se procesen atómicamente se siente como un problema. Claro, probablemente haya razones por las que hacerlo no sea trivial, pero todavía no he visto el código y algún día debería hacerlo.

  • Uno de los cambios relacionados es https://github.com/mastodon/mastodon/commit/13ec425b721c9594...
    Parece que hacerlo atómico era algo trivial.
    Antes simplemente no había necesidad. Es decir, que no fuera atómico no era un problema, salvo que alguien hiciera una mala configuración conectando sidekiq a un servidor de base de datos desactualizado, o sea, a una réplica. Aquí esa configuración parece ser el problema principal.

• La primera vez que tuve que restaurar un volcado SQL enorme, fue inolvidable ver cómo vim realmente daba un error de segmentación al intentar leerlo.
  Entonces descubrí la magia de split(1), es decir, dividir archivos en partes. Separé el volcado grande en un archivo por tabla.
  Claro que una sola tabla también puede ser enorme, pero al menos los archivos quedan más uniformes y es más fácil transformar consultas con otras herramientas como sed o awk.

  • Me sorprende que vim dé un error de segmentación. He visto que abrir archivos grandes sea lento, pero siempre pensé que podía manejar cualquier cosa con algún tipo de buffering mágico. Quizá me equivoque.
    Aun así, si llegas al punto de tener que editar un volcado para restaurar datos, algo está muy mal en el procedimiento de restauración. Claro que, cuando estás en esa situación en la práctica, saber eso no ayuda mucho.
  • Hace tiempo administré un sistema en el que había tantos archivos en una carpeta concreta que ni siquiera el comando ls terminaba. Probablemente era ext3 o ext2.
    La solución alternativa fue escribir un script en Python que procesara todo de forma incremental y moviera los archivos a subdirectorios según un prefijo común.

• En la parte de “Claire pidió el seguimiento completo de la pila de la entrada del log, y también pudieron extraerlo del log”, levanté una ceja.
  O esto es vudú profundo, o el código o la configuración convierten un Xeon en algo al nivel de un 286. ¿No serían megabytes por cada solicitud?

  • Al ver la cuenta aparecía un error HTTP 500, y se refiere al seguimiento de pila de ese 500.
    Es el comportamiento predeterminado de Ruby on Rails. Si ocurre un 500 o un error desconocido, imprime el seguimiento de pila, y el contenido es más o menos números de línea y rutas de archivos.
    Opero una app Rails bastante mal diseñada y acabo de comprobar que el seguimiento de pila de un 500 pesa 5 KiB. Como hay un error 500 aproximadamente una vez por hora, no llega ni a 1 MiB al día.
    Mantener cerca la pila de llamadas en realidad es bastante aceptable en términos de rendimiento. El comportamiento predeterminado de las excepciones en Java también es adjuntar un seguimiento de pila a cada excepción, incluso si no se imprime, y aun así las aplicaciones Java funcionan bien. De todos modos hay que saber cómo retornar, así que ya se tiene la pila de llamadas; la información adicional necesaria son solo los símbolos de depuración de nombre de archivo y número de línea. En Ruby, por las características del lenguaje, esa información ya es necesaria de todos modos.
  • Registrar el seguimiento de pila de los errores es algo bastante razonable. Idealmente, no todas las solicitudes producen errores.
  • ¿Quieres decir que en un sistema en producción no capturan el seguimiento de pila de los errores? ¿Cómo averiguan de dónde vino el error?
  • Parece que confundiste el seguimiento de pila con un volcado de memoria o algo parecido.

• ¿Cómo es posible eso de que “todas las cuentas locales de la instancia de Mastodon coincidían porque el campo URI tenía valor null”?
  NULL = NULL se evalúa como FALSE. SQL usa lógica de tres valores, más exactamente la lógica ternaria débil de Kleene, y aplicar cualquier operador a NULL da NULL.

  • Yo también me lo pregunté. Tal vez filtraban en la capa de la aplicación y comprobaban la igualdad usando el valor null del lenguaje que estaban usando.

• No entiendo cómo las cuentas con valores NULL en la columna URI coincidieron con la consulta. NULL no se compara como igual a NULL. ¿Es esto una horrible magia de Rails?

• Al ver la parte de que seis usuarios con símbolos en el nombre de usuario no podían iniciar sesión, y que era por un error en el script de recuperación que se arregló fácilmente, me da la impresión de que UTF-8 volvió a hacer de las suyas.