Forums PostgreSQL.fr

mortimer.pw

Membre

ERROR: could not find archived wal

Bonjour,
Je travaille sur un moteur 9.6.5 sous Cent-OS 7.3.
J'ai installé la streaming replication.
Pitrery gère mes sauvegardes et WAL.
J'ai ajouté une surveillance des traces via Tail&Mail.
Tout fonctionne correctement depuis quelques semaines.
Dans la nuit de vendredi à samedi, j'ai reçu des mails d'alerte de mon esclave :
        Date: Sat Feb 10 03:30:22 2018 CET
        Host: dev-postgres-02
        Unique items: 3
        Matches from /home/postgres/pg_log/6-03.log: 3
        [1] (from line 17)
        2018-02-10 03:27:04 CET [30744]
        : [2-1] user= 2018-02-05 03:17:10 CET FATAL: terminating walreceiver due to timeout
        [2] (from line 19)
        ?
        ERROR: could not find /BACKUP/dev-replic/GEO_WAL_ARCH/00000002.history.gz
        [3] (from line 24)
        ?
        ERROR: could not find /BACKUP/dev-replic/GEO_WAL_ARCH/000000010000007E00000042.gz
Mon fichier de log de cette période contient :
        2018-02-10 03:09:27 CET [10365]: [121859-1] user=  2017-10-27 09:25:02 CEST LOG:  recovery restart point at 7E/3C000060
        2018-02-10 03:09:27 CET [10365]: [121860-1] user=  2017-10-27 09:25:02 CEST DETAIL:  last completed transaction was at log time 2018-02-10 03:00:01.319474+01
        2018-02-10 03:14:28 CET [10365]: [121861-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint starting: time
        2018-02-10 03:14:28 CET [10365]: [121862-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint complete: wrote 5 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.507 s, sync=0.001 s, total=0.514 s; sync files=3, longest=0.001 s, average=0.000 s; distance=32767 kB, estimate=32767 kB
        2018-02-10 03:14:28 CET [10365]: [121863-1] user=  2017-10-27 09:25:02 CEST LOG:  recovery restart point at 7E/3E000028
        2018-02-10 03:14:28 CET [10365]: [121864-1] user=  2017-10-27 09:25:02 CEST DETAIL:  last completed transaction was at log time 2018-02-10 03:10:01.899938+01
        2018-02-10 03:19:28 CET [10365]: [121865-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint starting: time
        2018-02-10 03:19:28 CET [10365]: [121866-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint complete: wrote 1 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 2 recycled; write=0.110 s, sync=0.001 s, total=0.119 s; sync files=1, longest=0.001 s, average=0.001 s; distance=16389 kB, estimate=31130 kB
        2018-02-10 03:19:28 CET [10365]: [121867-1] user=  2017-10-27 09:25:02 CEST LOG:  recovery restart point at 7E/3F001778
        2018-02-10 03:19:28 CET [10365]: [121868-1] user=  2017-10-27 09:25:02 CEST DETAIL:  last completed transaction was at log time 2018-02-10 03:15:01.896948+01
        2018-02-10 03:27:04 CET [30744]: [2-1] user=  2018-02-05 03:17:10 CET FATAL:  terminating walreceiver due to timeout
        2018-02-10 03:27:04 CET [10365]: [121869-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint starting: time
ERROR: could not find /BACKUP/dev-replic/GEO_WAL_ARCH/00000002.history.gz
        2018-02-10 03:30:20 CET [10365]: [121870-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint complete: wrote 3 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.066 s, sync=0.001 s, total=195.591 s; sync files=3, longest=0.001 s, average=0.000 s; distance=16387 kB, estimate=29655 kB
        2018-02-10 03:30:20 CET [10365]: [121871-1] user=  2017-10-27 09:25:02 CEST LOG:  recovery restart point at 7E/400023E8
        2018-02-10 03:30:20 CET [10365]: [121872-1] user=  2017-10-27 09:25:02 CEST DETAIL:  last completed transaction was at log time 2018-02-10 03:20:01.228392+01
        2018-02-10 03:30:20 CET [10355]: [40-1] user=  2017-10-27 09:25:02 CEST LOG:  restored log file "000000010000007E00000041" from archive
ERROR: could not find /BACKUP/dev-replic/GEO_WAL_ARCH/000000010000007E00000042.gz
        2018-02-10 03:30:20 CET [10355]: [41-1] user=  2017-10-27 09:25:02 CEST LOG:  unexpected pageaddr 7E/3C000000 in log segment 000000010000007E00000042, offset 0
        2018-02-10 03:30:21 CET [29405]: [1-1] user=  2018-02-10 03:30:20 CET LOG:  started streaming WAL from primary at 7E/42000000 on timeline 1
        2018-02-10 03:32:04 CET [10365]: [121873-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint starting: time
        2018-02-10 03:32:06 CET [10365]: [121874-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint complete: wrote 15 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=1.544 s, sync=0.011 s, total=1.562 s; sync files=8, longest=0.011 s, average=0.001 s; distance=16375 kB, estimate=28327 kB
        2018-02-10 03:32:06 CET [10365]: [121875-1] user=  2017-10-27 09:25:02 CEST LOG:  recovery restart point at 7E/41000060
        2018-02-10 03:32:06 CET [10365]: [121876-1] user=  2017-10-27 09:25:02 CEST DETAIL:  last completed transaction was at log time 2018-02-10 03:30:33.730929+01
        2018-02-10 03:37:04 CET [10365]: [121877-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint starting: time
        2018-02-10 03:37:04 CET [10365]: [121878-1] user=  2017-10-27 09:25:02 CEST LOG:  restartpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.004 s, sync=0.000 s, total=0.007 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16415 kB, estimate=27136 kB
Mon répertoire d'archivage ne contient pas de fichier : 00000002.history.gz
Par contre, j'ai bien les archives :
        -rw-rw---- 1 postgres postgres 30819 10 févr. 03:10 000000010000007E0000003E.gz
        -rw-rw---- 1 postgres postgres   193 10 févr. 03:10 000000010000007E0000003E.00000028.backup.gz
        -rw-rw---- 1 postgres postgres 32525 10 févr. 03:15 000000010000007E0000003F.gz
        -rw-rw---- 1 postgres postgres 33822 10 févr. 03:20 000000010000007E00000040.gz
        -rw-rw---- 1 postgres postgres 41948 10 févr. 03:30 000000010000007E00000041.gz
        -rw-rw---- 1 postgres postgres 40374 10 févr. 03:35 000000010000007E00000042.gz
        -rw-rw---- 1 postgres postgres 34182 10 févr. 03:40 000000010000007E00000043.gz
        -rw-rw---- 1 postgres postgres 30815 10 févr. 03:45 000000010000007E00000044.gz
        -rw-rw---- 1 postgres postgres 35616 10 févr. 03:50 000000010000007E00000045.gz
        -rw-rw---- 1 postgres postgres 30842 10 févr. 03:55 000000010000007E00000046.gz
Sur le maître, une bizarrerie, un log à 03h24 intercalé entre deux logs 03h30 :
        2018-02-10 03:26:59 CET [3287]: [3-1] user=postgres 10.71.4.20 2018-02-05 03:17:12 CET LOG:  terminating walsender process due to replication timeout
        2018-02-10 03:26:59 CET [3287]: [4-1] user=postgres 10.71.4.20 2018-02-05 03:17:12 CET LOG:  disconnection: session time: 120:09:47.504 user=postgres database= host=10.71.4.20 port=41062
        2018-02-10 03:30:17 CET [15500]: [52889-1] user=  2017-11-10 07:59:11 CET LOG:  checkpoint starting: time
        2018-02-10 03:30:18 CET [11584]: [1-1] user=[unknown] 127.0.0.1 2018-02-10 03:30:18 CET LOG:  connection received: host=127.0.0.1 port=60994
        2018-02-10 03:30:18 CET [11585]: [1-1] user=[unknown] 127.0.0.1 2018-02-10 03:30:18 CET LOG:  connection received: host=127.0.0.1 port=60996
        2018-02-10 03:30:18 CET [11584]: [2-1] user=postgres 127.0.0.1 2018-02-10 03:30:18 CET LOG:  connection authorized: user=postgres database=geo
        2018-02-10 03:30:18 CET [11585]: [2-1] user=postgres 127.0.0.1 2018-02-10 03:30:18 CET LOG:  connection authorized: user=postgres database=geo
        2018-02-10 03:24:19 CET [15503]: [3-1] user=  2017-11-10 07:59:11 CET LOG:  using stale statistics instead of current ones because stats collector is not responding
        2018-02-10 03:30:18 CET [11585]: [3-1] user=postgres 127.0.0.1 2018-02-10 03:30:18 CET LOG:  duration: 591.921 ms  statement: SELECT dba.inf_conn('geo');
        2018-02-10 03:30:18 CET [11585]: [4-1] user=postgres 127.0.0.1 2018-02-10 03:30:18 CET LOG:  disconnection: session time: 0:00:00.660 user=postgres database=geo host=127.0.0.1 port=60996
        2018-02-10 03:30:18 CET [11584]: [3-1] user=postgres 127.0.0.1 2018-02-10 03:30:18 CET LOG:  duration: 610.197 ms  statement: SELECT dba.inf_bgw();
        2018-02-10 03:30:18 CET [11584]: [4-1] user=postgres 127.0.0.1 2018-02-10 03:30:18 CET LOG:  disconnection: session time: 0:00:00.662 user=postgres database=geo host=127.0.0.1 port=60994
        2018-02-10 03:30:18 CET [15500]: [52890-1] user=  2017-11-10 07:59:11 CET LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.012 s, sync=0.000 s, total=0.833 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16375 kB, estimate=28327 kB
        2018-02-10 03:30:20 CET [11668]: [1-1] user=[unknown] 10.71.4.20 2018-02-10 03:30:20 CET LOG:  connection received: host=10.71.4.20 port=41542
        2018-02-10 03:30:21 CET [11668]: [2-1] user=postgres 10.71.4.20 2018-02-10 03:30:20 CET LOG:  replication connection authorized: user=postgres
Pour info : il n'y a pas d'activité sur ce cluster, sauf des tests en journée. La sauvegarde Pitrery s'exécute à 3h10 sur le maître (pas d'alerte).
Avez-vous une idée de ce qui s'est passé ?
D'avance merci.

Dernière modification par mortimer.pw (12/02/2018 09:02:22)

ruizsebastien

Membre

Re : ERROR: could not find archived wal

Bonjour,

Moi ce qui me chagrine c'est :
2018-02-10 03:30:20 CET [10355]: [41-1] user=  2017-10-27 09:25:02 CEST LOG:  unexpected pageaddr 7E/3C000000 in log segment 000000010000007E00000042, offset 0

le slave et le master sont-ils synchronisés ?
quelle la timeline du master ?

---

Cordialement,

Sébastien.

Marc Cousin

Membre

Re : ERROR: could not find archived wal

Ce qui est inquiétant surtout dans ce message, c'est que l'adresse 7E/3C000000 est dans le fichier 000000010000007E0000003B. Et il voit ça dès le premier octet de ce fichier… comme si on essayait de restaurer un mauvais fichier (mal nommé…)

---

Marc.

mortimer.pw

Membre

Re : ERROR: could not find archived wal

Bonjour Messieurs,

J'ai extrait quelques infos sur le maître :

SELECT * FROM pg_stat_replication;
  pid  | usesysid | usename  | application_name | client_addr | client_hostname | client_port |         backend_start         | backend_xmin |   state   | sent_location | write_location | flush_location | replay_location | sync_priority
| sync_state
-------+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+--------------+-----------+---------------+----------------+----------------+-----------------+--------------
-+------------
11668 |       10 | postgres | walreceiver      | 10.71.4.20  |                 |       41542 | 2018-02-10 03:30:20.950022+01 |       351264 | streaming | 80/ED000000   | 80/ED000000    | 80/ED000000    | 80/ED000000     |             0
| async

SELECT * FROM pg_stat_archiver;
archived_count |    last_archived_wal     |      last_archived_time       | failed_count | last_failed_wal | last_failed_time |         stats_reset         
----------------+--------------------------+-------------------------------+--------------+-----------------+------------------+------------------------------
          32522 | 0000000100000080000000EC | 2018-02-12 12:15:33.470238+01 |            0 |                 |                  | 2017-10-24 11:25:51.24938+02
(1 row)

Sur l'esclave :
SELECT * FROM pg_stat_wal_receiver;
  pid  |  status   | receive_start_lsn | receive_start_tli | received_lsn | received_tli |      last_msg_send_time       |     last_msg_receipt_time     | latest_end_lsn |        latest_end_time        | slot_name |                     
                                                 conninfo                                                                       
-------+-----------+-------------------+-------------------+--------------+--------------+-------------------------------+-------------------------------+----------------+-------------------------------+-----------+---------------------
--------------------------------------------------------------------------------------------------------------------------------
29405 | streaming | 7E/42000000       |                 1 | 80/EE000060  |            1 | 2018-02-12 12:21:18.511457+01 | 2018-02-12 12:21:18.489944+01 | 80/EE000060    | 2018-02-12 12:20:48.449176+01 |           | user=postgres passwo
rd=******** dbname=replication host=10.71.4.19 port=5432 fallback_application_name=walreceiver sslmode=disable sslcompression=1
(1 row)

Quelles infos supplémentaires puis-je vous donner ?

Marc Cousin

Membre

Re : ERROR: could not find archived wal

Ce n'est pas une erreur de Streaming Replication:

2018-02-10 03:30:20 CET [10355]: [40-1] user=  2017-10-27 09:25:02 CEST LOG:  restored log file "000000010000007E00000041" from archive
ERROR: could not find /BACKUP/dev-replic/GEO_WAL_ARCH/000000010000007E00000042.gz
        2018-02-10 03:30:20 CET [10355]: [41-1] user=  2017-10-27 09:25:02 CEST LOG:  unexpected pageaddr 7E/3C000000 in log segment 000000010000007E00000042, offset 0

Comme vous êtes en 9.6, vous devez avoir l'outil pg_xlogdump disponible… voire installé, avec un peu de chance (probablement dans /usr/pgsql/9.6/bin).

Si c'est le cas, essayez un pg_xlogdump sur le fichier, et postez les lsn qu'on trouve dans ce fichier (pas tous, mais le premier, le dernier, et quelques uns intermédiaires)

---

Marc.

mortimer.pw

Membre

Re : ERROR: could not find archived wal

Voilà le résultat de la commande, après décompression du fichier :
[postgres@dev-postgres-01 ~]$ pg_xlogdump 000000010000007E00000042
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 7E/42000028, prev 7E/41009E38, desc: RUNNING_XACTS nextXid 350714 latestCompletedXid 350713 oldestRunningXid 350714
rmgr: Heap        len (rec/tot):     65/  6529, tx:     350714, lsn: 7E/42000060, prev 7E/42000028, desc: HOT_UPDATE off 4 xmax 350714 ; new off 5 xmax 0, blkref #0: rel 1663/16384/29662 blk 47 FPW
rmgr: Heap        len (rec/tot):     65/  7753, tx:     350714, lsn: 7E/420019E8, prev 7E/42000060, desc: HOT_UPDATE off 7 xmax 350714 ; new off 8 xmax 0, blkref #0: rel 1663/16384/29662 blk 16 FPW
rmgr: Heap        len (rec/tot):     65/  6685, tx:     350714, lsn: 7E/42003850, prev 7E/420019E8, desc: HOT_UPDATE off 15 xmax 350714 ; new off 14 xmax 0, blkref #0: rel 1663/16384/29662 blk 44 FPW
rmgr: Heap        len (rec/tot):    110/   110, tx:     350714, lsn: 7E/42005288, prev 7E/42003850, desc: HOT_UPDATE off 16 xmax 350714 ; new off 18 xmax 0, blkref #0: rel 1663/16384/29662 blk 44
rmgr: Heap        len (rec/tot):     65/  3397, tx:     350714, lsn: 7E/420052F8, prev 7E/42005288, desc: HOT_UPDATE off 17 xmax 350714 ; new off 18 xmax 0, blkref #0: rel 1663/16384/29662 blk 48 FPW
rmgr: Heap        len (rec/tot):     53/  5449, tx:     350714, lsn: 7E/42006058, prev 7E/420052F8, desc: INPLACE off 44, blkref #0: rel 1663/16384/29723 blk 3 FPW
rmgr: Heap        len (rec/tot):     53/  2201, tx:     350714, lsn: 7E/420075A8, prev 7E/42006058, desc: INPLACE off 2, blkref #0: rel 1663/16384/29723 blk 4 FPW
rmgr: Transaction len (rec/tot):    226/   226, tx:     350714, lsn: 7E/42007E48, prev 7E/420075A8, desc: COMMIT 2018-02-10 03:30:33.730929 CET; inval msgs: catcache 49 catcache 49 catcache 49 catcache 49 catcache 49 catcache 45 catcache 44 catcache 45 catcache 44 relcache 28281 relcache 28286
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 7E/42007F30, prev 7E/42007E48, desc: RUNNING_XACTS nextXid 350715 latestCompletedXid 350714 oldestRunningXid 350715
rmgr: XLOG        len (rec/tot):     24/    24, tx:          0, lsn: 7E/42007F68, prev 7E/42007F30, desc: SWITCH

Marc Cousin

Membre

Re : ERROR: could not find archived wal

Pour moi ce n'est pas le même fichier:

2018-02-10 03:30:20 CET [10355]: [41-1] user=  2017-10-27 09:25:02 CEST LOG:  unexpected pageaddr 7E/3C000000 in log segment 000000010000007E00000042, offset 0

n'est pas cohérent avec

rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 7E/42000028, prev 7E/41009E38, desc: RUNNING_XACTS nextXid 350714 latestCompletedXid 350713 oldestRunningXid 350714

De ce message, on voit qu'il dit être en train de lire un header d'un segment qui est censé être 000000010000007E00000042, et qui contient 7E/3C000000 comme adresse d'enregistrement (correspondant à un 3B). Forcément, ça lui déplait

La bonne nouvelle, c'est qu'il bascule alors en streaming, et trouve son bonheur dans le répertoire pg_xlog du maître, donc il n'y a pas de casse. Et que votre fichier semble être correct d'après pg_xlogdump. Franchement, aucune idée de ce qui a pu se passer… race condition dans un script de restore ? bug, corruption mémoire, etc ? un lutin qui a renommé le fichier à la main (peu probable…) ?

Si vous voulez vraiment en avoir le cœur net, vous pouvez essayer de restaurer une sauvegarde antérieure à ce journal et réappliquer les journaux par dessus sur un serveur de test, et vérifier. pg_xlogdump n'est pas aussi rigoureux sur ses contrôles de cohérence de postgres (vu que c'est un outil de debug).

---

Marc.

mortimer.pw

Membre

Re : ERROR: could not find archived wal

Bonjour,
Comme indiqué plus haut, c'est Pitrery qui gère l'archivage.
Nous fonctionnons avec des archives compressées (utilisation de PIGZ).
Les fichiers sont archivés sur un NAS (espace de stockage entre maître et esclave).
Une "micro coupure" réseau peut-elle être à l'origine ?
Si la streaming permet de remédier au problème, tant mieux.
En espérant que la situation ne se détériore pas.
Merci à vous.

ruizsebastien

Membre

Re : ERROR: could not find archived wal

Bonjour,

Je ne sais pas comment fonctionne pitrery mais envoyer l'archivage directement dans un NAS ne me semble pas une bonne pratique justement à cause de ce que vous dites : une micro coupure réseau et votre fichier peut être vérolé.
Il serait préférable de faire l'archivage en local puis seulement après d'envoyer l'archive sur le NAS.

---

Cordialement,

Sébastien.

Marc Cousin

Membre

Re : ERROR: could not find archived wal

En théorie, rien ne peut être à l'origine du problème… je ne sais pas quoi vous dire, excepté que le fichier que lisait postgres ne correspondait pas à ce qu'il attendait. Vous pouvez avoir un problème réseau, disque, système, un bug dans pitrery, dans postgres… après, le fichier est peut-être corrompu, je n'ai regardé qu'en diagonale le code de pg_xlogdump, je ne pense pas qu'il soit aussi rigoureux que postgres pour la vérification de l'intégrité du fichier. D'où ma suggestion de tester le replay sur une autre machine pour en avoir le cœur net...

---

Marc.

Marc Cousin

Membre

Re : ERROR: could not find archived wal

Effectivement, le fichier peut être vérolé sur un NAS. Malgré tout, on peut contourner ça avec un sync du fichier par exemple (mais ça n'est évidemment pas par défaut)… si le système de fichiers réseau ne ment pas

---

Marc.

mortimer.pw

Membre

Re : ERROR: could not find archived wal

Bonjour,
Je ne vais malheureusement pas pouvoir rejouer l'instance, je ne conserve (via pitrery) que 3 jours de sauvegarde et le problème est survenu samedi dernier, dommage.
Par contre, je prends bonne note de faire l'archivage en local puis de copier sur le NAS.
Merci à vous pour vos investigations et conseils.

stefan

Membre

Re : ERROR: could not find archived wal

Bonjour,

Pour s'assurer que le fichier archivé corresponde bien à l'original (au moment de la copie), pitrery propose l'option ARCHIVE_CHECK.

# Check the md5 of the archived file to the md5 of the original WAL file.
# Useful if you are paranoid or don't trust the remote storage reliability.
# Note that you can not check the archive if compression is enabled.
# If overwriting is disabled, the md5 check enabled and the archive already
# exists, the archiving returns success if the md5 check is successful.
#ARCHIVE_CHECK="no"

Si vous effectuez régulièrement des vérifications de vos sauvegardes, vous pouvez alors vous assurer que les archives restent correctes par exemple en créant un .md5 (par wal archivé) à la copie et comparer régulièrement le md5 des archives à ces fichiers de référence.

---

Stefan.