Corruption de fichiers WAL (partie 2)
2017-04-18
1196 mots, 6 minutes de lecture
Lætitia Avrot
2017-04-18
1196 mots, 6 minutes de lecture
Lætitia Avrot
Nous continuons notre aventure au pays des WALs corrompus en imaginant le scenario suivant: La machine a crashé et nous avons perdu l’instance et les données qu’elle comportait. Ce n’est pas un problème, car nous avons des sauvegardes physiques avec archivage des WALs. Ce que nous ne savons pas, c’est que l’un des WALs sauvegardé est corrompu.
Comment se comporte pg_xlogdump avec les fichiers corrompus ? Va-t-on pouvoir restaurer sans perte de données ?
Paramétrage pour mise en place de la sauvegarde
La première chose à faire est de modifier le paramétrage de l’instance. Pour ce faire, il suffit de setter les paramètres suivants:
archive_mode=on
archive_command='test ! -f /backup/archived/%f && cp %p /backup/archived/%f'
wal_level=logical
max_wal_senders=10
Vous pouvez mettre la commande de votre choix pour copier les fichiers WAL. Il est nécessaire d’avoir un niveau de log suffisant (> minimal) pour activer l’archivage. La nouvelle recommandation est d’avoir une instance “logical replication ready”.
Sauvegarde
Nous prenons une sauvegarde de notre base de données. Vous pouvez utiliser barman, backrest ou WAL-E, pour ma part, je vais rester basique et utiiser pg_basebackup.
sudo -u postgres mkdir /backup/20170403
sudo -u postgres pg_basebackup -h localhost -D /backup/20170403 -Ft -z -P
Script SQL
Nous reprenons le petit script SQL de l’article Corruption de fichiers WAL et modifions-le. Ce script crée toujours une table et y insère 5 premières lignes. Ensuite on affiche les données de LSN (Last Sequence Number), on fait un checkpoint explicite et on switche de fichier WAL. On affiche ensuite les informations de LSN.
CREATE TABLE test (
id INTEGER NOT NULL,
date_creation TIMESTAMP
);
BEGIN;
INSERT INTO test SELECT 1, current_timestamp;
INSERT INTO test SELECT 2, current_timestamp;
INSERT INTO test SELECT 3, current_timestamp;
INSERT INTO test SELECT 4, current_timestamp;
INSERT INTO test SELECT 5, current_timestamp;
COMMIT;
SELECT pg_current_xlog_location();
SELECT pg_xlogfile_name(pg_current_xlog_location());
CHECKPOINT;
SELECT pg_switch_xlog();
BEGIN;
INSERT INTO test SELECT 6, current_timestamp;
INSERT INTO test SELECT 7, current_timestamp;
INSERT INTO test SELECT 8, current_timestamp;
COMMIT;
SELECT * FROM test;
SELECT pg_current_xlog_location();
SELECT pg_xlogfile_name(pg_current_xlog_location());
SELECT pg_switch_xlog();
SELECT pg_current_xlog_location();
SELECT pg_xlogfile_name(pg_current_xlog_location());
Nous avons donc bien 8 lignes dans la table test:
id | date_creation
----+----------------------------
1 | 2017-04-03 16:24:54.019085
2 | 2017-04-03 16:24:54.019085
3 | 2017-04-03 16:24:54.019085
4 | 2017-04-03 16:24:54.019085
5 | 2017-04-03 16:24:54.019085
6 | 2017-04-03 16:25:06.57813
7 | 2017-04-03 16:25:06.57813
8 | 2017-04-03 16:25:06.57813
(8 rows)
Les informations de LSN sont les suivantes (dans l’ordre):
pg_xlogfile_name
--------------------------
00000006000000000000000A
00000006000000000000000B
00000006000000000000000C
pg_switch_xlog
----------------
0/A016918
0/B000270
0/C000060
Cette fois-ci, nous allons corrompre le fichier n°00000006000000000000000B qui est archivé. Mais nous allons d’abord le lire avec pg_xlogdump.
pg_xlogdump
Il est préférable d’arrêter l’instance pour pouvoir lancer pg_xlogdump. Avant corruption du fichier, nous tentons un pg_xlogdump dessus:
$ sudo pg_ctlcluster 9.6 main stop
Redirecting stop request to systemctl
$ sudo -u postgres /usr/lib/postgresql/9.6/bin/pg_xlogdump -p /backup/archived/000000006000000000000000B 0000000A0000000000000087
rmgr: Heap len (rec/tot): 3/ 342, tx: 591, lsn: 0/0B000028, prev 0/0A016900, desc: INSERT off 6, blkref #0: rel 1663/12441/24576 blk 0 FPW
rmgr: Heap len (rec/tot): 3/ 71, tx: 591, lsn: 0/0B000180, prev 0/0B000028, desc: INSERT off 7, blkref #0: rel 1663/12441/24576 blk 0
rmgr: Heap len (rec/tot): 3/ 71, tx: 591, lsn: 0/0B0001C8, prev 0/0B000180, desc: INSERT off 8, blkref #0: rel 1663/12441/24576 blk 0
rmgr: Transaction len (rec/tot): 8/ 34, tx: 591, lsn: 0/0B000210, prev 0/0B0001C8, desc: COMMIT 2017-04-03 18:15:29.645347 CEST
rmgr: Standby len (rec/tot): 24/ 50, tx: 0, lsn: 0/0B000238, prev 0/0B000210, desc: RUNNING_XACTS nextXid 592 latestCompletedXid 591 oldestRunningXid 592
rmgr: XLOG len (rec/tot): 0/ 24, tx: 0, lsn: 0/0B000270, prev 0/0B000238, desc: SWITCH
On retrouve bien les 3 derniers INSERT et le SWITCH dans ce fichier. Avant de le “corrompre”, nous allons le copier (on ne sait jamais).
Après corruption du fichier, pg_xlogdump n’est plus capable de le lire:
$ sudo -u postgres /usr/lib/postgresql/9.6/bin/pg_xlogdump -p /var/lib/postgresql/9.6/main/pg_xlog 0000000A0000000000000087
pg_xlogdump: FATAL: could not find a valid record after 0/B000000
Tentative de restauration
Je copie mon répertoire PGDATA ailleurs afin de faire une sauvegarde à froid avant d’entamer ma restauration, puis je supprime le contenu du répertoire.
$ sudo cp -R /var/lib/postgresql/9.6/main /backup/PGDATA
$ sudo rm -rf /var/lib/postgresql/9.6/main
$ sudo ls -l /var/lib/postgresql/9.6/main
ls: impossible d'accéder à '/var/lib/postgresql/9.6/main': Aucun fichier ou dossier de ce type
Je détare le fichier au bon endroit:
$ sudo cp base.tar.gz /var/lib/postgresql/9.6/main/
$ cd /var/lib/postgresql/9.6/main
$ sudo tar xvf /var/lib/postgresql/9.6/main/base.tar.gz
backup_label
tablespace_map
pg_notify/
pg_notify/0000
pg_subtrans/
pg_subtrans/0000
pg_stat/
pg_snapshots/
(...)
base/16385/2336_vm
base/16385/2610_fsm
postgresql.auto.conf.origin
pg_replslot/
backup_label.old
global/pg_control
Je modifie le fichier recovery.conf pour lui indiquer où sont stockés les WALs archivés.
Je crée le fichier recovery.conf:
restore_command = 'cp /var/lib/postgresql/archive/%f %p'
Et je tente le redémarrage:
$ sudo pg_ctlcluster 9.6 main start
Redirecting start request to systemctl
Job for postgresql@9.6-main.service failed because the control process exited with error code. See "systemctl status postgresql@9.6-main.service" and "journalctl -xe" for details.
Les logs montrent clairement le problème de WAL corrompu:
2017-04-03 18:24:08.069 CEST,,,11185,,58e27728.2bb1,1,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"database system was interrupted; last known up at 2017-04-03 18:14:52 CEST",,,,,,,,,""
2017-04-03 18:24:08.524 CEST,,,11186,"[local]",58e27728.2bb2,1,"",2017-04-03 18:24:08 CEST,,0,LOG,08P01,"incomplete startup packet",,,,,,,,,""
2017-04-03 18:24:09.045 CEST,"postgres","postgres",11189,"[local]",58e27729.2bb5,1,"",2017-04-03 18:24:09 CEST,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2017-04-03 18:24:09.579 CEST,"postgres","postgres",11192,"[local]",58e27729.2bb8,1,"",2017-04-03 18:24:09 CEST,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2017-04-03 18:24:09.747 CEST,,,11185,,58e27728.2bb1,2,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"starting point-in-time recovery to XID 591",,,,,,,,,""
2017-04-03 18:24:09.751 CEST,,,11185,,58e27728.2bb1,3,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"restored log file ""00000006.history"" from archive",,,,,,,,,""
2017-04-03 18:24:09.778 CEST,,,11185,,58e27728.2bb1,4,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"restored log file ""000000060000000000000009"" from archive",,,,,,,,,""
2017-04-03 18:24:09.947 CEST,,,11185,,58e27728.2bb1,5,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"redo starts at 0/9000060",,,,,,,,,""
2017-04-03 18:24:09.953 CEST,,,11185,,58e27728.2bb1,6,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"consistent recovery state reached at 0/9000130",,,,,,,,,""
2017-04-03 18:24:09.981 CEST,,,11185,,58e27728.2bb1,7,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"restored log file ""00000006000000000000000A"" from archive",,,,,,,,,""
2017-04-03 18:24:10.152 CEST,"postgres","postgres",11205,"[local]",58e2772a.2bc5,1,"",2017-04-03 18:24:10 CEST,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2017-04-03 18:24:10.159 CEST,,,11185,,58e27728.2bb1,8,,2017-04-03 18:24:08 CEST,,0,FATAL,XX000,"archive file ""00000006000000000000000B"" has wrong size: 16777252 instead of 16777216",,,,,,,,,""
2017-04-03 18:24:10.160 CEST,,,11183,,58e27728.2baf,2,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"startup process (PID 11185) exited with exit code 1",,,,,,,,,""
2017-04-03 18:24:10.160 CEST,,,11183,,58e27728.2baf,3,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"terminating any other active server processes",,,,,,,,,""
2017-04-03 18:24:10.163 CEST,,,11183,,58e27728.2baf,4,,2017-04-03 18:24:08 CEST,,0,LOG,00000,"database system is shut down",,,,,,,,,""
Il se plaint que la taille du WAL 00000006000000000000000B n’est pas la bonne. Effectivement, mon WAL comporte 16777252 octets au lieu de 16777216. J’ai donc rouvert mon fichier WAL pour supprimer (en fin de fichier) les 36 caractères superflus. Si j’avais manqué de caractères, j’aurai rajouté des 0 en fin de fichier.
A-t-on perdu des données ?
Après un SELECT sur la table test, on se rend compte qu’on a effectivement perdu les données insérées dans le fichier WAL qui avait été corrompu:
SELECT * FROM test;
id | date_creation
----+----------------------------
1 | 2017-04-03 18:15:17.223775
2 | 2017-04-03 18:15:17.223775
3 | 2017-04-03 18:15:17.223775
4 | 2017-04-03 18:15:17.223775
5 | 2017-04-03 18:15:17.223775
(5 rows)
Que s’est-il passé ?
Ces données se trouvaient dans les WALs archivés. Comme le WAL était corrompu, PostgreSQL n’a pas été capable des les récupérer. Nous n’avons cependant pas tout perdu car tout ce qui était dans la sauvegarde et dans les WAL avant la corruption a été conservé.
Conclusion
La corruption de WAL n’est pas la pire des corruptions que vous pourriez rencontrer, mais elle peut entrainer une perte significative de données. De plus, il est important de bien penser à tester les fichiers WAL archivés pour s’assurer qu’on archive des fichiers exploitables. Si vous vous retrouvez dans ce cas, sachez que vous pouvez soit arrêter le recovery avant d’atteindre le WAL corrompu, soit tenter de compléter le fichier avec des 0 (ou supprimer les caractères superflus) en cas de problème de taille du fichier.
