Date: Fri, 3 Jul 2015 00:05:24 +0200
From: Martijn van Oosterhout <kleptog@svana.org>
To: PostgreSQL-development <pgsql-hackers@postgresql.org>
Message-ID: <20150702220524.GA9392@svana.org>
Reply-To: Martijn van Oosterhout <kleptog@svana.org>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha256;
 protocol="application/pgp-signature"; boundary="6c2NcOVqGQ03X4Wi"
Content-Disposition: inline
User-Agent: Mutt/1.5.20 (2009-06-14)
Subject: WAL logging problem in 9.4.3?
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org


--6c2NcOVqGQ03X4Wi
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

Hoi,

I ran into this in our CI setup and I thinks it's an actual bug. The
issue appears to be that when a table is created *and truncated* in a
single transaction, that the WAL log is logging a truncate record it
shouldn't, such that if the database crashes you have a broken index.
It would also lose any data that was in the table at commit time.

I didn't test 9.4.4 yet, though I don't see anything in the release
notes that resemble this.

Detail:

=3D=3D=3D Start with an empty database

martijn@martijn-jessie:$ psql ctmp -h localhost -U username
Password for user username:
psql (9.4.3)
Type "help" for help.

ctmp=3D# begin;
BEGIN
ctmp=3D# create table test(id serial primary key);
CREATE TABLE
ctmp=3D# truncate table test;
TRUNCATE TABLE
ctmp=3D# commit;
COMMIT
ctmp=3D# select relname, relfilenode from pg_class where relname like 'test=
%';
   relname   | relfilenode
-------------+-------------
 test        |       16389
 test_id_seq |       16387
 test_pkey   |       16393
(3 rows)

=3D=3D=3D Note: if you do a CHECKPOINT here the issue doesn't happen
=3D=3D=3D obviously.

ctmp=3D# \q
martijn@martijn-jessie:$ sudo ls -l /data/postgres/base/16385/{16389,16387,=
16393}
[sudo] password for martijn:
-rw------- 1 messagebus ssl-cert 8192 Jul  2 23:34 /data/postgres/base/1638=
5/16387
-rw------- 1 messagebus ssl-cert    0 Jul  2 23:34 /data/postgres/base/1638=
5/16389
-rw------- 1 messagebus ssl-cert 8192 Jul  2 23:34 /data/postgres/base/1638=
5/16393

=3D=3D=3D Note the index file is 8KB.
=3D=3D=3D At this point nuke the database server (in this case it was simpl=
y=20
=3D=3D=3D destroying the container it was running in.

=3D=3D=3D Dump the xlogs just to show what got recorded. Note there's a
=3D=3D=3D truncate for the data file and the index file.

martijn@martijn-jessie:$ sudo /usr/lib/postgresql/9.4/bin/pg_xlogdump -p /d=
ata/postgres/pg_xlog/ 000000010000000000000001 |grep -wE '16389|16387|16393'
rmgr: XLOG        len (rec/tot):     72/   104, tx:          0, lsn: 0/016A=
9240, prev 0/016A9200, bkp: 0000, desc: checkpoint: redo 0/16A9240; tli 1; =
prev tli 1; fpw true; xid 0/686; oid 16387; multi 1; offset 0; oldest xid 6=
73 in DB 1; oldest multi 1 in DB 1; oldest running xid 0; shutdown
rmgr: Storage     len (rec/tot):     16/    48, tx:          0, lsn: 0/016A=
92D0, prev 0/016A92A8, bkp: 0000, desc: file create: base/16385/16387
rmgr: Sequence    len (rec/tot):    158/   190, tx:        686, lsn: 0/016B=
5E50, prev 0/016B5D88, bkp: 0000, desc: log: rel 1663/16385/16387
rmgr: Storage     len (rec/tot):     16/    48, tx:        686, lsn: 0/016B=
5F10, prev 0/016B5E50, bkp: 0000, desc: file create: base/16385/16389
rmgr: Storage     len (rec/tot):     16/    48, tx:        686, lsn: 0/016B=
B028, prev 0/016BAFD8, bkp: 0000, desc: file create: base/16385/16393
rmgr: Sequence    len (rec/tot):    158/   190, tx:        686, lsn: 0/016B=
E4F8, prev 0/016BE440, bkp: 0000, desc: log: rel 1663/16385/16387
rmgr: Storage     len (rec/tot):     16/    48, tx:        686, lsn: 0/016B=
E6B0, prev 0/016BE660, bkp: 0000, desc: file truncate: base/16385/16389 to =
0 blocks
rmgr: Storage     len (rec/tot):     16/    48, tx:        686, lsn: 0/016B=
E6E0, prev 0/016BE6B0, bkp: 0000, desc: file truncate: base/16385/16393 to =
0 blocks
pg_xlogdump: FATAL:  error in WAL record at 0/16BE710: record with zero len=
gth at 0/16BE740

=3D=3D=3D Start the DB up again

database_1 | LOG:  database system was interrupted; last known up at 2015-0=
7-02 21:08:05 UTC
database_1 | LOG:  database system was not properly shut down; automatic re=
covery in progress
database_1 | LOG:  redo starts at 0/16A92A8
database_1 | LOG:  record with zero length at 0/16BE740
database_1 | LOG:  redo done at 0/16BE710
database_1 | LOG:  last completed transaction was at log time 2015-07-02 21=
:34:45.664989+00
database_1 | LOG:  database system is ready to accept connections
database_1 | LOG:  autovacuum launcher started

=3D=3D=3D Oops, the index file is empty now

martijn@martijn-jessie:$ sudo ls -l /data/postgres/base/16385/{16389,16387,=
16393}
-rw------- 1 messagebus ssl-cert 8192 Jul  2 23:37 /data/postgres/base/1638=
5/16387
-rw------- 1 messagebus ssl-cert    0 Jul  2 23:34 /data/postgres/base/1638=
5/16389
-rw------- 1 messagebus ssl-cert    0 Jul  2 23:37 /data/postgres/base/1638=
5/16393

martijn@martijn-jessie:$ psql ctmp -h localhost -U username
Password for user username:
psql (9.4.3)
Type "help" for help.

=3D=3D=3D And now the index is broken. I think the only reason it doesn't
=3D=3D=3D complain about the data file is because zero bytes there is OK.  =
But if
=3D=3D=3D the table had data before it would be gone now.

ctmp=3D# select * from test;
ERROR:  could not read block 0 in file "base/16385/16393": read only 0 of 8=
192 bytes

ctmp=3D# select version();
                                            version                        =
                   =20
---------------------------------------------------------------------------=
--------------------
 PostgreSQL 9.4.3 on x86_64-unknown-linux-gnu, compiled by gcc (Debian 4.9.=
2-10) 4.9.2, 64-bit
(1 row)

Hope this helps.
--=20
Martijn van Oosterhout   <kleptog@svana.org>   http://svana.org/kleptog/
> He who writes carelessly confesses thereby at the very outset that he does
> not attach much importance to his own thoughts.
   -- Arthur Schopenhauer

--6c2NcOVqGQ03X4Wi
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: Digital signature
Content-Disposition: inline

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.12 (GNU/Linux)

iQIVAwUBVZW1pEvt++dL5i1EAQiqAw/9HOBzWwNyTljAwdXqRVV2jQM7PM8Obnni
NdrFNYMbHWycDUcFSlxUcbvqE3tTHF29YSEIZ2hoB8Kzrm96vU7U3y338PFTswzd
wbKmlBUngrocpdwDJawnyKtvRoW+UQTcblxaQwo3CASDMFNW2N5U7QOt2GFfDhPM
d+QTGDLfr4F8trZJ3wZr019E8mf6hY2zhhOaO75z2w2LdJ0TNc3TYvPcP/MdVbPg
xk6t59d74QH+jVFnsyyfiTX4XyDUOLAbrfM/nsl/Z5qIQEcsnZIkXUg+TtZJmOxn
456erfK7XPid2vnOlBuGEG0+E9aViKKNFqhRpMcqbxZ9cACknSkucx4pdL4ZB1+m
BAwZX+sQAo1UZD2XMEtJdqQAvdsYjRhQgXlMAAmbDYe+0ElMkM2+LIADb/nAUTjT
gM+2QFSXv8ovHMTEOAB0SqhmrA8Aan78nMYZCZJ8BQUAPQbZrYf+LZBkrGXHeVzb
jAh8hPn4JgHHtkw6Q6foShPaQ6tAHhSoDhkGY0hZNA2pL83889XqVuymIq6lKbIg
ThbD12uSvHZQwSVsWNkWIC55kPbKcPI1ijWvpgY/ABQZPBx4OUwDrrkAPPEJVfTz
c/Ice3xRalFGJPWnn+pK5MtUx/dyqXLOVtZIcS5LTkPYRnF74gAeIyo4Mgg21I+p
Sr1lpnBE4Po=
=O/07
-----END PGP SIGNATURE-----

--6c2NcOVqGQ03X4Wi--