Bug in linux kernel when playing DVDs.

Bug in linux kernel when playing DVDs.

[James Courtier-Dutton]

Hello,

I have found a bug in the linux kernel when it plays DVDs. I use xine 
(xine.sf.net) for playing DVDs.
At some point during the playing there is an error on the DVD. But 
currently this error is not handled correctly by the linux kernel.
This puts the kernel into an uncertain state, causing the kernel to take 
100% CPU and fail all future read requests.
One way to exit this "uncertain state" is to push a pin into the small 
hole on the front of all DVD drive. This causes the kernel to sense 
"tray open", which it knows about, and handles correctly. After this, 
the kernel releases it's grab on the CPU and linux runs normally again.
The strange thing is that during the "uncertain state", the kernel tries 
to read sectors that a way outside the DVD.
Please see kern.log extract for more details.
What is error 0x34 ? Does anyone know how we should handle it, because 
the current method for handling it is obviously wrong.
I am 100% sure that the application does not ask for these out of range 
sectors, because I have debugged that far. I have now compiled the 
ide-cd as a kernel module, so I could add kprintf's to the kernel source 
if that helps give more information.
Currently, I cannot find document that will explain what error 0x34 is. 
Can anybody help ?

Cheers
James

Apr 26 17:15:55 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:00 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:00 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:05 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:05 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:10 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:10 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:10 games kernel: hdd: ATAPI reset complete
Apr 26 17:16:15 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:15 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:20 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:20 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:24 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:24 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:24 games kernel: hdd: ATAPI reset complete
Apr 26 17:16:25 games kernel: end_request: I/O error, dev 16:40 (hdd), 
sector 7750464
Apr 26 17:16:29 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:29 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:34 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:34 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:39 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:39 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:44 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:44 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:44 games kernel: hdd: ATAPI reset complete
Apr 26 17:16:49 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:49 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:54 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:54 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:59 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }
Apr 26 17:16:59 games kernel: hdd: cdrom_decode_status: error=0x34
Apr 26 17:16:59 games kernel: hdd: ATAPI reset complete
Apr 26 17:16:59 games kernel: end_request: I/O error, dev 16:40 (hdd), 
sector 7750468
Apr 26 17:16:59 games kernel: hdd: cdrom_decode_status: status=0x51 { 
DriveReady SeekComplete Error }

"I use the PIN here"

Apr 26 17:16:59 games kernel: hdd: cdrom_decode_status: error=0xb4
Apr 26 17:16:59 games kernel: hdd: tray open
Apr 26 17:16:59 games kernel: end_request: I/O error, dev 16:40 (hdd), 
sector 7750472
Apr 26 17:16:59 games kernel: hdd: tray open
Apr 26 17:16:59 games kernel: end_request: I/O error, dev 16:40 (hdd), 
sector 7750476
Apr 26 17:16:59 games kernel: hdd: tray open
Apr 26 17:16:59 games kernel: end_request: I/O error, dev 16:40 (hdd), 
sector 7750480
Apr 26 17:16:59 games kernel: hdd: tray open
Apr 26 17:16:59 games kernel: end_request: I/O error, dev 16:40 (hdd), 
sector 7750484
Apr 26 17:16:59 games kernel: hdd: tray open

Re: Bug in linux kernel when playing DVDs.

[James Courtier-Dutton]

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

Elladan wrote:
> On Wed, Apr 30, 2003 at 09:46:41AM -0700, Elladan wrote:
> 
>>On Wed, Apr 30, 2003 at 04:23:47PM +0100, James Courtier-Dutton wrote:
>>
>>>Alan Cox wrote:
>>>
>>>>NOTABUG
>>>>
>>>>User space keeps asking it to read so it keeps using CPU, fix the user
>>>>space
>>>
>>>The application does an initial seek() command, which succeeds.
>>>It then just does read() commands for then on.
>>>For bug tracking, I have put printf statements in my application.
>>>I.e.
>>>
>>>[...]
>>>
>>>When an error occurs on the DVD, "read done" message is never printed on 
>>>the console and all applications fail to respond to user input. This is 
>>>why I thought that the kernel hogs CPU 100% and the application never 
>>>receives the error message.
>>>If I force a different error "tray open", by using a pin in the manual 
>>>eject hole on the front of the dvd rom device, I then see the "read 
>>>done" message and everything comes back to life.
>>
>>Are you sure it never returns, ever?
>>
>>The behavior most people seem to see here 90% of the time seems to be
>>that the IDE layer retries the request a few dozen times before
>>returning an error result.  This usually takes 1-5 minutes.
> 
> 
> Say, does this lame hack help at all?  I got so annoyed with the ide-cd
> driver the other night that I hacked this garbage in during the middle
> of a movie.  After patching, you load the module, possibly with a value,
> and it changes the max number of retries ide-cd will attempt on an
> error.
> 
> Numbers like 0 or 1 may be good.
> 
> Or maybe I'm just dreaming and this patch does nothing, because my
> hardware suddenly started working better.  It does that sometimes.  :-)
> 
> -J
> 
> 

I have not yet tried the patch, because I run kernel 2.6.2 at the moment.
I have concluded that the kernel (not user space) is doing some kind of 
read-ahead caching.
Example of a read happening correctly: -
bash-2.05b# dd if=/dev/dvd of=error.img skip=1598700 count=1
1+0 records in
1+0 records out

Example of a read failing, both on the same DVD, just different sectors.
bash-2.05b# dd if=/dev/dvd of=error.img skip=1598740 count=1
dd: reading `/dev/dvd': Input/output error
0+0 records in
0+0 records out
See attachment for output from dmesg for this single command.

As you can see, the read() call is at least returning now with kernel 
2.6.2, which did not happen with whichever previous kernel I tested 
with. The first error message arrives in the kernel log about 1 second 
after the request which is fine. We could work around that in the user 
space DVD player, but at the moment, the return takes about 20 seconds. 
20 seconds is an unacceptable break in the playing of a DVD.

As the kernel is at least returning control to the application, I can at 
least program some recovery logic into the linux dvd player now.

I think that this problem would be fixed if the kernel would stop the 
read-ahead function as soon as an error is seen, and thus pass control 
back to the application as soon as possible. read-ahead caching should 
only be enabled again on the next disc read() or lseek() request from 
user space.

Summary: -
If we could get the read() call to return as soon as the first error 
message arrives in the dmesg linux would play DVDs much better.

Cheers
James

[-- Attachment #2: dmesg.txt --]
[-- Type: text/plain, Size: 2772 bytes --]

hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598736
Buffer I/O error on device hda, logical block 199842
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598744
Buffer I/O error on device hda, logical block 199843
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598752
Buffer I/O error on device hda, logical block 199844
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598760
Buffer I/O error on device hda, logical block 199845
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598768
Buffer I/O error on device hda, logical block 199846
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598776
Buffer I/O error on device hda, logical block 199847
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598784
Buffer I/O error on device hda, logical block 199848
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598792
Buffer I/O error on device hda, logical block 199849
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598800
Buffer I/O error on device hda, logical block 199850
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598808
Buffer I/O error on device hda, logical block 199851
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598816
Buffer I/O error on device hda, logical block 199852
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598824
Buffer I/O error on device hda, logical block 199853
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598832
Buffer I/O error on device hda, logical block 199854
hda: command error: status=0x51 { DriveReady SeekComplete Error }
hda: command error: error=0x54
end_request: I/O error, dev hda, sector 1598840
Buffer I/O error on device hda, logical block 199855