Thread: BUG #16172: failure of vacuum file truncation can cause permanent data corruption
BUG #16172: failure of vacuum file truncation can cause permanent data corruption
From
PG Bug reporting form
Date:
The following bug has been logged on the website: Bug reference: 16172 Logged by: TAKATSUKA Haruka Email address: harukat@sraoss.co.jp PostgreSQL version: 12.1 Operating system: Windows/Linux Description: Hello, pgsql hackers, I found that failure of vacuum file truncation can cause permanent data corruption. I am reporting the reproduce steps below. In Windows installation, the truncation sometime fails by permission denied error because of anti-virus software. It has caused just ERROR and people have offen dismissed it. Truncation failure can also make the standby panic with the following messages when replaying Heap2/VISIBLE or Heap2/CLEAN, because truncation wal is emitted even if it doesn't complete actually in the primary. WARNING: page .. of relation base/..../.... does not exist CONTEXT: WAL redo at ..... for ....: cutoff xid ... flags ... PANIC: WAL contains references to invalid pages I think truncation failure is to be handled as more severe level. Any thoughts? with best regards, Haruka Takatsuka / SRA OSS, Inc. Japan reproduce steps (PG12) ====================== $ psql -U postgres -d db1 Pager usage is off. psql (12.1) Type "help" for help. db1=# $ gdb -p {its backend process} (gdb) b FileTruncate Breakpoint 1 at 0x73d320: file fd.c, line 2057. (gdb) c Continuing. db1=# SHOW autovacuum; autovacuum ------------ off (1 row) db1=# CREATE TABLE t1 (id int primary key, v text); CREATE db1=# INSERT INTO t1 SELECT g, md5(g::text) FROM generate_series(1, 10000) as g; INSERT 0 10000 db1=# CHECKPOINT; Program received signal SIGUSR1, User defined signal 1. 0x00000036caae91a3 in __epoll_wait_nocancel () from /lib64/libc.so.6 (gdb) c Continuing. CHECKPOINT db1=# DELETE FROM t1 WHERE id > 50; DELETE 9950 db1=# VACUUM t1; Breakpoint 1, FileTruncate (file=59, offset=8192, wait_event_info=167772175) at fd.c:2057 2057 { (gdb) n 2065 returnCode = FileAccess(file); (gdb) n 2066 if (returnCode < 0) (gdb) p returnCode = -100 $6 = -100 (gdb) c Continuing. ERROR: could not truncate file "base/16384/16645" to 1 blocks: Success db1=# SELECT count(*) FROM t1; count ------- 9930 (1 row) db1=# SELECT * FROM t1 WHERE id > 50 LIMIT 10; id | v -----+---------------------------------- 121 | 4c56ff4ce4aaf9573aa5dff913df997a 122 | a0a080f42e6f13b3a2df133f073095dd 123 | 202cb962ac59075b964b07152d234b70 124 | c8ffe9a587b126f152ed3d89a146b445 125 | 3def184ad8f4755ff269862ea77393dd 126 | 069059b7ef840f0c74a814ec9237b6ec 127 | ec5decca5ed3d6b8079e2e7e7bacc9f2 128 | 76dc611d6ebaafc66cc0879c71b5db5c 129 | d1f491a404d6854880943e5c3cd9ca25 130 | 9b8619251a19057cff70779273e95aa6 (10 rows) db1=# VACUUM FULL FREEZE t1; VACUUM db1=# REINDEX TABLE t1; REINDEX db1=# SELECT count(*) FROM t1; count ------- 9930 (1 row) db1=# SELECT * FROM t1 WHERE id > 50 LIMIT 10; id | v -----+---------------------------------- 121 | 4c56ff4ce4aaf9573aa5dff913df997a 122 | a0a080f42e6f13b3a2df133f073095dd 123 | 202cb962ac59075b964b07152d234b70 124 | c8ffe9a587b126f152ed3d89a146b445 125 | 3def184ad8f4755ff269862ea77393dd 126 | 069059b7ef840f0c74a814ec9237b6ec 127 | ec5decca5ed3d6b8079e2e7e7bacc9f2 128 | 76dc611d6ebaafc66cc0879c71b5db5c 129 | d1f491a404d6854880943e5c3cd9ca25 130 | 9b8619251a19057cff70779273e95aa6 (10 rows) real incident log sample (from Windows PG10.x) ============================================== primary server: --------------- 2019-12-17 19:10:19 JST [14321] ERROR: 42501: could not truncate file "base/444807/447791" to 7 blocks: Permission denied 2019-12-17 19:10:19 JST [14321] CONTEXT: automatic vacuum of table "ddd.ssss.tttt" hot standby server: ------------------- 2019-12-17 19:11:20 JST [12345] WARNING: 01000: page 7 of relation base/444807/447791 does not exist 2019-12-17 19:11:20 JST [12345] CONTEXT: WAL redo at 4E/FC5AD060 for Heap2/VISIBLE: cutoff xid 0 flags 3 2019-12-17 19:11:20 JST [12345] PANIC: XX000: WAL contains references to invalid pages 2019-12-17 19:11:20 JST [12345] CONTEXT: WAL redo at 4E/FC5AD060 for Heap2/VISIBLE: cutoff xid 0 flags 3
Re: BUG #16172: failure of vacuum file truncation can causepermanent data corruption
From
TAKATSUKA Haruka
Date:
I also tested PostgreSQL with the attached patch avoided this data corruption. The patch just removes DropRelFileNodeBuffers() from smgrtruncate(). On Thu, 19 Dec 2019 07:14:42 +0000 PG Bug reporting form <noreply@postgresql.org> wrote: > The following bug has been logged on the website: > > Bug reference: 16172 > Logged by: TAKATSUKA Haruka > Email address: harukat@sraoss.co.jp > PostgreSQL version: 12.1 > Operating system: Windows/Linux > Description: > > Hello, pgsql hackers, > > I found that failure of vacuum file truncation can cause permanent data > corruption. > I am reporting the reproduce steps below. > > In Windows installation, the truncation sometime fails by permission > denied error because of anti-virus software. It has caused just ERROR > and people have offen dismissed it. > > Truncation failure can also make the standby panic with the following > messages when replaying Heap2/VISIBLE or Heap2/CLEAN, because truncation > wal is emitted even if it doesn't complete actually in the primary. > > WARNING: page .. of relation base/..../.... does not exist > CONTEXT: WAL redo at ..... for ....: cutoff xid ... flags ... > PANIC: WAL contains references to invalid pages > > I think truncation failure is to be handled as more severe level. > Any thoughts? > > with best regards, > Haruka Takatsuka / SRA OSS, Inc. Japan > > > reproduce steps (PG12) > ====================== > > $ psql -U postgres -d db1 > Pager usage is off. > psql (12.1) > Type "help" for help. > > db1=# > > $ gdb -p {its backend process} > > (gdb) b FileTruncate > Breakpoint 1 at 0x73d320: file fd.c, line 2057. > (gdb) c > Continuing. > > db1=# SHOW autovacuum; > autovacuum > ------------ > off > (1 row) > > db1=# CREATE TABLE t1 (id int primary key, v text); > CREATE > > db1=# INSERT INTO t1 SELECT g, md5(g::text) FROM generate_series(1, 10000) > as g; > INSERT 0 10000 > > db1=# CHECKPOINT; > > Program received signal SIGUSR1, User defined signal 1. > 0x00000036caae91a3 in __epoll_wait_nocancel () from /lib64/libc.so.6 > (gdb) c > Continuing. > > CHECKPOINT > > db1=# DELETE FROM t1 WHERE id > 50; > DELETE 9950 > > db1=# VACUUM t1; > > Breakpoint 1, FileTruncate (file=59, offset=8192, > wait_event_info=167772175) > at fd.c:2057 > 2057 { > (gdb) n > 2065 returnCode = FileAccess(file); > (gdb) n > 2066 if (returnCode < 0) > (gdb) p returnCode = -100 > $6 = -100 > (gdb) c > Continuing. > > ERROR: could not truncate file "base/16384/16645" to 1 blocks: Success > > db1=# SELECT count(*) FROM t1; > count > ------- > 9930 > (1 row) > (snip)
Attachment
Re: BUG #16172: failure of vacuum file truncation can causepermanent data corruption
From
TAKATSUKA Haruka
Date:
I found moving DropRelFileNodeBuffers() from top to end in function smgrtruncate() is a proper modification. It passed the regression test and this reproduction test. with best regards, Haruka Takatsuka / SRA OSS, Inc. Japan On Fri, 20 Dec 2019 10:19:52 +0900 TAKATSUKA Haruka <harukat@sraoss.co.jp> wrote: > I also tested PostgreSQL with the attached patch avoided this data > corruption. The patch just removes DropRelFileNodeBuffers() from > smgrtruncate(). > > > On Thu, 19 Dec 2019 07:14:42 +0000 > PG Bug reporting form <noreply@postgresql.org> wrote: > > > The following bug has been logged on the website: > > > > Bug reference: 16172 > > Logged by: TAKATSUKA Haruka > > Email address: harukat@sraoss.co.jp > > PostgreSQL version: 12.1 > > Operating system: Windows/Linux > > Description: > > > > Hello, pgsql hackers, > > > > I found that failure of vacuum file truncation can cause permanent data > > corruption. > > I am reporting the reproduce steps below. > > > > In Windows installation, the truncation sometime fails by permission > > denied error because of anti-virus software. It has caused just ERROR > > and people have offen dismissed it. > > > > Truncation failure can also make the standby panic with the following > > messages when replaying Heap2/VISIBLE or Heap2/CLEAN, because truncation > > wal is emitted even if it doesn't complete actually in the primary. > > > > WARNING: page .. of relation base/..../.... does not exist > > CONTEXT: WAL redo at ..... for ....: cutoff xid ... flags ... > > PANIC: WAL contains references to invalid pages > > > > I think truncation failure is to be handled as more severe level. > > Any thoughts? > > > > with best regards, > > Haruka Takatsuka / SRA OSS, Inc. Japan > > > > > > reproduce steps (PG12) > > ====================== > > > > $ psql -U postgres -d db1 > > Pager usage is off. > > psql (12.1) > > Type "help" for help. > > > > db1=# > > > > $ gdb -p {its backend process} > > > > (gdb) b FileTruncate > > Breakpoint 1 at 0x73d320: file fd.c, line 2057. > > (gdb) c > > Continuing. > > > > db1=# SHOW autovacuum; > > autovacuum > > ------------ > > off > > (1 row) > > > > db1=# CREATE TABLE t1 (id int primary key, v text); > > CREATE > > > > db1=# INSERT INTO t1 SELECT g, md5(g::text) FROM generate_series(1, 10000) > > as g; > > INSERT 0 10000 > > > > db1=# CHECKPOINT; > > > > Program received signal SIGUSR1, User defined signal 1. > > 0x00000036caae91a3 in __epoll_wait_nocancel () from /lib64/libc.so.6 > > (gdb) c > > Continuing. > > > > CHECKPOINT > > > > db1=# DELETE FROM t1 WHERE id > 50; > > DELETE 9950 > > > > db1=# VACUUM t1; > > > > Breakpoint 1, FileTruncate (file=59, offset=8192, > > wait_event_info=167772175) > > at fd.c:2057 > > 2057 { > > (gdb) n > > 2065 returnCode = FileAccess(file); > > (gdb) n > > 2066 if (returnCode < 0) > > (gdb) p returnCode = -100 > > $6 = -100 > > (gdb) c > > Continuing. > > > > ERROR: could not truncate file "base/16384/16645" to 1 blocks: Success > > > > db1=# SELECT count(*) FROM t1; > > count > > ------- > > 9930 > > (1 row) > > > (snip) ______________________________________________________________________ 高塚 遥 harukat@sraoss.co.jp SRA OSS, Inc. http://www.sraoss.co.jp 〒171-0022 東京都豊島区南池袋2-32-8 TEL: 03-5979-2701 FAX: 03-5979-2702 CellPhone: 080-1292-3396
Attachment
Re: BUG #16172: failure of vacuum file truncation can causepermanent data corruption
From
Kyotaro Horiguchi
Date:
Hello, At Fri, 20 Dec 2019 11:00:28 +0900, TAKATSUKA Haruka <harukat@sraoss.co.jp> wrote in > > I found moving DropRelFileNodeBuffers() from top to end in function > smgrtruncate() is a proper modification. It passed the regression test > and this reproduction test. I don't recall clealy but I think there was a thread similar to this issue. Assume that checkpoint was running concurrently, the checkpoint can revive the just truncated blocks inadvertently with bogus content. reagards. -- Kyotaro Horiguchi NTT Open Source Software Center
Re: BUG #16172: failure of vacuum file truncation can causepermanent data corruption
From
TAKATSUKA Haruka
Date:
Horiguchi-san Thanks for pointing out it. I wasn't looking for past arguments enough. You may mean this links are: https://www.postgresql.org/message-id/flat/2348.1544474335%40sss.pgh.pa.us https://www.postgresql.org/message-id/15667-8d3fca4eba25174f%40postgresql.org regards, TAKATSUKA Haruka On Fri, 20 Dec 2019 14:22:22 +0900 (JST) Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote: > Hello, > > At Fri, 20 Dec 2019 11:00:28 +0900, TAKATSUKA Haruka <harukat@sraoss.co.jp> wrote in > > > > I found moving DropRelFileNodeBuffers() from top to end in function > > smgrtruncate() is a proper modification. It passed the regression test > > and this reproduction test. > > I don't recall clealy but I think there was a thread similar to this > issue. Assume that checkpoint was running concurrently, the > checkpoint can revive the just truncated blocks inadvertently with > bogus content. > > reagards. > > -- > Kyotaro Horiguchi > NTT Open Source Software Center