Re: Corrupt database? 8.1/FreeBSD6.0

Jeff Amiel <becauseimjeff@xxxxxxxxx> · Sat, 13 Jan 2007 06:58:43 -0800 (PST)

Tom Lane <tgl@xxxxxxxxxxxxx> wrote:
BTW, please don't do anything to try to correct the problem until we're
pretty sure we understand how this happened --- we might ask you for
more info.  AFAICS this isn't having any bad effects except for bleats
in your log file, so you can wait.

Happened again...however this time not appearingly related to an autovacuum.  I have a past example of this almost identical event a few weeks ago.  Here's what the logs look like with debug2 as the log_min level:

Jan 13 08:26:53 prod-app-1 postgres[41795]: [40171-1]  41795 LOG:  autovacuum: processing database "template1"
Jan 13 08:26:53 prod-app-1 postgres[560]: [40171-1]  560 DEBUG:  server process (PID 41794) exited with exit code
 0
Jan 13 08:26:57 prod-app-1 postgres[563]: [915-1]  563 DEBUG:  checkpoint starting
Jan 13 08:26:57 prod-app-1 postgres[563]: [916-1]  563 DEBUG:  recycled transaction log file "000000010000005D00000069"
Jan 13 08:26:57 prod-app-1 postgres[563]: [917-1]  563 DEBUG:  checkpoint complete; 0 transaction log file(s) added, 0 removed, 1 recycled
Jan 13 08:27:02 prod-app-1 postgres[560]: [40172-1]  560 DEBUG:  forked new backend, pid=42368 socket=8
Jan 13 08:27:02 prod-app-1 postgres[560]: [40173-1]  560 DEBUG:  forked new backend, pid=42369 socket=8
Jan 13 08:27:02 prod-app-1 postgres[560]: [40174-1]  560 DEBUG:  forked new backend, pid=42370 socket=8
Jan 13 08:27:02 prod-app-1 postgres[560]: [40175-1]  560 DEBUG:  server process (PID 42370) exited with exit code 0
Jan 13 08:27:02 prod-app-1 postgres[560]: [40176-1]  560 DEBUG:  forked new backend, pid=42371 socket=8
Jan
 13 08:27:02 prod-app-1 postgres[560]: [40177-1]  560 DEBUG:  server process (PID 42369) exited with exit code 0
Jan 13 08:27:02 prod-app-1 postgres[560]: [40178-1]  560 DEBUG:  server process (PID 42371) exited with exit code 0
Jan 13 08:27:02 prod-app-1 postgres[560]: [40179-1]  560 DEBUG:  forked new backend, pid=42372 socket=8
Jan 13 08:27:02 prod-app-1 postgres[560]: [40180-1]  560 DEBUG:  server process (PID 42372) exited with exit code 0
Jan 13 08:27:02 prod-app-1 postgres[560]: [40181-1]  560 DEBUG:  forked new backend, pid=42373 socket=8
Jan 13 08:27:02 prod-app-1 postgres[560]: [40182-1]  560 DEBUG:  server process (PID 42373) exited with exit code 0
Jan 13 08:27:02 prod-app-1 postgres[560]: [40183-1]  560 DEBUG:  forked new backend, pid=42374 socket=8
Jan 13 08:27:02 prod-app-1 postgres[560]: [40184-1]  560 DEBUG:  server process (PID 42374) exited with exit code
 0
Jan 13 08:27:02 prod-app-1 postgres[560]: [40185-1]  560 DEBUG:  server process (PID 42368) exited with exit code 0
Jan 13 08:27:08 prod-app-1 postgres[560]: [40186-1]  560 DEBUG:  forked new backend, pid=42375 socket=8
Jan 13 08:27:08 prod-app-1 postgres[560]: [40187-1]  560 DEBUG:  server process (PID 42375) exited with exit code 0
Jan 13 08:27:23 prod-app-1 postgres[560]: [40188-1]  560 DEBUG:  forked new backend, pid=42376 socket=8
Jan 13 08:27:23 prod-app-1 postgres[560]: [40189-1]  560 DEBUG:  server process (PID 42376) exited with exit code 0
Jan 13 08:27:26 prod-app-1 postgres[92257]: [30259-1] jboss 92257 ERROR:  could not access status of transaction 2107200825
Jan 13 08:27:26 prod-app-1 postgres[92257]: [30259-2] jboss 92257 DETAIL:  could not open file "pg_clog/07D9": No such file or directory
Jan 13 08:27:26 prod-app-1 postgres[92257]: [30259-3] jboss 92257 CONTEXT:  SQL
 statement "DELETE FROM audit_metadata WHERE user_id <> -1"
Jan 13 08:27:26 prod-app-1 postgres[92257]: [30259-4]     PL/pgSQL function "disable_auditing" line 2 at SQL statement
Jan 13 08:27:26 prod-app-1 postgres[92257]: [30259-5] jboss 92257 STATEMENT:  select disable_auditing()
Jan 13 08:27:38 prod-app-1 postgres[560]: [40190-1]  560 DEBUG:  forked new backend, pid=42377 socket=8
Jan 13 08:27:38 prod-app-1 postgres[560]: [40191-1]  560 DEBUG:  server process (PID 42377) exited with exit code 0
Jan 13 08:27:49 prod-app-1 postgres[560]: [40192-1]  560 DEBUG:  forked new backend, pid=42378 socket=8
Jan 13 08:27:50 prod-app-1 postgres[560]: [40193-1]  560 DEBUG:  forked new backend, pid=42379 socket=8
Jan 13 08:27:50 prod-app-1 postgres[560]: [40194-1]  560 DEBUG:  forked new backend, pid=42380 socket=8
Jan 13 08:27:53 prod-app-1 postgres[560]: [40195-1]  560
 DEBUG:  forked new backend, pid=42381 socket=8
Jan 13 08:27:53 prod-app-1 postgres[42382]: [40196-1]  42382 LOG:  autovacuum: processing database "postgres"
Jan 13 08:27:53 prod-app-1 postgres[560]: [40196-1]  560 DEBUG:  server process (PID 42381) exited with exit code 0
Jan 13 08:28:02 prod-app-1 postgres[560]: [40197-1]  560 DEBUG:  forked new backend, pid=42951 socket=8
Jan 13 08:28:02 prod-app-1 postgres[560]: [40198-1]  560 DEBUG:  forked new backend, pid=42952 socket=8

pg_clog dir looks like this:
-rw-------  1 pgsql  wheel  262144 Jan 13 05:41 07DA
-rw-------  1 pgsql  wheel  262144 Jan 13 08:06 07DB
-rw-------  1 pgsql  wheel   90112 Jan 13 08:51 07DC

Now that table, audit_metadata, is a temporary table (when accessed by jboss as it is here).  There is a 'rea'l table with the same name, but only used by batch processes that connect
 to postgres.

Thoughts?

Food fight? Enjoy some healthy debate
in the Yahoo! Answers Food & Drink Q&A.