[GENERAL] Unexpected WAL-archive restore behaviour - Mailing list pgsql-general

From Nikolay Petrov
Subject [GENERAL] Unexpected WAL-archive restore behaviour
Date
Msg-id 76D18D07-2BF2-4E8E-B1FD-7CA861F48645@yandex.ru
Whole thread Raw
Responses Re: [GENERAL] Unexpected WAL-archive restore behaviour  (Tomas Vondra <tomas.vondra@2ndquadrant.com>)
List pgsql-general
Hello everyone.
I use postgresql 9.6.1 running under a debian 8 (master - slave hot standby streaming replication).
I found out unexpected WAL-archive restore behaviour.

master:
    wal_level = replica
    archive_mode = on
    archive_command = 'gzip < %p > /var/lib/postgres/archives/%f'

slave recovery.conf:
    standby_mode = 'on'
    primary_conninfo = 'host=192.168.50.96 port=5432 user=replication password=password'
    primary_slot_name = 'myslot'
    restore_command = 'ssh postgres@192.168.50.96 \'cat /var/lib/postgres/archives/%f\' | gzip -d -c > %p'
    recovery_target_timeline = 'latest'

It was necessary to add replication delay (recovery_min_apply_delay = 30min).

Hot standby server was started with new recovery.conf, reached consistent recovery state and resumed to restore WAL
segmentsfrom archive. When couple of next wal segments became unavailable slave server just "skipped" them, instead to
startstreaming WAL from primary: 

2017-02-16 10:54:22 MSK [5956-1] LOG:  database system was shut down in recovery at 2017-02-16 10:19:01 MSK
2017-02-16 10:54:22 MSK [5957-1] [unknown]@[unknown] LOG:  incomplete startup packet
cat: /var/lib/postgres/archives/00000003.history: No such file or directory

gzip: stdin: unexpected end of file
2017-02-16 10:54:22 MSK [5956-2] LOG:  entering standby mode
cat: /var/lib/postgres/archives/00000002.history: No such file or directory

gzip: stdin: unexpected end of file
2017-02-16 10:54:22 MSK [5969-1] postgres@postgres FATAL:  the database system is starting up
2017-02-16 10:54:23 MSK [5956-3] LOG:  restored log file "00000002000012A2000000D0" from archive
2017-02-16 10:54:23 MSK [5977-1] postgres@postgres FATAL:  the database system is starting up
2017-02-16 10:54:23 MSK [5956-4] LOG:  restored log file "00000002000012A2000000B5" from archive
2017-02-16 10:54:23 MSK [5956-5] LOG:  redo starts at 12A2/B5ECC5C0
2017-02-16 10:54:23 MSK [5956-6] LOG:  restored log file "00000002000012A2000000B6" from archive

...

2017-02-16 10:54:48 MSK [5956-55] LOG:  restored log file "00000002000012A2000000E7" from archive
2017-02-16 10:54:48 MSK [5956-56] LOG:  restored log file "00000002000012A2000000E8" from archive
2017-02-16 10:54:48 MSK [5956-57] LOG:  consistent recovery state reached at 12A2/E81D86C8
2017-02-16 10:54:48 MSK [5954-3] LOG:  database system is ready to accept read only connections
2017-02-16 10:55:07 MSK [6233-1] [unknown]@[unknown] LOG:  incomplete startup packet

...

2017-02-16 11:27:37 MSK [5956-115] LOG:  restored log file "00000002000012A300000022" from archive
2017-02-16 11:27:38 MSK [5956-116] LOG:  restored log file "00000002000012A300000023" from archive
2017-02-16 11:27:59 MSK [5956-117] LOG:  restored log file "00000002000012A300000024" from archive
cat: /var/lib/postgres/archives/00000002000012A300000025: No such file or directory

gzip: stdin: unexpected end of file
cat: /var/lib/postgres/archives/00000002000012A300000026: No such file or directory

gzip: stdin: unexpected end of file
cat: /var/lib/postgres/archives/00000002000012A300000027: No such file or directory

gzip: stdin: unexpected end of file
2017-02-16 11:28:37 MSK [5956-118] LOG:  restored log file "00000002000012A300000028" from archive
2017-02-16 11:28:39 MSK [5956-119] LOG:  restored log file "00000002000012A300000029" from archive
2017-02-16 11:28:59 MSK [5956-120] LOG:  restored log file "00000002000012A30000002A" from archive

"Skipped" WAL segments looks like normal WAL archives:

postgres@myhost:/var/lib/postgres/archives/tmpwal$ /usr/lib/postgresql/9.6/bin/pg_xlogdump -z
./00000002000012A300000026
Type                    N  (%)      Record size (%)     FPI size    (%)    Combined size   (%)
----                    -  ---      ----------- ---     --------    ---    -------------   ---
XLOG                    0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Transaction            34 (0.43)          1472 (0.56)            0 (0.00)           1472 (0.01)
Storage                 0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
CLOG                    0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Database                0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Tablespace              0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
MultiXact               0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
RelMap                  0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Standby                 2 (0.03)           184 (0.07)            0 (0.00)            184 (0.00)
Heap2                 673 (8.51)         21544 (8.25)      2057620 (12.90)       2079164 (12.83)
Heap                 4854 (61.35)       171361 (65.59)     7642192 (47.92)       7813553 (48.20)
Btree                2330 (29.45)        63248 (24.21)     6248364 (39.18)       6311612 (38.94)
Hash                    0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Gin                     0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Gist                    0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Sequence               19 (0.24)          3458 (1.32)            0 (0.00)           3458 (0.02)
SPGist                  0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
BRIN                    0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
CommitTs                0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
ReplicationOrigin       0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
Generic                 0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
LogicalMessage          0 (0.00)             0 (0.00)            0 (0.00)              0 (0.00)
                 --------             --------           --------               --------
Total                7912              261267 [1.61%]    15948176 [98.39%]      16209443 [100%]

Is it normal behaviour?  Can it cause standby consistency damage?
Thank you.






pgsql-general by date:

Previous
From: "David G. Johnston"
Date:
Subject: [GENERAL] Re: [GENERAL] How tö select a column?
Next
From: Tomas Vondra
Date:
Subject: Re: [GENERAL] Unexpected WAL-archive restore behaviour