Database server hosed, no back-ups
A site on IDS 7.30.UC3A/HP-UX 10.20 crashed during a huge single transaction; the server now panics during logical recovery with "Page Check Error in bfput" and rollback error 172 on a DELITEM log record, and their only tape had the last archive overwritten by log backups. Art Kagel said the damage is in data pages (likely flaky disk), so truncating the logs would only get the engine up, not fix the data; the two-day-old ASCII unloads are the fallback. Madison Pruet suggested calling Tech Support (downed systems), noting he once NOP'd the offending log record to let recovery complete and then rebuilt the bad index. No outcome is reported in the thread.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
7.30 UC3 on HP-UX 10.20
A site, not yet a customer, has today had a large single-transaction update
crash, and now his database server is inaccessible (see log below).
The only have one tape, and they constantly use it to archive at night, than
back up the logs in the morning. So the tape with the most recent archive,
Friday night's, has been over-written by Saturday's logs(!)
They unloaded all 300 tables on Friday night, so have the option to re-build
the database from that. The only alternative I can think of is to get Tech
Support (and they have no current support contract) and patch the relevant
area to prevent logical recovery. Of course, their data will be logically
inconsistent, but they seem quite exceoted by this option.
Any other flashes of genius?
cheers
Neil
Mon Jan 12 20:25:44 2004
20:25:44 Event alarms enabled. ALARMPROG = '/usr/informix/etc/no_log.sh'
20:25:51 DR: DRAUTO is 0 (Off)
20:25:51 Informix Dynamic Server Version 7.30.UC3A Software Serial NumberAAD#J234612
20:25:51 Informix Dynamic Server Initialized -- Shared Memory Initialized.
20:25:52 Physical Recovery Started.
20:25:52 Physical Recovery Complete: 1174 Pages Restored.
20:25:52 Logical Recovery Started.
20:26:17 Assert Failed: Page Check Error in bfput
20:26:17 Informix Dynamic Server Version 7.30.UC3A
20:26:17 Who: Session(11, root@sta154, 0, 0)
Thread(37, fast_rec, 0, 4)
File: rsdebug.c Line: 998
20:26:17 Results: Possible inconsistencies in 'bha:"".'
20:26:17 Action: Run 'oncheck -cDI bha:"".'
20:27:44 See Also: /tmp/af.2502e8, shmem.2502e8.0
20:27:44 Error writing '/tmp/shmem.2502e8.0' errno = 28
20:27:44 Assert Failed: Rollback error 172
20:27:44 Informix Dynamic Server Version 7.30.UC3A
20:27:44 Who: Session(11, root@sta154, 0, 0)
Thread(37, fast_rec, 0, 4)
File: rstrans.c Line: 2115
20:27:44 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset0xd4018 was not rolled back
20:27:44 Action: Use 'onlog' to view the transaction and repair manually.
20:29:15 See Also: /tmp/af.2502e8, shmem.2502e8.1
20:29:15 Error writing '/tmp/shmem.2502e8.1' errno = 28
20:29:15 Assert Failed: Rollback error 172
20:29:15 Informix Dynamic Server Version 7.30.UC3A
20:29:15 Who: Session(11, root@sta154, 0, 0)
Thread(37, fast_rec, 0, 4)
File: rsextlog.c Line: 1412
20:29:15 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset0xd4018 was not rolled back
20:29:15 Action: Use 'onlog' to view the transaction and repair manually.
20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.2
20:30:48 Error writing '/tmp/shmem.2502e8.2' errno = 28
20:30:48 Assert Failed: Dynamic Server must abort
20:30:48 Informix Dynamic Server Version 7.30.UC3A
20:30:48 Who: Session(11, root@sta154, 0, 0)
Thread(37, fast_rec, 0, 4)
File: rslog.c Line: 3152
20:30:48 Results: Dynamic Server must abort
20:30:48 Action: Reinitialize shared memory
20:30:48 stack trace for pid 10183 written to /tmp/af.2502e8
20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.3
20:30:48 Error writing '/tmp/shmem.2502e8.3' errno = 28
20:30:48 rslog.c, line 3152, thread 37, proc id 10183, Dynamic Server must
abort.
20:30:48 PANIC: Attempting to bring system down
On Mon, 12 Jan 2004 16:48:11 -0500, Neil Truby wrote:
No help for it Neil. Support could truncate the logical logs so the engine
can come online, but the damage is to the data pages not the log pages so the
data's still hosed. The log is complaining that it could not rollback a
delete (well ... many deletes) because of bad page header/trailer matching
caused by disk corruption. Sounds like besides a complete lack of
understanding of how archives work, the site is also using RAID5 and has some
very old disks that have now gone flaky on them (I'd put some money on it).
Art S. Kagel
> 7.30 UC3 on HP-UX 10.20
>
> A site, not yet a customer, has today had a large single-transaction update
> crash, and now his database server is inaccessible (see log below).
>
> The only have one tape, and they constantly use it to archive at night, than
> back up the logs in the morning. So the tape with the most recent archive,
> Friday night's, has been over-written by Saturday's logs(!)
>
> They unloaded all 300 tables on Friday night, so have the option to re-build
> the database from that. The only alternative I can think of is to get Tech
> Support (and they have no current support contract) and patch the relevant
> area to prevent logical recovery. Of course, their data will be logically
> inconsistent, but they seem quite exceoted by this option.
>
> Any other flashes of genius?
>
> cheers
> Neil
>
> Mon Jan 12 20:25:44 2004
>
> 20:25:44 Event alarms enabled. ALARMPROG = '/usr/informix/etc/no_log.sh'
> 20:25:51 DR: DRAUTO is 0 (Off)
> 20:25:51 Informix Dynamic Server Version 7.30.UC3A Software Serial Number> AAD#J234612
> 20:25:51 Informix Dynamic Server Initialized -- Shared Memory Initialized.
> 20:25:52 Physical Recovery Started.
> 20:25:52 Physical Recovery Complete: 1174 Pages Restored. 20:25:52 Logical> Recovery Started.
> 20:26:17 Assert Failed: Page Check Error in bfput 20:26:17 Informix
> Dynamic Server Version 7.30.UC3A 20:26:17 Who: Session(11, root@sta154, 0,
> 0)
> Thread(37, fast_rec, 0, 4)
> File: rsdebug.c Line: 998
> 20:26:17 Results: Possible inconsistencies in 'bha:"".' 20:26:17 Action:
> Run 'oncheck -cDI bha:"".' 20:27:44 See Also: /tmp/af.2502e8,
> shmem.2502e8.0 20:27:44 Error writing '/tmp/shmem.2502e8.0' errno = 28
> 20:27:44 Assert Failed: Rollback error 172 20:27:44 Informix Dynamic
> Server Version 7.30.UC3A 20:27:44 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rstrans.c Line: 2115
> 20:27:44 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> 0xd4018 was not rolled back
> 20:27:44 Action: Use 'onlog' to view the transaction and repair manually.
> 20:29:15 See Also: /tmp/af.2502e8, shmem.2502e8.1 20:29:15 Error writing
> '/tmp/shmem.2502e8.1' errno = 28 20:29:15 Assert Failed: Rollback error 172
> 20:29:15 Informix Dynamic Server Version 7.30.UC3A 20:29:15 Who:
> Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rsextlog.c Line: 1412
> 20:29:15 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> 0xd4018 was not rolled back
> 20:29:15 Action: Use 'onlog' to view the transaction and repair manually.
> 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.2 20:30:48 Error writing
> '/tmp/shmem.2502e8.2' errno = 28 20:30:48 Assert Failed: Dynamic Server> must abort 20:30:48 Informix Dynamic Server Version 7.30.UC3A 20:30:48 Who:
> Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rslog.c Line: 3152
> 20:30:48 Results: Dynamic Server must abort 20:30:48 Action:> Reinitialize shared memory 20:30:48 stack trace for pid 10183 written to
> /tmp/af.2502e8 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.3 20:30:48
> Error writing '/tmp/shmem.2502e8.3' errno = 28 20:30:48 rslog.c, line 3152,
> thread 37, proc id 10183, Dynamic Server must abort. 20:30:48 PANIC:
> Attempting to bring system down
Art
I've explained the point about the logical recovery to them. They believe
that, because they know which 30 tables were running in the single
transaction that was running at the time of failure, it would be preferable
to rebuild those 30 to remove the logical inconsistency, than rebuild all
300 from 2-day-old ASCII unloads.
Reference the RAID: I didn't ask but I did have /var/adm/syslog/syslog.log
checked and there were no SCSI errors ....
cheers
Neil
"Art S. Kagel" <kagel@bloomberg.net> wrote in message
news:pan.2004.01.12.17.04.34.187881.12806@bloomberg.net...
> On Mon, 12 Jan 2004 16:48:11 -0500, Neil Truby wrote:
>
> No help for it Neil. Support could truncate the logical logs so the
engine
> can come online, but the damage is to the data pages not the log pages so
the
> data's still hosed. The log is complaining that it could not rollback a
> delete (well ... many deletes) because of bad page header/trailer matching
> caused by disk corruption. Sounds like besides a complete lack of
> understanding of how archives work, the site is also using RAID5 and has
some
> very old disks that have now gone flaky on them (I'd put some money on
it).
>
> Art S. Kagel
>
>
> > 7.30 UC3 on HP-UX 10.20
> >
> > A site, not yet a customer, has today had a large single-transaction
update
> > crash, and now his database server is inaccessible (see log below).
> >
> > The only have one tape, and they constantly use it to archive at night,
than
> > back up the logs in the morning. So the tape with the most recent
archive,
> > Friday night's, has been over-written by Saturday's logs(!)
> >
> > They unloaded all 300 tables on Friday night, so have the option to
re-build
> > the database from that. The only alternative I can think of is to get
Tech
> > Support (and they have no current support contract) and patch the
relevant
> > area to prevent logical recovery. Of course, their data will be
logically
> > inconsistent, but they seem quite exceoted by this option.
> >
> > Any other flashes of genius?
> >
> > cheers
> > Neil
> >
> > Mon Jan 12 20:25:44 2004
> >
> > 20:25:44 Event alarms enabled. ALARMPROG =
'/usr/informix/etc/no_log.sh'
> > 20:25:51 DR: DRAUTO is 0 (Off)
> > 20:25:51 Informix Dynamic Server Version 7.30.UC3A Software SerialNumber
> > AAD#J234612
> > 20:25:51 Informix Dynamic Server Initialized -- Shared MemoryInitialized.
> > 20:25:52 Physical Recovery Started.
> > 20:25:52 Physical Recovery Complete: 1174 Pages Restored. 20:25:52Logical
> > Recovery Started.
> > 20:26:17 Assert Failed: Page Check Error in bfput 20:26:17 Informix
> > Dynamic Server Version 7.30.UC3A 20:26:17 Who: Session(11,
root@sta154, 0,
> > 0)
> > Thread(37, fast_rec, 0, 4)
> > File: rsdebug.c Line: 998
> > 20:26:17 Results: Possible inconsistencies in 'bha:"".' 20:26:17
Action:
> > Run 'oncheck -cDI bha:"".' 20:27:44 See Also: /tmp/af.2502e8,
> > shmem.2502e8.0 20:27:44 Error writing '/tmp/shmem.2502e8.0' errno = 28
> > 20:27:44 Assert Failed: Rollback error 172 20:27:44 Informix Dynamic
> > Server Version 7.30.UC3A 20:27:44 Who: Session(11, root@sta154, 0, 0)
> > Thread(37, fast_rec, 0, 4)
> > File: rstrans.c Line: 2115
> > 20:27:44 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> > 0xd4018 was not rolled back
> > 20:27:44 Action: Use 'onlog' to view the transaction and repair
manually.
> > 20:29:15 See Also: /tmp/af.2502e8, shmem.2502e8.1 20:29:15 Errorwriting
> > '/tmp/shmem.2502e8.1' errno = 28 20:29:15 Assert Failed: Rollback error
172
> > 20:29:15 Informix Dynamic Server Version 7.30.UC3A 20:29:15 Who:
> > Session(11, root@sta154, 0, 0)
> > Thread(37, fast_rec, 0, 4)
> > File: rsextlog.c Line: 1412
> > 20:29:15 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> > 0xd4018 was not rolled back
> > 20:29:15 Action: Use 'onlog' to view the transaction and repair
manually.
> > 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.2 20:30:48 Errorwriting
> > '/tmp/shmem.2502e8.2' errno = 28 20:30:48 Assert Failed: Dynamic Server
> > must abort 20:30:48 Informix Dynamic Server Version 7.30.UC3A 20:30:48
Who:
> > Session(11, root@sta154, 0, 0)
> > Thread(37, fast_rec, 0, 4)
> > File: rslog.c Line: 3152
> > 20:30:48 Results: Dynamic Server must abort 20:30:48 Action:> > Reinitialize shared memory 20:30:48 stack trace for pid 10183 written
to
> > /tmp/af.2502e8 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.3
20:30:48
> > Error writing '/tmp/shmem.2502e8.3' errno = 28 20:30:48 rslog.c, line
3152,
> > thread 37, proc id 10183, Dynamic Server must abort. 20:30:48 PANIC:
> > Attempting to bring system down
Tech support time.
I once got arround this type of failure by modifying the logical log so that
the log record was a NOP, which allowed the recovery to finish. After the
engine was up, I dropped and rebuilt the bad index.
I don't know if tech support has a tool to convert all of the index items
for a specific index into NOPs or not, but that's what would be needed to
get out of this.
M.P.
The DELETEITEM has to do with an index, not the
"Neil Truby" <neil.truby@ardenta.com> wrote in message
news:btv4l8$bosf1$1@ID-162943.news.uni-berlin.de...
> 7.30 UC3 on HP-UX 10.20
>
> A site, not yet a customer, has today had a large single-transaction
update
> crash, and now his database server is inaccessible (see log below).
>
> The only have one tape, and they constantly use it to archive at night,
than
> back up the logs in the morning. So the tape with the most recent
archive,
> Friday night's, has been over-written by Saturday's logs(!)
>
> They unloaded all 300 tables on Friday night, so have the option to
re-build
> the database from that. The only alternative I can think of is to get
Tech
> Support (and they have no current support contract) and patch the relevant
> area to prevent logical recovery. Of course, their data will be logically
> inconsistent, but they seem quite exceoted by this option.
>
> Any other flashes of genius?
>
> cheers
> Neil
>
> Mon Jan 12 20:25:44 2004
>
> 20:25:44 Event alarms enabled. ALARMPROG = '/usr/informix/etc/no_log.sh'
> 20:25:51 DR: DRAUTO is 0 (Off)
> 20:25:51 Informix Dynamic Server Version 7.30.UC3A Software SerialNumber
> AAD#J234612
> 20:25:51 Informix Dynamic Server Initialized -- Shared MemoryInitialized.
> 20:25:52 Physical Recovery Started.
> 20:25:52 Physical Recovery Complete: 1174 Pages Restored.
> 20:25:52 Logical Recovery Started.
> 20:26:17 Assert Failed: Page Check Error in bfput
> 20:26:17 Informix Dynamic Server Version 7.30.UC3A
> 20:26:17 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rsdebug.c Line: 998
> 20:26:17 Results: Possible inconsistencies in 'bha:"".'
> 20:26:17 Action: Run 'oncheck -cDI bha:"".'
> 20:27:44 See Also: /tmp/af.2502e8, shmem.2502e8.0
> 20:27:44 Error writing '/tmp/shmem.2502e8.0' errno = 28
> 20:27:44 Assert Failed: Rollback error 172
> 20:27:44 Informix Dynamic Server Version 7.30.UC3A
> 20:27:44 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rstrans.c Line: 2115
> 20:27:44 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> 0xd4018 was not rolled back
> 20:27:44 Action: Use 'onlog' to view the transaction and repair
manually.
> 20:29:15 See Also: /tmp/af.2502e8, shmem.2502e8.1
> 20:29:15 Error writing '/tmp/shmem.2502e8.1' errno = 28
> 20:29:15 Assert Failed: Rollback error 172
> 20:29:15 Informix Dynamic Server Version 7.30.UC3A
> 20:29:15 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rsextlog.c Line: 1412
> 20:29:15 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> 0xd4018 was not rolled back
> 20:29:15 Action: Use 'onlog' to view the transaction and repair
manually.
> 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.2
> 20:30:48 Error writing '/tmp/shmem.2502e8.2' errno = 28
> 20:30:48 Assert Failed: Dynamic Server must abort
> 20:30:48 Informix Dynamic Server Version 7.30.UC3A
> 20:30:48 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rslog.c Line: 3152
> 20:30:48 Results: Dynamic Server must abort
> 20:30:48 Action: Reinitialize shared memory
> 20:30:48 stack trace for pid 10183 written to /tmp/af.2502e8
> 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.3
> 20:30:48 Error writing '/tmp/shmem.2502e8.3' errno = 28
> 20:30:48 rslog.c, line 3152, thread 37, proc id 10183, Dynamic Servermust
> abort.
> 20:30:48 PANIC: Attempting to bring system down>
>
Neil Truby wrote: > 7.30 UC3 on HP-UX 10.20 > > A site, not yet a customer, has today had a large single-transaction > update crash, and now his database server is inaccessible (see log below). > > The only have one tape, and they constantly use it to archive at night, > than > back up the logs in the morning. So the tape with the most recent > archive, Friday night's, has been over-written by Saturday's logs(!) Aha. Aha. Ahahahahahahahahahahahahahaha. And HPUX 10.20. My sympathy cup runneth over. :o) -- "C'est pas parce qu'on n'a rien ' dire qu'il faut fermer sa gueule" - Coluche
I'm pretty sure that tech support (downed systems) has a technique that will
be able to help out.
M.P.
"Neil Truby" <neil.truby@ardenta.com> wrote in message
news:btv4l8$bosf1$1@ID-162943.news.uni-berlin.de...
> 7.30 UC3 on HP-UX 10.20
>
> A site, not yet a customer, has today had a large single-transaction
update
> crash, and now his database server is inaccessible (see log below).
>
> The only have one tape, and they constantly use it to archive at night,
than
> back up the logs in the morning. So the tape with the most recent
archive,
> Friday night's, has been over-written by Saturday's logs(!)
>
> They unloaded all 300 tables on Friday night, so have the option to
re-build
> the database from that. The only alternative I can think of is to get
Tech
> Support (and they have no current support contract) and patch the relevant
> area to prevent logical recovery. Of course, their data will be logically
> inconsistent, but they seem quite exceoted by this option.
>
> Any other flashes of genius?
>
> cheers
> Neil
>
> Mon Jan 12 20:25:44 2004
>
> 20:25:44 Event alarms enabled. ALARMPROG = '/usr/informix/etc/no_log.sh'
> 20:25:51 DR: DRAUTO is 0 (Off)
> 20:25:51 Informix Dynamic Server Version 7.30.UC3A Software SerialNumber
> AAD#J234612
> 20:25:51 Informix Dynamic Server Initialized -- Shared MemoryInitialized.
> 20:25:52 Physical Recovery Started.
> 20:25:52 Physical Recovery Complete: 1174 Pages Restored.
> 20:25:52 Logical Recovery Started.
> 20:26:17 Assert Failed: Page Check Error in bfput
> 20:26:17 Informix Dynamic Server Version 7.30.UC3A
> 20:26:17 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rsdebug.c Line: 998
> 20:26:17 Results: Possible inconsistencies in 'bha:"".'
> 20:26:17 Action: Run 'oncheck -cDI bha:"".'
> 20:27:44 See Also: /tmp/af.2502e8, shmem.2502e8.0
> 20:27:44 Error writing '/tmp/shmem.2502e8.0' errno = 28
> 20:27:44 Assert Failed: Rollback error 172
> 20:27:44 Informix Dynamic Server Version 7.30.UC3A
> 20:27:44 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rstrans.c Line: 2115
> 20:27:44 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> 0xd4018 was not rolled back
> 20:27:44 Action: Use 'onlog' to view the transaction and repair
manually.
> 20:29:15 See Also: /tmp/af.2502e8, shmem.2502e8.1
> 20:29:15 Error writing '/tmp/shmem.2502e8.1' errno = 28
> 20:29:15 Assert Failed: Rollback error 172
> 20:29:15 Informix Dynamic Server Version 7.30.UC3A
> 20:29:15 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rsextlog.c Line: 1412
> 20:29:15 Results: Log record (OLDRSAM:DELITEM) in log 47852, offset> 0xd4018 was not rolled back
> 20:29:15 Action: Use 'onlog' to view the transaction and repair
manually.
> 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.2
> 20:30:48 Error writing '/tmp/shmem.2502e8.2' errno = 28
> 20:30:48 Assert Failed: Dynamic Server must abort
> 20:30:48 Informix Dynamic Server Version 7.30.UC3A
> 20:30:48 Who: Session(11, root@sta154, 0, 0)
> Thread(37, fast_rec, 0, 4)
> File: rslog.c Line: 3152
> 20:30:48 Results: Dynamic Server must abort
> 20:30:48 Action: Reinitialize shared memory
> 20:30:48 stack trace for pid 10183 written to /tmp/af.2502e8
> 20:30:48 See Also: /tmp/af.2502e8, shmem.2502e8.3
> 20:30:48 Error writing '/tmp/shmem.2502e8.3' errno = 28
> 20:30:48 rslog.c, line 3152, thread 37, proc id 10183, Dynamic Servermust
> abort.
> 20:30:48 PANIC: Attempting to bring system down>
>