Vous n'êtes pas identifié(e).
Pages : 1
Bonjour,
Je travaille sur un moteur 9.5.3 sous Cent-OS 7.2.
J'ai mis en place un warm-standby (log_shipping+streaming replication).
J'ai un répertoire PG_ARC sur mon maître et sur mon esclave qui contient les WAL archivés de moins de 3 jours.
Je teste aujourdhui la bascule (failover).
J'ai arrêté mon maître : ./pgsql stop. J'ai les logs suivants sur l'esclave :
2016-06-15 07:10:15 CEST [17265]: [445-1] user= 2016-06-14 12:08:09 CEST LOG: restartpoint starting: time
2016-06-15 07:10:19 CEST [17265]: [446-1] user= 2016-06-14 12:08:09 CEST LOG: restartpoint complete: wrote 32 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=3.114 s, sync=0.019 s, total=3.140 s; sync files=18, longest=0.006 s, average=0.001 s; distance=153 kB, estimate=2794 kB
2016-06-15 07:10:19 CEST [17265]: [447-1] user= 2016-06-14 12:08:09 CEST LOG: recovery restart point at 2/220ECD68
2016-06-15 07:10:19 CEST [17265]: [448-1] user= 2016-06-14 12:08:09 CEST DETAIL: last completed transaction was at log time 2016-06-15 07:10:12.097019+02
2016-06-15 07:10:44 CEST [17268]: [2-1] user= 2016-06-14 12:08:09 CEST LOG: replication terminated by primary server
2016-06-15 07:10:44 CEST [17268]: [3-1] user= 2016-06-14 12:08:09 CEST DETAIL: End of WAL reached on timeline 1 at 2/23000098.
2016-06-15 07:10:44 CEST [17268]: [4-1] user= 2016-06-14 12:08:09 CEST FATAL: could not send end-of-streaming message to primary: no COPY in progress
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
2016-06-15 07:10:44 CEST [17263]: [6-1] user= 2016-06-14 12:08:07 CEST LOG: invalid record length at 2/23000098
2016-06-15 07:10:44 CEST [7195]: [1-1] user= 2016-06-15 07:10:44 CEST FATAL: could not connect to the primary server: FATAL: the database system is shutting down
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
2016-06-15 07:10:49 CEST [7223]: [1-1] user= 2016-06-15 07:10:49 CEST FATAL: could not connect to the primary server: could not connect to server: Connexion refusée
Is the server running on host "dev-postgres-01" (10.71.4.19) and accepting
TCP/IP connections on port 5432?
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
J'ai donc fait un pg_ctl promote sur mon esclave. J'ai les logs suivants :
2016-06-15 07:10:58 CEST [17263]: [7-1] user= 2016-06-14 12:08:07 CEST LOG: received promote request
2016-06-15 07:10:58 CEST [17263]: [8-1] user= 2016-06-14 12:08:07 CEST LOG: redo done at 2/23000028
2016-06-15 07:10:58 CEST [17263]: [9-1] user= 2016-06-14 12:08:07 CEST LOG: last completed transaction was at log time 2016-06-15 07:10:12.097019+02
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
cp: impossible d'évaluer « /home/postgres/PG_ARC/00000002.history »: Aucun fichier ou dossier de ce type
2016-06-15 07:10:58 CEST [17263]: [10-1] user= 2016-06-14 12:08:07 CEST LOG: selected new timeline ID: 2
cp: impossible d'évaluer « /home/postgres/PG_ARC/00000001.history »: Aucun fichier ou dossier de ce type
2016-06-15 07:10:59 CEST [17263]: [11-1] user= 2016-06-14 12:08:07 CEST LOG: archive recovery complete
2016-06-15 07:10:59 CEST [17263]: [12-1] user= 2016-06-14 12:08:07 CEST LOG: MultiXact member wraparound protections are now enabled
2016-06-15 07:10:59 CEST [17265]: [449-1] user= 2016-06-14 12:08:09 CEST LOG: checkpoint starting: force
2016-06-15 07:10:59 CEST [17261]: [3-1] user= 2016-06-14 12:08:07 CEST LOG: database system is ready to accept connections
2016-06-15 07:10:59 CEST [7234]: [1-1] user= 2016-06-15 07:10:59 CEST LOG: autovacuum launcher started
2016-06-15 07:10:59 CEST [17265]: [450-1] user= 2016-06-14 12:08:09 CEST LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.000 s, total=0.559 s; sync files=0, longest=0.000 s, average=0.000 s; distance=15436 kB, estimate=15436 kB
2016-06-15 07:11:00 Archivage du WAL pg_xlog/000000010000000200000023.partial.
2016-06-15 07:11:00 Archivage du WAL pg_xlog/00000002.history.
Jusque là tout semble ok. Je me connecte sur mon nouveau maître, les dernières mises à jour sont faites.
Je veux maintenant restaurer la sauvegarde de cette nuit sur mon ancien maître, qui doit devenir mon nouvel esclave. Après démarrage, j'ai les logs suivants :
2016-06-15 08:11:50 CEST [1717]: [1-1] user= 2016-06-15 08:11:50 CEST LOG: database system was interrupted; last known up at 2016-06-15 04:10:02 CEST
2016-06-15 08:11:50 CEST [1717]: [2-1] user= 2016-06-15 08:11:50 CEST LOG: entering standby mode
2016-06-15 08:11:50 CEST [1717]: [3-1] user= 2016-06-15 08:11:50 CEST LOG: restored log file "000000010000000200000021" from archive
2016-06-15 08:11:51 CEST [1717]: [4-1] user= 2016-06-15 08:11:50 CEST LOG: redo starts at 2/21000098
2016-06-15 08:11:51 CEST [1717]: [5-1] user= 2016-06-15 08:11:50 CEST LOG: consistent recovery state reached at 2/210000C0
2016-06-15 08:11:51 CEST [1717]: [6-1] user= 2016-06-15 08:11:50 CEST LOG: restored log file "000000010000000200000022" from archive
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
2016-06-15 08:11:51 CEST [1723]: [1-1] user= 2016-06-15 08:11:51 CEST LOG: fetching timeline history file for timeline 2 from primary server
2016-06-15 08:11:51 CEST [1723]: [2-1] user= 2016-06-15 08:11:51 CEST LOG: started streaming WAL from primary at 2/23000000 on timeline 1
2016-06-15 08:11:51 CEST [1723]: [3-1] user= 2016-06-15 08:11:51 CEST FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 000000020000000200000023 has already been removed
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
Dans mon répertoire de WAL archivés, j'ai :
-rw------- 1 postgres postgres 16777216 15 juin 04:10 000000010000000200000020
-rw------- 1 postgres postgres 16777216 15 juin 04:10 000000010000000200000021
-rw------- 1 postgres postgres 319 15 juin 04:10 000000010000000200000021.00000028.backup
-rw------- 1 postgres postgres 16777216 15 juin 07:10 000000010000000200000022
-rw------- 1 postgres postgres 16777216 15 juin 07:11 000000010000000200000023.partial
-rw------- 1 postgres postgres 16777216 15 juin 07:28 000000020000000200000023
-rw------- 1 postgres postgres 16777216 15 juin 07:28 000000020000000200000024
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000025
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000026
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000027
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000028
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000029
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000002A
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000002B
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000002C
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000002D
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000002E
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000002F
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000030
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000031
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000032
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000033
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000034
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000035
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000036
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000037
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000038
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000039
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000003A
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000003B
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000003C
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000003D
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000003E
-rw------- 1 postgres postgres 16777216 15 juin 07:29 00000002000000020000003F
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000040
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000041
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000042
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000043
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000044
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000045
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000046
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000047
-rw------- 1 postgres postgres 16777216 15 juin 07:29 000000020000000200000048
-rw------- 1 postgres postgres 16777216 15 juin 07:32 000000020000000200000049
-rw------- 1 postgres postgres 16777216 15 juin 07:32 00000002000000020000004A
-rw------- 1 postgres postgres 16777216 15 juin 07:32 00000002000000020000004B
-rw------- 1 postgres postgres 16777216 15 juin 07:32 00000002000000020000004C
-rw------- 1 postgres postgres 16777216 15 juin 07:32 00000002000000020000004D
-rw------- 1 postgres postgres 16777216 15 juin 07:32 00000002000000020000004E
-rw------- 1 postgres postgres 16777216 15 juin 07:32 00000002000000020000004F
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000050
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000051
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000052
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000053
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000054
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000055
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000056
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000057
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000058
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000059
-rw------- 1 postgres postgres 16777216 15 juin 07:33 00000002000000020000005A
-rw------- 1 postgres postgres 16777216 15 juin 07:33 00000002000000020000005B
-rw------- 1 postgres postgres 16777216 15 juin 07:33 00000002000000020000005C
-rw------- 1 postgres postgres 16777216 15 juin 07:33 00000002000000020000005D
-rw------- 1 postgres postgres 16777216 15 juin 07:33 00000002000000020000005E
-rw------- 1 postgres postgres 16777216 15 juin 07:33 00000002000000020000005F
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000060
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000061
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000062
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000063
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000064
-rw------- 1 postgres postgres 16777216 15 juin 07:33 000000020000000200000065
-rw------- 1 postgres postgres 16777216 15 juin 08:01 000000020000000200000066
-rw------- 1 postgres postgres 16777216 15 juin 08:10 000000020000000200000067
-rw------- 1 postgres postgres 16777216 15 juin 08:10 000000020000000200000068
-rw------- 1 postgres postgres 319 15 juin 08:10 000000020000000200000068.00000028.backup
-rw------- 1 postgres postgres 42 15 juin 07:11 00000002.history
Avez-vous une idée du problème ?
D'avancer merci pour votre aide.
Hors ligne
Bonjour,
Vous devriez retenter une hotback de votre nouveau maitre et une restore sur le nouveau slave dans la foulée.
La précédente sauvegarde devait être trop "lointaine".
Le changement de timeline a impacté le wal n°23 (d'où le fichier .partial), donc c'est pour ça que la sauvegarde doit être faite après le changement de timeline.
Cordialement,
Sébastien.
Hors ligne
2016-06-15 08:11:50 CEST [1717]: [2-1] user= 2016-06-15 08:11:50 CEST LOG: entering standby mode
Le nouvel esclave entre en mode standby.
2016-06-15 08:11:50 CEST [1717]: [3-1] user= 2016-06-15 08:11:50 CEST LOG: restored log file "000000010000000200000021" from archive
Il copie et rejoue le journal 0...1...2...21.
2016-06-15 08:11:51 CEST [1717]: [4-1] user= 2016-06-15 08:11:50 CEST LOG: redo starts at 2/21000098
2016-06-15 08:11:51 CEST [1717]: [5-1] user= 2016-06-15 08:11:50 CEST LOG: consistent recovery state reached at 2/210000C0
Il indique l'entrée dans le mode de rejeu, et qu'il a atteint l'état de cohérence (ie, le pg_stop_backup() de l'ancien maître).
2016-06-15 08:11:51 CEST [1717]: [6-1] user= 2016-06-15 08:11:50 CEST LOG: restored log file "000000010000000200000022" from archive
Il copie et rejoue le 0...1...2...22.
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
La restore_command a échoué à récupérer le 0...1...2...23, ce qui est normal. Le fichier 23 était en cours de remplissage pendant le promote de l'esclave.
2016-06-15 08:11:51 CEST [1723]: [1-1] user= 2016-06-15 08:11:51 CEST LOG: fetching timeline history file for timeline 2 from primary server
Donc il récupère le fichier historique pour la timeline 2.
2016-06-15 08:11:51 CEST [1723]: [2-1] user= 2016-06-15 08:11:51 CEST LOG: started streaming WAL from primary at 2/23000000 on timeline 1
L'esclave (nouveau) lance le streaming sur la timeline 1, pour voir si le maître peut lui fournir les infos mais...
2016-06-15 08:11:51 CEST [1723]: [3-1] user= 2016-06-15 08:11:51 CEST FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 000000020000000200000023 has already been removed
Le maître ne dispose plus du journal 0...2...2...23. Vu le nombre de journaux archivés, ça semble logique. Du coup, il bascule vers l'utilisation de l'archive_command.
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000200000023 »: Aucun fichier ou dossier de ce type
Mais l'archive_command ne trouve pas le fichier 0...1...2...23 dans le répertoire d'archivage. Fin du jeu.
Le répertoire que vous listez semble le contenir. Et PostgreSQL dit que non. Donc vous ne regardez pas le bon répertoire. Et soit l'archivage soit la restauration est mal configuré.
Guillaume.
Hors ligne
Bonjour Sébastien,
Merci pour la réponse.
Le hot-backup fait à 4h et la bascule à 7h.
Cela ne peut pas fonctionner ?
Il faut forcément faire un hot-backup après bascule ?
Hors ligne
Guillaume pourra nous dire exactement pourquoi mais pour ma part en cas de bascule je fais toujours une hotback du nouveau maitre dans la foulée pour pouvoir reconstruire les nouveaux slaves.
Cordialement,
Sébastien.
Hors ligne
Bonjour Guillaume,
Je n'ai qu'un répertoire PG_ARC des WAL archivés, au même endroit sur les 2 machines, ce qui semble écarter ce problème.
L'archivage est configuré de la façon suivante :
J'ai les paramètres suivants sur le maître :
wal_level = 'archive'
archive_mode = on
archive_command = 'sh /home/postgres/scripts/pg_archive_wal.sh "%p" "%f"'
Le pg_archive_wal.sh fait un CP en local dans le répertoire PG_ARC et un RSYNC sur l'esclave toujours dans le répertoire PG_ARC.
La restauration est configurée de la façon suivante :
Sur l'esclave j'ai le même fichier postgresql.conf.
Le recovery.conf contient :
standby_mode = 'on'
primary_conninfo = 'host=dev-postgres-01 port=5432 user=replic'
restore_command = 'cp $HOME/PG_ARC/%f %p'
trigger_file = '$HOME/bascule.txt'
Cela peut-il vous aider dans le diagnostic ?
Hors ligne
vite fait comme ça tout me semble correct.
essayez quand même de refaire une hotback et de restorer tout de suite sur le slave pour voir les logs.
Cordialement,
Sébastien.
Hors ligne
J'ai refait la procédure complète (mise en place Warm-Standby+Streaming, puis bascule, puis reconstruction) mais cette fois en partant d'un hot-backup de l'esclave devenu maître et CA MARCHE :-)
Peut-être le $HOME dans la restore_command ?
Je vais refaire la procédure complète en remplaçant le $HOME par /home/postgres pour voir.
Hors ligne
Le changement sur la restore_command ne change rien.
Je refais toute la procédure en reconstruisant mon nouvel esclave (après bascule) à partir du même hot-backup qui m'a servi à construire mon premier esclave (avant bascule).
Les traces me disent :
2016-06-15 13:29:40 CEST [21775]: [1-1] user= 2016-06-15 13:29:40 CEST LOG: database system was interrupted; last known up at 2016-06-15 13:15:59 CEST
2016-06-15 13:29:40 CEST [21775]: [2-1] user= 2016-06-15 13:29:40 CEST LOG: entering standby mode
2016-06-15 13:29:40 CEST [21775]: [3-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "00000001000000000000000B" from archive
2016-06-15 13:29:40 CEST [21775]: [4-1] user= 2016-06-15 13:29:40 CEST LOG: redo starts at 0/B000028
2016-06-15 13:29:40 CEST [21775]: [5-1] user= 2016-06-15 13:29:40 CEST LOG: consistent recovery state reached at 0/B00EFB8
2016-06-15 13:29:40 CEST [21775]: [6-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "00000001000000000000000C" from archive
2016-06-15 13:29:41 CEST [21775]: [7-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "00000001000000000000000D" from archive
2016-06-15 13:29:41 CEST [21775]: [8-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "00000001000000000000000E" from archive
2016-06-15 13:29:42 CEST [21775]: [9-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "00000001000000000000000F" from archive
2016-06-15 13:29:42 CEST [21775]: [10-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "000000010000000000000010" from archive
2016-06-15 13:29:43 CEST [21775]: [11-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "000000010000000000000011" from archive
2016-06-15 13:29:43 CEST [21775]: [12-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "000000010000000000000012" from archive
2016-06-15 13:29:43 CEST [21775]: [13-1] user= 2016-06-15 13:29:40 CEST LOG: restored log file "000000010000000000000013" from archive
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000000000014 »: Aucun fichier ou dossier de ce type
2016-06-15 13:29:44 CEST [21788]: [1-1] user= 2016-06-15 13:29:44 CEST LOG: fetching timeline history file for timeline 2 from primary server
2016-06-15 13:29:44 CEST [21788]: [2-1] user= 2016-06-15 13:29:44 CEST LOG: started streaming WAL from primary at 0/14000000 on timeline 1
2016-06-15 13:29:44 CEST [21788]: [3-1] user= 2016-06-15 13:29:44 CEST LOG: replication terminated by primary server
2016-06-15 13:29:44 CEST [21788]: [4-1] user= 2016-06-15 13:29:44 CEST DETAIL: End of WAL reached on timeline 1 at 0/14000098.
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000000000014 »: Aucun fichier ou dossier de ce type
2016-06-15 13:29:44 CEST [21775]: [14-1] user= 2016-06-15 13:29:40 CEST LOG: invalid record length at 0/14000098
2016-06-15 13:29:44 CEST [21788]: [5-1] user= 2016-06-15 13:29:44 CEST LOG: restarted WAL streaming at 0/14000000 on timeline 1
2016-06-15 13:29:44 CEST [21788]: [6-1] user= 2016-06-15 13:29:44 CEST LOG: replication terminated by primary server
2016-06-15 13:29:44 CEST [21788]: [7-1] user= 2016-06-15 13:29:44 CEST DETAIL: End of WAL reached on timeline 1 at 0/14000098.
cp: impossible d'évaluer « /home/postgres/PG_ARC/000000010000000000000014 »: Aucun fichier ou dossier de ce type
2016-06-15 13:29:49 CEST [21788]: [8-1] user= 2016-06-15 13:29:44 CEST LOG: restarted WAL streaming at 0/14000000 on timeline 1
2016-06-15 13:29:49 CEST [21788]: [9-1] user= 2016-06-15 13:29:44 CEST LOG: replication terminated by primary server
Le fichier 0...1...14 n'existe pas dans mon PG_ARC, c'est un 0...1...14.partial
Ensuite j'ai un 00000002.history, qui je présume correspond au moment ou j'ai promu mon esclave
Puis des 0...2...14, 0...2...15, ...
Il y a certainement quelque chose que je n'ai pas compris au niveau timeline ? Pouvez-vous m'éclairer ?
Ou un problème de configuration mais je ne vois pas où ? Quelle piste creuser ?
Hors ligne
Pages : 1