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 :
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 45228Commande 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=100MPour 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-limitde 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 binaireblog_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ètrerelay-log-space-limitde 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.