LOXODATA

Corruption de fichiers WAL (partie 1)

2017-03-21   1426 mots, 7 minutes de lecture   Lætitia Avrot

La corruption des fichiers WAL (Write Ahead Log) n’est pas ce qui peut vous arriver de pire dans votre vie de DBA… Quoique…

Imaginez le scenario suivant: vous avez une simple instance en standalone. Elle semble bien fonctionner jusqu’au jour où elle tombe pour une raison quelconque. Supposons que la loi de Murphy s’en mêle et que le dernier WAL soit corrompu.

Comment pourrez-vous faire redémarrer l’instance suite à ce problème ? Aurez-vous perdu des données ? Si oui, combien ? Comment pouvez-vous réduire le risque et/ou les conséquences d’un tel scenario ?

Script SQL

Voici le petit script que j’ai écrit. Il permet de créer une table et d’y insérer une première partie de données horodatées. Ensuite, les données de LSN (Log Sequence Number) sont affichées avant de faire un checkpoint. Puis, une deuxième série de données horodatées est ajoutée à la table et les nouvelles données de LSN sont affichées.

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 * FROM test;

SELECT pg_current_xlog_location();
SELECT pg_xlogfile_name(pg_current_xlog_location());
CHECKPOINT;

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());

Le deuxième SELECT me donne les données de toute la table, à savoir :

 id |       date_creation
----+----------------------------
  1 | 2017-02-23 16:09:26.949461
  2 | 2017-02-23 16:09:26.949461
  3 | 2017-02-23 16:09:26.949461
  4 | 2017-02-23 16:09:26.949461
  5 | 2017-02-23 16:09:26.949461
  6 | 2017-02-23 16:09:38.523275
  7 | 2017-02-23 16:09:38.523275
  8 | 2017-02-23 16:09:38.523275
    (8 lignes)

Les infos de LSN sont les suivantes (dans l’ordre) :

 pg_current_xlog_location
--------------------------
0/84039CD0

 pg_current_xlog_location
--------------------------
0/84039FA8

pg_xlogfile_name
--------------------------
0000000A0000000000000084

Crash de l’instance

Pour simuler le crash de l’instance, le plus simple reste de faire un kill -9 du process maître.

$ ps -ef | grep postgres
postgres  4466     1  0 15:36 ? 00:00:00 /usr/lib/postgresql/9.6/bin/postgres -D /var/lib/postgresql/9.6/main -c config_file=/etc/postgresql/9.6/main/postgresql.conf
postgres  4467  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: logger process
postgres  4469  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: checkpointer process
postgres  4470  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: writer process
postgres  4471  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: wal writer process
postgres  4472  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: autovacuum launcher process
postgres  4473  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: archiver process   last was 0000000A0000000000000083
postgres  4474  4466  0 15:36 ? 00:00:00 postgres: 9.6/main: stats collector process
$ sudo kill -9 4466

Lors d’un arrêt normal de PostgreSQL, l’instance fait un checkpoint automatiquement. En faisant un kill -9 du process maître, on empêche l’instance de faire ce checkpoint.

“Corrompre” un fichiers WAL

Pour “corrompre” un fichier, le plus simple est de l’ouvrir et de supprimer ou/et d’ajouter des caractères au hasard (plutôt en début de fichier pour être sûr d’écraser des données valables). Tout le but de l’exercice étant de visualiser la perte de données après un crash, il faut corrompre le dernier fichier WAL.

Tentative de redémarrage

Comme tout bon DBA, après avoir lu les logs et réparé l’origine du crash, vous tentez un redémarrage de l’instance car vous ignorez que le dernier WAL est corrompu…

$ 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 du serveur indiquent clairement un souci avec le WAL :

LOG:  database system was interrupted; last known up at 2017-02-23 16:09:28 CET
LOG:  WAL file is from different database system: WAL file database system identifier is 7742649176712309348, pg_control database system identifier is 6384733785499945054
LOG:  invalid primary checkpoint record
LOG:  WAL file is from different database system: WAL file database system identifier is 7742649176712309348, pg_control database system identifier is 6384733785499945054
LOG:  invalid secondary checkpoint record
PANIC:  could not locate a valid checkpoint record
LOG:  startup process (PID 6407) was terminated by signal 6: Aborted
LOG:  aborting startup due to startup process failure
LOG:  database system is shut down

Clairement, PostgreSQL n’est pas très content et refuse de démarrer. A priori mes ajouts/suppressions de caractères en début de fichier WAL ont modifié l’identifiant de la base de données d’appartenance du WAL dans l’entête du fichier.

Réparation (mais perte de données)

La documentation prévoit l’utilisation de pg_resetxlog dans le cas de corruption de fichiers WAL. Cependant, après avoir utilisé cet outil, vous devrez vérifier de manière très scrupuleuse vos données car il y a de fortes chances que vous ayez perdu les dernières transactions.

$ sudo -u postgres /usr/lib/postgresql/9.6/bin/pg_resetxlog -f /var/lib/postgresql/9.6/main
Réinitialisation du journal des transactions

Le redémarrage peut ensuite se faire :

$ sudo pg_ctlcluster 9.6 main start
Redirecting start request to systemctl

L’instance démarre.

A-t-on perdu des données ?

SELECT * FROM test;
 id |       date_creation
----+----------------------------
  1 | 2017-02-23 16:09:26.949461
  2 | 2017-02-23 16:09:26.949461
  3 | 2017-02-23 16:09:26.949461
  4 | 2017-02-23 16:09:26.949461
  5 | 2017-02-23 16:09:26.949461
    (5 lignes)

Effectivement, de manière prévisible, les données qui étaient contenues uniquement dans les WAL (donc les données liées aux transactions ayant eu lieu entre le dernier checkpoint et le crash) sont perdues. Notre table ne contient donc pas les 3 dernières lignes.

Explication

Pour des raisons de performance, les données ne sont pas inscrites sur le disque à chaque COMMIT de transaction. À la place, les données modifiées sont insérées dans le WAL courant. Ce n’est que lors du prochain checkpoint que les données sont écrites dans le fichier de données.

Au démarrage de l’instance, celle-ci vérifie les données du dernier checkpoint pour faire un REDO des données commitées (se trouvant donc dans les WAL) mais pas encore écrites sur le disque.

Dans notre cas, le WAL était corrompu, l’instance n’a donc même pas pu le lire pour récupérer les données et assurer la durabilité des données (le ’D’ de ACID). Dans ce cas, PostgreSQL joue la sécurité et refuse de démarrer.

N’ayant ni sauvegarde, ni standby, nous n’avons pas d’autre solution que de lui fournir un fichier WAL vide et de perdre les transactions qui ont eu lieu entre le dernier checkpoint et le crash de la base de données.

Comment diminuer le risque d’un tel scenario

Tout d’abord, le risque zéro n’existe pas et comme le souligne très justement Werner Vogels, CTO d’Amazon: “Everything fails all the time”. Appliquer le pattern cloud “design for failure”, c’est aussi apprendre à vivre avec cette contrainte.

La première chose à faire pour éviter ce genre de problème est d’acheter du matériel (carte contrôleur et disques) de qualité, ou de s’assurer que son prestataire se base sur du matériel de qualité. Tous les disques ne se valent pas et prendre les moins chers systématiquement n’est pas forcément une bonne chose. La carte contrôleur devra être fournie avec un cache sur batterie. Ce serait dommage de perdre des données suite à une coupure de courant…

Ensuite, il faut mettre en place une redondance sur ces disques pour pouvoir se permettre d’en perdre un sans que cela ne soit une catastrophe. Les différentes configurations RAID sont une bonne idée (ma préférence va au RAID 10, qui combine du mirroring et du stripping, mais qui est plus cher).

On configurera aussi le cache et les accès disque, mais c’est en dehors du scope de ce billet.

Puis, vous pourrez trouver utile de jouer cette requête pour savoir à quelle fréquence ont lieu vos checkpoints et donc quantifier le risque que cela représente. Il ne vous reste plus qu’à vérifier que cet intervalle est compatible avec votre objectif de perte de données maximale admissible.

SELECT total_checkpoints,
    seconds_since_start / total_checkpoints / 60 AS minutes_between_checkpoints
FROM
    (SELECT EXTRACT(EPOCH FROM (now() - pg_postmaster_start_time())) AS seconds_since_start,
        (checkpoints_timed+checkpoints_req) AS total_checkpoints
    FROM pg_stat_bgwriter
    ) AS sub;

Enfin, il peut être intéressant de s’assurer que les personnes ayant accès au serveur de la base de données savent ce qu’elles font et/ou ne sont pas hostiles à l’entreprise.

Le travail de DBA est toujours un compromis entre les performances, la sûreté des données et le coût. Il n’est pas toujours facile de résoudre cette équation à trois inconnues, mais c’est aussi ce qui rend ce travail intéressant!

Note importante: Dans cet article, j’ai fait un kill -9 sur le process maître de PostgreSQL. Je l’ai fait car je souhaitais simuler un crash. (Avec le recul, il aurait été plus opportun de killer la machine virtuelle.)
Ne faites JAMAIS de kill -9 sur vos instances.
Utilisez pg_ctl --mode=immediate si vous devez arrêter une instance rapidement.