Обсуждение: System in Recovery Mode

On Mon, 2008-02-25 at 08:11 -0600, Aaron Bono wrote:
> Our database was going along just fine this morning when, out of the
> blue, we started getting the following errors:
>
> FATAL:  the database system is in recovery mode
>
> We are using PostgreSQL 8.1.3 on CentOS.  I was the only person on the
> machine and had recently started a small batch that had just finished
> querying and updating the database.  This batch runs constantly and
> has not been changed in months.

Your database has crashed and is recovering. You should look at the
server log to find out when and why this happened, then either correct
the problem or report the bug.

On Mon, 2008-02-25 at 09:53 -0600, Aaron Bono wrote:

<2008-02-25 07:15:24 CST username 127.0.0.1>ERROR:  unrecognized node
type: 4260493
>

...

> <2008-02-25 07:15:49 CST username 127.0.0.1>CONTEXT:  PL/pgSQL
> function "get_branch_for_zip" line 61 at fetch

...

> <2008-02-25 07:15:56 CST  >LOG:  could not truncate directory
> "pg_multixact/members": apparent wraparound

Some interesting failures there.

Is this a modified Postgres server? Are you running externally supplied
C language functions? Have you had hardware problems?

On Mon, Feb 25, 2008 at 9:42 AM, Simon Riggs <simon@2ndquadrant.com> wrote:

On Mon, 2008-02-25 at 08:11 -0600, Aaron Bono wrote:

> Our database was going along just fine this morning when, out of the
> blue, we started getting the following errors:
>
> FATAL:  the database system is in recovery mode
>
> We are using PostgreSQL 8.1.3 on CentOS.  I was the only person on the
> machine and had recently started a small batch that had just finished
> querying and updating the database.  This batch runs constantly and
> has not been changed in months.

Your database has crashed and is recovering. You should look at the
server log to find out when and why this happened, then either correct
the problem or report the bug.

Here is what I am seeing:

<2008-02-25 07:15:24 CST username 127.0.0.1>ERROR:  unrecognized node type: 4260493
<2008-02-25 07:15:25 CST [unknown] >LOG:  connection received: host=127.0.0.1 port=51295
<2008-02-25 07:15:25 CST username 127.0.0.1>LOG:  connection authorized: user=username database=my_db
<2008-02-25 07:15:25 CST username 127.0.0.1>LOG:  disconnection: session time: 0:00:00.04 user=username database=my_db host=127.0.0.1 port=51295
<2008-02-25 07:15:25 CST [unknown] >LOG:  connection received: host=127.0.0.1 port=51296
<2008-02-25 07:15:25 CST username 127.0.0.1>LOG:  connection authorized: user=username database=clockwork_db_prod
<2008-02-25 07:15:38 CST username 127.0.0.1>ERROR:  unrecognized node type: 4260493
<2008-02-25 07:15:49 CST  >LOG:  server process (PID 10876) was terminated by signal 11
<2008-02-25 07:15:49 CST  >LOG:  terminating any other active server processes
<2008-02-25 07:15:49 CST username 127.0.0.1>WARNING:  terminating connection because of crash of another server process
<2008-02-25 07:15:49 CST username 127.0.0.1>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.
<2008-02-25 07:15:49 CST username 127.0.0.1>HINT:  In a moment you should be able to reconnect to the database and repeat your command.
<2008-02-25 07:15:49 CST username 127.0.0.1>WARNING:  terminating connection because of crash of another server process

and it continues like this as it terminated all connections followed by:

<2008-02-25 07:15:49 CST username 127.0.0.1>CONTEXT:  PL/pgSQL function "get_branch_for_zip" line 61 at fetch
<2008-02-25 07:15:50 CST  >LOG:  all server processes terminated; reinitializing
<2008-02-25 07:15:50 CST  >LOG:  database system was interrupted at 2008-02-25 07:11:10 CST
<2008-02-25 07:15:50 CST  >LOG:  checkpoint record is at 14/9F015F54
<2008-02-25 07:15:50 CST  >LOG:  redo record is at 14/9F015F54; undo record is at 0/0; shutdown FALSE
<2008-02-25 07:15:50 CST  >LOG:  next transaction ID: 911288200; next OID: 90133045
<2008-02-25 07:15:50 CST  >LOG:  next MultiXactId: 27095; next MultiXactOffset: 66130
<2008-02-25 07:15:50 CST  >LOG:  database system was not properly shut down; automatic recovery in progress
<2008-02-25 07:15:50 CST  >LOG:  redo starts at 14/9F015F98
<2008-02-25 07:15:50 CST  >LOG:  record with zero length at 14/9F08C23C
<2008-02-25 07:15:50 CST  >LOG:  redo done at 14/9F08C214
<2008-02-25 07:15:50 CST  >LOG:  could not truncate directory "pg_multixact/members": apparent wraparound
<2008-02-25 07:15:50 CST  >LOG:  database system is ready
<2008-02-25 07:15:50 CST  >LOG:  transaction ID wrap limit is 1576224515, limited by database "another_db"
<2008-02-25 07:15:56 CST [unknown] >LOG:  connection received: host=127.0.0.1 port=51987
<2008-02-25 07:15:56 CST username 127.0.0.1>LOG:  connection authorized: user=onehour database=my_db
<2008-02-25 07:15:56 CST  >LOG:  server process (PID 14433) was terminated by signal 11
<2008-02-25 07:15:56 CST  >LOG:  terminating any other active server processes
<2008-02-25 07:15:56 CST  >LOG:  all server processes terminated; reinitializing
<2008-02-25 07:15:56 CST  >LOG:  database system was interrupted at 2008-02-25 07:15:50 CST
<2008-02-25 07:15:56 CST  >LOG:  checkpoint record is at 14/9F08C23C
<2008-02-25 07:15:56 CST  >LOG:  redo record is at 14/9F08C23C; undo record is at 0/0; shutdown TRUE
<2008-02-25 07:15:56 CST  >LOG:  next transaction ID: 911293548; next OID: 90133045
<2008-02-25 07:15:56 CST  >LOG:  next MultiXactId: 27095; next MultiXactOffset: 66130
<2008-02-25 07:15:56 CST  >LOG:  database system was not properly shut down; automatic recovery in progress
<2008-02-25 07:15:56 CST  >LOG:  record with zero length at 14/9F08C280
<2008-02-25 07:15:56 CST  >LOG:  redo is not required
<2008-02-25 07:15:56 CST  >LOG:  could not truncate directory "pg_multixact/members": apparent wraparound
<2008-02-25 07:15:56 CST  >LOG:  database system is ready
<2008-02-25 07:15:56 CST  >LOG:  transaction ID wrap limit is 1576224515, limited by database "another_db"

and it then continues with this.

On Montag, 25. Februar 2008 Aaron Bono wrote:
> We did have a hard drive problem (errors on the drive) in the past
> and they had to swap out a drive.  It is a RAID configuration so no
> backup/restore was necessary.

Even with a RAID system, a broken hard drive that doesn't show that it's
broken can cause severe data destroying: We've had this several times
already, with different RAID and drive combinations, SATA and SCSI,
doesn't matter. The symptom was that you write data to the drive, it
says OK, but upon reading you receive other data than you wrote. Even
RAID 1/5/6 doesn't help you here.

Doesn't mean you have the same, but from what you wrote I just wanted to
inform you that it's a fact that a single broken drive can destroy even
a RAIDs data very nasty.

mfg zmi