oops w/ 2.6.2-mm1 on ppc32

oops w/ 2.6.2-mm1 on ppc32

[Marc Heckmann]

It happened while the machine was waking up from sleep. There were no
UDF or ISO filesystems mounted at the time, in fact, there wasn't even
a cd in the drive. The "autorun" process was running though (polls the
cdrom drive, to see if a disc has been inserted...). There were some
request timeouts on the cdrom drive (hdc) just before, it went to
sleep (system was idle at the time, I wasn't even at home).

Here is the kernel output before and after the machine went to sleep. The Oops
is at the bottom.

ide-cd: cmd 0x3 timed out
hdc: irq timeout: status=0xd0 { Busy }
hdc: irq timeout: error=0xd0LastFailedSense 0x0d
hdc: DMA disabled
hdc: ATAPI reset timed-out, status=0x80
ide1: reset timed-out, status=0x80
hdc: status timeout: status=0x80 { Busy }
hdc: status timeout: error=0x80LastFailedSense 0x08
hdc: drive not ready for command
hdc: ATAPI reset timed-out, status=0x80
ide1: reset timed-out, status=0x80
hda: start_power_step(step: 0)
hda: start_power_step(step: 1)
hda: complete_power_step(step: 1, stat: 50, err: 0)
hda: completing PM request, suspend
mediabay0: powering down
ohci_hcd 0000:00:0e.0: USB continue from host wakeup
mediabay0: powering down
mediabay0: powering up                       <--------- wakeup starts here.
mediabay0: enabling (kind:3)
mediabay0: waiting reset (kind:3)
mediabay0: waiting IDE reset (kind:3)
mediabay0: waiting IDE ready (kind:3)
media-bay 0 is ide1
mediabay 0 IDE ready
mesh: performing initial bus reset...
phy registers:
 3500 7869 2000 5c10 01e1 0021 0004 2001
 0000 0000 0000 0000 0000 0000 0000 0000
 0a23 0000 0000 0000 0000 0000 0020 0000
 0000 0000 0109 0100 0006 0f00 0000 0000
hda: Wakeup request inited, waiting for !BSY...
hda: start_power_step(step: 1000)
hda: MDMA, cycleTime: 120, accessTime: 75, recTime: 45
hda: Set MDMA timing for mode 2, reg: 0x00211526
hda: Enabling MultiWord DMA 2
hda: completing PM request, resume
adb: starting probe task...
adb devices: [2]: 2 c3 [3]: 3 1 [7]: 7 1f
ADB keyboard at 2, handler 1
ADB mouse at 3, handler set to 4 (trackpad)
adb: finished probe task...
UDF-fs DEBUG fs/udf/super.c:502:udf_set_blocksize: Bad block size (2048)
udf: bad block size (2048)
kernel BUG in grow_buffers at fs/buffer.c:1195!
Oops: Exception in kernel mode, sig: 5 [#1]
NIP: C0055B30 LR: C0055AF0 SP: C862FCF0 REGS: c862fc40 TRAP: 0700    Not tainted
MSR: 00029032 EE: 1 PR: 0 FP: 0 ME: 1 IR/DR: 11
TASK = cf1e1b60[3743] 'mount' Last syscall: 21
GPR00: 0000FBFF C862FCF0 CF1E1B60 00000000 00000000 00000000 00000000 C02CE75C
GPR08: 0000001C 00000000 00000000 0000FC00 22004422 100289FC 00000000 7FFFF978
GPR16: 7FFFF82C 00000000 00000000 100EDD08 00000000 00000000 00000000 00000000
GPR24: 00000000 00000064 00000000 00000000 00008000 D7FF4AC0 00000010 00000000
Call trace:
 [c00560a0] __getblk+0x54/0x5c
 [c0056100] __bread+0x10/0x40
 [c00b40fc] isofs_fill_super+0x590/0x6fc
 [c005acc4] get_sb_bdev+0x128/0x180
 [c00b4dac] isofs_get_sb+0x18/0x28
 [c005afe8] do_kern_mount+0xb4/0x1dc
 [c0071ad8] do_add_mount+0x8c/0x1b8
 [c0071e94] do_mount+0x184/0x1bc
 [c0072318] sys_mount+0xd4/0x11c
 [c000781c] ret_from_syscall+0x0/0x44

-m

Re: oops w/ 2.6.2-mm1 on ppc32

[Benjamin Herrenschmidt]

On Sun, 2004-02-15 at 18:41, Marc Heckmann wrote:
> It happened while the machine was waking up from sleep. There were no
> UDF or ISO filesystems mounted at the time, in fact, there wasn't even
> a cd in the drive. The "autorun" process was running though (polls the
> cdrom drive, to see if a disc has been inserted...). There were some
> request timeouts on the cdrom drive (hdc) just before, it went to
> sleep (system was idle at the time, I wasn't even at home).
> 
> Here is the kernel output before and after the machine went to sleep. The Oops
> is at the bottom.

Looks like CD went berserk, and something didn't deal with the
error correctly... I don't know those code path in there
very well... Can you paste more of the ide-cd errors,
those are weird.

Ben.

Re: oops w/ 2.6.2-mm1 on ppc32

[Andrew Morton]

Benjamin Herrenschmidt <benh@kernel.crashing.org> wrote:
>
> On Sun, 2004-02-15 at 18:41, Marc Heckmann wrote:
> > It happened while the machine was waking up from sleep. There were no
> > UDF or ISO filesystems mounted at the time, in fact, there wasn't even
> > a cd in the drive. The "autorun" process was running though (polls the
> > cdrom drive, to see if a disc has been inserted...). There were some
> > request timeouts on the cdrom drive (hdc) just before, it went to
> > sleep (system was idle at the time, I wasn't even at home).
> > 
> > Here is the kernel output before and after the machine went to sleep. The Oops
> > is at the bottom.
> 
> Looks like CD went berserk, and something didn't deal with the
> error correctly... I don't know those code path in there
> very well... Can you paste more of the ide-cd errors,
> those are weird.

Note that isofs_fill_super() calls sb_bread() before setting the blocksize.
For this it is relying on blockdev.bd_block_size being set up
appropriately.

Which all tends to imply that the underlying queue's ->hardsect_size is
very wrong.

The code which is responsible for setting up the queue's hardsect_size
appears to live in cdrom_read_toc():

	/* Check to see if the existing data is still valid.
	   If it is, just return. */
	(void) cdrom_check_status(drive, sense);

	if (CDROM_STATE_FLAGS(drive)->toc_valid)
		return 0;

	/* Try to get the total cdrom capacity and sector size. */
	stat = cdrom_read_capacity(drive, &toc->capacity, &sectors_per_frame,
				   sense);
	if (stat)
		toc->capacity = 0x1fffff;

	set_capacity(drive->disk, toc->capacity * sectors_per_frame);
	blk_queue_hardsect_size(drive->queue,
				sectors_per_frame << SECTOR_BITS);

I'm wondering about that `return 0;' in there.  That will return "success"
even though we haven't set up half the things which should have been set
up.

Jens, should we be returning some sort of error code there?

Re: oops w/ 2.6.2-mm1 on ppc32

[Jens Axboe]

On Sun, Feb 15 2004, Andrew Morton wrote:
> Benjamin Herrenschmidt <benh@kernel.crashing.org> wrote:
> >
> > On Sun, 2004-02-15 at 18:41, Marc Heckmann wrote:
> > > It happened while the machine was waking up from sleep. There were no
> > > UDF or ISO filesystems mounted at the time, in fact, there wasn't even
> > > a cd in the drive. The "autorun" process was running though (polls the
> > > cdrom drive, to see if a disc has been inserted...). There were some
> > > request timeouts on the cdrom drive (hdc) just before, it went to
> > > sleep (system was idle at the time, I wasn't even at home).
> > > 
> > > Here is the kernel output before and after the machine went to sleep. The Oops
> > > is at the bottom.
> > 
> > Looks like CD went berserk, and something didn't deal with the
> > error correctly... I don't know those code path in there
> > very well... Can you paste more of the ide-cd errors,
> > those are weird.
> 
> Note that isofs_fill_super() calls sb_bread() before setting the blocksize.
> For this it is relying on blockdev.bd_block_size being set up
> appropriately.
> 
> Which all tends to imply that the underlying queue's ->hardsect_size is
> very wrong.
> 
> The code which is responsible for setting up the queue's hardsect_size
> appears to live in cdrom_read_toc():
> 
> 	/* Check to see if the existing data is still valid.
> 	   If it is, just return. */
> 	(void) cdrom_check_status(drive, sense);
> 
> 	if (CDROM_STATE_FLAGS(drive)->toc_valid)
> 		return 0;
> 
> 	/* Try to get the total cdrom capacity and sector size. */
> 	stat = cdrom_read_capacity(drive, &toc->capacity, &sectors_per_frame,
> 				   sense);
> 	if (stat)
> 		toc->capacity = 0x1fffff;
> 
> 	set_capacity(drive->disk, toc->capacity * sectors_per_frame);
> 	blk_queue_hardsect_size(drive->queue,
> 				sectors_per_frame << SECTOR_BITS);
> 
> I'm wondering about that `return 0;' in there.  That will return "success"
> even though we haven't set up half the things which should have been set
> up.
> 
> Jens, should we be returning some sort of error code there?

I'll have a look to see if it can go wrong, but ->toc_valid should never
be set if the hardsector stuff etc hasn't been set up yet.

-- 
Jens Axboe

Re: oops w/ 2.6.2-mm1 on ppc32

[Benjamin Herrenschmidt]

> Note that isofs_fill_super() calls sb_bread() before setting the blocksize.
> For this it is relying on blockdev.bd_block_size being set up
> appropriately.
> 
> Which all tends to imply that the underlying queue's ->hardsect_size is
> very wrong.
> 
> The code which is responsible for setting up the queue's hardsect_size
> appears to live in cdrom_read_toc()
> 
  .../...

I have to double check, but that sounds a bit like some oops report
I got with HFS/HFS+ on CD-ROMs... I'll check my archives tomorrow

Ben.

Re: oops w/ 2.6.2-mm1 on ppc32

[Marc Heckmann]

On Sun, Feb 15, 2004 at 06:49:43PM +1100, Benjamin Herrenschmidt wrote:
> On Sun, 2004-02-15 at 18:41, Marc Heckmann wrote:
> > It happened while the machine was waking up from sleep. There were no
> > UDF or ISO filesystems mounted at the time, in fact, there wasn't even
> > a cd in the drive. The "autorun" process was running though (polls the
> > cdrom drive, to see if a disc has been inserted...). There were some
> > request timeouts on the cdrom drive (hdc) just before, it went to
> > sleep (system was idle at the time, I wasn't even at home).
> > 
> > Here is the kernel output before and after the machine went to sleep. The Oops
> > is at the bottom.
> 
> Looks like CD went berserk, and something didn't deal with the
> error correctly... I don't know those code path in there
> very well... Can you paste more of the ide-cd errors,
> those are weird.

the last cd related errors were half a month ago. As a side note, the
cdrom drive in this powerbook G3 (Lombard) only really worked right,
if at all, 50% (or less) of the time in 2.6 (it's fine in 2.4). It
does seem to work now (maybe due to the pmac patches in -mm?) though.
I'll continue to test the drive after more uptime and a few
sleep/wakeup cycles.


Jan 31 00:01:30 claw kernel: ide-cd: cmd 0x3 timed out
Jan 31 00:01:30 claw kernel: hdc: irq timeout: status=0xd0 { Busy }
Jan 31 00:01:30 claw kernel: hdc: irq timeout: error=0xd0LastFailedSense 0x0d
Jan 31 00:01:30 claw kernel: hdc: DMA disabled
Jan 31 00:02:00 claw kernel: hdc: ATAPI reset timed-out, status=0x80
Jan 31 00:02:21 claw su(pam_unix)[10335]: session closed for user root
Jan 31 00:02:30 claw kernel: ide1: reset timed-out, status=0x80
Jan 31 00:02:30 claw kernel: hdc: status timeout: status=0x80 { Busy }
Jan 31 00:02:30 claw kernel: hdc: status timeout: error=0x80LastFailedSense 0x08
Jan 31 00:02:30 claw kernel: hdc: drive not ready for command
Jan 31 00:03:00 claw kernel: hdc: ATAPI reset timed-out, status=0x80
Jan 31 00:03:30 claw kernel: ide1: reset timed-out, status=0x80
Jan 31 00:03:31 claw kernel: end_request: I/O error, dev hdc, sector 4291125764
Jan 31 00:03:31 claw kernel: end_request: I/O error, dev hdc, sector 4548260
Jan 31 00:03:31 claw kernel: end_request: I/O error, dev hdc, sector 4548036
Jan 31 00:03:31 claw kernel: UDF-fs: No partition found (1)
Jan 31 00:03:31 claw kernel: end_request: I/O error, dev hdc, sector 4547076
Jan 31 00:03:31 claw kernel: isofs_fill_super: bread failed, dev=hdc, iso_blknum=1136
769, block=1136769

-m