Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eZJF3-00059F-4c for pgsql-admin@arkaria.postgresql.org; Wed, 10 Jan 2018 16:28:41 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eZJF2-0007eh-MV for pgsql-admin@arkaria.postgresql.org; Wed, 10 Jan 2018 16:28:40 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eZJF2-0007e5-97 for pgsql-admin@lists.postgresql.org; Wed, 10 Jan 2018 16:28:40 +0000 Received: from smtp-32-i5.italiaonline.it ([213.209.9.32] helo=libero.it) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1eZJEx-0004T6-E4 for pgsql-admin@lists.postgresql.org; Wed, 10 Jan 2018 16:28:39 +0000 Received: from oxapps-09-053.iol.local ([10.101.8.63]) by smtp-32.iol.local with SMTP id ZJEuexk2pUOedZJEuen8fB; Wed, 10 Jan 2018 17:28:33 +0100 x-libjamoibt: 1601 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=virgilio.it; s=s2017; t=1515601713; bh=tu7O036JPW3kWxYNJmzEv/mu9otGIXMxtuL7/5aZADY=; h=Date:From:To:In-Reply-To:References:Subject; b=Izo/AUBTcKOGJ5l8JLjVObOV000UG6dUSBSXzdnePPGLAziOPraqcaotMhgdqwgR5 8j8bQa/gtsOWOadBAeqKXRDkDfxn0n3HHV1Ly6tCH+eRdqg3ea4cdH8LRgC9wy2viK MMg8FGCcsSKBPaUSE5/47PMggCjlBAa+5tOBAKvfMf5TFTcwbVy3CU3PEzJpt/L4m4 Hvnz3Eber5rUYtL4QL6Mu578vyyelETLoeQS3aXDmrgE5Jvjro0wTBESVMzIyyPvuV +XlfDIMZmD5wAEbIg4SIZbN/7mhmUsUccW0bPUATMgHeoKvBKxHkiEQ88TfZvCEHHu Bcxb26i7s5hMg== X-CNFS-Analysis: v=2.2 cv=H56r+6Qi c=1 sm=1 tr=0 a=h9nG7A+Nx8W9eq05Vsxl+g==:117 a=f8JpAwMoorgA:10 a=xJTDAyycAAAA:8 a=kPg10VR9AAAA:8 a=XymiYkNO9nAlrz4LP0QA:9 a=QEXdDO2ut3YA:10 a=UDlnAjvpr0hHQh3BoNUA:9 a=qEXrR9ltaXKIqABL:21 a=_W_S_7VecoQA:10 a=swXOJ3vSs_fEAyTCSpdh:22 a=pbkouhIAMd91kwdrYYoq:22 Date: Wed, 10 Jan 2018 17:28:32 +0100 (CET) From: flumbador@virgilio.it To: Alvaro Herrera , pgsql-admin@lists.postgresql.org Message-ID: <858243188.823822.1515601712820@mail.virgilio.it> In-Reply-To: <1623608978.635173.1515419600795@mail.virgilio.it> References: <524817289.230206.1514560886805@mail.virgilio.it> <20180102153854.nldw2ouxnehtp63k@alvherre.pgsql> <1623608978.635173.1515419600795@mail.virgilio.it> Subject: Re: Issue on restore / recover MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_823821_2048468995.1515601712807" X-Priority: 3 Importance: Medium X-Mailer: Open-Xchange Mailer v7.8.3-Rev40 X-Originating-IP: 46.235.159.86 X-Originating-Client: open-xchange-appsuite x-libjamsun: TIUqU2BzZ3Z3gPB46jckecFIn4hywQhH x-libjamv: 0K3hlr/xwwk= X-CMAE-Envelope: MS4wfBOu3VFFgc3vSz2aWP4J1RPRHv3mukTxowHE6hjFITqO8gq24zxGrAzci8g0Tq7bo3x8536CLuVT7wO2LaC7IO/ok+TOl83IMZg8o/+lHxngf63n8Gfd 8caPkzb1vLxJi/8Q5YNTBpnfqE/YNJY4Kh+p5PFkm+sMVJ9AmYVVGfAKvOoJ0yViPzDjM89Kxxq0/8cyDyHMZkkQ/CFG4cUpxEQ1syHIJkTgdiMZrOz79pQ1 List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk ------=_Part_823821_2048468995.1515601712807 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Hi All,=20 I reproduced the issue with the following test case: 1) Create a table for testing porpouse: pdbabe=3D# CREATE TABLE test_corrupt (order_date timestamptz, item char(102= 4)); CREATE TABLE 2) Insert some data in the table pdbabe=3D# INSERT INTO test_corrupt (order_date, item) SELECT x, 'generic item' FROM generate_series('2018-01-01 00:00:00'::timestamptz, '2018-01-01 00:10:= 00'::timestamptz,'60 seconds'::interval) a(x); INSERT 0 11 pdbabe=3D# select order_date, substring(item, 1, 20) from test_corrupt ; order_date | substring ------------------------+-------------- 2018-01-01 00:00:00+01 | generic item 2018-01-01 00:01:00+01 | generic item 2018-01-01 00:02:00+01 | generic item 2018-01-01 00:03:00+01 | generic item 2018-01-01 00:04:00+01 | generic item 2018-01-01 00:05:00+01 | generic item 2018-01-01 00:06:00+01 | generic item 2018-01-01 00:07:00+01 | generic item 2018-01-01 00:08:00+01 | generic item 2018-01-01 00:09:00+01 | generic item 2018-01-01 00:10:00+01 | generic item 3) Check the file that contain the table: pdbabe=3D# SELECT pg_relation_filepath('test_corrupt'); pg_relation_filepath ---------------------------------------------- pg_tblspc/16385/PG_9.4_201409291/16386/49391 (1 row) pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_2014= 09291/16386> ls -la | grep 49391 -rw------- 1 pgpdbabe pdbabe 16384 Jan 9 14:13 49391 -rw------- 1 pgpdbabe pdbabe 24576 Jan 9 14:13 49391_fsm 4) At 2.40 A.M. Start the backup of the database (filesystem backup): pg_start_backup ----------------- 17/30000028 (1 row) 5) At 2:57 A.M. new record is inserted in the table. insert into test_corrupt values (current_timestamp, 'new item') ; After the insert the content of the table is: pdbabe=3D# select order_date, substring(item, 1, 20) from test_corrupt ; order_date | substring -------------------------------+-------------- 2018-01-01 00:00:00+01 | generic item 2018-01-01 00:01:00+01 | generic item 2018-01-01 00:02:00+01 | generic item 2018-01-01 00:03:00+01 | generic item 2018-01-01 00:04:00+01 | generic item 2018-01-01 00:05:00+01 | generic item 2018-01-01 00:06:00+01 | generic item 2018-01-01 00:07:00+01 | generic item 2018-01-01 00:08:00+01 | generic item 2018-01-01 00:09:00+01 | generic item 2018-01-01 00:10:00+01 | generic item 2018-01-10 02:57:01.106676+01 | new item (12 rows) No other insert / update / delete are executed against the table until the = restore / recover. 6) The backup of filesystem on which resides the Postgresql, ended at 4:01 = A.M pg_stop_backup | now ----------------+------------------------------- 17/7EFE3900 | 2018-01-10 04:01:53.496869+01 (1 row) 8) Restore of the postgresql database, by executung the restore of the prev= ious filesystem backup. 9) Contets of backup_label restored: pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe> more backup_label START WAL LOCATION: 17/30000028 (file 000000070000001700000030) CHECKPOINT LOCATION: 17/30000060 BACKUP METHOD: pg_start_backup BACKUP FROM: master START TIME: 2018-01-10 02:40:00 CET LABEL: bckdb 10) Delete of the file containg the table "test_corrupt" to simulate the fi= le missing in the backup: pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe> cd $PGDATA/pg_tblspc/16385= /PG_9.4_201409291/16386 pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_2014= 09291/16386> ls -la | grep 49391 -rw------- 1 pgpdbabe pdbabe 16384 Jan 10 02:57 49391 -rw------- 1 pgpdbabe pdbabe 24576 Jan 9 14:13 49391_fsm pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_2014= 09291/16386> rm ./49391 pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_2014= 09291/16386> ls -la | grep 49391 -rw------- 1 pgpdbabe pdbabe 24576 Jan 9 14:13 49391_fsm pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_2014= 09291/16386> 12) Create file recovery.conf: restore_command =3D 'cp /pgsql/pdbabe/archive/%f %p' archive_cleanup_command =3D 'pg_archivecleanup /pgsql/pdbabe/archive %r' 13) Start Postgresql to recover the database ... Recover is successfull ...= NO error in logfile: 2018-01-10 12:05:25 CET [30299]: [1-1] user=3D,db=3D,app=3D,client=3D LOG: = database system was interrupted; last known up at 2018-01 -10 02:50:00 CET 2018-01-10 12:05:25 CET [30299]: [2-1] user=3D,db=3D,app=3D,client=3D LOG: = creating missing WAL directory "pg_xlog/archive_status" 2018-01-10 12:05:25 CET [30299]: [3-1] user=3D,db=3D,app=3D,client=3D LOG: = starting archive recovery 2018-01-10 12:05:25 CET [30299]: [4-1] user=3D,db=3D,app=3D,client=3D LOG: = restored log file "00000007.history" from archive 2018-01-10 12:05:25 CET [30299]: [5-1] user=3D,db=3D,app=3D,client=3D LOG: = restored log file "000000070000001700000030" from archive 2018-01-10 12:05:25 CET [30299]: [6-1] user=3D,db=3D,app=3D,client=3D LOG: = redo starts at 17/30000028 2018-01-10 12:05:25 CET [30299]: [7-1] user=3D,db=3D,app=3D,client=3D LOG: = restored log file "000000070000001700000031" from archive 2018-01-10 12:05:26 CET [30299]: [8-1] user=3D,db=3D,app=3D,client=3D LOG: = restored log file "000000070000001700000032" from archive 2018-01-10 12:05:26 CET [30299]: [9-1] user=3D,db=3D,app=3D,client=3D LOG: = restored log file "000000070000001700000033" from archive ...... 2018-01-10 12:05:46 CET [30299]: [81-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "00000007000000170000007B" from archiv e 2018-01-10 12:05:48 CET [30299]: [82-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "00000007000000170000007C" from archiv e 2018-01-10 12:05:49 CET [30299]: [83-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "00000007000000170000007D" from archiv e 2018-01-10 12:05:50 CET [30299]: [84-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "00000007000000170000007E" from archiv e 2018-01-10 12:05:50 CET [30299]: [85-1] user=3D,db=3D,app=3D,client=3D LOG:= consistent recovery state reached at 17/7EFE3900 2018-01-10 12:05:50 CET [30297]: [3-1] user=3D,db=3D,app=3D,client=3D LOG: = database system is ready to accept read only connections 2018-01-10 12:05:50 CET [30299]: [86-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "00000007000000170000007F" from archiv e 2018-01-10 12:05:50 CET [30299]: [87-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "000000070000001700000080" from archiv e cp: cannot stat `/pgsql/pdbabe/archive/000000070000001700000081': No such f= ile or directory 2018-01-10 12:05:50 CET [30299]: [88-1] user=3D,db=3D,app=3D,client=3D LOG:= redo done at 17/800875F0 2018-01-10 12:05:50 CET [30299]: [89-1] user=3D,db=3D,app=3D,client=3D LOG:= last completed transaction was at log time 2018-01-10 09 :17:01.870329+01 2018-01-10 12:05:53 CET [30299]: [90-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "000000070000001700000080" from archiv e cp: cannot stat `/pgsql/pdbabe/archive/00000008.history': No such file or d= irectory 2018-01-10 12:05:53 CET [30299]: [91-1] user=3D,db=3D,app=3D,client=3D LOG:= selected new timeline ID: 8 2018-01-10 12:05:53 CET [30299]: [92-1] user=3D,db=3D,app=3D,client=3D LOG:= restored log file "00000007.history" from archive 2018-01-10 12:05:53 CET [30299]: [93-1] user=3D,db=3D,app=3D,client=3D LOG:= archive recovery complete 2018-01-10 12:05:53 CET [30302]: [1-1] user=3D,db=3D,app=3D,client=3D LOG: = checkpoint starting: end-of-recovery immediate wait 2018-01-10 12:05:57 CET [30397]: [1-1] user=3D[unknown],db=3D[unknown],app= =3D[unknown],client=3D10.151.201.1 LOG: connection receive d: host=3D10.151.201.1 port=3D51057 2018-01-10 12:05:57 CET [30397]: [2-1] user=3Dpatrol,db=3Dpdbabe,app=3D[unk= nown],client=3D10.151.201.1 FATAL: no pg_hba.conf entry f or host "10.151.201.1", user "patrol", database "pdbabe", SSL off 2018-01-10 12:06:57 CET [30410]: [1-1] user=3D[unknown],db=3D[unknown],app= =3D[unknown],client=3D10.151.201.1 LOG: connection receive d: host=3D10.151.201.1 port=3D51058 2018-01-10 12:06:57 CET [30410]: [2-1] user=3Dpatrol,db=3Dpdbabe,app=3D[unk= nown],client=3D10.151.201.1 FATAL: no pg_hba.conf entry f or host "10.151.201.1", user "patrol", database "pdbabe", SSL off 2018-01-10 12:07:15 CET [30302]: [2-1] user=3D,db=3D,app=3D,client=3D LOG: = checkpoint complete: wrote 254519 buffers (99.4%); 0 tran saction log file(s) added, 0 removed, 0 recycled; write=3D71.245 s, sync=3D= 10.241 s, total=3D81.566 s; sync files=3D39, longest=3D10.21 4 s, average=3D0.262 s 2018-01-10 12:07:15 CET [30299]: [94-1] user=3D,db=3D,app=3D,client=3D LOG:= MultiXact member wraparound protections are now enabled 2018-01-10 12:07:15 CET [30297]: [4-1] user=3D,db=3D,app=3D,client=3D LOG: = database system is ready to accept connections 2018-01-10 12:07:15 CET [30421]: [1-1] user=3D,db=3D,app=3D,client=3D LOG: = autovacuum launcher started 14) After the recover the file deleted is in place: pgpdbabe@elaawddbad00:/pgsql/pdbabe/admin/log> cd $PGDATA/pg_tblspc/16385/P= G_9.4_201409291/16386 pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_2014= 09291/16386> ls -la | grep 49391 -rw------- 1 pgpdbabe pdbabe 16384 Jan 10 12:10 49391 <----------- -rw------- 1 pgpdbabe pdbabe 24576 Jan 9 14:13 49391_fsm 15) Let's check the content of the table ... no errors raised but the table= has 5 records and not 12 records (as it should have). pgpdbabe@elaawddbad00:/pgsql/pdbabe/admin/log> psql psql (9.4.9) Type "help" for help. pdbabe=3D# select order_date, substring(item, 1, 20) from test_corrupt ; order_date | substring -------------------------------+-------------- 2018-01-01 00:07:00+01 | generic item 2018-01-01 00:08:00+01 | generic item 2018-01-01 00:09:00+01 | generic item 2018-01-01 00:10:00+01 | generic item 2018-01-10 02:57:01.106676+01 | new item (5 rows) In conclusion, the recover operation was successfully but the database is c= orrupted. The point is: when the recover find a missing file it should exit with an error instead of going ahead and terminating succesfull= y. What do you think about this opinion? Am I missing something? Thanks & Regards Gabriele > Il 8 gennaio 2018 alle 14.53 flumbador@virgilio.it ha scritto: >=20 >=20 > Hi postgresql is 9.4.9 on SUSE 11sp4 ... The backup is a filesystem b= ackup with Networker. > I confirm that I handle WAL archiving and backup_label file was in pl= ace when I started the recovery. The table is Persistent (Relpersistence = =3D 'p'). > The postgresql was succesfully restored from another backup and now i= s up and running; i'm not able to provide further datails. > I try to reproduce the issue on a test environment. > I'll update the thread with further details as soon as I reproduce th= e issue. > Thanks to all > Best Regards > Gabriele >=20 > > >=20 > > Il 2 gennaio 2018 alle 16.38 Alvaro Herrera ha scritto: > >=20 > > flumbador@virgilio.it wrote: > >=20 > > > > >=20 > > > During the restore 3 files were missing; these three file= s belong to a table with high transaction workload, and for sure during the= backup many transactions had modified this table and those missing files. = What is surprising to me is that even if the files were missing the recover= phase ended successfully. I expect an error (for example file not found) r= aised when postgresql try to apply the wal entries related to this table an= d those files. After the recover I find that these three file has been crea= ted during recover but when I try to query the table I get the error: > > >=20 > > > db4=3D# select count(*) from pgbench_accounts ; > > >=20 > > > ERROR: could not read block 1999996 in file "pg_tblspc/16= 471/PG_9.4_201409291/16474/16593.15": read only 0 of 8192 bytes > > >=20 > > > > >=20 > > Can you please get a backtrace from this error? I suspect that = the > > problem here is that the planner is trying to estimate cardinal= ity by > > descending a btree index, and failing because the index points = to a part > > of the table that has been truncated. But if the table has been > > truncated because it's unlogged, then the index should have bee= n > > truncated too; and if it's a permanent table, then it has been = truncated > > improperly (because no index pointer to the truncated part shou= ld > > remain). > >=20 > > What files do exist for pg_tblspc/16471/PG_9.4_201409291/16474/= 16593* ? > > (In particular I'm curious about whether 16593.14 exists and wh= at size > > it is) > >=20 > > -- > > =C3=81lvaro Herrera https://www.2ndQuadrant.com/ > > PostgreSQL Development, 24x7 Support, Remote DBA, Training & Se= rvices > >=20 > > >=20 ------=_Part_823821_2048468995.1515601712807 MIME-Version: 1.0 Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable

Hi All, 

I reproduced the issue with the followi= ng test case:


1) Create a table for testing porp= ouse:

pdbabe=3D# CREATE TABLE test_corrupt (order_date timestamptz, i= tem char(1024));
CREATE TABLE

2) Insert some data in the table

=

pdbabe=3D# INSERT INTO test_corrupt (order_date, item)
SELECT x, = 9;generic item'
FROM generate_series('2018-01-01 00:00:00':= :timestamptz, '2018-01-01 00:10:00'::timestamptz,'60 seconds= 9;::interval) a(x);
INSERT 0 11


pdbabe=3D# select order_date, = substring(item, 1, 20) from test_corrupt ;
order_date | substring
--= ----------------------+--------------
2018-01-01 00:00:00+01 | generic = item
2018-01-01 00:01:00+01 | generic item
2018-01-01 00:02:00+01 |= generic item
2018-01-01 00:03:00+01 | generic item
2018-01-01 00:0= 4:00+01 | generic item
2018-01-01 00:05:00+01 | generic item
2018-0= 1-01 00:06:00+01 | generic item
2018-01-01 00:07:00+01 | generic item 2018-01-01 00:08:00+01 | generic item
2018-01-01 00:09:00+01 | gener= ic item
2018-01-01 00:10:00+01 | generic item


3) Check the fi= le that contain the table:

pdbabe=3D# SELECT pg_relation_filepath(= 9;test_corrupt');
pg_relation_filepath
-------------------------= ---------------------
pg_tblspc/16385/PG_9.4_201409291/16386/49391
(= 1 row)


pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/= 16385/PG_9.4_201409291/16386> ls -la | grep 49391
-rw------- 1 pgpdb= abe pdbabe 16384 Jan 9 14:13 49391
-rw------- 1 pgpdbabe pdbabe 24576 Ja= n 9 14:13 49391_fsm


4) At 2.40 A.M. Start the backup of th= e database (filesystem backup):

pg_start_backup
-----------------<= br> 17/30000028
(1 row)


5) At 2:57 A.M.  new record is in= serted in the table.

insert into test_corrupt values (current_timesta= mp, 'new item') ;

After the insert the content of the table i= s:

pdbabe=3D# select order_date, substring(item, 1, 20) from test_cor= rupt ;
order_date | substring
-------------------------------+------= --------
2018-01-01 00:00:00+01 | generic item
2018-01-01 00:01:00+= 01 | generic item
2018-01-01 00:02:00+01 | generic item
2018-01-01 = 00:03:00+01 | generic item
2018-01-01 00:04:00+01 | generic item
20= 18-01-01 00:05:00+01 | generic item
2018-01-01 00:06:00+01 | generic it= em
2018-01-01 00:07:00+01 | generic item
2018-01-01 00:08:00+01 | g= eneric item
2018-01-01 00:09:00+01 | generic item
2018-01-01 00:10:= 00+01 | generic item
2018-01-10 02:57:01.106676+01 | new item
(12 ro= ws)

No other insert / update / delete are executed against the table = until the restore / recover.


6) The backup of filesystem o= n which resides the Postgresql, ended at 4:01 A.M

pg_stop_backup |= now
----------------+-------------------------------
17/7EFE3900 | = 2018-01-10 04:01:53.496869+01
(1 row)


8) Restore of the= postgresql database, by executung the restore of the previous filesystem b= ackup.


9) Contets of backup_label restored:

pgpdbabe@elaawd= dbad00:/pgsql/pdbabe/data/pdbabe> more backup_label
START WAL LOCATI= ON: 17/30000028 (file 000000070000001700000030)
CHECKPOINT LOCATION: 17/= 30000060
BACKUP METHOD: pg_start_backup
BACKUP FROM: master
START = TIME: 2018-01-10 02:40:00 CET
LABEL: bckdb


10) Delete of the f= ile containg the table "test_corrupt" to simulate the file missing = in the backup:

pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe> c= d $PGDATA/pg_tblspc/16385/PG_9.4_201409291/16386
pgpdbabe@elaawddbad00:/= pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_201409291/16386> ls -la= | grep 49391
-rw------- 1 pgpdbabe pdbabe 16384 Jan 10 02:57 49391
-= rw------- 1 pgpdbabe pdbabe 24576 Jan 9 14:13 49391_fsm
pgpdbabe@elaawdd= bad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16385/PG_9.4_201409291/16386>= rm ./49391
pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tblspc/16= 385/PG_9.4_201409291/16386> ls -la | grep 49391
-rw------- 1 pgpdbab= e pdbabe 24576 Jan 9 14:13 49391_fsm
pgpdbabe@elaawddbad00:/pgsql/pdbabe= /data/pdbabe/pg_tblspc/16385/PG_9.4_201409291/16386>


12) Crea= te file recovery.conf:

restore_command =3D 'cp /pgsql/pdbabe/arch= ive/%f %p'
archive_cleanup_command =3D 'pg_archivecleanup /pgsql= /pdbabe/archive %r'


13) Start Postgresql to recover the datab= ase ... Recover is successfull ... NO error in logfile:

2018-01-10 12= :05:25 CET [30299]: [1-1] user=3D,db=3D,app=3D,client=3D LOG: database syst= em was interrupted; last known up at 2018-01
-10 02:50:00 CET
2018-01= -10 12:05:25 CET [30299]: [2-1] user=3D,db=3D,app=3D,client=3D LOG: creatin= g missing WAL directory "pg_xlog/archive_status"
2018-01-10 12:0= 5:25 CET [30299]: [3-1] user=3D,db=3D,app=3D,client=3D LOG: starting archiv= e recovery
2018-01-10 12:05:25 CET [30299]: [4-1] user=3D,db=3D,app=3D,c= lient=3D LOG: restored log file "00000007.history" from archive
= 2018-01-10 12:05:25 CET [30299]: [5-1] user=3D,db=3D,app=3D,client=3D LOG: = restored log file "000000070000001700000030" from archive
2018-0= 1-10 12:05:25 CET [30299]: [6-1] user=3D,db=3D,app=3D,client=3D LOG: redo s= tarts at 17/30000028
2018-01-10 12:05:25 CET [30299]: [7-1] user=3D,db= =3D,app=3D,client=3D LOG: restored log file "000000070000001700000031&#= 34; from archive
2018-01-10 12:05:26 CET [30299]: [8-1] user=3D,db=3D,ap= p=3D,client=3D LOG: restored log file "000000070000001700000032" fr= om archive
2018-01-10 12:05:26 CET [30299]: [9-1] user=3D,db=3D,app=3D,c= lient=3D LOG: restored log file "000000070000001700000033" from arc= hive
......
2018-01-10 12:05:46 CET [30299]: [81-1] user=3D,db=3D,app= =3D,client=3D LOG: restored log file "00000007000000170000007B" fro= m archiv
e
2018-01-10 12:05:48 CET [30299]: [82-1] user=3D,db=3D,app= =3D,client=3D LOG: restored log file "00000007000000170000007C" fro= m archiv
e
2018-01-10 12:05:49 CET [30299]: [83-1] user=3D,db=3D,app= =3D,client=3D LOG: restored log file "00000007000000170000007D" fro= m archiv
e
2018-01-10 12:05:50 CET [30299]: [84-1] user=3D,db=3D,app= =3D,client=3D LOG: restored log file "00000007000000170000007E" fro= m archiv
e
2018-01-10 12:05:50 CET [30299]: [85-1] user=3D,db=3D,app= =3D,client=3D LOG: consistent recovery state reached at 17/7EFE3900
2018= -01-10 12:05:50 CET [30297]: [3-1] user=3D,db=3D,app=3D,client=3D LOG: data= base system is ready to accept read only connections
2018-01-10 12:05:50= CET [30299]: [86-1] user=3D,db=3D,app=3D,client=3D LOG: restored log file = "00000007000000170000007F" from archiv
e
2018-01-10 12:05:50 = CET [30299]: [87-1] user=3D,db=3D,app=3D,client=3D LOG: restored log file &= #34;000000070000001700000080" from archiv
e
cp: cannot stat `/pgs= ql/pdbabe/archive/000000070000001700000081': No such file or directory<= br>2018-01-10 12:05:50 CET [30299]: [88-1] user=3D,db=3D,app=3D,client=3D L= OG: redo done at 17/800875F0
2018-01-10 12:05:50 CET [30299]: [89-1] use= r=3D,db=3D,app=3D,client=3D LOG: last completed transaction was at log time= 2018-01-10 09
:17:01.870329+01
2018-01-10 12:05:53 CET [30299]: [90-= 1] user=3D,db=3D,app=3D,client=3D LOG: restored log file "0000000700000= 01700000080" from archiv
e
cp: cannot stat `/pgsql/pdbabe/archive= /00000008.history': No such file or directory
2018-01-10 12:05:53 CE= T [30299]: [91-1] user=3D,db=3D,app=3D,client=3D LOG: selected new timeline= ID: 8
2018-01-10 12:05:53 CET [30299]: [92-1] user=3D,db=3D,app=3D,clie= nt=3D LOG: restored log file "00000007.history" from archive
201= 8-01-10 12:05:53 CET [30299]: [93-1] user=3D,db=3D,app=3D,client=3D LOG: ar= chive recovery complete
2018-01-10 12:05:53 CET [30302]: [1-1] user=3D,d= b=3D,app=3D,client=3D LOG: checkpoint starting: end-of-recovery immediate w= ait
2018-01-10 12:05:57 CET [30397]: [1-1] user=3D[unknown],db=3D[unknow= n],app=3D[unknown],client=3D10.151.201.1 LOG: connection receive
d: host= =3D10.151.201.1 port=3D51057
2018-01-10 12:05:57 CET [30397]: [2-1] user= =3Dpatrol,db=3Dpdbabe,app=3D[unknown],client=3D10.151.201.1 FATAL: no pg_hb= a.conf entry f
or host "10.151.201.1", user "patrol", da= tabase "pdbabe", SSL off
2018-01-10 12:06:57 CET [30410]: [1-1] = user=3D[unknown],db=3D[unknown],app=3D[unknown],client=3D10.151.201.1 LOG: = connection receive
d: host=3D10.151.201.1 port=3D51058
2018-01-10 12:= 06:57 CET [30410]: [2-1] user=3Dpatrol,db=3Dpdbabe,app=3D[unknown],client= =3D10.151.201.1 FATAL: no pg_hba.conf entry f
or host "10.151.201.1&= #34;, user "patrol", database "pdbabe", SSL off
2018-01-= 10 12:07:15 CET [30302]: [2-1] user=3D,db=3D,app=3D,client=3D LOG: checkpoi= nt complete: wrote 254519 buffers (99.4%); 0 tran
saction log file(s) ad= ded, 0 removed, 0 recycled; write=3D71.245 s, sync=3D10.241 s, total=3D81.5= 66 s; sync files=3D39, longest=3D10.21
4 s, average=3D0.262 s
2018-01= -10 12:07:15 CET [30299]: [94-1] user=3D,db=3D,app=3D,client=3D LOG: MultiX= act member wraparound protections are now enabled
2018-01-10 12:07:15 CE= T [30297]: [4-1] user=3D,db=3D,app=3D,client=3D LOG: database system is rea= dy to accept connections
2018-01-10 12:07:15 CET [30421]: [1-1] user=3D,= db=3D,app=3D,client=3D LOG: autovacuum launcher started


14) After the recover the file deleted is in place:

pgpdbabe= @elaawddbad00:/pgsql/pdbabe/admin/log> cd $PGDATA/pg_tblspc/16385/PG_9.= 4_201409291/16386
pgpdbabe@elaawddbad00:/pgsql/pdbabe/data/pdbabe/pg_tbl= spc/16385/PG_9.4_201409291/16386> ls -la | grep 49391
-rw------- 1 p= gpdbabe pdbabe 16384 Jan 10 12:10 49391         &#= 60;-----------
-rw------- 1 pgpdbabe pdbabe 24576 Jan 9 14:13 49391_fsm<= /p>



15) Let's check the content of the table ... no er= rors raised but the table has 5 records and not 12 records (as it should ha= ve).

pgpdbabe@elaawddbad00:/pgsql/pdbabe/admin/log> psql
psql = (9.4.9)
Type "help" for help.

pdbabe=3D# select order_date= , substring(item, 1, 20) from test_corrupt ;
order_date | substring
= -------------------------------+--------------
2018-01-01 00:07:00+01 |= generic item
2018-01-01 00:08:00+01 | generic item
2018-01-01 00:0= 9:00+01 | generic item
2018-01-01 00:10:00+01 | generic item
2018-0= 1-10 02:57:01.106676+01 | new item
(5 rows)

In conclusion, the rec= over operation was successfully but the database is corrupted. The point is= : when the recover find a missing file it
should exit with an error ins= tead of going ahead and terminating succesfully. What do you think about th= is opinion? Am I missing something?

Thanks & Regards
Gabriele<= /p>

Il 8 gennaio 2018 alle 14.53 flumbador@virgili= o.it ha scritto:

Hi postgresql is 9.4.9 on SUSE 11sp4 ... The bac= kup is a filesystem backup with Networker.
I confirm that I handle WAL a= rchiving and backup_label file was in place when I started the recovery. Th= e table is Persistent (Relpersistence =3D 'p').
The postgresql w= as succesfully restored from another backup and now is up and running; i= 9;m not able to provide further datails.
I try to reproduce the issue on= a test environment.
I'll update the thread with further details as = soon as I reproduce the issue.
Thanks to all
Best Regards
Gabriele=

Il 2 gennaio 2018 alle 16.38 Alvaro Herrera <alvherr= e@alvh.no-ip.org> ha scritto:

flumbador@virgilio.it wrote:

During the restore 3 files were missing; these three files belo= ng to a table with high transaction workload, and for sure during the backu= p many transactions had modified this table and those missing files. What i= s surprising to me is that even if the files were missing the recover phase= ended successfully. I expect an error (for example file not found) raised = when postgresql try to apply the wal entries related to this table and thos= e files. After the recover I find that these three file has been created du= ring recover but when I try to query the table I get the error:

db4= =3D# select count(*) from pgbench_accounts ;

ERROR: could not read bl= ock 1999996 in file "pg_tblspc/16471/PG_9.4_201409291/16474/16593.15= 4;: read only 0 of 8192 bytes

Can you please get a backt= race from this error? I suspect that the
problem here is that the planne= r is trying to estimate cardinality by
descending a btree index, and fai= ling because the index points to a part
of the table that has been trunc= ated. But if the table has been
truncated because it's unlogged, the= n the index should have been
truncated too; and if it's a permanent = table, then it has been truncated
improperly (because no index pointer t= o the truncated part should
remain).

What files do exist for pg_tb= lspc/16471/PG_9.4_201409291/16474/16593* ?
(In particular I'm curiou= s about whether 16593.14 exists and what size
it is)

--
Ál= varo Herrera https://www.2ndQuadra= nt.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training &= #38; Services

=20 ------=_Part_823821_2048468995.1515601712807--