Thread: BUG #7562: could not read block 0 in file "base/16385/16585": read only 0 of 8192 bytes

The following bug has been logged on the website:

Bug reference:      7562
Logged by:          Mayank Mittal
Email address:      mayank.mittal.1982@hotmail.com
PostgreSQL version: 9.1.5
Operating system:   Debian Linux 6.0
Description:        =


We are using 2 node set-up of PostgreSQL 9.1.5 in which one is master and
other is slave which is in sync of master with streaming replication. =

The design is in such a way that in case of master node failure the slave
node has to take master role. I'm controlling this behaviour using Corosync
and Heartbeat.
My application is requirement needs heavy database updates. Upon fail-over
I've noticed that database indexes got corrupted. =

I'm not sure why this is happening. I was referring release notes of 9.1.3
and found similar issue is already fixed in it, but we are facing the same.

mayank.mittal.1982@hotmail.com writes:
> The following bug has been logged on the website:
> Bug reference:      7562
> Logged by:          Mayank Mittal
> Email address:      mayank.mittal.1982@hotmail.com
> PostgreSQL version: 9.1.5
> Operating system:   Debian Linux 6.0
> Description:

> We are using 2 node set-up of PostgreSQL 9.1.5 in which one is master and
> other is slave which is in sync of master with streaming replication.
> The design is in such a way that in case of master node failure the slave
> node has to take master role. I'm controlling this behaviour using Corosync
> and Heartbeat.
> My application is requirement needs heavy database updates. Upon fail-over
> I've noticed that database indexes got corrupted.

Hmm.  There is a fix for a slave-side-index-corruption problem in 9.1.6,
which is due to be announced Monday.  I am not certain whether this is
the same thing though; that bug is low-probability as far as we can
tell (it would only happen if the master had been in the middle of an
index page split or page deletion at the instant of failover).  Anyway
the first thing to find out is whether 9.1.6 fixes it.

            regards, tom lane

Hello Tom=2C   Thanks for the information.   But problem is it is occurring=
 quite frequently in my case.
Regards=2C
Mayank Mittal

> From: tgl@sss.pgh.pa.us
> To: mayank.mittal.1982@hotmail.com
> CC: pgsql-bugs@postgresql.org
> Subject: Re: [BUGS] BUG #7562: could not read block 0 in file "base/16385=
/16585": read only 0 of 8192 bytes
> Date: Thu=2C 20 Sep 2012 13:15:17 -0400
>=20
> mayank.mittal.1982@hotmail.com writes:
> > The following bug has been logged on the website:
> > Bug reference:      7562
> > Logged by:          Mayank Mittal
> > Email address:      mayank.mittal.1982@hotmail.com
> > PostgreSQL version: 9.1.5
> > Operating system:   Debian Linux 6.0
> > Description:       =20
>=20
> > We are using 2 node set-up of PostgreSQL 9.1.5 in which one is master a=
nd
> > other is slave which is in sync of master with streaming replication.=20
> > The design is in such a way that in case of master node failure the sla=
ve
> > node has to take master role. I'm controlling this behaviour using Coro=
sync
> > and Heartbeat.
> > My application is requirement needs heavy database updates. Upon fail-o=
ver
> > I've noticed that database indexes got corrupted.=20
>=20
> Hmm.  There is a fix for a slave-side-index-corruption problem in 9.1.6=
=2C
> which is due to be announced Monday.  I am not certain whether this is
> the same thing though=3B that bug is low-probability as far as we can
> tell (it would only happen if the master had been in the middle of an
> index page split or page deletion at the instant of failover).  Anyway
> the first thing to find out is whether 9.1.6 fixes it.
>=20
>             regards=2C tom lane
>=20
>=20
> --=20
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs
                           =

On Thursday, September 20, 2012 07:15:17 PM Tom Lane wrote:
> mayank.mittal.1982@hotmail.com writes:
> > The following bug has been logged on the website:
> > Bug reference:      7562
> > Logged by:          Mayank Mittal
> > Email address:      mayank.mittal.1982@hotmail.com
> > PostgreSQL version: 9.1.5
> > Operating system:   Debian Linux 6.0
> > Description:
> >
> > We are using 2 node set-up of PostgreSQL 9.1.5 in which one is master and
> > other is slave which is in sync of master with streaming replication.
> > The design is in such a way that in case of master node failure the slave
> > node has to take master role. I'm controlling this behaviour using
> > Corosync and Heartbeat.
> > My application is requirement needs heavy database updates. Upon
> > fail-over I've noticed that database indexes got corrupted.
What kind of indexes are you using? Hash indexes by any chance?

As you say downthread the failures are frequent could you provide a bit more
details about your setup (including configuration, initial setup etc) and the
logs on both machines?

> Hmm.  There is a fix for a slave-side-index-corruption problem in 9.1.6,
> which is due to be announced Monday.  I am not certain whether this is
> the same thing though; that bug is low-probability as far as we can
> tell (it would only happen if the master had been in the middle of an
> index page split or page deletion at the instant of failover).  Anyway
> the first thing to find out is whether 9.1.6 fixes it.
I think the likelihood of that bug causing the the index file to be zero bytes
- at least thats what I read from $subject - is really, really small:

The index would need to be created (setting a proper BM_PERMANENT flag on the
meta page), evicted from the buffer cache and thus written to the filesystem,
the root page would need to split causing the meta page to be rewritten (this
time without a proper BM_PERMANENT) in a very quick succession followed by a
OS/HW failure loosing the data already in the OS cache.
So, unless I am missing something, I don't see how that can happen.

Greetings,

Andres
--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

Andres Freund <andres@2ndquadrant.com> writes:
> On Thursday, September 20, 2012 07:15:17 PM Tom Lane wrote:
>> Hmm.  There is a fix for a slave-side-index-corruption problem in 9.1.6,
>> which is due to be announced Monday.  I am not certain whether this is
>> the same thing though; that bug is low-probability as far as we can
>> tell (it would only happen if the master had been in the middle of an
>> index page split or page deletion at the instant of failover).  Anyway
>> the first thing to find out is whether 9.1.6 fixes it.

> I think the likelihood of that bug causing the the index file to be zero bytes
> - at least thats what I read from $subject - is really, really small:

Sure, but what about the heap?  The case I was speculating about was
that the heap had been truncated, but because of the corruption problem,
the index still had heap pointers in it.  We don't know what file 16585
is supposed to be.

Your point about hash indexes is definitely worth asking though...
that would square with the reported symptoms.

            regards, tom lane

On Thursday, September 20, 2012 11:38:52 PM Tom Lane wrote:
> Andres Freund <andres@2ndquadrant.com> writes:
> > On Thursday, September 20, 2012 07:15:17 PM Tom Lane wrote:
> >> Hmm.  There is a fix for a slave-side-index-corruption problem in 9.1.6,
> >> which is due to be announced Monday.  I am not certain whether this is
> >> the same thing though; that bug is low-probability as far as we can
> >> tell (it would only happen if the master had been in the middle of an
> >> index page split or page deletion at the instant of failover).  Anyway
> >> the first thing to find out is whether 9.1.6 fixes it.
> >
> > I think the likelihood of that bug causing the the index file to be zero
> > bytes
>
> > - at least thats what I read from $subject - is really, really small:
> Sure, but what about the heap?  The case I was speculating about was
> that the heap had been truncated, but because of the corruption problem,
> the index still had heap pointers in it.  We don't know what file 16585
> is supposed to be.
Hm. Interesting thought.

*think*

Wouldn't the truncation have created a completely new index relation?

Greetings,

Andres
--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

Andres Freund <andres@2ndquadrant.com> writes:
> On Thursday, September 20, 2012 11:38:52 PM Tom Lane wrote:
>> Sure, but what about the heap?  The case I was speculating about was
>> that the heap had been truncated, but because of the corruption problem,
>> the index still had heap pointers in it.  We don't know what file 16585
>> is supposed to be.

> Wouldn't the truncation have created a completely new index relation?

If it were an actual TRUNCATE, yeah.  But it could be a case of VACUUM
truncating a now-empty table to zero blocks.

But nothing like this would explain the OP's report that corruption is
completely reproducible for him.  So I like your theory about hash index
use better.  We really oughta get some WAL support in there.

            regards, tom lane

Here is a snapshot of installed postgresql packages:
mayank@server:~$ dpkg -l | grep postgres=0A=
=0A=
ii =0A=
postgresql-9.1                     =0A=
9.1.5-1~bpo60+1             =0A=
object-relational SQL database=2C version 9.1 server=0A=
=0A=
ii =0A=
postgresql-client-9.1              =0A=
9.1.5-1~bpo60+1             =0A=
front-end programs for PostgreSQL 9.1=0A=
=0A=
ii =0A=
postgresql-client-common           =0A=
130~bpo60+1                 =0A=
manager for multiple PostgreSQL client versions=0A=
=0A=
ii  postgresql-common                  =0A=
130~bpo60+1                 =0A=
PostgreSQL database-cluster manager=0A=
=0A=
ii =0A=
postgresql-contrib                 =0A=
9.1+130~bpo60+2             =0A=
additional facilities for PostgreSQL (supported=0A=
version)=0A=
=0A=
ii =0A=
postgresql-contrib-9.1             =0A=
9.1.5-1~bpo60+1             =0A=
additional facilities for PostgreSQL
Regards=2C
Mayank Mittal


> Date: Thu=2C 20 Sep 2012 16:15:11 +0000
> Subject: [BUGS] BUG #7562: could not read block 0 in file "base/16385/165=
85": read    only 0 of 8192 bytes
> To: pgsql-bugs@postgresql.org
> From: mayank.mittal.1982@hotmail.com
>=20
> The following bug has been logged on the website:
>=20
> Bug reference:      7562
> Logged by:          Mayank Mittal
> Email address:      mayank.mittal.1982@hotmail.com
> PostgreSQL version: 9.1.5
> Operating system:   Debian Linux 6.0
> Description:       =20
>=20
> We are using 2 node set-up of PostgreSQL 9.1.5 in which one is master and
> other is slave which is in sync of master with streaming replication.=20
> The design is in such a way that in case of master node failure the slave
> node has to take master role. I'm controlling this behaviour using Corosy=
nc
> and Heartbeat.
> My application is requirement needs heavy database updates. Upon fail-ove=
r
> I've noticed that database indexes got corrupted.=20
> I'm not sure why this is happening. I was referring release notes of 9.1.=
3
> and found similar issue is already fixed in it=2C but we are facing the s=
ame.
>=20
>=20
>=20
>=20
>=20
> --=20
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs
                           =

--On 20. September 2012 18:18:12 -0400 Tom Lane <tgl@sss.pgh.pa.us> wrote:

> If it were an actual TRUNCATE, yeah.  But it could be a case of VACUUM
> truncating a now-empty table to zero blocks.
>
> But nothing like this would explain the OP's report that corruption is
> completely reproducible for him.  So I like your theory about hash index
> use better.  We really oughta get some WAL support in there.

We had a similar issue at a customer site. The server was shut down for
updating it from 9.1.4 to 9.1.5, after starting it again the log was
immediately cluttered with

ERROR:  could not read block 251 in file "base/6447890/7843708": read only
0 of 8192 bytes

The index was a primary key on table with mostly INSERTS (only a few
hundred DELETEs, autovacuum didn't even bother to vacuum it yet and no
manual VACUUM). According to the customer, no DDL action takes place on
this specific table. The kernel didn't show any errors.

--
Thanks

    Bernd

On Friday, September 21, 2012 10:18:39 AM Bernd Helmle wrote:
> --On 20. September 2012 18:18:12 -0400 Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > If it were an actual TRUNCATE, yeah.  But it could be a case of VACUUM
> > truncating a now-empty table to zero blocks.
> >
> > But nothing like this would explain the OP's report that corruption is
> > completely reproducible for him.  So I like your theory about hash index
> > use better.  We really oughta get some WAL support in there.
>
> We had a similar issue at a customer site. The server was shut down for
> updating it from 9.1.4 to 9.1.5, after starting it again the log was
> immediately cluttered with
How was it shutdown? -m fast or -m immediate?

> ERROR:  could not read block 251 in file "base/6447890/7843708": read only
> 0 of 8192 bytes
So, not block 0. How many blocks does the new index contain?

Mayank:
Do you always see the error in block 0?

> The index was a primary key on table with mostly INSERTS (only a few
> hundred DELETEs, autovacuum didn't even bother to vacuum it yet and no
> manual VACUUM). According to the customer, no DDL action takes place on
> this specific table. The kernel didn't show any errors.
Ok, this is getting wierd. Bernd some minutes ago confirmed on IRC that the
table is older than the last checkpoint...

Greetings,

Andres
--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

No=2C Most of the time I've seen in block 0=2C but 2-3 time it was with oth=
er blocks as well.

Regards=2C
Mayank MittalBarco Electronics System Ltd.Mob. +91 9873437922

> From: andres@2ndquadrant.com
> To: mailings@oopsware.de
> Subject: Re: [BUGS] BUG #7562: could not read block 0 in file "base/16385=
/16585": read only 0 of 8192 bytes
> Date: Fri=2C 21 Sep 2012 10:25:50 +0200
> CC: tgl@sss.pgh.pa.us=3B pgsql-bugs@postgresql.org=3B mayank.mittal.1982@=
hotmail.com
>=20
> On Friday=2C September 21=2C 2012 10:18:39 AM Bernd Helmle wrote:
> > --On 20. September 2012 18:18:12 -0400 Tom Lane <tgl@sss.pgh.pa.us> wro=
te:
> > > If it were an actual TRUNCATE=2C yeah.  But it could be a case of VAC=
UUM
> > > truncating a now-empty table to zero blocks.
> > >=20
> > > But nothing like this would explain the OP's report that corruption i=
s
> > > completely reproducible for him.  So I like your theory about hash in=
dex
> > > use better.  We really oughta get some WAL support in there.
> >=20
> > We had a similar issue at a customer site. The server was shut down for
> > updating it from 9.1.4 to 9.1.5=2C after starting it again the log was
> > immediately cluttered with
> How was it shutdown? -m fast or -m immediate?
>=20
> > ERROR:  could not read block 251 in file "base/6447890/7843708": read o=
nly
> > 0 of 8192 bytes
> So=2C not block 0. How many blocks does the new index contain?
>=20
> Mayank:
> Do you always see the error in block 0?
>=20
> > The index was a primary key on table with mostly INSERTS (only a few
> > hundred DELETEs=2C autovacuum didn't even bother to vacuum it yet and n=
o
> > manual VACUUM). According to the customer=2C no DDL action takes place =
on
> > this specific table. The kernel didn't show any errors.
> Ok=2C this is getting wierd. Bernd some minutes ago confirmed on IRC that=
 the=20
> table is older than the last checkpoint...
>=20
> Greetings=2C
>=20
> Andres
> --=20
>  Andres Freund                       http://www.2ndQuadrant.com/
>  PostgreSQL Development=2C 24x7 Support=2C Training & Services
>=20
>=20
> --=20
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs
                           =

--On 21. September 2012 10:25:50 +0200 Andres Freund
<andres@2ndquadrant.com> wrote:

>> We had a similar issue at a customer site. The server was shut down for
>> updating it from 9.1.4 to 9.1.5, after starting it again the log was
>> immediately cluttered with
> How was it shutdown? -m fast or -m immediate?
>

-m fast

>> ERROR:  could not read block 251 in file "base/6447890/7843708": read
>> only 0 of 8192 bytes
> So, not block 0. How many blocks does the new index contain?

255 blocks according to its current size.

--
Thanks

    Bernd

On Friday, September 21, 2012 01:37:38 PM Mayank Mittal wrote:
> As discussed with Andres on IRC, I tried to reproduce the issue with some
> debug log enabled.In order to reproduce I fixed my already broken system
> (index corrupted) by running REINDEX database <database_name>.Once done I
> performed the failover and now I'm getting following
> error:[org.postgresql.util.PSQLException: ERROR: missing chunk number 0
> for toast value 33972 in pg_toast_16582]
Unfortunately I don't think its really a valid approach to start from an
already corrupted database when doing this :( There might already be lingering
corruption causing the problem.

Have you seen the missing chunk error before? Did you reproduce the issue from
a corrupted database as well before?

Greetings,

Andres

> Regards,
> Mayank MittalBarco Electronics System Ltd.Mob. +91 9873437922
>
> > Date: Fri, 21 Sep 2012 11:34:49 +0200
> > From: mailings@oopsware.de
> > To: andres@2ndquadrant.com
> > CC: tgl@sss.pgh.pa.us; pgsql-bugs@postgresql.org;
> > mayank.mittal.1982@hotmail.com Subject: Re: [BUGS] BUG #7562: could not
> > read block 0 in file "base/16385/16585": read only 0 of 8192 bytes
> >
> >
> >
> > --On 21. September 2012 10:25:50 +0200 Andres Freund
> >
> > <andres@2ndquadrant.com> wrote:
> > >> We had a similar issue at a customer site. The server was shut down
> > >> for updating it from 9.1.4 to 9.1.5, after starting it again the log
> > >> was immediately cluttered with
> > >
> > > How was it shutdown? -m fast or -m immediate?
> >
> > -m fast
> >
> > >> ERROR:  could not read block 251 in file "base/6447890/7843708": read
> > >> only 0 of 8192 bytes
> > >
> > > So, not block 0. How many blocks does the new index contain?
> >
> > 255 blocks according to its current size.

--
 Andres Freund                       http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

No=2C this is the first time=2C I've seen this issue.In past as well reinde=
x the tables and it works well.
BTW now I'm resetting the database to start from fresh.

Regards=2C
Mayank MittalBarco Electronics System Ltd.Mob. +91 9873437922

> From: andres@2ndquadrant.com
> To: mayank.mittal.1982@hotmail.com
> Subject: Re: [BUGS] BUG #7562: could not read block 0 in file "base/16385=
/16585": read only 0 of 8192 bytes
> Date: Fri=2C 21 Sep 2012 13:43:00 +0200
> CC: tgl@sss.pgh.pa.us=3B pgsql-bugs@postgresql.org
>=20
> On Friday=2C September 21=2C 2012 01:37:38 PM Mayank Mittal wrote:
> > As discussed with Andres on IRC=2C I tried to reproduce the issue with =
some
> > debug log enabled.In order to reproduce I fixed my already broken syste=
m
> > (index corrupted) by running REINDEX database <database_name>.Once done=
 I
> > performed the failover and now I'm getting following
> > error:[org.postgresql.util.PSQLException: ERROR: missing chunk number 0
> > for toast value 33972 in pg_toast_16582]
> Unfortunately I don't think its really a valid approach to start from an=
=20
> already corrupted database when doing this :( There might already be ling=
ering=20
> corruption causing the problem.
>=20
> Have you seen the missing chunk error before? Did you reproduce the issue=
 from=20
> a corrupted database as well before?
>=20
> Greetings=2C
>=20
> Andres
>=20
> > Regards=2C
> > Mayank MittalBarco Electronics System Ltd.Mob. +91 9873437922
> >=20
> > > Date: Fri=2C 21 Sep 2012 11:34:49 +0200
> > > From: mailings@oopsware.de
> > > To: andres@2ndquadrant.com
> > > CC: tgl@sss.pgh.pa.us=3B pgsql-bugs@postgresql.org=3B
> > > mayank.mittal.1982@hotmail.com Subject: Re: [BUGS] BUG #7562: could n=
ot
> > > read block 0 in file "base/16385/16585": read only 0 of 8192 bytes
> > >=20
> > >=20
> > >=20
> > > --On 21. September 2012 10:25:50 +0200 Andres Freund
> > >=20
> > > <andres@2ndquadrant.com> wrote:
> > > >> We had a similar issue at a customer site. The server was shut dow=
n
> > > >> for updating it from 9.1.4 to 9.1.5=2C after starting it again the=
 log
> > > >> was immediately cluttered with
> > > >=20
> > > > How was it shutdown? -m fast or -m immediate?
> > >=20
> > > -m fast
> > >=20
> > > >> ERROR:  could not read block 251 in file "base/6447890/7843708": r=
ead
> > > >> only 0 of 8192 bytes
> > > >=20
> > > > So=2C not block 0. How many blocks does the new index contain?
> > >=20
> > > 255 blocks according to its current size.
>=20
> --=20
>  Andres Freund                       http://www.2ndQuadrant.com/
>  PostgreSQL Development=2C 24x7 Support=2C Training & Services
>=20
>=20
> --=20
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs
                           =