Received: from localhost (unknown [200.46.204.183]) by postgresql.org (Postfix) with ESMTP id B6B2764FC2D for ; Thu, 25 Sep 2008 13:10:00 -0300 (ADT) Received: from postgresql.org ([200.46.204.86]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 44181-05 for ; Thu, 25 Sep 2008 13:09:52 -0300 (ADT) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from qb-out-0506.google.com (qb-out-0506.google.com [72.14.204.238]) by postgresql.org (Postfix) with ESMTP id 0DD0564FC20 for ; Thu, 25 Sep 2008 13:09:51 -0300 (ADT) Received: by qb-out-0506.google.com with SMTP id d8so356583qbc.23 for ; Thu, 25 Sep 2008 09:09:49 -0700 (PDT) Received: by 10.187.166.12 with SMTP id t12mr2539451fao.2.1222358988401; Thu, 25 Sep 2008 09:09:48 -0700 (PDT) Received: by 10.187.198.18 with HTTP; Thu, 25 Sep 2008 09:09:48 -0700 (PDT) Message-ID: <3d78fcfd0809250909h148daba8k2ad29e176d9a06fd@mail.gmail.com> Date: Thu, 25 Sep 2008 10:09:48 -0600 From: "BJ Taylor" To: pgsql-admin@postgresql.org Subject: Re: missing chunk number 0 for toast value In-Reply-To: <5723.1222349048@sss.pgh.pa.us> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_9580_24175270.1222358988408" References: <3d78fcfd0809241132y14a832cai8b32bc32e936699e@mail.gmail.com> <10862.1222287999@sss.pgh.pa.us> <3d78fcfd0809241446j326110c4p9907e04dbd10106b@mail.gmail.com> <5723.1222349048@sss.pgh.pa.us> X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0.002 tagged_above=0 required=5 tests=HTML_MESSAGE=0.001, NORMAL_HTTP_TO_IP=0.001 X-Spam-Level: X-Archive-Number: 200809/301 X-Sequence-Number: 30394 ------=_Part_9580_24175270.1222358988408 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline Hey Tom, Here are some recent logs from our system. Unfortunately, I didn't think to grab the logs at the time I killed those processes, and now they are gone. I found those processes by using ps, and then I killed them with a simple kill *processid*. Here are samples of our current log files: FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode LOG: autovacuum launcher started LOG: database system is ready to accept connections PANIC: right sibling's left-link doesn't match: block 175337 links to 243096 instead of expected 29675 in index "dbmail_headervalue_3" STATEMENT: INSERT INTO dbmail_headervalue (headername_id, physmessage_id, headervalue) VALUES (4,12335778,'from [76.13.13.25] by n6.bullet.mail.ac4.yahoo.com with NNFMP; 25 Sep 2008 04:01:36 -0000') LOG: server process (PID 13888) was terminated by signal 6: Aborted LOG: terminating any other active server processes WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. FATAL: the database system is in recovery mode WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode LOG: all server processes terminated; reinitializing LOG: database system was interrupted; last known up at 2008-09-25 09:12:41 MDT LOG: database system was not properly shut down; automatic recovery in progress FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode ... FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode LOG: redo starts at 3A/2D0DEA78 LOG: record with zero length at 3A/2D1B8D68 LOG: redo done at 3A/2D1B8D3C LOG: last completed transaction was at log time 2008-09-25 09:12:45.204162-06 FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode ... FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode LOG: redo starts at 3A/2D1B8DA8 LOG: unexpected pageaddr 3A/2520A000 in log file 58, segment 45, offset 2138112 LOG: redo done at 3A/2D208660 LOG: last completed transaction was at log time 2008-09-25 09:12:47.971207-06 FATAL: the database system is in recovery mode FATAL: the database system is in recovery mode ... LOG: unexpected EOF on client connection LOG: unexpected EOF on client connection ERROR: missing chunk number 0 for toast value 554365 STATEMENT: SELECT messageblk, is_header FROM dbmail_messageblks WHERE physmessage_id = 12111760 ORDER BY messageblk_idnr LOG: unexpected EOF on client connection LOG: unexpected EOF on client connection To be honest, I don't know if all of these logs are relevant or not. I half way suspect that nagios causes the "unexpected EOF on client connection" notices, but I can't be certain. You also asked how it is being unstable. It drops connections seemingly at random. The error received when a connection is dropped is the following: WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. Please let me know if there are any other questions I can answer for you. Thanks, BJ On Thu, Sep 25, 2008 at 7:24 AM, Tom Lane wrote: > "BJ Taylor" writes: > > We are using version 8.3.1. And to be precise, when I started the > vacuum > > (analyze), I started it as a cron job to run daily around midnight. The > > next day I came in and checked on it and it was still running. Not > thinking > > that it would take more than a full 24 hours to run, I let it be, and the > > next day I came in and the server started acting weird. I believe the > > vacuum process continued to run, and a second vacuum process was started. > > The server became unstable, and refused incoming connections. > > Unstable how? What error did you get on the refused connections? What > was showing up in the postmaster log? > > > At which > > point, I killed all vacuum processes, and restarted postgresql. > > How did you do that killing exactly? > > > I believe > > it was somewhere during this process that the database became corrupted. > I > > am not certain what happens when two vacuum processes run at the same > time. > > Nothing of interest, it's done all the time. > > > That may have been the problem, or it may not have. Or it may have been > > that I killed the vacuum process in the middle of what it was doing. One > > way or another, the problem that we have now, is that we are unable to > get a > > dump of the database for backups, and the database seems less stable than > it > > was previously (dropping connections, and refusing connections seemingly > at > > random). > > Again, what errors are you getting exactly, and what shows up in the > postmaster log? > > regards, tom lane > > -- > Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-admin > ------=_Part_9580_24175270.1222358988408 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline
Hey Tom,

Here are some recent logs from our system.  Unfortunately, I didn't think to grab the logs at the time I killed those processes, and now they are gone.  I found those processes by using ps, and then I killed them with a simple kill processid.  Here are samples of our current log files:

FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
LOG:  autovacuum launcher started
LOG:  database system is ready to accept connections
PANIC:  right sibling's left-link doesn't match: block 175337 links to 243096 instead of expected 29675 in index "dbmail_headervalue_3"
STATEMENT:  INSERT INTO dbmail_headervalue (headername_id, physmessage_id, headervalue) VALUES (4,12335778,'from [76.13.13.25] by n6.bullet.mail.ac4.yahoo.com with NNFMP; 25 Sep 2008 04:01:36 -0000')
LOG:  server process (PID 13888) was terminated by signal 6: Aborted
LOG:  terminating any other active server processes
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
FATAL:  the database system is in recovery mode
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
LOG:  all server processes terminated; reinitializing
LOG:  database system was interrupted; last known up at 2008-09-25 09:12:41 MDT
LOG:  database system was not properly shut down; automatic recovery in progress
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode

...

FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
LOG:  redo starts at 3A/2D0DEA78
LOG:  record with zero length at 3A/2D1B8D68
LOG:  redo done at 3A/2D1B8D3C
LOG:  last completed transaction was at log time 2008-09-25 09:12:45.204162-06
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode

...

FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode
LOG:  redo starts at 3A/2D1B8DA8
LOG:  unexpected pageaddr 3A/2520A000 in log file 58, segment 45, offset 2138112
LOG:  redo done at 3A/2D208660
LOG:  last completed transaction was at log time 2008-09-25 09:12:47.971207-06
FATAL:  the database system is in recovery mode
FATAL:  the database system is in recovery mode

...

LOG:  unexpected EOF on client connection
LOG:  unexpected EOF on client connection
ERROR:  missing chunk number 0 for toast value 554365
STATEMENT:  SELECT messageblk, is_header FROM dbmail_messageblks WHERE physmessage_id = 12111760 ORDER BY messageblk_idnr
LOG:  unexpected EOF on client connection
LOG:  unexpected EOF on client connection

To be honest, I don't know if all of these logs are relevant or not.  I half way suspect that nagios causes the "unexpected EOF on client connection" notices, but I can't be certain.

You also asked how it is being unstable.  It drops connections seemingly at random.  The error received when a connection is dropped is the following:

WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.

Please let me know if there are any other questions I can answer for you.

Thanks,
BJ

On Thu, Sep 25, 2008 at 7:24 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
"BJ Taylor" <btaylor@propertysolutions.com> writes:
> We are using version 8.3.1.  And to be precise, when I started the vacuum
> (analyze), I started it as a cron job to run daily around midnight.  The
> next day I came in and checked on it and it was still running.  Not thinking
> that it would take more than a full 24 hours to run, I let it be, and the
> next day I came in and the server started acting weird.  I believe the
> vacuum process continued to run, and a second vacuum process was started.
> The server became unstable, and refused incoming connections.

Unstable how?  What error did you get on the refused connections?  What
was showing up in the postmaster log?

> At which
> point, I killed all vacuum processes, and restarted postgresql.

How did you do that killing exactly?

> I believe
> it was somewhere during this process that the database became corrupted.  I
> am not certain what happens when two vacuum processes run at the same time.

Nothing of interest, it's done all the time.

> That may have been the problem, or it may not have.  Or it may have been
> that I killed the vacuum process in the middle of what it was doing.  One
> way or another, the problem that we have now, is that we are unable to get a
> dump of the database for backups, and the database seems less stable than it
> was previously (dropping connections, and refusing connections seemingly at
> random).

Again, what errors are you getting exactly, and what shows up in the
postmaster log?

                       regards, tom lane

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

------=_Part_9580_24175270.1222358988408--