Re: FATAL: the database system is in recovery mode

Doug McNaught wrote:

>Ron St-Pierre <rstpierre(at)syscor(dot)com> writes:
>
>
>
>>We're developing a java app and are using postgres as the database. On
>>our dev server I started the app, closed it, but the java process was
>>still open so I killed it, which caused the above error. I've had to
>>do this in the past but have not had this happen before. I've searched
>>the archives and found a message/reply from Andrew Sullivan about this
>>which implies that it may be more a file system problem. We're using
>>postgresql 7.4.1 on a debian box (and yes, ext2). And fsync is turned
>>on.
>>
>>
>
>Killing a client process shouldn't cause fatal errors on the
>server--the most you should get is "client unexpectedly closed
>connection". Something else is wrong.
>
>
>
>>Aside from not killing processes which hang, is there anything I can
>>do to avoid this problem in the future?
>>
>>
>
>What is the actual problem with Postgres? Did the server die? Is it
>refusing to start up? If you can give more complete logs that would
>be helpful.
>
>-Doug
>
>
>
It looks as if it hung up trying to write some customer preferences to
the db. Here's the snippet from /var/log/messages:

Jul 7 09:32:58 imp postgres[32351]: [550-1] LOG: statement: UPDATE
customer.clientPreferences SET preferences='<?xml version="1.0"
encoding="UTF-8"?>
Jul 7 09:32:58 imp postgres[32351]: [550-2] ^I<java version="1.4.2_03"
class="java.beans.XMLDecoder">
Jul 7 09:32:58 imp postgres[32351]: [550-3] ^I <object
class="java.util.HashMap">
Jul 7 09:32:58 imp postgres[32351]: [550-4] ^I <void method="put">

.... thousand(s) lines of XML ...

Jul 7 09:32:58 imp postgres[32351]: [550-1626] ^I <void
method="put">
Jul 7 09:32:58 imp postgres[26784]: [448-1] LOG: server process (PID
32349) was terminated by signal 11
Jul 7 09:32:58 imp postgres[26784]: [449-1] LOG: terminating any other
active server processes
Jul 7 09:32:58 imp postgres[32352]: [567-1] WARNING: terminating
connection because of crash of another server process
Jul 7 09:32:58 imp postgres[32350]: [482-1] WARNING: terminating
connection because of crash of another server process
Jul 7 09:32:58 imp postgres[32348]: [450-1] WARNING: terminating
connection because of crash of another server process
Jul 7 09:32:58 imp postgres[32352]: [567-2] DETAIL: The postmaster has
commanded this server process to roll back the current transaction and
exit, because another server
Jul 7 09:32:58 imp postgres[32352]: [567-3] process exited abnormally
and possibly corrupted shared memory.
Jul 7 09:32:58 imp postgres[32350]: [482-2] DETAIL: The postmaster has
commanded this server process to roll back the current transaction and
exit, because another server
Jul 7 09:32:58 imp postgres[32348]: [450-2] DETAIL: The postmaster has
commanded this server process to roll back the current transaction and
exit, because another server
Jul 7 09:32:58 imp postgres[32352]: [567-4] HINT: In a moment you
should be able to reconnect to the database and repeat your command.
Jul 7 09:32:58 imp postgres[32350]: [482-3] process exited abnormally
and possibly corrupted shared memory.
Jul 7 09:32:58 imp postgres[32350]: [482-4] HINT: In a moment you
should be able to reconnect to the database and repeat your command.
Jul 7 09:32:58 imp postgres[32348]: [450-3] process exited abnormally
and possibly corrupted shared memory.
Jul 7 09:32:58 imp postgres[32348]: [450-4] HINT: In a moment you
should be able to reconnect to the database and repeat your command.
Jul 7 09:32:58 imp postgres[32351]: [551-1] ERROR: terminating
connection because of crash of another server process
^ ^
^ ^ ^
Jul 7 09:32:58 imp postgres[32351]: [551-2] DETAIL: The postmaster has
commanded this server process to roll back the current transaction and
exit, because another server
Jul 7 09:32:58 imp postgres[32351]: [551-3] process exited abnormally
and possibly corrupted shared memory.
Jul 7 09:32:58 imp postgres[32351]: [551-4] HINT: In a moment you
should be able to reconnect to the database and repeat your command.
Jul 7 09:32:58 imp postgres[19223]: [432-1] WARNING: terminating
connection because of crash of another server process
Jul 7 09:32:58 imp postgres[19223]: [432-2] DETAIL: The postmaster has
commanded this server process to roll back the current transaction and
exit, because another server
... more ...
Jul 7 09:32:58 imp postgres[3802]: [295-3] process exited abnormally
and possibly corrupted shared memory.
Jul 7 09:32:58 imp postgres[3802]: [295-4] HINT: In a moment you
should be able to reconnect to the database and repeat your command.
Jul 7 10:02:24 imp -- MARK --
Jul 7 10:22:24 imp -- MARK --
Jul 7 10:42:24 imp -- MARK --
Jul 7 11:02:24 imp -- MARK --
Jul 7 11:22:24 imp -- MARK --
Jul 7 11:42:24 imp -- MARK --
Jul 7 12:02:24 imp -- MARK --
Jul 7 12:22:24 imp -- MARK --
Jul 7 12:42:24 imp -- MARK --
Jul 7 13:02:24 imp -- MARK --
Jul 7 13:22:24 imp -- MARK --
Jul 7 13:42:24 imp -- MARK --
Jul 7 14:00:36 imp postgres[32351]: [552-1] LOG: could not receive
data from client: Connection reset by peer
Jul 7 14:00:36 imp postgres[32351]: [553-1] LOG: unexpected EOF on
client connection
Jul 7 14:00:36 imp postgres[26784]: [450-1] LOG: all server processes
terminated; reinitializing
Jul 7 14:00:36 imp postgres[7962]: [451-1] LOG: database system was
interrupted at 2004-07-07 09:31:44 PDT
Jul 7 14:00:36 imp postgres[7962]: [452-1] LOG: checkpoint record is
at 5E/7DB31300
Jul 7 14:00:36 imp postgres[7962]: [453-1] LOG: redo record is at
5E/7DB31300; undo record is at 0/0; shutdown FALSE
Jul 7 14:00:36 imp postgres[7962]: [454-1] LOG: next transaction ID:
21787900; next OID: 125814322
Jul 7 14:00:36 imp postgres[7962]: [455-1] LOG: database system was
not properly shut down; automatic recovery in progress
Jul 7 14:00:36 imp postgres[7962]: [456-1] LOG: record with zero
length at 5E/7DB31340
Jul 7 14:00:36 imp postgres[7962]: [457-1] LOG: redo is not required
Jul 7 14:00:38 imp postgres[7962]: [458-1] LOG: database system is ready

^ ^ ^ ^
I just checked it again, and as you can see from the logs it has
restarted. Looking at the times in the logs, it crashed at 09:32:58 and
restarted at 14:00:36, but there's nothing scheduled in cron that I can
see which would cause the restart. Odd. Normally I would have restarted
it manually with pg_ctl but I wanted to see what would happen so I left it.

Anyway my original question still stands, any idea how to avoid this
problem in the future?

Thanks
Ron