Thread: restore and recovery using WAL: unkown messages in serverlog

Hello,

I'm testing WAL based backup and restore/recovery and encounter some
unclear messages in the 'serverlog' on recovery. The used procedure on a
test server is:

Kick the copy of the current WAL to the archive:

$ psql -Usisis -c "select pg_switch_wal();"
$ ls -l /data/postgresql11/wal_archive
insgesamt 49212
-rw------- 1 postgres postgres 16777216  3. Sep 07:53 00000001000000010000008B
-rw------- 1 postgres postgres 16777216  3. Sep 08:52 00000001000000010000008C
-rw------- 1 postgres postgres 16777216  3. Sep 08:54 00000001000000010000008D

Now we backup the cluster:

$ pg_basebackup -Usisis -Ft -D /data/postgresql11/backup-20190903-1

$ ls -l /data/postgresql11/backup-20190903-1
insgesamt 6379972
-rw------- 1 postgres postgres 6509913088  3. Sep 09:02 base.tar
-rw------- 1 postgres postgres   16779264  3. Sep 09:02 pg_wal.tar

$ ls -l /data/postgresql11/wal_archive/
insgesamt 65620
-rw------- 1 postgres postgres 16777216  3. Sep 07:53 00000001000000010000008B
-rw------- 1 postgres postgres 16777216  3. Sep 08:52 00000001000000010000008C
-rw------- 1 postgres postgres 16777216  3. Sep 08:54 00000001000000010000008D
-rw------- 1 postgres postgres 16777216  3. Sep 09:02 00000001000000010000008E
-rw------- 1 postgres postgres      342  3. Sep 09:02 00000001000000010000008E.00000028.backup

We stop and "destroy" the cluster (i.e. we move it away):

# /etc/init.d/postgres stop
# mv /data/postgresql11/data /data/postgresql11/data.away
# mkdir /data/postgresql11/data
# chown postgres:postgres /data/postgresql11/data
# chmod 0700 /data/postgresql11/data

We restore the cluster as user 'postgres' and recover based on the WAL:

$ tar xf /data/postgresql11/backup-20190903-1/base.tar    -C /data/postgresql11/data/
$ tar xf /data/postgresql11/backup-20190903-1/pg_wal.tar  -C /data/postgresql11/data/pg_wal/

For recover we create a file recovery.conf

$ vim /data/postgresql11/data/recovery.conf

  restore_command = 'cp /data/postgresql11/wal_archive/%f %p'

Now start PostgreSQL again:

# /etc/init.d/postgres start

In the 'serverlog' it gives some errors (marked with ***>); sorry that the
messages are in German, it means 'cp: stat failed for ..., file or directory not found':

     2019-09-03 09:18:44.355 CEST [25388] LOG:  starte Wiederherstellung aus Archiv
     2019-09-03 09:18:45.249 CEST [25388] LOG:  Logdatei »00000001000000010000008E« aus Archiv wiederhergestellt
     2019-09-03 09:18:45.306 CEST [25388] LOG:  Redo beginnt bei 1/8E000028
     2019-09-03 09:18:45.308 CEST [25388] LOG:  konsistenter Wiederherstellungszustand erreicht bei 1/8E000130
     2019-09-03 09:18:45.308 CEST [25387] LOG:  Datenbanksystem ist bereit, um lesende Verbindungen anzunehmen
     2019-09-03 09:18:46.024 CEST [25388] LOG:  Logdatei »00000001000000010000008F« aus Archiv wiederhergestellt
***> cp: der Aufruf von stat für '/data/postgresql11/wal_archive/000000010000000100000090' ist nicht möglich: Datei
oderVerzeichnis nicht gefunden
 
     2019-09-03 09:18:47.838 CEST [25388] LOG:  Redo fertig bei 1/8F000140
     2019-09-03 09:18:47.869 CEST [25388] LOG:  Logdatei »00000001000000010000008F« aus Archiv wiederhergestellt
***> cp: der Aufruf von stat für '/data/postgresql11/wal_archive/00000002.history' ist nicht möglich: Datei oder
Verzeichnisnicht gefunden
 
     2019-09-03 09:18:47.900 CEST [25388] LOG:  gewählte neue Zeitleisten-ID: 2
     2019-09-03 09:18:47.961 CEST [25388] LOG:  Wiederherstellung aus Archiv abgeschlossen
***> cp: der Aufruf von stat für '/data/postgresql11/wal_archive/00000001.history' ist nicht möglich: Datei oder
Verzeichnisnicht gefunden
 
     2019-09-03 09:18:48.072 CEST [25387] LOG:  Datenbanksystem ist bereit, um Verbindungen anzunehmen
     
What is causing the errors about the missing files in /data/postgresql11/wal_archive?

Btw: Is there away to run the server for German UTF-8, but with English
messages in the log?

Thanks

    matthias

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub

On Tue, Sep 3, 2019 at 9:57 AM Matthias Apitz <guru@unixarea.de> wrote:
>      2019-09-03 09:18:46.024 CEST [25388] LOG:  Logdatei »00000001000000010000008F« aus Archiv wiederhergestellt
> ***> cp: der Aufruf von stat für '/data/postgresql11/wal_archive/000000010000000100000090' ist nicht möglich: Datei
oderVerzeichnis nicht gefunden 

It's not an error, it is searching the next wal that after 0x8F is
0x90, but the log is not there, so the recovery has finished. The
cluster does not know where to stop because your recovery.conf did not
specified, so it tries to do as much wal processing as it can and
stops when it finds no more.

>      2019-09-03 09:18:47.838 CEST [25388] LOG:  Redo fertig bei 1/8F000140

Redo is done.


> ***> cp: der Aufruf von stat für '/data/postgresql11/wal_archive/00000002.history' ist nicht möglich: Datei oder
Verzeichnisnicht gefunden 

having finisched the wals it is searching for a branch on timeline 2

>      2019-09-03 09:18:47.900 CEST [25388] LOG:  gewählte neue Zeitleisten-ID: 2

and it switches on timeline 2 autonomously

Pretty much that should be what you see in the logs.

> Btw: Is there away to run the server for German UTF-8, but with English
> messages in the log?

Set lc_messages in the postgresql.conf to something in english, I
think 'en_US.UTF-8' could do the trick, but haven't tried it.

Luca