Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Harald Dunkel]

Hi folks,

Tejun Heo suggested to post my problem here.

If I enter a movie DVD into my drive (Samsung SH-S183A, SATA)
and run xine dvd:/dev/scd0 immediately (while the drive's LED
is still blinking), then there is some timeout problem.
kern.log says:


May  4 19:10:17 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May  4 19:10:17 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xa4 data 8 in
May  4 19:10:17 pluto kernel:          res 40/00:02:00:04:08/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  4 19:10:17 pluto kernel: ata2: soft resetting port
May  4 19:10:24 pluto kernel: ata2: port is slow to respond, please be patient (Status 0xf8)
May  4 19:10:47 pluto kernel: ata2: port failed to respond (30 secs, Status 0xf8)
May  4 19:10:47 pluto kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  4 19:10:47 pluto kernel: ATA: abnormal status 0xF8 on port 0xffffc2000001a0c7
May  4 19:10:47 pluto last message repeated 5 times
May  4 19:11:17 pluto kernel: ata2.00: qc timeout (cmd 0xa1)
May  4 19:11:17 pluto kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
May  4 19:11:17 pluto kernel: ata2.00: revalidation failed (errno=-5)
May  4 19:11:17 pluto kernel: ata2: failed to recover some devices, retrying in 5 secs
May  4 19:11:22 pluto kernel: ata2: hard resetting port
May  4 19:11:23 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  4 19:11:23 pluto kernel: ata2.00: XXX: IDENTIFY
May  4 19:11:23 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 08: 0000 0000 2020 2020  2020 2020 2020 2020
May  4 19:11:23 pluto kernel: 10: 2020 2020 2020 2020  0000 0000 0000 5342
May  4 19:11:23 pluto kernel: 18: 3032 2020 2020 5453  5354 636f 7270 4344
May  4 19:11:23 pluto kernel: 20: 2f44 5644 5720 5348  2d53 3138 3341 2020
May  4 19:11:23 pluto kernel: 28: 2020 2020 2020 2020  2020 2020 2020 0000
May  4 19:11:23 pluto kernel: 30: 0000 0f00 0000 0200  0200 0006 0000 0000
May  4 19:11:23 pluto kernel: 38: 0000 0000 0000 0000  0000 0000 0000 0007
May  4 19:11:23 pluto kernel: 40: 0003 0078 0078 0078  0078 0000 0000 0000
May  4 19:11:23 pluto kernel: 48: 0000 0000 0000 0000  0602 0000 0068 0040
May  4 19:11:23 pluto kernel: 50: 0000 0000 0000 4000  4000 0000 0000 4000
May  4 19:11:23 pluto kernel: 58: 0407 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 60: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 68: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 70: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 78: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 80: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 88: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 90: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: 98: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: a0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: a8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: b0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: b8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: c0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: c8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: d0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: d8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: e0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: e8: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: f0: 0000 0000 0000 0000  0000 0000 0000 0000
May  4 19:11:23 pluto kernel: f8: 0000 0000 0000 0000  0000 0000 0000 9ca5
May  4 19:11:23 pluto kernel: ata2.00: configured for UDMA/33
May  4 19:11:23 pluto kernel: ata2: EH complete


Its pretty much reproducible. For the example above the DVD played
at the end, but sometimes the DVD drive dies, and I have to reboot.

If I enter a data DVD and try to mount it without waiting, then I get

% mount /cdrom
mount: /dev/scd0 already mounted or /cdrom busy
% mount /cdrom
%

There is no message in kern.log in this case. On the second try it
succeeds, as shown above.

If I enter a data DVD without running anything, then it takes
about 15 seconds till the LED goes off. Movie DVDs are a little
bit faster: 12 secs. But I am sure this depends.

Any help would be highly appreciated. Please keep me on CC:; I haven't
subscribed this ML.


Regards

Harri
==========================================================================
Tejun Heo wrote:
> Harald Dunkel wrote:
>> Hi Tejun,
>>
>> Tejun Heo wrote:
>>> The timeout is normal.  As the drive is still trying to recognize the
>>> dvd, it doesn't respond to commands in the time specified by xine or
>>> whatever. 
>> I never saw this before with any other drive.
>>
>>> Interestingly, the drive reports illegal device type after
>>> such event.  Can you please apply the attached patch and report the
>>> dmesg after such failure?
>>>
>>>
>> Here it is:
>>
>> ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
>> ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data
>> 2052 in
>>          res 40/00:02:00:0c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
>> ata2: soft resetting port
>> CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus
>> 113 SControl 310)
>> ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)
>> ata2.00: revalidation failed (errno=-22)
>> ata2.00: disabled
>> ata2: EH complete
> 
> Thanks.
> 
> Can you please apply the attached patch and report this problem to
> linux-ide@vger.kernel.org with the resulting dmesg?   It seems your
> drive reports incorrect IDENTIFY data (maybe due to unflushed FIFO)
> after such timeout event.  I think the timeout itself is probably okay.
>  The drive might just take a tad bit longer than other drives (how long
> do you have to wait?).
> 
> Thanks.
> 
> 

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

[-- Attachment #1: Type: text/plain, Size: 4165 bytes --]

Hello, Harald.

Harald Dunkel wrote:
> If I enter a movie DVD into my drive (Samsung SH-S183A, SATA)
> and run xine dvd:/dev/scd0 immediately (while the drive's LED
> is still blinking), then there is some timeout problem.
> kern.log says:
> 
> May  4 19:10:17 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr
> 0x0 action 0x2 frozen
> May  4 19:10:17 pluto kernel: ata2.00: cmd
> a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xa4 data 8 in
> May  4 19:10:17 pluto kernel:          res
> 40/00:02:00:04:08/00:00:00:00:00/a0 Emask 0x4 (timeout)
> May  4 19:10:17 pluto kernel: ata2: soft resetting port
> May  4 19:10:24 pluto kernel: ata2: port is slow to respond, please be
> patient (Status 0xf8)
> May  4 19:10:47 pluto kernel: ata2: port failed to respond (30 secs,
> Status 0xf8)
> May  4 19:10:47 pluto kernel: ata2: SATA link up 1.5 Gbps (SStatus 113
> SControl 310)
> May  4 19:10:47 pluto kernel: ATA: abnormal status 0xF8 on port
> 0xffffc2000001a0c7
> May  4 19:10:47 pluto last message repeated 5 times
> May  4 19:11:17 pluto kernel: ata2.00: qc timeout (cmd 0xa1)
> May  4 19:11:17 pluto kernel: ata2.00: failed to IDENTIFY (I/O error,
> err_mask=0x4)
> May  4 19:11:17 pluto kernel: ata2.00: revalidation failed (errno=-5)
> May  4 19:11:17 pluto kernel: ata2: failed to recover some devices,
> retrying in 5 secs
> May  4 19:11:22 pluto kernel: ata2: hard resetting port
> May  4 19:11:23 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
> SATA link up 1.5 Gbps (SStatus 113 SControl 310)
> May  4 19:11:23 pluto kernel: ata2.00: XXX: IDENTIFY
> May  4 19:11:23 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
[--snip--]
> May  4 19:11:23 pluto kernel: ata2.00: configured for UDMA/33
> May  4 19:11:23 pluto kernel: ata2: EH complete

The above is slightly different from the last one in that the device
times out the following IDENTIFY command instead of sending corrupt
data.  The last log looked like...

 ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
 ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
          res 40/00:02:00:0c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
 ata2: soft resetting port
 CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
 ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)
 ata2.00: revalidation failed (errno=-22)
 ata2.00: disabled
 ata2: EH complete

Note how the device is offlined after the error because it reported
the wrong IDENTIFY data wheras IDENTIFY timeout was recovered properly
(you can still access the device after the EH is complete).

> Its pretty much reproducible. For the example above the DVD played
> at the end, but sometimes the DVD drive dies, and I have to reboot.
> 
> If I enter a data DVD and try to mount it without waiting, then I get
> 
> % mount /cdrom
> mount: /dev/scd0 already mounted or /cdrom busy
> % mount /cdrom
> %
> 
> There is no message in kern.log in this case. On the second try it
> succeeds, as shown above.

This is probably because xine is opening the dvd device with
O_NONBLOCK set.  That tells the cdrom driver to skip
readiness/integrity check.  If it sets O_NONBLOCK, it's the
application's responsibility to perform readiness check but it seems
xine skips that and just issue REPORT KEY, which times out as the
device takes more time to recognize the media than the specified
timeout and kicks EH into action.

Please report the result of...

$ strace xine <whatever you need to play dvd> > out 2>&1

> If I enter a data DVD without running anything, then it takes
> about 15 seconds till the LED goes off. Movie DVDs are a little
> bit faster: 12 secs. But I am sure this depends.

I think the waiting itself isn't a bug in the driver.  It seems that
the particular device needs a tad bit more time to recognize what's in
it and xine seems to be not testing for device readiness before
issuing other commands (needs verification tho).

What I'm primarily concerned about is the device getting disabled due
to corrupt IDENTIFY data.  Can you test whether the attached patch
fixes the device disabling?

Thanks.

-- 
tejun

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: give-one-last-chance-on-EINVAL.patch --]
[-- Type: text/x-patch; name="give-one-last-chance-on-EINVAL.patch", Size: 0 bytes --]

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Harald Dunkel]

Hi Tejun,

Your last patch contained zero bytes. Please check.

Tejun Heo wrote:
> 
> Please report the result of...
> 
> $ strace xine <whatever you need to play dvd> > out 2>&1
> 

out.gz is >400KByte compressed. See private EMail. Below is
the output in kern.log. This time it is the correct output
(hopefully). After this the drive was unaccessible.


Regards

Harri
=============================================================
May  7 20:16:10 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May  7 20:16:10 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
May  7 20:16:10 pluto kernel:          res 40/00:00:00:10:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  7 20:16:10 pluto kernel: ata2: soft resetting port
May  7 20:16:10 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  7 20:16:10 pluto kernel: ata2.00: XXX: IDENTIFY
May  7 20:16:10 pluto kernel: 00: 6d58 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: 08: 35e8 5e2c c8b8 0c15  b87e 15c8 7e0c c8b8
May  7 20:16:10 pluto kernel: 10: 0c15 b87e 15c8 7e0c  e898 2c35 985e 66aa
May  7 20:16:10 pluto kernel: 18: 6e1e c8b8 0c15 cc0d  66bc 3d43 9ae8 6f71
May  7 20:16:10 pluto kernel: 20: b71a 63ac 090c bbd0  0166 a966 06a9 7e0c
May  7 20:16:10 pluto kernel: 28: c8b8 0c15 b87e 15c8  7e0c c8b8 0c15 985e
May  7 20:16:10 pluto kernel: 30: 35e8 512c e898 2e35  9a5e 35ee 5e2c e898
May  7 20:16:10 pluto kernel: 38: 2c35 985e 35e8 5e2c  e898 2c35 985e 35ef
May  7 20:16:10 pluto kernel: 40: 5e2f e8e0 2c4d 9826  3590 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 48: 985e 35e8 5e2c e898  2a37 985e 3580 5e6c
May  7 20:16:10 pluto kernel: 50: e898 2c35 985e 75e8  1e2c e898 2c35 d85e
May  7 20:16:10 pluto kernel: 58: 31ef 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: 60: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: 68: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 70: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: 78: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: 80: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: 88: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: 90: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: 98: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: a0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: a8: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: b0: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: b8: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: c0: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: c8: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: d0: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
May  7 20:16:10 pluto kernel: d8: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
May  7 20:16:10 pluto kernel: e0: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
May  7 20:16:10 pluto kernel: e8: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
May  7 20:16:10 pluto kernel: f0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
May  7 20:16:10 pluto kernel: f8: 35e8 5e2c e898 2c35  985e 35e8 5e2c 743d
May  7 20:16:10 pluto kernel: ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)
May  7 20:16:10 pluto kernel: ata2.00: revalidation failed (errno=-22)
May  7 20:16:10 pluto kernel: ata2.00: disabled
May  7 20:16:11 pluto kernel: ata2: EH complete
May  7 20:16:11 pluto kernel: cdrom: This disc doesn't have any tracks I recognize!
May  7 20:16:48 pluto kernel: Buffer I/O error on device sr0, logical block 0
May  7 20:16:48 pluto kernel: Buffer I/O error on device sr0, logical block 1
:
:

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

[-- Attachment #1: Type: text/plain, Size: 3900 bytes --]

Harald Dunkel wrote:
> Hi Tejun,
> 
> Your last patch contained zero bytes. Please check.

Sorry, new patch attached.

> Tejun Heo wrote:
>>
>> Please report the result of...
>>
>> $ strace xine <whatever you need to play dvd> > out 2>&1
>>
> 
> out.gz is >400KByte compressed. See private EMail. Below is
> the output in kern.log. This time it is the correct output
> (hopefully). After this the drive was unaccessible.

Thanks.  xine was opening it the regular way.  Can't tell why it times
out.  :(

> =============================================================
> May  7 20:16:10 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr
> 0x0 action 0x2 frozen
> May  7 20:16:10 pluto kernel: ata2.00: cmd
> a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
> May  7 20:16:10 pluto kernel:          res
> 40/00:00:00:10:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
> May  7 20:16:10 pluto kernel: ata2: soft resetting port
> May  7 20:16:10 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
> SATA link up 1.5 Gbps (SStatus 113 SControl 310)
> May  7 20:16:10 pluto kernel: ata2.00: XXX: IDENTIFY
> May  7 20:16:10 pluto kernel: 00: 6d58 2c35 985e 35e8  5e2c e898 2c35 985e
> May  7 20:16:10 pluto kernel: 08: 35e8 5e2c c8b8 0c15  b87e 15c8 7e0c c8b8
> May  7 20:16:10 pluto kernel: 10: 0c15 b87e 15c8 7e0c  e898 2c35 985e 66aa
> May  7 20:16:10 pluto kernel: 18: 6e1e c8b8 0c15 cc0d  66bc 3d43 9ae8 6f71
> May  7 20:16:10 pluto kernel: 20: b71a 63ac 090c bbd0  0166 a966 06a9 7e0c
> May  7 20:16:10 pluto kernel: 28: c8b8 0c15 b87e 15c8  7e0c c8b8 0c15 985e
> May  7 20:16:10 pluto kernel: 30: 35e8 512c e898 2e35  9a5e 35ee 5e2c e898
> May  7 20:16:10 pluto kernel: 38: 2c35 985e 35e8 5e2c  e898 2c35 985e 35ef
> May  7 20:16:10 pluto kernel: 40: 5e2f e8e0 2c4d 9826  3590 5e2c e898 2c35
> May  7 20:16:10 pluto kernel: 48: 985e 35e8 5e2c e898  2a37 985e 3580 5e6c
> May  7 20:16:10 pluto kernel: 50: e898 2c35 985e 75e8  1e2c e898 2c35 d85e
> May  7 20:16:10 pluto kernel: 58: 31ef 5e2c e898 2c35  985e 35e8 5e2c e898
> May  7 20:16:10 pluto kernel: 60: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
> May  7 20:16:10 pluto kernel: 68: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
> May  7 20:16:10 pluto kernel: 70: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
> May  7 20:16:10 pluto kernel: 78: e898 2c35 985e 35e8  5e2c e898 2c35 985e
> May  7 20:16:10 pluto kernel: 80: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
> May  7 20:16:10 pluto kernel: 88: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
> May  7 20:16:10 pluto kernel: 90: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
> May  7 20:16:10 pluto kernel: 98: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
> May  7 20:16:10 pluto kernel: a0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
> May  7 20:16:10 pluto kernel: a8: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
> May  7 20:16:10 pluto kernel: b0: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
> May  7 20:16:10 pluto kernel: b8: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
> May  7 20:16:10 pluto kernel: c0: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
> May  7 20:16:10 pluto kernel: c8: e898 2c35 985e 35e8  5e2c e898 2c35 985e
> May  7 20:16:10 pluto kernel: d0: 35e8 5e2c e898 2c35  985e 35e8 5e2c e898
> May  7 20:16:10 pluto kernel: d8: 2c35 985e 35e8 5e2c  e898 2c35 985e 35e8
> May  7 20:16:10 pluto kernel: e0: 5e2c e898 2c35 985e  35e8 5e2c e898 2c35
> May  7 20:16:10 pluto kernel: e8: 985e 35e8 5e2c e898  2c35 985e 35e8 5e2c
> May  7 20:16:10 pluto kernel: f0: e898 2c35 985e 35e8  5e2c e898 2c35 985e
> May  7 20:16:10 pluto kernel: f8: 35e8 5e2c e898 2c35  985e 35e8 5e2c 743d
> May  7 20:16:10 pluto kernel: ata2.00: failed to IDENTIFY (device

Yeap, this is what I was talking about.  The whole IDENTIFY area seems
to contain repeating pattern.  Probably something to do with unflushed
FIFO.  The attached patch should allow EH to recover properly from this.
 Please test.

Thanks.

-- 
tejun

[-- Attachment #2: give-one-last-chance-on-EINVAL.patch --]
[-- Type: text/x-patch, Size: 624 bytes --]

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 2bff9ad..82b212f 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2177,14 +2177,10 @@ static int ata_eh_recover(struct ata_por
 	ehc->tries[dev->devno]--;
 
 	switch (rc) {
-	case -EINVAL:
-		/* eeek, something went very wrong, give up */
-		ehc->tries[dev->devno] = 0;
-		break;
-
 	case -ENODEV:
 		/* device missing or wrong IDENTIFY data, schedule probing */
 		ehc->i.probe_mask |= (1 << dev->devno);
+	case -EINVAL:
 		/* give it just one more chance */
 		ehc->tries[dev->devno] = min(ehc->tries[dev->devno], 1);
 	case -EIO:

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Harald Dunkel]

Hi Tejun,

Sorry to say, but after applying your patch it still doesn't work.

If I insert the DVD and wait before running xine, then I can watch
it. But if I keep the tray open and run xine, then xine closes
the tray. It gets stuck for some time, and then I get

% xine dvd:/dev/scd0
This is xine (X11 gui) - a free video player v0.99.5cvs.
(c) 2000-2006 The xine Team.
libdvdread: Using libdvdcss version 1.2.9 for DVD access
libdvdread: Could not open /dev/scd0 with libdvdcss.
libdvdread: Can't open /dev/scd0 for reading


kern.log says:

May  9 19:11:57 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May  9 19:11:57 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xa4 data 12 in
May  9 19:11:57 pluto kernel:          res 40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May  9 19:11:57 pluto kernel: ata2: soft resetting port
May  9 19:12:05 pluto kernel: ata2: port is slow to respond, please be patient (Status 0xf8)
May  9 19:12:28 pluto kernel: ata2: port failed to respond (30 secs, Status 0xf8)
May  9 19:12:28 pluto kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  9 19:12:28 pluto kernel: ATA: abnormal status 0xF8 on port 0xffffc2000001a0c7
May  9 19:12:28 pluto last message repeated 5 times
May  9 19:12:58 pluto kernel: ata2.00: qc timeout (cmd 0xa1)
May  9 19:12:58 pluto kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
May  9 19:12:58 pluto kernel: ata2.00: revalidation failed (errno=-5)
May  9 19:12:58 pluto kernel: ata2: failed to recover some devices, retrying in 5 secs
May  9 19:13:03 pluto kernel: ata2: hard resetting port
May  9 19:13:03 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May  9 19:13:03 pluto kernel: ata2.00: XXX: IDENTIFY
May  9 19:13:03 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 08: 0000 0000 2020 2020  2020 2020 2020 2020
May  9 19:13:03 pluto kernel: 10: 2020 2020 2020 2020  0000 0000 0000 5342
May  9 19:13:03 pluto kernel: 18: 3032 2020 2020 5453  5354 636f 7270 4344
May  9 19:13:03 pluto kernel: 20: 2f44 5644 5720 5348  2d53 3138 3341 2020
May  9 19:13:03 pluto kernel: 28: 2020 2020 2020 2020  2020 2020 2020 0000
May  9 19:13:03 pluto kernel: 30: 0000 0f00 0000 0200  0200 0006 0000 0000
May  9 19:13:03 pluto kernel: 38: 0000 0000 0000 0000  0000 0000 0000 0007
May  9 19:13:03 pluto kernel: 40: 0003 0078 0078 0078  0078 0000 0000 0000
May  9 19:13:03 pluto kernel: 48: 0000 0000 0000 0000  0602 0000 0068 0040
May  9 19:13:03 pluto kernel: 50: 0000 0000 0000 4000  4000 0000 0000 4000
May  9 19:13:03 pluto kernel: 58: 0407 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 60: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 68: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 70: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 78: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 80: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 88: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 90: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: 98: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: a0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: a8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: b0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: b8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: c0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: c8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: d0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: d8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: e0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: e8: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: f0: 0000 0000 0000 0000  0000 0000 0000 0000
May  9 19:13:03 pluto kernel: f8: 0000 0000 0000 0000  0000 0000 0000 9ca5
May  9 19:13:04 pluto kernel: ata2.00: configured for UDMA/33
May  9 19:13:04 pluto kernel: ata2: EH complete


After that (the DVD is still in) I can rerun xine, and it works.
This is reproducible using CSS DVDs. Using a DVD without CSS there
is no such problem. It takes some time till the DVD is played,
but there is no soft reset.

Using "gmplayer dvd://" I get the same problem.


You told me some time ago that you bought the same drive. Can you
reproduce this problem? Please don't get me wrong, I am glad to
support you by trying out new patches.


Regards

Harri

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

[-- Attachment #1: Type: text/plain, Size: 2111 bytes --]

Hello,

Harald Dunkel wrote:
> Hi Tejun,
> 
> Sorry to say, but after applying your patch it still doesn't work.
> 
> If I insert the DVD and wait before running xine, then I can watch
> it. But if I keep the tray open and run xine, then xine closes
> the tray. It gets stuck for some time, and then I get
> 
> % xine dvd:/dev/scd0
> This is xine (X11 gui) - a free video player v0.99.5cvs.
> (c) 2000-2006 The xine Team.
> libdvdread: Using libdvdcss version 1.2.9 for DVD access
> libdvdread: Could not open /dev/scd0 with libdvdcss.
> libdvdread: Can't open /dev/scd0 for reading
> 
> 
> kern.log says:
[--snip--]
> May  9 19:13:04 pluto kernel: ata2.00: configured for UDMA/33
> May  9 19:13:04 pluto kernel: ata2: EH complete

The patch wasn't trying to fix the original problem.  All it does it
making sure the device itself doesn't get disabled after such an event -
/dev/sr0 should be accessible even after garbled IDENTIFY.  Can you try
to trigger the condition where the device reports garbled IDENTIFY data
and says...

ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)

Without the patch, the device will be offlined so you can't use it
anymore unless you issue manual rescan or unplug and replug the device.
 With the patch, you should be able to access the device after EH is
complete.

> After that (the DVD is still in) I can rerun xine, and it works.
> This is reproducible using CSS DVDs. Using a DVD without CSS there
> is no such problem. It takes some time till the DVD is played,
> but there is no soft reset.
> 
> Using "gmplayer dvd://" I get the same problem.
>
> You told me some time ago that you bought the same drive. Can you
> reproduce this problem? Please don't get me wrong, I am glad to
> support you by trying out new patches.

I'd love to but I'm half globe away from my toys at the moment and not
going back till the end of this month, so....  If this isn't resolved
till I get back, I'll test myself.

It still could be that the dvd reading commands are issued with too
short timeout.  Does applying the attached patch make any difference?

-- 
tejun

[-- Attachment #2: lengthen-cdrom-timeout.patch --]
[-- Type: text/x-patch, Size: 498 bytes --]

diff --git a/drivers/cdrom/cdrom.c b/drivers/cdrom/cdrom.c
index 3625a05..e404464 100644
--- a/drivers/cdrom/cdrom.c
+++ b/drivers/cdrom/cdrom.c
@@ -341,7 +341,7 @@ static const char *mrw_address_space[] =
  * Another popular OS uses 7 seconds as the hard timeout for default
  * commands, so it is a good choice for us as well.
  */
-#define CDROM_DEF_TIMEOUT	(7 * HZ)
+#define CDROM_DEF_TIMEOUT	(15 * HZ)
 
 /* Not-exported routines. */
 static int open_for_data(struct cdrom_device_info * cdi);

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Harald Dunkel]

Hi Tejun,

Setting the timeout to 15 did not help, either :-(. All your patches
are still in, of course.


Regards

Harri
=======================================================================
kern.log says:

May 10 22:15:55 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
May 10 22:15:55 pluto kernel: ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
May 10 22:15:55 pluto kernel:          res 40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
May 10 22:15:55 pluto kernel: ata2: soft resetting port
May 10 22:15:55 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May 10 22:15:55 pluto kernel: ata2.00: XXX: IDENTIFY
May 10 22:15:55 pluto kernel: 00: 3b38 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: 08: edbe 8013 9ed8 33cd  d8a0 cd9e a033 9ed8
May 10 22:15:55 pluto kernel: 10: 33cd d8a0 cd9e a033  bef8 13ed f880 befc
May 10 22:15:55 pluto kernel: 18: b021 9ed8 33cd acd3  beea e37c cc88 50a9
May 10 22:15:55 pluto kernel: 20: d7c4 bbfa d733 edb0  3ebe c9b8 deff a033
May 10 22:15:55 pluto kernel: 28: 9ed8 33cd d8a0 cd9e  a033 9ed8 33cd f880
May 10 22:15:55 pluto kernel: 30: edbe 8f13 bef8 11ed  fa80 edb8 8013 bef8
May 10 22:15:55 pluto kernel: 38: 13ed f880 edbe 8013  bef8 13ed f880 edb9
May 10 22:15:55 pluto kernel: 40: 8010 be80 1395 f8f8  edc6 8013 bef8 13ed
May 10 22:15:55 pluto kernel: 48: f880 edbe 8013 bef8  15ef f880 edd6 8053
May 10 22:15:55 pluto kernel: 50: bef8 13ed f880 adbe  c013 bef8 13ed b880
May 10 22:15:55 pluto kernel: 58: e9b9 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: 60: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: 68: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: 70: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: 78: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: 80: edbe 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: 88: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: 90: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: 98: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: a0: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: a8: edbe 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: b0: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: b8: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: c0: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: c8: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: d0: edbe 8013 bef8 13ed  f880 edbe 8013 bef8
May 10 22:15:55 pluto kernel: d8: 13ed f880 edbe 8013  bef8 13ed f880 edbe
May 10 22:15:55 pluto kernel: e0: 8013 bef8 13ed f880  edbe 8013 bef8 13ed
May 10 22:15:55 pluto kernel: e8: f880 edbe 8013 bef8  13ed f880 edbe 8013
May 10 22:15:55 pluto kernel: f0: bef8 13ed f880 edbe  8013 bef8 13ed f880
May 10 22:15:55 pluto kernel: f8: edbe 8013 bef8 13ed  f880 edbe 8013 225d
May 10 22:15:55 pluto kernel: ata2.00: failed to IDENTIFY (device reports illegal type, err_mask=0x0)
May 10 22:15:55 pluto kernel: ata2.00: revalidation failed (errno=-22)
May 10 22:15:55 pluto kernel: ata2.00: limiting speed to UDMA/33:PIO3
May 10 22:15:55 pluto kernel: ata2: failed to recover some devices, retrying in 5 secs
May 10 22:16:00 pluto kernel: ata2: hard resetting port
May 10 22:16:01 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
May 10 22:16:01 pluto kernel: ata2.00: XXX: IDENTIFY
May 10 22:16:01 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 08: 0000 0000 2020 2020  2020 2020 2020 2020
May 10 22:16:01 pluto kernel: 10: 2020 2020 2020 2020  0000 0000 0000 5342
May 10 22:16:01 pluto kernel: 18: 3032 2020 2020 5453  5354 636f 7270 4344
May 10 22:16:01 pluto kernel: 20: 2f44 5644 5720 5348  2d53 3138 3341 2020
May 10 22:16:01 pluto kernel: 28: 2020 2020 2020 2020  2020 2020 2020 0000
May 10 22:16:01 pluto kernel: 30: 0000 0f00 0000 0200  0200 0006 0000 0000
May 10 22:16:01 pluto kernel: 38: 0000 0000 0000 0000  0000 0000 0000 0007
May 10 22:16:01 pluto kernel: 40: 0003 0078 0078 0078  0078 0000 0000 0000
May 10 22:16:01 pluto kernel: 48: 0000 0000 0000 0000  0602 0000 0068 0040
May 10 22:16:01 pluto kernel: 50: 0000 0000 0000 4000  4000 0000 0000 4000
May 10 22:16:01 pluto kernel: 58: 0407 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 60: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 68: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 70: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 78: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 80: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 88: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 90: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: 98: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: a0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: a8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: b0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: b8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: c0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: c8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: d0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: d8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: e0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: e8: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: f0: 0000 0000 0000 0000  0000 0000 0000 0000
May 10 22:16:01 pluto kernel: f8: 0000 0000 0000 0000  0000 0000 0000 9ca5
May 10 22:16:01 pluto kernel: ata2.00: configured for UDMA/33
May 10 22:16:01 pluto kernel: ata2: EH complete

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

Hello,

Harald Dunkel wrote:
> Hi Tejun,
> 
> Setting the timeout to 15 did not help, either :-(. All your patches
> are still in, of course.

Hmm... I'm out of ideas.  I'll try it when I get back home.

> May 10 22:15:55 pluto kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr
> 0x0 action 0x2 frozen
> May 10 22:15:55 pluto kernel: ata2.00: cmd
> a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xad data 2052 in
> May 10 22:15:55 pluto kernel:          res
> 40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
> May 10 22:15:55 pluto kernel: ata2: soft resetting port
> May 10 22:15:55 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
> SATA link up 1.5 Gbps (SStatus 113 SControl 310)
> May 10 22:15:55 pluto kernel: ata2.00: XXX: IDENTIFY
> May 10 22:15:55 pluto kernel: 00: 3b38 13ed f880 edbe  8013 bef8 13ed f880
[--snip--]
> May 10 22:15:55 pluto kernel: ata2.00: failed to IDENTIFY (device
> reports illegal type, err_mask=0x0)
> May 10 22:15:55 pluto kernel: ata2.00: revalidation failed (errno=-22)
> May 10 22:15:55 pluto kernel: ata2.00: limiting speed to UDMA/33:PIO3
> May 10 22:15:55 pluto kernel: ata2: failed to recover some devices,
> retrying in 5 secs
> May 10 22:16:00 pluto kernel: ata2: hard resetting port
> May 10 22:16:01 pluto kernel: CLASSIFY TF 00/01:01:01:14:eb/a0 <6>ata2:
> SATA link up 1.5 Gbps (SStatus 113 SControl 310)
> May 10 22:16:01 pluto kernel: ata2.00: XXX: IDENTIFY
> May 10 22:16:01 pluto kernel: 00: 85c0 0000 0000 0000  0000 0000 0000 0000
[--snip--]
> May 10 22:16:01 pluto kernel: ata2.00: configured for UDMA/33
> May 10 22:16:01 pluto kernel: ata2: EH complete

Well, at least one thing worked.  I'll push the patch upstream soon.

Thanks.

-- 
tejun

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Harald Dunkel]

Hi Tejun,

Tejun Heo wrote:
> Hello,
> 
> Harald Dunkel wrote:
>> Hi Tejun,
>>
>> Setting the timeout to 15 did not help, either :-(. All your patches
>> are still in, of course.
> 
> Hmm... I'm out of ideas.  I'll try it when I get back home.
> 

I think I will survive for the next few days.

>> May 10 22:16:01 pluto kernel: ata2.00: configured for UDMA/33
>> May 10 22:16:01 pluto kernel: ata2: EH complete
> 
> Well, at least one thing worked.  I'll push the patch upstream soon.
> 

This was indeed a huge improvement. Before this patch I had
to reboot to wake up the DVD drive.


Many thanx

Harri

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Harald Dunkel]

Hi Tejun,

Tejun Heo wrote:
> Hello,
> 
> Harald Dunkel wrote:
>> Hi Tejun,
>>
>> Setting the timeout to 15 did not help, either :-(. All your patches
>> are still in, of course.
> 
> Hmm... I'm out of ideas.  I'll try it when I get back home.
> 

Any news about this? At the end I had the impression that this is
a bug in the chip design. Is this correct?

Is there any chance to get the 60-byte patch into the kernel?


Regards

Harri

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

Harald Dunkel wrote:
>> Harald Dunkel wrote:
>>> Hi Tejun,
>>>
>>> Setting the timeout to 15 did not help, either :-(. All your patches
>>> are still in, of course.
>>
>> Hmm... I'm out of ideas.  I'll try it when I get back home.
>>
> 
> Any news about this? At the end I had the impression that this is
> a bug in the chip design. Is this correct?

I can't reproduce that with sil3112 and the same SH-S183A.  I don't know
what's going on here.  Mine behaves really good but yours seems to be
causing all sorts of problems.

> Is there any chance to get the 60-byte patch into the kernel?

We still don't know what's going on so....

-- 
tejun

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Daniel Beichl]

[-- Attachment #1: Type: text/plain, Size: 3844 bytes --]

Tejun Heo wrote:
> Daniel Beichl wrote:
>   
>> I reverted to my initial patch and added a printk line to log the first
>> command byte and
>> qc->nbytes for each command that has been reduced to pio and
>> authenticated a dvd:
>>
>> not Authenticated
>> ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
>> Request AGID [1]...     AGID 3
>> Host sending challenge:  68 96 40 A8 F2 1A 66 ED A9 33
>> ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
>> ata2.00: Reduce cmd 0xa3 (nbytes=0) to pio
>> LU sent key1:  65 A0 60 C5 22
>> Drive Authentic - using varient 0
>> ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
>> LU sent challenge:  D8 D1 AA A6 45 A8 40 33 1C CB
>> Host sending key 2:  A7 90 93 04 B6
>> ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
>> DVD is authenticated
>> Received Session Key:   7C A0 0F E9 E2
>> ata2.00: Reduce cmd 0xa3 (nbytes=0) to pio
>> not Authenticated
>> ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
>> Received Disc Key:      55 43 42 B3 C5 FB 6A 00 46 39
>> Authenticated
>> ata2.00: Reduce cmd 0xa4 (nbytes=0) to pio
>>
>> As you can see, every command had a qc->nbytes of zero,
>> therefore your code would have allowed dma transfer as "(0 & 511) != 0"
>> is false(0)
>> and returning 0 allows dma.
>>
>> I wonder why these commands have a nbytes of zero, perhaps its the
>> amount of data sectors transferred? I have searched
>> the libata documentation pdf and did a quick google search, but i
>> didn't come up with anything useful.
>> So your suggestion would work if you say size is not aligned to
>> ATA_SECT_SIZE or zero, i.e:
>>
>> /* returning 0 allows dma everything else does not */
>> return ((qc->nbytes & (ATA_SECT_SIZE-1)) || (qc->nbytes == 0));
>>
>> But why do you think this should be dependent on the qc->nbytes attribute
>> as the authentification commands all have nbytes set to zero?
>> Are you aware of some other issues with this sata controller?
>>
>> It would be great to drill this down further, but i have no clue how to
>> continue. If you have any suggestions please let me know.
>>     
>
> Okay, I've been thinking about it for some time.  I think I know what's
> going on now.  Those authentication related commands are issued by
> invoking ioctls on the device node.  The cdrom driver receives the
> ioctls and issues respective SCSI commands for it.  All those DVD auth
> commands either transfer or receive data from the device and thus
> specifies certain data direction when they're issued.  libata selects
> command protocol accordingly.
>
> It's all good and dandy till now but the problem is that those commands
> can be issued with data length of zero!  This is allowed by the SCSI MMC
> standard and used to probe whether the command succeeds or not before
> taking further actions.  When this happens, libata chooses command
> protocol according to the data direction, but has to feed 0-length data
> to the DMA engine.  It seems sata_sil dma engine barfs if that happens.
>  Can you please add the following code snippet at the head of atapi_xlat()?
>
> 	if (!nodata && !qc->nbytes) {
> 		printk("XXX forcing PIO for 0 length data cdb %02x\n",
> 			scmd->cmnd[0]);
> 		dump_stack();
> 		using_pio = 1;
> 	}
>
> Also, do you mind cc'ing linux-ide@vger.kernel.org?
>
>   
Hi Tejun,


i inserted the code snippet you mentioned to atapi_xlat() in libata-scsi.c
and the dvd authentication succeeds.

Please see the attached dmesg file for the generated stack dumps.

The question is whether this is the right place to fix it, as this seems 
to limit all
drivers to pio if a zero data length command is transferred.
It would make more sense to me if the individual driver decides this by
performing a similar check in the check_atapi_dma function implemented 
by the
individual driver. I did this for the sata_sil driver in the attached patch.

Thanks for sharing your insight,

Daniel

[-- Attachment #2: dmesg --]
[-- Type: text/plain, Size: 30299 bytes --]

.c: subsystem: 01297:a550 bound to 0000:00:05.0
ACPI: PCI Interrupt Link [LNK2] enabled at IRQ 11
PCI: setting IRQ 11 as level-triggered
ACPI: PCI Interrupt 0000:01:05.0[A] -> Link [LNK2] -> GSI 11 (level, low) -> IRQ 11
sym0: <875> rev 0x26 at pci 0000:01:05.0 irq 11
ACPI: PCI Interrupt Link [LUB2] enabled at IRQ 9
PCI: setting IRQ 9 as level-triggered
ACPI: PCI Interrupt 0000:00:02.2[C] -> Link [LUB2] -> GSI 9 (level, low) -> IRQ 9
PCI: Setting latency timer of device 0000:00:02.2 to 64
ehci_hcd 0000:00:02.2: EHCI Host Controller
ehci_hcd 0000:00:02.2: new USB bus registered, assigned bus number 1
ehci_hcd 0000:00:02.2: debug port 1
PCI: cache line size of 64 is not supported by device 0000:00:02.2
ehci_hcd 0000:00:02.2: irq 9, io mem 0xe8005000
ehci_hcd 0000:00:02.2: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
usb usb1: configuration #1 chosen from 1 choice
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 6 ports detected
sym0: Tekram NVRAM, ID 7, Fast-20, SE, parity checking
sym0: SCSI BUS has been reset.
scsi2 : sym-2.2.3
usb 1-2: new high speed USB device using ehci_hcd and address 3
usb 1-2: configuration #1 chosen from 1 choice
hub 1-2:1.0: USB hub found
hub 1-2:1.0: 4 ports detected
usb 1-3: new high speed USB device using ehci_hcd and address 4
usb 1-3: configuration #1 chosen from 1 choice
usb 1-2.1: new high speed USB device using ehci_hcd and address 5
usb 1-2.1: configuration #1 chosen from 1 choice
ACPI: PCI Interrupt Link [LUBA] enabled at IRQ 9
ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [LUBA] -> GSI 9 (level, low) -> IRQ 9
PCI: Setting latency timer of device 0000:00:02.0 to 64
ohci_hcd 0000:00:02.0: OHCI Host Controller
ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2
ohci_hcd 0000:00:02.0: irq 9, io mem 0xe8003000
usb usb2: configuration #1 chosen from 1 choice
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 3 ports detected
ACPI: PCI Interrupt Link [LUBB] enabled at IRQ 9
ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [LUBB] -> GSI 9 (level, low) -> IRQ 9
PCI: Setting latency timer of device 0000:00:02.1 to 64
ohci_hcd 0000:00:02.1: OHCI Host Controller
ohci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 3
ohci_hcd 0000:00:02.1: irq 9, io mem 0xe8004000
Initializing USB Mass Storage driver...
ieee80211_crypt: registered algorithm 'NULL'
usb usb3: configuration #1 chosen from 1 choice
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 3 ports detected
ieee80211: 802.11 data/management/control stack, git-1.1.13
ieee80211: Copyright (C) 2004-2005 Intel Corporation <jketreno@linux.intel.com>
scsi3 : SCSI emulation for USB Mass Storage devices
usb-storage: device found at 4
usb-storage: waiting for device to settle before scanning
i2c_adapter i2c-0: nForce2 SMBus adapter at 0x4c00
i2c_adapter i2c-1: nForce2 SMBus adapter at 0x4c40
ACPI: PCI Interrupt Link [LNK3] enabled at IRQ 3
PCI: setting IRQ 3 as level-triggered
ACPI: PCI Interrupt 0000:01:06.0[A] -> Link [LNK3] -> GSI 3 (level, low) -> IRQ 3
ohci1394: fw-host0: OHCI-1394 1.0 (PCI): IRQ=[3]  MMIO=[e7002000-e70027ff]  Max Packet=[2048]  IR/IT contexts=[4/8]
ACPI: PCI Interrupt Link [LNK5] enabled at IRQ 14
PCI: setting IRQ 14 as level-triggered
ACPI: PCI Interrupt 0000:02:00.0[A] -> Link [LNK5] -> GSI 14 (level, low) -> IRQ 14
radeonfb: Found Intel x86 BIOS ROM Image
radeonfb: Retrieved PLL infos from BIOS
radeonfb: Reference=27.00 MHz (RefDiv=12) Memory=250.00 Mhz, System=200.00 MHz
radeonfb: PLL min 20000 max 40000
usb 2-1: new low speed USB device using ohci_hcd and address 2
usb 2-1: configuration #1 chosen from 1 choice
usbcore: registered new interface driver usb-storage
USB Mass Storage support registered.
radeonfb: Monitor 1 type DFP found
radeonfb: EDID probed
radeonfb: Monitor 2 type CRT found
radeonfb: EDID probed
Console: switching to colour frame buffer device 160x64
radeonfb (0000:02:00.0): ATI Radeon Ya 
usb 1-2.1: reset high speed USB device using ehci_hcd and address 5
zd1211rw 1-2.1:1.0: firmware version 4725
zd1211rw 1-2.1:1.0: zd1211b chip 0586:340f v4810 high 00-13-49 AL2230_RF pa0 g---
zd1211rw 1-2.1:1.0: eth1
usbcore: registered new interface driver zd1211rw
input: Logitech USB Mouse as /class/input/input2
usbcore: registered new interface driver usbmouse
drivers/usb/input/usbmouse.c: v1.6:USB HID Boot Protocol mouse driver
usbcore: registered new interface driver hiddev
usbcore: registered new interface driver usbhid
drivers/usb/input/hid-core.c: v2.6:USB HID core driver
ieee1394: Host added: ID:BUS[0-00:1023]  GUID[00301bb10000d279]
eth1394: eth1: IEEE-1394 IPv4 over 1394 Ethernet (fw-host0)
EXT3 FS on sda2, internal journal
usbcore: registered new interface driver usbkbd
drivers/usb/input/usbkbd.c: :USB HID Boot Protocol keyboard driver
powernow-k8: Found 1 AMD Athlon(tm) 64 Processor 3000+ processors (version 2.00.00)
powernow-k8:    0 : fid 0xc (2000 MHz), vid 0x2
powernow-k8:    1 : fid 0xa (1800 MHz), vid 0x6
powernow-k8:    2 : fid 0x0 (800 MHz), vid 0xa
it87: Found IT8712F chip at 0x290, revision 5
device-mapper: ioctl: 4.11.0-ioctl (2006-10-12) initialised: dm-devel@redhat.com
fuse init (API version 7.8)
kjournald starting.  Commit interval 5 seconds
EXT3 FS on sda3, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
scsi 3:0:0:0: Direct-Access     USB2.0   CardReader CF RW 0.0> PQ: 0 ANSI: 0
sd 3:0:0:0: Attached scsi removable disk sdb
sd 3:0:0:0: Attached scsi generic sg2 type 0
scsi 3:0:0:1: Direct-Access     USB2.0   CardReader Combo 0.0> PQ: 0 ANSI: 0
sd 3:0:0:1: Attached scsi removable disk sdc
sd 3:0:0:1: Attached scsi generic sg3 type 0
usb-storage: device scan complete
eth0: no link during initialization.
ttyS1: LSR safety check engaged!
ttyS1: LSR safety check engaged!
eth0: no link during initialization.
SoftMAC: Open Authentication completed with 00:13:49:9a:e2:79
input: Power Button (FF) as /class/input/input3
ACPI: Power Button (FF) [PWRF]
input: Power Button (CM) as /class/input/input4
ACPI: Power Button (CM) [PWRB]
ACPI: Fan [FAN] (on)
ACPI: Thermal Zone [THRM] (40 C)
NET: Registered protocol family 10
lo: Disabled Privacy Extensions
ADDRCONF(NETDEV_UP): eth0: link is not ready
ieee80211_crypt: registered algorithm 'TKIP'
Time: acpi_pm clocksource has been installed.
Clocksource tsc unstable (delta = -259997568 ns)
[drm] Initialized drm 1.1.0 20060810
[drm] Initialized radeon 1.25.0 20060524 on minor 0
agpgart: Found an AGP 3.0 compliant device at 0000:00:00.0.
agpgart: Putting AGP V3 device at 0000:00:00.0 into 4x mode
agpgart: Putting AGP V3 device at 0000:02:00.0 into 4x mode
[drm] Setting GART location based on new memory map
[drm] Loading R200 Microcode
[drm] writeback test succeeded in 1 usecs
wlan0: no IPv6 routers present
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862934>] dvd_do_auth+0x261/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c016ab9e>] link_path_walk+0xa9/0xb3
 [<c0161589>] get_unused_fd+0x4a/0xa9
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c016a961>] __link_path_walk+0xa66/0xbfa
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01bdfd2>] exact_lock+0x7/0xd
 [<c01c436f>] kobject_get+0xf/0x13
 [<f8845363>] sr_block_open+0x74/0x81 [sr_mod]
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c018186a>] bdget+0xe7/0xef
 [<c0149071>] find_get_page+0x18/0x38
 [<c014b33f>] filemap_nopage+0x18d/0x2ef
 [<c0181c6d>] blkdev_open+0x25/0x4d
 [<c0153ddc>] __handle_mm_fault+0x2cd/0x793
 [<c016181d>] do_filp_open+0x32/0x39
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862766>] dvd_do_auth+0x93/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0149071>] find_get_page+0x18/0x38
 [<c014b33f>] filemap_nopage+0x18d/0x2ef
 [<c0211893>] pty_write+0x2f/0x39
 [<c0153ddc>] __handle_mm_fault+0x2cd/0x793
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a3
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f88629b9>] dvd_do_auth+0x2e6/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f88627c8>] dvd_do_auth+0xf5/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862826>] dvd_do_auth+0x153/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a3
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862a1f>] dvd_do_auth+0x34c/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862934>] dvd_do_auth+0x261/0x4a8 [cdrom]
 [<c011bc40>] default_wake_function+0x0/0xc
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c01bb55b>] blk_execute_rq+0x8b/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<f886106e>] media_changed+0x40/0x6e [cdrom]
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<f8865254>] cdrom_open+0x8da/0x91d [cdrom]
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb ad
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0146ff6>] handle_IRQ_event+0x1a/0x3f
 [<c0107acc>] enable_8259A_irq+0xd/0x42
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0106382>] do_IRQ+0x5c/0x72
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8863939>] mmc_ioctl+0xdbe/0x11e5 [cdrom]
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01b84b0>] elv_set_request+0x14/0x22
 [<c01baf52>] get_request+0x1d7/0x1f0
 [<c01ba7c7>] __freed_request+0x23/0x74
 [<c01ba835>] freed_request+0x1d/0x37
 [<c01baac2>] blk_put_request+0x22/0x36
 [<c022d67c>] scsi_execute+0xed/0xf6
 [<c022d702>] scsi_execute_req+0x7d/0xd5
 [<c022d79d>] scsi_test_unit_ready+0x43/0x80
 [<f88450ea>] sr_media_change+0x32/0x1e5 [sr_mod]
 [<c0168a91>] do_lookup+0x4f/0x140
 [<c011bc36>] try_to_wake_up+0x3a1/0x3ab
 [<c0119aae>] __activate_task+0x1c/0x29
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c01198b2>] __wake_up_common+0x32/0x55
 [<c0119df7>] __wake_up+0x32/0x43
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c01bdfb5>] get_disk+0x31/0x47
 [<c01c7c34>] mmx_clear_page+0x24/0x60
 [<c014d12a>] get_page_from_freelist+0x26a/0x2e6
 [<c0181a4f>] do_open+0x1dd/0x25c
 [<c0211893>] pty_write+0x2f/0x39
 [<c020b9a5>] tty_default_put_char+0x17/0x1a
 [<c0119df7>] __wake_up+0x32/0x43
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================
XXX forcing PIO for 0 length data cdb a4
 [<c0238e37>] atapi_xlat+0x42/0x13f
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c0238940>] ata_scsi_translate+0xec/0x151
 [<c0228ae7>] scsi_done+0x0/0x16
 [<c023a947>] ata_scsi_queuecmd+0x121/0x13f
 [<c0238df5>] atapi_xlat+0x0/0x13f
 [<c012845d>] __mod_timer+0x90/0x9a
 [<c0229055>] scsi_dispatch_cmd+0x1d3/0x250
 [<c0128355>] lock_timer_base+0x15/0x2f
 [<c022da42>] scsi_request_fn+0x268/0x31d
 [<c01bb419>] blk_remove_plug+0x4f/0x5b
 [<c01bb442>] __generic_unplug_device+0x1d/0x1f
 [<c01bb4bf>] blk_execute_rq_nowait+0x7b/0x8c
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01c2715>] cfq_set_request+0x299/0x315
 [<c01bb554>] blk_execute_rq+0x84/0x9e
 [<c01baa7d>] blk_end_sync_rq+0x0/0x23
 [<c01c247c>] cfq_set_request+0x0/0x315
 [<c01807dd>] bio_map_kern+0x91/0xd5
 [<c01b9d21>] blk_rq_bio_prep+0x61/0x85
 [<c022d672>] scsi_execute+0xe3/0xf6
 [<f8845e66>] sr_do_ioctl+0x9a/0x1dc [sr_mod]
 [<f8852b92>] do_get_write_access+0x4b6/0x4e3 [jbd]
 [<f88450b3>] sr_packet+0x1a/0x1f [sr_mod]
 [<f8862934>] dvd_do_auth+0x261/0x4a8 [cdrom]
 [<f88949d2>] __ext3_journal_dirty_metadata+0x16/0x3a [ext3]
 [<f88896d1>] __ext3_get_inode_loc+0x115/0x2e3 [ext3]
 [<f8887405>] ext3_new_blocks+0x4b7/0x5bd [ext3]
 [<f8863bb2>] mmc_ioctl+0x1037/0x11e5 [cdrom]
 [<c017dad1>] __find_get_block+0x14c/0x156
 [<c017dafe>] __getblk+0x23/0x26c
 [<f8852b92>] do_get_write_access+0x4b6/0x4e3 [jbd]
 [<c017dad1>] __find_get_block+0x14c/0x156
 [<f88896d1>] __ext3_get_inode_loc+0x115/0x2e3 [ext3]
 [<f88949d2>] __ext3_journal_dirty_metadata+0x16/0x3a [ext3]
 [<f8852be0>] journal_get_write_access+0x21/0x26 [jbd]
 [<f8889556>] ext3_mark_iloc_dirty+0x26e/0x2d4 [ext3]
 [<f888992d>] ext3_mark_inode_dirty+0x20/0x27 [ext3]
 [<c0119df7>] __wake_up+0x32/0x43
 [<c01c436f>] kobject_get+0xf/0x13
 [<c01bed7f>] scsi_cmd_ioctl+0x330/0x35d
 [<c014a791>] generic_file_buffered_write+0x597/0x606
 [<f886450c>] cdrom_ioctl+0x7ac/0xb3e [cdrom]
 [<c0124548>] current_fs_time+0x41/0x46
 [<c014ace5>] __generic_file_aio_write_nolock+0x4e5/0x55e
 [<f8845d5c>] sr_block_ioctl+0x47/0x7f [sr_mod]
 [<c01bcd92>] blkdev_driver_ioctl+0x4e/0x5e
 [<c01bd3d4>] blkdev_ioctl+0x632/0x67e
 [<c014adbc>] generic_file_aio_write+0x5e/0xb3
 [<f8888020>] ext3_file_write+0x24/0x8f [ext3]
 [<c016290a>] do_sync_write+0xc7/0x10a
 [<c016bae2>] open_namei+0x24c/0x552
 [<c01617dc>] nameidata_to_filp+0x24/0x33
 [<c0130b89>] autoremove_wake_function+0x0/0x35
 [<c0181291>] block_ioctl+0x18/0x1b
 [<c0181279>] block_ioctl+0x0/0x1b
 [<c016c863>] do_ioctl+0x1f/0x62
 [<c016caf2>] vfs_ioctl+0x24c/0x25e
 [<c0174aed>] mntput_no_expire+0x11/0x68
 [<c016cb50>] sys_ioctl+0x4c/0x64
 [<c0103c88>] sysenter_past_esp+0x5d/0x81
 =======================

[-- Attachment #3: sata_sil.c.patch --]
[-- Type: text/x-patch, Size: 1626 bytes --]

--- sata_sil.c	2007-04-26 05:08:32.000000000 +0200
+++ sata_sil.c	2007-05-04 20:06:03.000000000 +0200
@@ -43,10 +43,11 @@
 #include <linux/interrupt.h>
 #include <linux/device.h>
 #include <scsi/scsi_host.h>
+#include <scsi/scsi_cmnd.h>
 #include <linux/libata.h>
 
 #define DRV_NAME	"sata_sil"
-#define DRV_VERSION	"2.1"
+#define DRV_VERSION	"2.1a"
 
 enum {
 	SIL_MMIO_BAR		= 5,
@@ -121,6 +122,7 @@
 static irqreturn_t sil_interrupt(int irq, void *dev_instance);
 static void sil_freeze(struct ata_port *ap);
 static void sil_thaw(struct ata_port *ap);
+static int sil_check_atapi_dma(struct ata_queued_cmd *qc);
 
 
 static const struct pci_device_id sil_pci_tbl[] = {
@@ -196,6 +198,7 @@
 	.tf_read		= ata_tf_read,
 	.check_status		= ata_check_status,
 	.exec_command		= ata_exec_command,
+	.check_atapi_dma	= sil_check_atapi_dma,
 	.dev_select		= ata_std_dev_select,
 	.post_set_mode		= sil_post_set_mode,
 	.bmdma_setup            = ata_bmdma_setup,
@@ -289,6 +292,22 @@
 module_param(slow_down, int, 0444);
 MODULE_PARM_DESC(slow_down, "Sledgehammer used to work around random problems, by limiting commands to 15 sectors (0=off, 1=on)");
 
+static int sil_check_atapi_dma(struct ata_queued_cmd *qc)
+{
+	/* limit zero data size atapi commands to pio as certain sil */
+	/* chips seem to have trouble to perform dma for these commands */
+	if ( (qc->scsicmd != NULL) &&
+             (qc->scsicmd->sc_data_direction != DMA_NONE) &&
+	     (qc->nbytes == 0) )
+	{
+		/* do not allow dma */
+		return -1;
+	}
+
+	/* allow dma */
+	return 0;
+}
+
 
 static unsigned char sil_get_device_cache_line(struct pci_dev *pdev)
 {

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

[-- Attachment #1: Type: text/plain, Size: 2576 bytes --]

Hello, Daniel.

Daniel Beichl wrote:
>> Okay, I've been thinking about it for some time.  I think I know what's
>> going on now.  Those authentication related commands are issued by
>> invoking ioctls on the device node.  The cdrom driver receives the
>> ioctls and issues respective SCSI commands for it.  All those DVD auth
>> commands either transfer or receive data from the device and thus
>> specifies certain data direction when they're issued.  libata selects
>> command protocol accordingly.
>>
>> It's all good and dandy till now but the problem is that those commands
>> can be issued with data length of zero!  This is allowed by the SCSI MMC
>> standard and used to probe whether the command succeeds or not before
>> taking further actions.  When this happens, libata chooses command
>> protocol according to the data direction, but has to feed 0-length data
>> to the DMA engine.  It seems sata_sil dma engine barfs if that happens.
>>  Can you please add the following code snippet at the head of
>> atapi_xlat()?
>>
>>     if (!nodata && !qc->nbytes) {
>>         printk("XXX forcing PIO for 0 length data cdb %02x\n",
>>             scmd->cmnd[0]);
>>         dump_stack();
>>         using_pio = 1;
>>     }
>>
>> Also, do you mind cc'ing linux-ide@vger.kernel.org?
>>
>>   
> Hi Tejun,
> 
> 
> i inserted the code snippet you mentioned to atapi_xlat() in libata-scsi.c
> and the dvd authentication succeeds.
> 
> Please see the attached dmesg file for the generated stack dumps.

Good to know it works.  :-)

> The question is whether this is the right place to fix it, as this seems
> to limit all
> drivers to pio if a zero data length command is transferred.
> It would make more sense to me if the individual driver decides this by
> performing a similar check in the check_atapi_dma function implemented
> by the
> individual driver. I did this for the sata_sil driver in the attached
> patch.

The thing is that those commands don't transfer any data at all, so it
doesn't really matter whether the data phase is specified as DMA or PIO.
 ATA_PROT_ATAPI degenerates into ATA_PROT_ATAPI_NODATA if there is no
data to transfer (in ATA spec they share the same protocol state machine
and the data request status bit dictates what actually happens).

I think this actually should be fixed in the cdrom driver.  It shouldn't
issue data command with 0 data length with data protocol.  Can you test
whether the attached patch works?  Also, it seems we'll need to add a
WARN_ON() in sr such that bugs like this can be caught more easily.

Thanks.

-- 
tejun

[-- Attachment #2: DATA_NONE-if-len-zero.patch --]
[-- Type: text/x-patch, Size: 511 bytes --]

diff --git a/drivers/ata/libata-scsi.c b/drivers/ata/libata-scsi.c
diff --git a/drivers/cdrom/cdrom.c b/drivers/cdrom/cdrom.c
index b36f44d..5a5639d 100644
--- a/drivers/cdrom/cdrom.c
+++ b/drivers/cdrom/cdrom.c
@@ -1533,7 +1533,10 @@ void init_cdrom_command(struct packet_co
 		memset(buf, 0, len);
 	cgc->buffer = (char *) buf;
 	cgc->buflen = len;
-	cgc->data_direction = type;
+	if (len)
+		cgc->data_direction = type;
+	else
+		cgc->data_direction = CGC_DATA_NONE;
 	cgc->timeout = CDROM_DEF_TIMEOUT;
 }
 

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

Hello,

Daniel Beichl wrote:
> I gave the whole thing some thought. You suspected the sil dma engine to
> cause the issue, because it might only be usable with a certain command
> packet size.
> If these commands result in packets their size is not zero. Not all
> packet commands transfer
> data sectors, but they themselves have a size.
> 
> So i investigated libata and learnt from libata-scsi.c that nbytes is
> set to the size of the scsi
> command corresponding to the atapi command that should be sent to the
> device near the end of atapi_xlat().
> 
> I added code to dump the packet size and data direction as set in the
> scsi command and noticed that the
> controller freezes the port if a packet with the direction DMA_TO_DEVICE
> and a length smaller than ~60 bytes is issued, the command type does not
> matter at all.

Hmmmmm.... This is weird.  < ~60 bytes?  The zero-length protocol thing
is a plain bug but this is something completely different.  Can you test
this with a different controller?  Is the problem always reproducible?

> I tried this with the cdrecord -atip option which generate packets of
> command cdb[0] = 0x00, length 60 and 16 in said direction.
> The first command succeeds, the second one triggers the dma bug.
> 
> The question now is, is the dma engine of the sil chip indeed the
> problem, or did i cover
> another problem located somewhere else by restricting dma to packets not
> smaller than 60 bytes.
> The datasheet of the sil3512 does not specify a lower limit for dma
> transfers.
> 
> It does not appear to be a modulo N issue either as i have seen the
> transfer of
> packets of 12 or 16 bytes fail but then again packets of 60 bytes succeeds.
> 
> size       result
> ==========
> 001100 fail
> 010000 fail
> 111100 succeed
> 
> A thing that crossed my mind was a timing issue. Perhaps the dmaing of <
> 60 bytes is that
> fast that the interrupt that causes it is not yet handled correctly. But
> this is just a very wild guess.

I don't think that can happen.  Controllers are required to queue
interrupt till FIFO is flushed.  Can you post dmesg after such errors?

> I tried your latest patch and the dma bug did show up. I have attached a
> patch to this mail that
> decides based on the dma direction and the command size in the
> sil_check_atapi_dma() routine
> whether to allow dma or not. This fixed the dvd auth issue and the
> cdrecord -atip issue for me,
> but i am pretty sure there is a better solution.

I'm not really sure what we're looking at and where the problem actually
is.  We need to find out more about this problem.

-- 
tejun

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Alan Cox]

> > A thing that crossed my mind was a timing issue. Perhaps the dmaing of <
> > 60 bytes is that
> > fast that the interrupt that causes it is not yet handled correctly. But
> > this is just a very wild guess.
> 
> I don't think that can happen.  Controllers are required to queue
> interrupt till FIFO is flushed.  Can you post dmesg after such errors?

Random finger in the air guess - the FIFO on the SIL DMA engine is 64
bytes long ? Perhaps this is something Jeff can query with his contacts
at Silicon Image ?

Alan

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Tejun Heo]

Alan Cox wrote:
>>> A thing that crossed my mind was a timing issue. Perhaps the dmaing of <
>>> 60 bytes is that
>>> fast that the interrupt that causes it is not yet handled correctly. But
>>> this is just a very wild guess.
>> I don't think that can happen.  Controllers are required to queue
>> interrupt till FIFO is flushed.  Can you post dmesg after such errors?
> 
> Random finger in the air guess - the FIFO on the SIL DMA engine is 64
> bytes long ? Perhaps this is something Jeff can query with his contacts
> at Silicon Image ?

That sounds plausible.  I have pretty good relationship with SIMG.  I'll
ask them.

Thanks.

-- 
tejun

Re: [PATCH] Re: 2.6.19.1, sata_sil: sata dvd writer doesn't work

[Jeff Garzik]

Daniel Beichl wrote:
> +static int sil_check_atapi_dma(struct ata_queued_cmd *qc)
> +{
> +	/* limit atapi commands less than 60bytes to pio as certain sil */
> +	/* chips seem to have trouble to perform dma for these commands */
> +	if ( (qc->scsicmd != NULL) &&
> +	     (qc->scsicmd->sc_data_direction == DMA_TO_DEVICE) &&
> +	     (qc->scsicmd->request_bufflen < 60) )
> +	{
> +		ata_dev_printk( qc->dev, KERN_INFO, "reducing cmd %02x (direction=%d, len=%d) to pio\n", 
> +			qc->cdb[0], 
> +			qc->scsicmd->sc_data_direction, 
> +			qc->scsicmd->request_bufflen );
> +		/* do not allow dma */
> +		return -1;
> +	}
> +
> +	/* allow dma */
> +	return 0;


Comments:

1) Return values are zero or one for this hook

2) There are two data bundling methods in SCSI:  single-buffer and 
scatterlist.  Further, SCSI is deprecating single-buffer method in favor 
of always using a scatterlist.  Your patch needs to support scatterlist. 
  Here is an example test found in libata-scsi.c that illustrates how 
SCSI-aware code tests for and uses this:

         if (cmd->use_sg) {
                 qc->__sg = (struct scatterlist *) cmd->request_buffer;

3) You need to always include a signoff line: 
http://linux.yyz.us/patch-format.html

	Jeff