Réplication MySQL 5 : Corruption d’un fichier de relai

Logo

Introduction

Dans ce cas pratique, un fichier de relai de log dans un système de réplication est corrompu. Cet article se propose de montrer les étapes qui ont permis d’analyser et de contourner ce problème. Pour aborder cette documentation, il faut avoir une très bonne vision de la réplication MySQL 5 (une documentation complète sur ce sujet est proposée dans la rubrique DocumentationMySQLRéplication > MySQL 5.0 et la réplication : mise en œuvre pratique).

Dans l’architecture, DBA_T1_MYS est le serveur master et DBA_T2_MYS est le serveur esclave (slave). Les serveurs MySQL DBA_T1_MYS et DBA_T2_MYS sont installés dans un environnement normalisé ( rubrique Documentation > MySQL > Administration > Normalisation et installation de serveurs MySQL 4.1.x et 5.0.x sous Solaris).

Le schéma détaillé de la réplication de DBA_T1_MYS vers DBA_T2_MYS est rappelé ci-dessous :

Schéma de la réplication

Une corruption de se produit sur le fichier de relai de log relay_DBA_T2_MYS.000075.

Détection de l’arrêt de la réplication

2 outils ont permis de détecter l’arrêt de la réplication : les lignes de commande et le fichier de log.

Fichier de log du serveur esclave DBA_T2_MYS

Le fichier de log DBA_T2_MYS.log du serveur esclave DBA_T2_MYS situé dans le répertoire $LOG (/Software/mysql/dba/DBA_T2_MYS/log) montre clairement que le thread SQL dans le système de réplication est arrêté à cause d’un ordre SQL à répliquer qui échoue sur le serveur secondaire DBA_T2_MYS avec l’erreur 1064.

051024 15:20:18 [ERROR] Error reading packet from server:
Lost connection to MySQL server during query ( server_errno=2013)
051024 15:20:19 [Note] Slave I/O thread: Failed reading log event,
reconnecting to retry, log 'blog_DBA_T1_MYS.000029' position 45404
051024 15:20:21 [ERROR] Slave: Error 'You have an error in
your SQL syntax; check the manual that corresponds to your MySQL
server version for the right syntax to use near '[1]' at line 1'
on query. Default database: 'cgcam'.
Query: 'INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14',
'2004-02-16', 0.00, 15.22, C[1]', Error_code: 1064
051024 15:20:21 [ERROR] Error running query, slave SQL thread aborted.
Fix the problem, and restart the slave SQL thread with "SLAVE START".
We stopped at log 'blog_DBA_T1_MYS.000029' position 45228

Commande SHOW PROCESSLIST

La commande SHOW PROCESSLIST dans un serveur esclave doit en toute logique montrer deux process "system user" : un process slave I/O et un process SQL.

mysql-DBA_T2_MYS> show processlist;
Id  User   Host           db    Command   Time State                                Info
1   system                NULL  Connect   8604 Waiting for the slave SQL thread to  NULL
                                               free enough relay log space
3   root   localhost:1878 NULL  Query        0                                      show processlist

La commande SHOW PROCESSLIST indique que le thread SQL n’est plus présent. Le thread esclave I/O est lui présent mais inactif depuis 8604 secondes avec le motif suivant : Waiting for the slave SQL thread to free enough relay log space.

Ce message est très explicite, il indique que le paramètre relay-log-space-limit est atteint, paramètre statique au démarrage du serveur DBA_T2_MYS et qui permet de contrôler la taille maximale en Mb des fichiers de relai de log situé dans le répertoire $RPL (/dba/mysql/DBA_T2_MYS/rpl). Dans notre configuration, le paramètre relay-log-space-limit est fixé à 100Mb et la somme totale de la taille des fichiers de relai en Mb a atteint ce paramètre :

Fichier de configuration du serveur DBA_T2_MYS : DBA_T2_MYS.cfg dans le répertoire $CFG (/Software/mysql/dba/DBA_T2_MYS/cfg) :

/Software/mysql/dba/DBA_T2_MYS/cfg/DBA_T2_MYS.cfg
relay-log=C:/dba/mysql/DBA_T2_MYS/rpl/relay_DBA_T2_MYS
relay-log-index=C:/dba/mysql/DBA_T2_MYS/rpl/relay_DBA_T2_MYS.index
relay-log-space-limit=100M

Pour retrouver tous les paramètres concernant les fichiers de relai, utiliser la commande SHOW VARIABLES.

mysql> show variables like '%relay%';

+-----------------------+-----------+
| Variable_name         | Value     |
+-----------------------+-----------+
| max_relay_log_size    | 10485760  |
| relay_log_purge       | ON        |
| relay_log_space_limit | 104857600 |
+-----------------------+-----------+

Commande SHOW SLAVE STATUS

La commande SHOW SLAVE STATUS confirme les premiers éléments d’information récoltés avec la commande SHOW PROCESSLIST et avec le fichier de log du serveur esclave DBA_T2_MYS.

mysql-DBA_T2_MYS> show slave status \G;
          *************************** 1. row ***************************
              Slave_IO_State: Waiting for the slave SQL thread to free enough relay log space
                 Master_Host: CGC
                 Master_User: DBA_T2_MYS_maint
                 Master_Port: 40102
               Connect_Retry: 60
             Master_Log_File: blog_DBA_T1_MYS.000038
         Read_Master_Log_Pos: 10479201
              Relay_Log_File: relay_DBA_T2_MYS.000075
               Relay_Log_Pos: 45371
       Relay_Master_Log_File: blog_DBA_T1_MYS.000029
            Slave_IO_Running: Yes
           Slave_SQL_Running: No
             Replicate_Do_DB:
         Replicate_Ignore_DB:
          Replicate_Do_Table:
      Replicate_Ignore_Table:
     Replicate_Wild_Do_Table: cgcam.t_adm%
 Replicate_Wild_Ignore_Table:
                  Last_Errno: 1064
                  Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '☻☺' at line 1' on query. Default database: 'cgcam'. Query: 'INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00, 15.22, C☻☺'  
                Skip_Counter: 0
         Exec_Master_Log_Pos: 45228
             Relay_Log_Space: 104857730
             Until_Condition: None
              Until_Log_File:
               Until_Log_Pos: 0
          Master_SSL_Allowed: No
          Master_SSL_CA_File:
          Master_SSL_CA_Path:
             Master_SSL_Cert:
           Master_SSL_Cipher:
              Master_SSL_Key:
       Seconds_Behind_Master: NULL

La commande SHOW SLAVE STATUS confirme :

  • que le thread slave I/O attend que le thread SQL libère de l’espace, le paramètre relay-log-space-limit de 100 Mb étant atteint ( Slave_IO_State : Waiting for the slave SQL thread to free enough relay log space).
  • que le thread SQL est arrêté ( Slave_SQL_running : No)
  • que la cause de l’arrêt du thread SQL est un ordre SQL INSERT à répliquer avec une erreur N°1064 (Last_error)

La commande SHOW SLAVE STATUS donne en revanche des informations complémentaires :

  • l’échec concerne le fichier de relai relay_DBA_T2_MYS.000075 (Relay_Log_File) à la position 45371 (Relay_Log_Pos), position qui correspond à la position 45228 (Exec_Master_Log_Pos) du fichier de log binaire blog_DBA_T1_MYS.000029 (Relay_Master_Log_File) du serveur master DBA_T1_MYS.
  • Malgré l’échec du thread SQL, le thread I/O a poursuivi la construction des fichiers de relai jusqu’au fichier de log binaire blog_DBA_T1_MYS.000038 (Master_Log_File) du serveur master DBA_T1_MYS jusqu’à la position 10479201 (Master_Log_Pos), position à laquelle le paramètre relay-log-space-limit de 100 Mb a été atteint.

Détection de la corruption dans le fichier de relai relay_DBA_T2_MYS.000075

Le binaire mysqlbinlog va être utilisé pour lire le fichier relay_DBA_T2_MYS.000075 avec l’option --start-position pour demander de commencer la lecture du fichier de relai de log à partir de la position 45371.

DBA_T2_MYS> mysqlbinlog $RPL/relay_DBA_T2_MYS.000075 --start-position=45371

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 45371
#051024 15:18:45 server id 1  end_log_pos 45404         Query   thread_id=2
exec_time=0     error_code=0
use cgcam;
SET TIMESTAMP=1130159925;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1;
SET @@session.sql_mode=0;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.
collation_server=8;

INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00,
 15.22, C☻☺   └   ¦Æ    ☻       ;

# at 45547
#051024 15:20:23 server id 2  end_log_pos 45597         Rotate to relay_DBA_T2_MYS.000076  pos: 4

# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Il est très surprenant de voir des caractères spéciaux dans la commande INSERT :

INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00,15.22, C☻☺ └ ¦Æ ☻ ;

et de constater également que le fichier relay_DBA_T2_MYS.000075 ne fait que 75Kb alors que le paramètre max-relay-log-size est fixé à 10Mb et qu’une rotation du fichier de relai a été immédiatement déclenchée à l’issue de cet ordre INSERT mal formaté.

A priori une corruption s’est bien produite dans le fichier de relai relay_DBA_T2_MYS.000075.

Sachant que la position 45371 correspond à la position 45228 du fichier binaire blog_DBA_T1_MYS.000029 du serveur master DBA_T1_MYS, il est de bon ton de rechercher l’ordre original dans ce fichier de log binaire du serveur master :

DBA_T1_MYS > mysqlbinlog $BINLOG/blog_DBA_T1_MYS.000029 --start-position=45228

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;

# at 45228
#051024 15:18:45 server id 1  end_log_pos 45404         Query   thread_id=2
exec_time=0     error_code=0
use cgcam;
SET TIMESTAMP=1130159925;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1;
SET @@session.sql_mode=0;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.
collation_server=8;
INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00,
 15.22, 'FNAC 14/02/2004');

Résolution et contournement du problème

Connaissant l’ordre INSERT original, ce dernier ordre a été exécuté manuellement sur le serveur esclave DBA_T2_MYS, puis le système de réplication a été repris avec la commande START SLAVE en spécifiant d’écarter la position qui nous pose problème dans le fichier de relay_DBA_T2_MYS.000075 grâce à la commande SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1.

mysql-DBA_T2_MYS> use cgcam;
mysql-DBA_T2_MYS> INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00,15.22, 'FNAC 14/02/2004');
mysql-DBA_T2_MYS> set global sql_slave_skip_counter=1;
mysql-DBA_T2_MYS> start slave;

Les commandes SHOW PROCESSLIST et SHOW SLAVE STATUS ont confirmé après ces opérations que le système de réplication est repris avec succès.