LOXODATA

Le syndrome « oups »

2017-06-02   1851 mots, 9 minutes de lecture   Lætitia AVROT

Parfois, mais c’est très rare (!), un utilisateur se trompe et envoie une requête destructrice en production.

Nous allons voir, dans cet article, les techniques d’investigation à utiliser pour trouver le numéro de transaction et/ou la date/heure à laquelle nous voulons revenir.

Environnement

L’OS utilisé est Ubuntu sur une machine virtuelle VirtualBox. Les outils postgresql-common sont utilisés pour gérer l’instance.

Nous supposerons que nous travaillons sur une instance avec l’archivage des WAL activé (sans cela, ça risque d'être compliqué de faire du Point In Time Recovery).

Pour simuler du trafic et ne pas retrouver trop facilement notre transaction fautive, nous lancerons régulièrement pg_bench. pg_bench a été initialisé avec ces commandes:

postgres@vm1:~$ createdb pgbench
postgres@vm1:~$ pgbench -i -s 600

La commande lancée régulièrement sera celle-ci:

postgres@vm1:~$ pgbench -c 4 -j 2 -T 600

Les sauvegardes et restaurations sont effectuées avec pgBackRest.

Scénario

Voici le scénario que nous allons dérouler :

  • la sauvegarde full a eu lieu la nuit dernière ;
  • dans la matinée, un développeur a fait un DELETE sur une table en oubliant la clause WHERE (spéciale dédicace à toi, FX) ;
  • il s’en rend compte 15 minutes plus tard en revenant de la pause café et nous prévient ;
  • il faut arrêter l’instance et rechercher le DELETE destructeur. Deux cas se présentent alors :
    • nous traçons les requêtes de modification et il faut aller voir dans les journaux de l’instance ;
    • nous ne traçons pas les requêtes de modification et il faut aller voir dans les journaux de transactions ;
  • après récupération de la date/heure et/ou du numéro de transaction, nous faisons un PITR pour revenir avant l’erreur.

La boulette

Voici le petit script que j’ai écrit pour simuler l’erreur:

BEGIN;
    SELECT  pg_current_xlog_location(), current_timestamp;
    SELECT COUNT(*) FROM pgbench_tellers;
    DELETE FROM pgbench_tellers;
    SELECT COUNT(*) FROM pgbench_tellers;
    SELECT  pg_current_xlog_location(), current_timestamp;
END;

Je récupère les xlog_location et current_timestamp pour information uniquement. J’utilise le COUNT(*) pour montrer que le DELETE a bien eu lieu. Lorsque pgbench fait des modifications, il ne fait que des INSERT ou des UPDATE.

Voici les traces d’exécution:

SELECT  pg_current_xlog_location(), current_timestamp;
 pg_current_xlog_location |              now
--------------------------+-------------------------------
 2/441E1160               | 2017-05-18 08:18:45.956708+00

SELECT COUNT(*) FROM pgbench_tellers;
 count
-------
  6000

DELETE FROM pgbench_tellers;
DELETE 6000

SELECT COUNT(*) FROM pgbench_tellers;
 count
-------
     0

SELECT  pg_current_xlog_location(), current_timestamp;
 pg_current_xlog_location |              now
--------------------------+-------------------------------
 2/441F3078               | 2017-05-18 08:18:45.956708+00

 COMMIT

Arrêter l’instance

Forcément, si une erreur de cette envergure a été faite sur des données critiques, il faut arrêter l’instance. De plus, les réplications, même asynchrones, ne servent à rien dans ce cas, car les données sont déjà présentes sur les serveurs secondaires.

Il peut arriver, dans ce cas, qu’on vous demande de récupérer une sauvegarde de la table et d’insérer les données dans la table de production actuelle. Il faut bien s’assurer que cela ne risque pas de poser de problème de cohérence des données. Par exemple, il est possible de gérer le problème de cette manière pour une table de référence qui bouge peu, mais il sera beaucoup plus difficile d’appliquer un tel traitement sur une table qui est liée à d’autres tables qui évoluent beaucoup.

Une autre complication réside dans la gestion de l’intégrité référentielle et les éventuelles opérations en cascade qui résultent d’une suppression de données référencées. Mais c’est un autre débat.

Dans mon cas, il a été acté que les 15 minutes de production seraient définitivement perdues. Le coût pour essayer de récupérer les autres transactions tout en conservant une cohérence des données était trop important.

sudo pg_ctlcluster 9.6 main stop --mode fast

NB: J’utilise le wrapper perl pg_ctlcluster disponible sur les distributions basées sur Debian uniquement. Je vous laisse utiliser les outils disponibles sur votre distribution (systemctl ou pg_ctl).

Technique 1: les requêtes de modification sont traçées

Le paramètre log_statement permet de tracer :

  • soit toutes les requêtes ;
  • soit rien (off) ;
  • soit uniquement le ddl (CREATE, ALTER, DROP) ;
  • soit le DDL et les modifications de données (MOD);
  • soit toutes les requêtes (all).

(Je vous déconseille all, verbeux et moins intéressant que log_min_duration_statement positionné à 0.)

Dans le cas où les requêtes de modification de donnée sont traçées, vous devrez donc trouver le DELETE fatidique dans les traces de l’instance.

grep DELETE FROM pgbench_tellers /var/log/postgresql/
2017-05-18 08:18:45 UTC LOG:  statement: DELETE FROM pgbench_tellers;

Et voilà le travail ! Il faut donc revenir avant 08:18:45 le 18 mai 2017 (heure UTC).

Technique 2: les requêtes de modification ne sont pas traçées

Autant vous le dire tout de suite, suivant le nombre de transactions sur votre instance, vous allez avoir besoin de café et de patience…

La solution consiste à utiliser pg_xlogdump et grep pour retrouver le DELETE.

NB: À partir de la version 10 de postgreSQL, l’outil pg_xlogdump change de nom. Il s’appellera désormais pg_waldump. Cela ne change rien à son fonctionnement.

Mais comme vous vous en doutez, il risque d’y avoir eu de nombreuses transactions sur votre base et il peut être utile de pouvoir restreindre les résultats à la table sur laquelle il y a eu un problème.

Dans les WAL, vous trouverez en fin de ligne la partie concernant la table touchée par la modification tracée:

rmgr: Heap        len (rec/tot):     14/    72, tx:     125752, lsn: 2/44000810, prev 2/43FFE898, desc: HOT_UPDATE off 12 xmax 125752 ; new off 63 xmax 0, blkref #0: rel 1663/16388/16401 blk 984834

Ce qui nous intéresse est en fin de ligne et commence par rel. Vous trouverez également l’oid du tablespace, l’oid de la base puis l’oid de la table.

La requête suivante vous permettra de retrouver ces numéros (assurez-vous que l’application ne puisse pas se reconnecter automatiquement à la base avant de redémarrer l’instance).

SELECT COALESCE(tbs.oid, db.dattablespace) AS tablespace,
   db.oid AS database,
   t.relfilenode AS table
 FROM pg_class t LEFT OUTER JOIN pg_tablespace tbs ON t.reltablespace=tbs.oid
    CROSS JOIN pg_database db
 WHERE t.relname='pgbench_tellers'
   AND db.datname=current_database();

NB: On remarquera le produit cartésien dans cette requête qui permet juste de récupérer toutes les données d’un coup. Normalement, un produit cartésien est une erreur et ne devrait pas exister. Dans mon cas, je me permets exceptionnellement de le faire, car le produit cartésien porte sur une table réduite à une seule ligne (grâce à la clause WHERE) et les résultats mis ensemble ont un sens.

Voici le résultat de cette requête:

 tablespace | database | table
------------+----------+-------
       1663 |    16388 | 16392

Pour commencer, je vais copier les WAL dans un autre répertoire avant de les dézipper.

Un WAL est nommé ainsi 000000XX000000YY000000ZZ, avec XX le numéro de timeline, YY le numéro de fichier logique et ZZ le numéro de fichier physique, aussi appelé segment.

PgBackRest crée un répertoire par fichier logique. Ensuite, pour s’assurer qu’il n’y a pas eu de corruption, pgBackRest ajoute un checksum dans le nom du fichier, il faudra donc ensuite tronquer le nom des fichiers à 24 caractères.

cp /var/lib/pgbackrest/archive/main/9.6-1/0000000100000001/* /tmp/WAL
cp /var/lib/pgbackrest/archive/main/9.6-1/0000000100000002/* /tmp/WAL
cp /var/lib/pgbackrest/archive/main/9.6-1/0000000100000003/* /tmp/WAL
cd /tmp/WAL
rm *.backup
gunzip *
rename 's/^(.{24}).*/$1/' *

Les WAL récupérés vont du fichier 0000000100000001000000D1 au fichier 000000010000000300000046, soit 375 fichiers. Il ne reste plus qu'à lancer le pg_xlogdump avec un grep sur DELETE et sur rel 1663/16388/16392.

pg_xlogdump 0000000100000001000000D1 000000010000000300000046 | grep DELETE | grep "rel 1663/16388/16392" > delete_pgbench_tellers.txt

Vous allez trouver un résultat de ce style:

rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F3078, prev 2/441F3050, desc: DELETE off 4 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F30B0, prev 2/441F3078, desc: DELETE off 8 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F30E8, prev 2/441F30B0, desc: DELETE off 9 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F3120, prev 2/441F30E8, desc: DELETE off 12 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
...

Ce qui est important dans ce résultat, c’est lsn: 2/44XXXXXX. Dans le LSN (Log Sequence Number), le premier nombre (avant le ‘/') indique le numéro de fichier logique. Les 2 chiffres suivants donnent le numéro de fichier physique et les 6 chiffres d’après fournissent la position dans le fichier. Il faut donc aller voir dans le fichier 0000001000000200000044 pour retrouver cette transaction.

pg_xlogdump 000000010000000200000044 > 000000010000000200000044.txt

Après avoir extrait les lignes dans un fichier texte, il suffit de faire une recherche sur 2/441F3078 pour retrouver les transactions qui nous intéressent :

rmgr: Transaction len (rec/tot):      8/    34, tx:     125893, lsn: 2/441F3028, prev 2/441F2FD8, desc: COMMIT 2017-05-18 08:18:45.975416 UTC
rmgr: Transaction len (rec/tot):      8/    34, tx:     125891, lsn: 2/441F3050, prev 2/441F3028, desc: COMMIT 2017-05-18 08:18:45.975439 UTC
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F3078, prev 2/441F3050, desc: DELETE off 4 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F30B0, prev 2/441F3078, desc: DELETE off 8 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F30E8, prev 2/441F30B0, desc: DELETE off 9 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0
rmgr: Heap        len (rec/tot):      8/    54, tx:     125894, lsn: 2/441F3120, prev 2/441F30E8, desc: DELETE off 12 KEYS_UPDATED , blkref #0: rel 1663/16388/16392 blk 0

On remarque donc que le dernier COMMIT effectué avant les DELETE fatidiques a eu lieu exactement le 18 mai 2017, à 8h18 et 45,975439 secondes, heure UTC.

Il faut donc faire du Point In Time Recovery (PITR) jusqu'à l’heure exacte 2017-05-18 08:18:45.975439 UTC. On remarquera que si cette technique est plus fastidieuse que celle qui consiste à aller voir l’heure dans les traces de l’instance, elle est aussi plus précise. Cependant, si on accepte de perdre 15 minutes de production, on ne doit pas être à une seconde près.

La restauration

Il suffit ensuite de faire la restauration. J’utilise pgBackRest, mais vous êtes bien sûr libre d’utiliser votre outil préféré.

postgres@vm1:~$ postgres pgbackrest --stanza=main --delta --type=time --target="2017-05-18 08:18:45.975439 UTC" restore

J’utilise le mode delta qui permet de ne restaurer que les fichiers nécessaires et de garder les fichiers qui n’ont pas changé entre mon backup et maintenant. Il n’y a plus qu'à redémarrer l’instance et laisser faire le recovery.

sudo pg_ctlcluster 9.6 main start

Un petit COUNT(*) sur pgbench_tellers pour s’assurer qu’on a bien retrouvé toutes nos lignes:

SELECT COUNT(*) FROM pgbench_tellers;

 count
-------
  6000

On a bien retrouvé les 6000 lignes qu’il y avait au départ ! (Bien sûr, ce n’est qu’une vérification grossière…)

Comment empêcher que cela arrive à nouveau ?

La première chose qui me vient à l’esprit est de limiter les droits sur les tables contenant des données sensibles.

Ensuite, il faut privilégier les manipulations de données via l’application. De plus, je conseille à toute personne se connectant directement à la base de données de vérifier 2 fois qu’il est bien connecté à la bonne avant de faire la modification, voire d’utiliser des environnements avec des couleurs différentes suivant les environnements auxquels il se connecte. En précaution supplémentaire, on peut conseiller de systématiquement faire ce genre de manipulations dans une transaction en prenant le temps de réfléchir avant de valider.

Enfin, si de telles manipulations en base sont nécessaires, il convient de travailler dans un certain calme et en étant reposé, afin d'éviter les problèmes de concentration.