1. Introducción
A continuación se explican distintas notas para poder recuperar ante errores de replicación Primario Secundario de MariaDB/MySQL basados en:
MariaDB [xxxx]> show slave status \G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.x.x.61
Master_User: replication_user
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: master-bin.007801
Read_Master_Log_Pos: 12996960
Relay_Log_File: slave-relay-bin.000002
Relay_Log_Pos: 61391
Relay_Master_Log_File: master-bin.007800
Slave_IO_Running: Yes
Slave_SQL_Running: No
…
Last_Errno: 1032
Last_Error: Could not execute Update_rows_v1 event on table xxxx.xxxxx_session; Can’t find record in ‘xxxx_session’, Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event’s master log master-bin.007800, end_log_pos 97986450
Skip_Counter: 0
Exec_Master_Log_Pos: 97980157
2. Pasos de resolución
-
Si tras aplicar una configuración de replicación primario secundario con MySQL/MariaDB, obtenemos el siguiente error:
Last_Errno: 1032 Last_Error: Could not execute Update_rows_v1 event on table xxx.xxxx_session; Can't find record in 'xxxx_session', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log master-bin.007800, end_log_pos 97973150 Skip_Counter: 0 Exec_Master_Log_Pos: 97967369 -
Esto implica que la replicación está desincronizada con el estado de la base de datos (hay diferencias entre la base de datos en el secundario y el master log del primario que se está replicando).
Esto puede ser debido a distintos motivos, principalmente:
-
Cambios pendientes de ser enviados a la base de datos entre medias de las llamadas (FLUSH TABLES WITH READ LOCK) y el dump realizado para establecer el punto de partida en el secundario.
-
Modificaciones enviadas al secundario mientras se está haciendo el dump y el importado del primario al secundario.
-
Bugs de MariaDB/MySQL de la versión en uso.
-
-
Para resolverlo, hay que partir con bastante seguridad de que hay lo mismo en el primario que en el secundario (con muy pocas diferencias), ya sea porque se acaba de hacer el dump/import o porque son base de datos con pocos cambios o cambios controlados.
-
Asumiendo el escenario anterior, inspeccionar en qué punto de log del master se ha quedado. Para ello:
# Ejecutamos en el secundario la siguiente instrucción y nos fijamos en el Exec_Master_Log_pos que significa:
#
# The position in the current source binary log file to which the SQL thread has read and executed,
# marking the start of the next transaction or event to be processed
#
# Referencias en: https://dev.mysql.com/doc/refman/5.7/en/show-slave-status.html
# |
# | Es decir, es la posición última ejecutada y donde está parado el log:
#
MariaDB [xxxx]> show slave status \G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.xx.xx.61
Master_User: slave
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: master-bin.007801
Read_Master_Log_Pos: 12996960
Relay_Log_File: slave-relay-bin.000002
Relay_Log_Pos: 61391
Relay_Master_Log_File: master-bin.007800
Slave_IO_Running: Yes
Slave_SQL_Running: No
…
Last_Errno: 1032
Last_Error: Could not execute Update_rows_v1 event on table xxx.xxx_session; Can’t find record in ‘gelt7_session’, Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event’s master log master-bin.007800, end_log_pos 97986450
Skip_Counter: 0
Exec_Master_Log_Pos: 97980157 -
En el comando anterior nos está explicando que lleva leídos del log maestro (Master_Log_File: master-bin.007801, Read_Master_Log_Pos: 12996960) pero que se ha quedado en Exec_Master_Log_Pos: 97980157
-
Ahora, con esta información (Exec_Master_Log_Pos: 97980157 y Master_Log_File: master-bin.007801) nos vamos al servidor primario y localizamos ese fichero de log binario:
# find /var/ | grep master-bin.007800
/var/log/mysql/master-bin.007800…y a continuación, ejecutamos el siguiente comando para ver cuál es la sentencia que está causando problemas:
# /usr/bin/mysqlbinlog -v --start-position=97980157 /var/log/mysql/master-bin.007800 --base64-output=decode-rows | less
-
Con la información del punto intentar:
a) Determinar si se puede ignorar la transacción ya que representa una tabla temporal, o de sesiones, que no tiene mucha relevancia
b) O intentar reproducir la transacción para que la sentencia en fallo funcione. -
Si es el caso a, entonces se puede ejecutar lo siguiente para “reiniciar” la replicación, saltando un paso de la replicación. Lo siguiente también nos vale si hemos reproducido la parte que nos interesaba de la transacción:
MariaDB [xxxx]> stop slave; SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1; start slave; show slave status \G
-
Tras esto, el log avanzará, y se verá que queda actualizado el Exec_Master_Log_Pos: a un nuevo valor en el secundario:
MariaDB [xxxx]> show slave status \G*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.xx.xx.61
Master_User: slave
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: master-bin.007801
Read_Master_Log_Pos: 12996960
Relay_Log_File: slave-relay-bin.000002
Relay_Log_Pos: 61391
Relay_Master_Log_File: master-bin.007800
Slave_IO_Running: Yes
Slave_SQL_Running: No
…
Last_Errno:
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 97992367 -
Llevados a este punto, sería ir repitiendo este proceso algunas veces más hasta que el log quede replicado y sin errores, hasta que quede (Slave_IO_Running: Yes y Slave_SQL_Running: Yes, sin errores):
MariaDB [xxxx]> show slave status \G*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.xx.xx.61
Master_User: slave
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: master-bin.007801
Read_Master_Log_Pos: 12996960
Relay_Log_File: slave-relay-bin.000002
Relay_Log_Pos: 61391
Relay_Master_Log_File: master-bin.007800
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
…
Last_Errno:
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 97992367