2006-11-08 09:32:30

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

On Wed, Nov 08 2006, Adrian Bunk wrote:
> Subject : unable to rip cd
> References : http://lkml.org/lkml/2006/10/13/100
> Submitter : Alex Romosan <[email protected]>
> Status : unknown

Alex, was/is this repeatable? If so I'd like you to repeat with this
debug patch applied, I cannot reproduce it locally.

diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
index bddfebd..ad03e19 100644
--- a/drivers/ide/ide-cd.c
+++ b/drivers/ide/ide-cd.c
@@ -1726,8 +1726,10 @@ static ide_startstop_t cdrom_newpc_intr(
/*
* write to drive
*/
- if (cdrom_write_check_ireason(drive, len, ireason))
+ if (cdrom_write_check_ireason(drive, len, ireason)) {
+ blk_dump_rq_flags(rq, "cdrom_newpc");
return ide_stopped;
+ }

xferfunc = HWIF(drive)->atapi_output_bytes;
} else {
@@ -1859,8 +1861,10 @@ static ide_startstop_t cdrom_write_intr(
}

/* Check that the drive is expecting to do the same thing we are. */
- if (cdrom_write_check_ireason(drive, len, ireason))
+ if (cdrom_write_check_ireason(drive, len, ireason)) {
+ blk_dump_rq_flags(rq, "cdrom_pc");
return ide_stopped;
+ }

sectors_to_transfer = len / SECTOR_SIZE;


--
Jens Axboe


2006-11-08 19:09:54

by Alex Romosan

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

Jens Axboe <[email protected]> writes:

> On Wed, Nov 08 2006, Adrian Bunk wrote:
>> Subject : unable to rip cd
>> References : http://lkml.org/lkml/2006/10/13/100
>> Submitter : Alex Romosan <[email protected]>
>> Status : unknown
>
> Alex, was/is this repeatable? If so I'd like you to repeat with this
> debug patch applied, I cannot reproduce it locally.
>
> diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
> index bddfebd..ad03e19 100644
> --- a/drivers/ide/ide-cd.c
> +++ b/drivers/ide/ide-cd.c
> @@ -1726,8 +1726,10 @@ static ide_startstop_t cdrom_newpc_intr(
> /*
> * write to drive
> */
> - if (cdrom_write_check_ireason(drive, len, ireason))
> + if (cdrom_write_check_ireason(drive, len, ireason)) {
> + blk_dump_rq_flags(rq, "cdrom_newpc");
> return ide_stopped;
> + }
>
> xferfunc = HWIF(drive)->atapi_output_bytes;
> } else {
> @@ -1859,8 +1861,10 @@ static ide_startstop_t cdrom_write_intr(
> }
>
> /* Check that the drive is expecting to do the same thing we are. */
> - if (cdrom_write_check_ireason(drive, len, ireason))
> + if (cdrom_write_check_ireason(drive, len, ireason)) {
> + blk_dump_rq_flags(rq, "cdrom_pc");
> return ide_stopped;
> + }
>
> sectors_to_transfer = len / SECTOR_SIZE;
>

i've tried it again with the above patch applied and when i start
cdparanoia i get:

kernel: hdc: write_intr: wrong transfer direction!
kernel: cdrom_newpc: dev hdc: type=2, flags=114c9
kernel:
kernel: sector 59534648, nr/cnr 0/0
kernel: bio 00000000, biotail c14b2800, buffer 00000000, data 00000000, len 56
kernel: cdb: 12 00 00 00 38 00 00 00 00 00 00 00 00 00 00 00

as for the lock up, the ripping process never completes, it starts and
then it hangs somewhere in the middle of the track. it could be that
the disk has some problems. anyway, abort execution doesn't work until
i physically eject the cd from the drive (which seems to be an
improvement from a couple of rc's ago). hope this helps.

--alex--

--
| I believe the moment is at hand when, by a paranoiac and active |
| advance of the mind, it will be possible (simultaneously with |
| automatism and other passive states) to systematize confusion |
| and thus to help to discredit completely the world of reality. |

2006-11-08 19:27:11

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

On Wed, Nov 08 2006, Alex Romosan wrote:
> Jens Axboe <[email protected]> writes:
>
> > On Wed, Nov 08 2006, Adrian Bunk wrote:
> >> Subject : unable to rip cd
> >> References : http://lkml.org/lkml/2006/10/13/100
> >> Submitter : Alex Romosan <[email protected]>
> >> Status : unknown
> >
> > Alex, was/is this repeatable? If so I'd like you to repeat with this
> > debug patch applied, I cannot reproduce it locally.
> >
> > diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
> > index bddfebd..ad03e19 100644
> > --- a/drivers/ide/ide-cd.c
> > +++ b/drivers/ide/ide-cd.c
> > @@ -1726,8 +1726,10 @@ static ide_startstop_t cdrom_newpc_intr(
> > /*
> > * write to drive
> > */
> > - if (cdrom_write_check_ireason(drive, len, ireason))
> > + if (cdrom_write_check_ireason(drive, len, ireason)) {
> > + blk_dump_rq_flags(rq, "cdrom_newpc");
> > return ide_stopped;
> > + }
> >
> > xferfunc = HWIF(drive)->atapi_output_bytes;
> > } else {
> > @@ -1859,8 +1861,10 @@ static ide_startstop_t cdrom_write_intr(
> > }
> >
> > /* Check that the drive is expecting to do the same thing we are. */
> > - if (cdrom_write_check_ireason(drive, len, ireason))
> > + if (cdrom_write_check_ireason(drive, len, ireason)) {
> > + blk_dump_rq_flags(rq, "cdrom_pc");
> > return ide_stopped;
> > + }
> >
> > sectors_to_transfer = len / SECTOR_SIZE;
> >
>
> i've tried it again with the above patch applied and when i start
> cdparanoia i get:
>
> kernel: hdc: write_intr: wrong transfer direction!
> kernel: cdrom_newpc: dev hdc: type=2, flags=114c9
> kernel:
> kernel: sector 59534648, nr/cnr 0/0
> kernel: bio 00000000, biotail c14b2800, buffer 00000000, data 00000000, len 56
> kernel: cdb: 12 00 00 00 38 00 00 00 00 00 00 00 00 00 00 00

Wonderful! So this is an INQUIRY command, yet the WRITE bit is set. The
drive gets really confused about that, for good reason. The question is
where that write bit comes from, it looks really odd. Additionally, we
have killed ->bio but ->biotail still looks valid. Perhaps it's some of
the error handling that got screwed.

> as for the lock up, the ripping process never completes, it starts and
> then it hangs somewhere in the middle of the track. it could be that
> the disk has some problems. anyway, abort execution doesn't work until
> i physically eject the cd from the drive (which seems to be an
> improvement from a couple of rc's ago). hope this helps.

It helps a lot, thanks! I may ask you to retest with another patch, if
you don't mind.

--
Jens Axboe

2006-11-08 19:38:11

by Alex Romosan

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

Jens Axboe <[email protected]> writes:

> It helps a lot, thanks! I may ask you to retest with another patch,
> if you don't mind.

send the patches, i'll test them all. thanks.

--alex--

--
| I believe the moment is at hand when, by a paranoiac and active |
| advance of the mind, it will be possible (simultaneously with |
| automatism and other passive states) to systematize confusion |
| and thus to help to discredit completely the world of reality. |

2006-11-08 19:43:17

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

On Wed, Nov 08 2006, Alex Romosan wrote:
> Jens Axboe <[email protected]> writes:
>
> > It helps a lot, thanks! I may ask you to retest with another patch,
> > if you don't mind.
>
> send the patches, i'll test them all. thanks.

If you could retest with something crazy like this, then that would
likely help:

diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
index 7c47e62..010acfa 100644
--- a/drivers/ide/ide-cd.c
+++ b/drivers/ide/ide-cd.c
@@ -630,6 +630,9 @@ static void cdrom_end_request (ide_drive
struct request *rq = HWGROUP(drive)->rq;
int nsectors = rq->hard_cur_sectors;

+ if (blk_pc_request(rq) && rq->cmd[0] == 0x12)
+ printk("ide-cd: end INQ rq %p\n", rq);
+
if (blk_sense_request(rq) && uptodate) {
/*
* For REQ_TYPE_SENSE, "rq->buffer" points to the original
@@ -1671,6 +1674,9 @@ static ide_startstop_t cdrom_newpc_intr(
xfer_func_t *xferfunc;
unsigned long flags;

+ if (rq->cmd[0] == 0x12)
+ printk("ide-cd: newpc %p\n", rq);
+
/* Check for errors. */
dma_error = 0;
dma = info->dma;
@@ -1789,6 +1795,8 @@ static ide_startstop_t cdrom_newpc_intr(
return ide_started;

end_request:
+ if (rq->cmd[0] == 0x12)
+ printk("ide-cd: newpc end INQ %p\n", rq);
if (!rq->data_len)
post_transform_command(rq);

@@ -1959,7 +1967,13 @@ static ide_startstop_t cdrom_do_block_pc
{
struct cdrom_info *info = drive->driver_data;

- rq->cmd_flags |= REQ_QUIET;
+ if (rq->cmd[0] == 0x12) {
+ printk("ide-cd: starting INQ %p\n", rq);
+ if (rq_data_dir(rq) == WRITE)
+ printk("ide-cd: INQ with write set seen\n");
+ }
+ if (!rq->bio && rq->biotail)
+ printk("ide-cd: no bio, but biotail\n");

info->dma = 0;


--
Jens Axboe

2006-11-08 20:03:38

by Arjan van de Ven

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

> Wonderful! So this is an INQUIRY command, yet the WRITE bit is set. The
> drive gets really confused about that, for good reason. The question is
> where that write bit comes from, it looks really odd. Additionally, we

it could be a userspace command; some userspace tools send inquiry via
sg...


2006-11-08 20:17:30

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

On Wed, Nov 08 2006, Arjan van de Ven wrote:
> > Wonderful! So this is an INQUIRY command, yet the WRITE bit is set. The
> > drive gets really confused about that, for good reason. The question is
> > where that write bit comes from, it looks really odd. Additionally, we
>
> it could be a userspace command; some userspace tools send inquiry via
> sg...

it is a userspace command, it originates from SG_IO. So that is a given.
The question is where the write bit comes from, I'd be puzzled if the
user app sets it - cdparanoia in this case. Seeing as there's other
request mangling, I hope the new debug patch can shed some light on
that.

--
Jens Axboe

2006-11-08 21:40:35

by Alex Romosan

[permalink] [raw]
Subject: Re: 2.6.19-rc5: known regressions

Jens Axboe <[email protected]> writes:

> If you could retest with something crazy like this, then that would
> likely help:
>
> diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
> index 7c47e62..010acfa 100644
> --- a/drivers/ide/ide-cd.c
> +++ b/drivers/ide/ide-cd.c
> @@ -630,6 +630,9 @@ static void cdrom_end_request (ide_drive
> struct request *rq = HWGROUP(drive)->rq;
> int nsectors = rq->hard_cur_sectors;
>
> + if (blk_pc_request(rq) && rq->cmd[0] == 0x12)
> + printk("ide-cd: end INQ rq %p\n", rq);
> +
> if (blk_sense_request(rq) && uptodate) {
> /*
> * For REQ_TYPE_SENSE, "rq->buffer" points to the original
> @@ -1671,6 +1674,9 @@ static ide_startstop_t cdrom_newpc_intr(
> xfer_func_t *xferfunc;
> unsigned long flags;
>
> + if (rq->cmd[0] == 0x12)
> + printk("ide-cd: newpc %p\n", rq);
> +
> /* Check for errors. */
> dma_error = 0;
> dma = info->dma;
> @@ -1789,6 +1795,8 @@ static ide_startstop_t cdrom_newpc_intr(
> return ide_started;
>
> end_request:
> + if (rq->cmd[0] == 0x12)
> + printk("ide-cd: newpc end INQ %p\n", rq);
> if (!rq->data_len)
> post_transform_command(rq);
>
> @@ -1959,7 +1967,13 @@ static ide_startstop_t cdrom_do_block_pc
> {
> struct cdrom_info *info = drive->driver_data;
>
> - rq->cmd_flags |= REQ_QUIET;
> + if (rq->cmd[0] == 0x12) {
> + printk("ide-cd: starting INQ %p\n", rq);
> + if (rq_data_dir(rq) == WRITE)
> + printk("ide-cd: INQ with write set seen\n");
> + }
> + if (!rq->bio && rq->biotail)
> + printk("ide-cd: no bio, but biotail\n");
>
> info->dma = 0;

i applied this patch on top of the old one. this is what i get now:

kernel: ide-cd: starting INQ df5ad074
kernel: ide-cd: INQ with write set seen
kernel: ide-cd: newpc df5ad074
kernel: hdc: write_intr: wrong transfer direction!
kernel: ide-cd: end INQ rq df5ad074
kernel: cdrom_newpc: dev hdc: type=2, flags=104c9
kernel:
kernel: sector 59534648, nr/cnr 0/0
kernel: bio 00000000, biotail dee57c80, buffer 00000000, data 00000000, len 56
kernel: cdb: 12 00 00 00 38 00 00 00 00 00 00 00 00 00 00 00
kernel: ide-cd: starting INQ df5ad074
kernel: ide-cd: newpc df5ad074
kernel: ide-cd: newpc df5ad074
kernel: ide-cd: newpc end INQ df5ad074
kernel: hdc: packet command error: status=0x51 { DriveReady SeekComplete Error }
kernel: hdc: packet command error: error=0xb4 { AbortedCommand LastFailedSense=0x0b }
kernel: ide: failed opcode was: unknown
kernel: ATAPI device hdc:
kernel: Error: Aborted command -- (Sense key=0x0b)
kernel: (reserved error code) -- (asc=0x11, ascq=0x11)
kernel: The failed "Read CD" packet command was:
kernel: "be 00 00 00 51 93 00 00 0d f8 00 00 00 00 00 00 "
kernel: hdc: packet command error: status=0x51 { DriveReady SeekComplete Error }
kernel: hdc: packet command error: error=0x30 { LastFailedSense=0x03 }
kernel: ide: failed opcode was: unknown
kernel: ATAPI device hdc:
kernel: Error: Medium error -- (Sense key=0x03)
kernel: Unrecovered read error -- (asc=0x11, ascq=0x00)
kernel: The failed "Read CD" packet command was:
kernel: "be 00 00 00 51 a0 00 00 07 f8 00 00 00 00 00 00 "
kernel: hdc: packet command error: status=0x51 { DriveReady SeekComplete Error }
kernel: hdc: packet command error: error=0xb4 { AbortedCommand LastFailedSense=0x0b }
kernel: ide: failed opcode was: unknown
kernel: ATAPI device hdc:
kernel: Error: Aborted command -- (Sense key=0x0b)
kernel: (reserved error code) -- (asc=0x11, ascq=0x11)
kernel: The failed "Read CD" packet command was:
kernel: "be 00 00 00 51 9b 00 00 0d f8 00 00 00 00 00 00 "

hdc is the cdrom drive and the errors started showing up when
cdparanoia hung.

--alex--

--
| I believe the moment is at hand when, by a paranoiac and active |
| advance of the mind, it will be possible (simultaneously with |
| automatism and other passive states) to systematize confusion |
| and thus to help to discredit completely the world of reality. |