2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Alex Romosan]

Jens Axboe <jens.axboe@oracle.com> writes:

> On Thu, Oct 12 2006, Alex Romosan wrote:
>>
>> please ignore my previous message, i am an idiot. if i actually put a
>> dvd in the drive then this patch works as expected. sorry for the
>> noise.
>
> Good, thanks for the update :-)

looks like the dvd problem was fixed but this morning i got the same
message:

  kernel: hdc: write_intr: wrong transfer direction!

trying to rip a cd with grip (cdparanoia). the process is stuck, i
can't kill it, and it's not making any more progress (but it still has
the smiling face so it probably thinks everything's fine). sysrq-t
shows this:


kernel: grip          D 00000007     0 17133   3835               16719 (NOTLB)
kernel:        d9677bac 00200082 d0ad2a70 00000007 d0ad2a70 23f93e80 000031a2 00000000 
kernel:        d0ad2b7c 00000000 d9677c44 540ae480 00000000 da8d7740 d9677c44 dfe9679c 
kernel:        d9677bc8 d9677bd0 c02f06ac 00000001 d0ad2a70 c011486c d9677c48 d9677c48 
kernel: Call Trace:
kernel:  [<c02f06ac>] wait_for_completion+0x85/0xd5
kernel:  [<c011486c>] default_wake_function+0x0/0xc
kernel:  [<c01b619d>] blk_execute_rq+0x78/0x8b
kernel:  [<c01b59cf>] blk_end_sync_rq+0x0/0x23
kernel:  [<c01b4c97>] blk_rq_bio_prep+0x28/0x7c
kernel:  [<c01b8eb2>] sg_io+0x253/0x34e
kernel:  [<c01b93ec>] scsi_cmd_ioctl+0x1ab/0x357
kernel:  [<c01256a9>] __rcu_process_callbacks+0xf4/0x178
kernel:  [<c011baf5>] tasklet_action+0x37/0x5c
kernel:  [<c011ba67>] __do_softirq+0x59/0x85
kernel:  [<c0118a2f>] profile_tick+0x3d/0x4e
kernel:  [<c0258582>] cdrom_ioctl+0x22/0xb30
kernel:  [<c0156228>] send_sigio+0x13b/0x146
kernel:  [<c025301c>] idecd_ioctl+0x12d/0x142
kernel:  [<c011ee00>] do_timer+0x679/0x6ff
kernel:  [<c01b7a87>] blkdev_driver_ioctl+0x4b/0x5b
kernel:  [<c01b80d8>] blkdev_ioctl+0x641/0x691
kernel:  [<c0217a93>] add_timer_randomness+0x106/0x120
kernel:  [<c025d3c0>] input_event+0x33/0x40e
kernel:  [<c025d77a>] input_event+0x3ed/0x40e
kernel:  [<c0137adf>] get_page_from_freelist+0x72/0x2f7
kernel:  [<c0137c33>] get_page_from_freelist+0x1c6/0x2f7
kernel:  [<c0137f1a>] __alloc_pages+0x4e/0x267
kernel:  [<c013a250>] lru_cache_add_active+0x47/0x5d
kernel:  [<c013e5d1>] __handle_mm_fault+0x458/0x7e4
kernel:  [<c016b3e6>] block_ioctl+0x10/0x13
kernel:  [<c016b3d6>] block_ioctl+0x0/0x13
kernel:  [<c0156b08>] do_ioctl+0x1c/0x5d
kernel:  [<c0156d90>] vfs_ioctl+0x247/0x25a
kernel:  [<c0156dcf>] sys_ioctl+0x2c/0x45
kernel:  [<c0102cbf>] syscall_call+0x7/0xb
kernel:  [<c02f007b>] __sched_text_start+0x123/0x560

let me know if i can help debug this.

--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. |

re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Jens Axboe]

Hi Alex,

Can you retest with this? This must be where the wrong write bit comes
from.

diff --git a/block/scsi_ioctl.c b/block/scsi_ioctl.c
index 2dc3264..a19338e 100644
--- a/block/scsi_ioctl.c
+++ b/block/scsi_ioctl.c
@@ -246,10 +246,10 @@ static int sg_io(struct file *file, requ
 		switch (hdr->dxfer_direction) {
 		default:
 			return -EINVAL;
-		case SG_DXFER_TO_FROM_DEV:
 		case SG_DXFER_TO_DEV:
 			writing = 1;
 			break;
+		case SG_DXFER_TO_FROM_DEV:
 		case SG_DXFER_FROM_DEV:
 			break;
 		}

-- 
Jens Axboe

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Alex Romosan]

Jens Axboe <jens.axboe@oracle.com> writes:

> Can you retest with this? This must be where the wrong write bit comes
> from.
>
> diff --git a/block/scsi_ioctl.c b/block/scsi_ioctl.c
> index 2dc3264..a19338e 100644
> --- a/block/scsi_ioctl.c
> +++ b/block/scsi_ioctl.c
> @@ -246,10 +246,10 @@ static int sg_io(struct file *file, requ
>  		switch (hdr->dxfer_direction) {
>  		default:
>  			return -EINVAL;
> -		case SG_DXFER_TO_FROM_DEV:
>  		case SG_DXFER_TO_DEV:
>  			writing = 1;
>  			break;
> +		case SG_DXFER_TO_FROM_DEV:
>  		case SG_DXFER_FROM_DEV:
>  			break;
>  		}
>

i think this finally got it to work! when i start cdparanoia now i get
(all the previous debug patches are still applied):

kernel: ide-cd: starting INQ da76fee4
kernel: ide-cd: newpc da76fee4
kernel: ide-cd: newpc da76fee4
kernel: ide-cd: newpc end INQ da76fee4

and then when it gets to the parts where the cd might have some
problems i get a bunch of:

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 "

but cdparanoia continues (albeit more slowly) and eventually finishes.
thank you!

--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. |

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Jens Axboe]

On Fri, Nov 10 2006, Alex Romosan wrote:
> Jens Axboe <jens.axboe@oracle.com> writes:
> 
> > Can you retest with this? This must be where the wrong write bit comes
> > from.
> >
> > diff --git a/block/scsi_ioctl.c b/block/scsi_ioctl.c
> > index 2dc3264..a19338e 100644
> > --- a/block/scsi_ioctl.c
> > +++ b/block/scsi_ioctl.c
> > @@ -246,10 +246,10 @@ static int sg_io(struct file *file, requ
> >  		switch (hdr->dxfer_direction) {
> >  		default:
> >  			return -EINVAL;
> > -		case SG_DXFER_TO_FROM_DEV:
> >  		case SG_DXFER_TO_DEV:
> >  			writing = 1;
> >  			break;
> > +		case SG_DXFER_TO_FROM_DEV:
> >  		case SG_DXFER_FROM_DEV:
> >  			break;
> >  		}
> >
> 
> i think this finally got it to work! when i start cdparanoia now i get
> (all the previous debug patches are still applied):
> 
> kernel: ide-cd: starting INQ da76fee4
> kernel: ide-cd: newpc da76fee4
> kernel: ide-cd: newpc da76fee4
> kernel: ide-cd: newpc end INQ da76fee4
> 
> and then when it gets to the parts where the cd might have some
> problems i get a bunch of:
> 
> 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 "
> 
> but cdparanoia continues (albeit more slowly) and eventually finishes.
> thank you!

Great, problem fixed then, patch is already merged upstream so 2.6.19
and next -rc (if any :-) should work. Thanks for your persistent
testing.

-- 
Jens Axboe

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Alex Romosan]

Jens Axboe <jens.axboe@oracle.com> writes:

> Great, problem fixed then, patch is already merged upstream so
> 2.6.19 and next -rc (if any :-) should work. Thanks for your
> persistent testing.

i've played with this a little bit more over the weekend. sometimes
cdparanoia gets stuck trying to read some sector. with your patches i
can now stop the process and restart it, and without touching the cd
at all this next time cdparanoia finishes just fine. usually this
happens after i try to rip a series of tracks so i wonder if some
error counters don't get reset or something like that. maybe this is
the expected behaviour, but i don't think i saw cdparanoia get stuck
on the first track ever, usually it happens after some time.

--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. |

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Jens Axboe]

On Mon, Nov 13 2006, Alex Romosan wrote:
> Jens Axboe <jens.axboe@oracle.com> writes:
> 
> > Great, problem fixed then, patch is already merged upstream so
> > 2.6.19 and next -rc (if any :-) should work. Thanks for your
> > persistent testing.
> 
> i've played with this a little bit more over the weekend. sometimes
> cdparanoia gets stuck trying to read some sector. with your patches i
> can now stop the process and restart it, and without touching the cd
> at all this next time cdparanoia finishes just fine. usually this
> happens after i try to rip a series of tracks so i wonder if some
> error counters don't get reset or something like that. maybe this is
> the expected behaviour, but i don't think i saw cdparanoia get stuck
> on the first track ever, usually it happens after some time.

There is a second error handling patch merged with the first patch as
well, perhaps it'll help you out. Attached here as well.

diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
index bddfebd..8821494 100644
--- a/drivers/ide/ide-cd.c
+++ b/drivers/ide/ide-cd.c
@@ -724,7 +724,7 @@ static int cdrom_decode_status(ide_drive
 		 * if we have an error, pass back CHECK_CONDITION as the
 		 * scsi status byte
 		 */
-		if (!rq->errors)
+		if (blk_pc_request(rq) && !rq->errors)
 			rq->errors = SAM_STAT_CHECK_CONDITION;
 
 		/* Check for tray open. */

-- 
Jens Axboe

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Alex Romosan]

Jens Axboe <jens.axboe@oracle.com> writes:

> There is a second error handling patch merged with the first patch as
> well, perhaps it'll help you out. Attached here as well.
>
> diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
> index bddfebd..8821494 100644
> --- a/drivers/ide/ide-cd.c
> +++ b/drivers/ide/ide-cd.c
> @@ -724,7 +724,7 @@ static int cdrom_decode_status(ide_drive
>  		 * if we have an error, pass back CHECK_CONDITION as the
>  		 * scsi status byte
>  		 */
> -		if (!rq->errors)
> +		if (blk_pc_request(rq) && !rq->errors)
>  			rq->errors = SAM_STAT_CHECK_CONDITION;
>  
>  		/* Check for tray open. */
>

tried it again with this patch (on top of all the other patches).
overall things are much better than they've been in a long time
(thanks!), but... when cdparanoia gets stuck, if i abort the process
and restart it the ripping proceeds very slowly (~5x before, ~1.5x
after). if i eject/insert the cd and then restart cdparanoia the speed
is as before (~5x). something doesn't get reset until the cd is
ejected, don't know if it's the kernel's fault though. same thing
happens if i get an error reading a sector but then cdparanoia manages
to recover. from that point on the speed is very slow (again until i
eject/insert the cd; a new instance of cdparanoia is just as slow).

--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. |

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Jens Axboe]

On Tue, Nov 14 2006, Alex Romosan wrote:
> Jens Axboe <jens.axboe@oracle.com> writes:
> 
> > There is a second error handling patch merged with the first patch as
> > well, perhaps it'll help you out. Attached here as well.
> >
> > diff --git a/drivers/ide/ide-cd.c b/drivers/ide/ide-cd.c
> > index bddfebd..8821494 100644
> > --- a/drivers/ide/ide-cd.c
> > +++ b/drivers/ide/ide-cd.c
> > @@ -724,7 +724,7 @@ static int cdrom_decode_status(ide_drive
> >  		 * if we have an error, pass back CHECK_CONDITION as the
> >  		 * scsi status byte
> >  		 */
> > -		if (!rq->errors)
> > +		if (blk_pc_request(rq) && !rq->errors)
> >  			rq->errors = SAM_STAT_CHECK_CONDITION;
> >  
> >  		/* Check for tray open. */
> >
> 
> tried it again with this patch (on top of all the other patches).
> overall things are much better than they've been in a long time
> (thanks!), but... when cdparanoia gets stuck, if i abort the process
> and restart it the ripping proceeds very slowly (~5x before, ~1.5x
> after). if i eject/insert the cd and then restart cdparanoia the speed
> is as before (~5x). something doesn't get reset until the cd is
> ejected, don't know if it's the kernel's fault though. same thing
> happens if i get an error reading a sector but then cdparanoia manages
> to recover. from that point on the speed is very slow (again until i
> eject/insert the cd; a new instance of cdparanoia is just as slow).

When cdparanoia gets stuck, how is it stuck? Can you give me a backtrace
of that? If you can abort it, sounds like it isn't stuck in the kernel.

-- 
Jens Axboe

Re: 2.6.19-rc1 (+ide-cd patches) regression: unable to rip cd

[Alex Romosan]

Jens Axboe <jens.axboe@oracle.com> writes:

> When cdparanoia gets stuck, how is it stuck? Can you give me a
> backtrace of that? If you can abort it, sounds like it isn't stuck
> in the kernel.

i don't have my laptop with me but the error message i get in syslog
is somewhere along the lines of (this is copied from the initial bug
report):

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 "

and i assume cdparanoia has problems reading that particular sector
and then it retries and i get similar messages every 5 seconds.
sometimes it recovers from this, at other times it's just stuck there
trying to read the same sector over and over again.

but after i get this message the ripping speed is greatly reduced
until i eject/insert the cd. then the speed goes back to normal. it
doesn't matter if cdparanoia recovers, or if i start a new cdparanoia
process, only if i eject/insert the cd. does this make sense?

--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. |