Lo hice y lo entendí

El blog de Vicente Navarro
30 ago

Recuperar una entrada perdida de WordPress. MySQL Point-in-Time recovery: mysqlbinlog.

Estaba ayer finalizando la entrada Los Linux de mi vida en el editor de WordPress cuando en un momento dado quise deshacer lo último que había escrito y pulsé Control+Z. Vi algo raro en la pantalla (aparecía todo el texto seleccionado y hubo unos movimientos raros de texto) pero no le di mayor importancia. Le di a guardar y refresqué la página para ver cómo iba quedando el borrador.

Cuando vi que únicamente me aparecían unos cuantos párrafos del principio me dio un vuelvo el corazón. ¡No sé cómo, había borrado casi todo el texto y lo había guardado!

Y bueno, no es que la pérdida fuera brutal. Supongo que algún empleado de banca que pierda todas las transacciones de un día tiene más motivos de qué preocuparse, pero el cabreo y el disgusto no te lo quita nadie por un rato. Por supuesto, pasé por todas las fases que se requieren en estos casos. A saber:

  • Negación: ¡No puede ser! ¡No ha ocurrido! ¡Es un mal sueño!
  • Enfado: ¡Me ca%$ en tó lo que se menea!
  • Discusión: ¡Pues ahora la entrada esta la va a escribir Rita la Cantaora!
  • Depresión: ¿Por qué a mí? ¿Qué he hecho yo para merecer esto?
  • Aceptación: ¡En fin! ¿Qué voy a hacer? Reescribiré la entrada… como ya la había escrito una vez y tenía las ideas claras, igual ahora sale mejor.

Cuando se me fue despejando la mente pensé que si en Oracle existían los Redo Logs (Oracle: Managing the Online Redo Log) y la posibilidad de indagar en ellos con el LogMiner (Oracle 10g: Using LogMiner to Analyze Redo Log Files, Oracle Magazine: Mining for Clues), y la capacidad de dejar la base de datos como estaba en un momento dado en el pasado o Point-In-Time Recovery (Oracle 10g: Performing Database Point-In-Time Recovery), igual había algo similar para MySQL que me permitiera deshacer los últimos cambios.

Y es que este blog se sustenta sobre tecnología LAMP (Linux, Apache, MySQL, PHP), aunque para ser justos debería de ser LDAMPW (y metemos a Debian y a WordPress en el acrónimo). Un servidor se maneja con MySQL lo justo para facilitar que el WordPress, el MythTV y el ZoneMinder puedan hacer su trabajo, ayudado un poco de conocimiento básicos de Oracle que hacen más fácil, al menos, entender los conceptos.

Y a la primera fue la vencida. Buscar “mysql point-in-time recovery” me llevó al capítulo del manual de MySQL de exactamente el mismo nombre: MySQL 5.0: Point-in-Time Recovery. Y de ahí a MySQL 5.0: The Binary Log y a MySQL 5.0: mysqlbinlog — Utility for Processing Binary Log Files.

Leyendo me enteré de que había una herramienta llamada mysqlbinlog que permite examinar los binary logs y volver a lanzar las transacciones desde un determinado punto en el tiempo partiendo desde un supuesto backup anterior (MySQL 5.0: Database Backups). Para ello, es necesario tener estos logs binarios activados:

When started with the --log-bin[=base_name] option, mysqld writes a log file containing all SQL commands that update data (both DDL and DML statements).

Cuando leí esto me fui desesperado al fichero de configuración de MySQL en Debian, el /etc/mysql/my.cnf y suspiré aliviado al ver que sí estaban activados:

# The following can be used as easy to replay backup logs or for replication.
#server-id              = 1
log_bin                 = /var/log/mysql/mysql-bin.log
# WARNING: Using expire_logs_days without bin_log crashes the server! See README.Debian!
expire_logs_days        = 10
max_binlog_size         = 100M
#binlog_do_db           = include_database_name
#binlog_ignore_db       = include_database_name

y más aún al ver que sí se estaban generando:

ls /var/log/mysql/
mysql-bin.000285  mysql-bin.000289  mysql-bin.000293  mysql-bin.000297
mysql-bin.000286  mysql-bin.000290  mysql-bin.000294  mysql-bin.000298
mysql-bin.000287  mysql-bin.000291  mysql-bin.000295  mysql-bin.000299
mysql-bin.000288  mysql-bin.000292  mysql-bin.000296  mysql-bin.index

Por cierto, fijémonos en que Debian pone por defecto “log_bin=/var/log/mysql/mysql-bin.log” pero el .log no es usado. Esto lo explica el manual:

If you supply an extension in the log name (for example, --log-bin=base_name.extension), the extension is silently removed and ignored.

El comando mysqlbinlog convierte los logs binarios en sentencias SQL listas para volver a ser ejecutadas. Así, para volver a aplicar un par de logs binarios sobre una base de datos, haríamos:

# mysqlbinlog binlog.000001 binlog.000002 | mysql

o

$ mysqlbinlog binlog.000001 >  /tmp/statements.sql
# mysqlbinlog binlog.000002 >> /tmp/statements.sql
# mysql -e "source /tmp/statements.sql"

Como yo hago backups muy a menudo podría haber seguido este camino, pero había otra alternativa, porque lo más interesante del comando es que permite examinar fácilmente dichas transacciones simplemente eligiendo el log con la primera fecha inmediatamente posterior al suceso que nos interesa (en este caso la pérdida de casi todo el texto de una entrada):

# mysqlbinlog /var/log/mysql/mysql-bin.000297 | less

Recorrí el fichero en cuestión y encontré la transacción de la última vez que había guardado correctamente la entrada:

# at 1121852
#070828 23:03:08 server id 1  end_log_pos 1137236       Query   thread_id=7448  exec_time=0     error_code=0
SET TIMESTAMP=1188334988;
UPDATE IGNORE wp_posts SET
                        post_author = '1',
                        post_date = '',
                        post_date_gmt = '',
                        post_content = 'Como hoy tengo cuerpo de 
<a href=\"http://eltiovazquez.blogspot.com/2005/08/la-familia-cebolleta.html\">abuelo cebolleta</a>, 
voy a contaros la batallita de los Linux que han pasado hasta el momento por mi vida.
Tal que el programa de <a href=\"http://www.rtve.es/\">TVE</a> que habí­a hace tiempo llamado 
<em>Las canciones de tu vida</em> pero con distribuciones de Linux en vez de con canciones. ...',
                        post_content_filtered = '',
                        post_title = 'Los Linux de mi vida',
                        post_excerpt = '',
                        post_status = 'draft',
                        post_type = 'post',
                        comment_status = 'open',
                        ping_status = 'open',
                        post_password = '',
                        post_name = '',
                        to_ping = '',
                        pinged = '',
                        post_modified = '2007-08-28 23:03:08',
                        post_modified_gmt = '2007-08-28 21:03:08',
                        post_parent = '0',
                        menu_order = '0'
                        WHERE ID = 300;
# at 1137236
#070828 23:03:08 server id 1  end_log_pos 1137368       Query   thread_id=7448  exec_time=0     error_code=0

Así, identificando la posición en el log del principio (# at 1121852) y del final (# at 1137236) pude construir este comando que me devolvió mi entrada perdida íntegra.

# mysqlbinlog --start-position=1121852 --stop-position=1137236 /var/log/mysql/mysql-bin.000297 | mysql -p

Es conveniente examinar la salida del comando mysqlbinlog antes de empiparla al mysql para asegurarnos de que es exactamente la transacción que nos interesa. Y por supuesto, es imprescindible hacer un backup antes de aventurarse con estas cosas.

La salida del mysqlbinlog con el principio y el final bien delimitados es muy últil para volver a ejecutar la transacción. Vemos que se especifica la base de datos a usar (wordpress) y los parámetros de sesión:

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 1121852
#070828 23:03:08 server id 1  end_log_pos 1137236       Query   thread_id=7448  exec_time=0     erro
r_code=0
use wordpress;
SET TIMESTAMP=1188334988;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1;
SET @@session.sql_mode=0;
/*!\C latin1 */;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8;
UPDATE IGNORE wp_posts SET
                        post_author = '1',
                        post_date = '',
                        post_date_gmt = '',
                        post_content = 'Como hoy tengo cuerpo de...',
                        post_content_filtered = '',
                        post_title = 'Los Linux de mi vida',
                        post_excerpt = '',
                        post_status = 'draft',
                        post_type = 'post',
                        comment_status = 'open',
                        ping_status = 'open',
                        post_password = '',
                        post_name = '',
                        to_ping = '',
                        pinged = '',
                        post_modified = '2007-08-28 23:03:08',
                        post_modified_gmt = '2007-08-28 21:03:08',
                        post_parent = '0',
                        menu_order = '0'
                        WHERE ID = 300;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/

El ROLLBACK del final se añade desde MySQL 5.0.3. Está documentado en MySQL 5.0: Changes in release 5.0.3:

mysqlbinlog now prints a ROLLBACK statement at the end of its output, in case the server crashed while it was in the process of writing the final entry into the last binary log named on the command line. This causes any half-written transaction to be rolled back when the output is executed. The ROLLBACK is harmless if the binary log file was written and closed normally.

Así que aquí me tenéis, encantado con el MySQL y con un argumento más para todos esos que dicen que MySQL es un juguete comparado con Oracle. ¡Y estoy seguro de que lo es!… Pero si alguien tuviera que haber hecho esto mismo con Oracle y con su enrevesado LogMiner, es posible que aún estuviéramos esperando. :mrgreen:

Entradas relacionadas

6 Comentarios a “Recuperar una entrada perdida de WordPress. MySQL Point-in-Time recovery: mysqlbinlog.”

  • RuBiCK dice:

    Tu blog es mi perdición, un post me lleva a otro y otro a otro…

    Resulta muy interesante ver los pasos que vas dando hasta que llegas a la solución final ;)

  • RuBiCK ¡Gracias! Me alegro de ser capaz de quitarte tanto tiempo ;-)

  • LuCSmar dice:

    Hola muy interesante el articulo, una preguntita, y si se quiere implementar lo que en oracle se conoce como flasback, como lo hacemos?

  • @LuCSmar No estoy seguro de qué es lo que necesitas hacer pero ¿tal vez partir de un backup completo y aplicar estos logs te serviría? Esto es equivalente a partir de un backup y aplicar archive logs en Oracle, claro.

    Si te refieres a algo como lo que leemos en Oracle Flashback Technology, no te sé decir seguro si MySQL tendrá herramientas tan avanzadas, pero yo diría que no.

Trackbacks y pingbacks:

Tema LHYLE09, creado por Vicente Navarro