Bug 14329

Summary:	errors when some programs read files from DVD
Product:	Sisyphus	Reporter:	Ivan Zakharyaschev <imz>
Component:	kernel-image-std-smp	Assignee:	Sergey Vlasov <vsu>
Status:	CLOSED WORKSFORME	QA Contact:	qa-sisyphus
Severity:	critical
Priority:	P2
Version:	unstable
Hardware:	all
OS:	Linux

Description Ivan Zakharyaschev 2008-02-05 22:39:50 MSK

kernel-image-std-smp-2.6.18-alt8

Some programs reading a DVD cause kernel errors. I can reproduce this with 
rhythmbox-0.11.3-alt1 playing an mp3 file from the DVD. After that, the file
remains unreadable until remounting.

The errors don't occur when the same files are being read with `cat'. Also, the
errors don't occur when using rhythmbox after the mp3 files have been read with
`cat' beforehand.

I couldn't get this kind of errors with a CD.

Sometimes the DVD-ROM remains unusable after such errors until a reboot. (This
makes this bug more serious. But I couldn't reproduce this now.)

Because of this bug, I switched to kernels 2.6.22 and 2.6.24
(kernel-image-wks-smp-2.6.24-alt1) -- they work OK.

# cat /proc/scsi/scsi 
Attached devices:
Host: scsi0 Channel: 00 Id: 00 Lun: 00
  Vendor: ATA      Model: HTS726060M9AT00  Rev: MH4O
  Type:   Direct-Access                    ANSI SCSI revision: 05
Host: scsi1 Channel: 00 Id: 00 Lun: 00
  Vendor: SONY     Model: DVD+-RW DW-Q58A  Rev: UDS1
  Type:   CD-ROM                           ANSI SCSI revision: 05
# 

ata_piix module is used. The kernel is booted with combined_mode=libata (in case
 this still plays a role).
Steps to Reproduce:
1. I burned a DVD with mp3 files
2. I inserted the DVD, mount /mnt/cdrom/, and then I added the folders on it to
rhythmbox-0.11.3-alt1
3. Stopped rhythmbox, ejected and re-inserted the DVD, started rhythmbox.
4. Started playing an album.
Actual Results:  
The playback of the first song stopped at 2:02. Kernel reported errors:
# fgrep 21:49 -r /var/log/kernel/
/var/log/kernel/info:Feb  5 21:21:49 dell kernel: ISO 9660 Extensions: Microsoft
Joliet Level 3
/var/log/kernel/info:Feb  5 21:21:49 dell kernel: ISO 9660 Extensions: RRIP_1991A
/var/log/kernel/info:Feb  5 21:49:34 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 21:49:34 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 21:49:34 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/info:Feb  5 21:49:41 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 21:49:41 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 21:49:41 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604630
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604631
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604632
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604633
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604634
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604635
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604636
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604637
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604638
/var/log/kernel/errors:Feb  5 21:49:34 dell kernel: Buffer I/O error on device
sr0, logical block 1604639
/var/log/kernel/errors:Feb  5 21:49:41 dell kernel: Buffer I/O error on device
sr0, logical block 1604680
/var/log/kernel/warnings:Feb  5 21:49:34 dell kernel: end_request: I/O error,
dev sr0, sector 6418520
/var/log/kernel/warnings:Feb  5 21:49:41 dell kernel: end_request: I/O error,
dev sr0, sector 6418720
/var/log/kernel/warnings:Feb  5 21:49:41 dell kernel: printk: 40 messages
suppressed.
# 

After this, the file remains unreadable until re-mounting:

$ cat /mnt/cdrom/Led\ Zeppelin/172.19.7.113/Pub/Music/Led\ Zeppelin/Robert\
Plant/2005\ -\ Mighty\ Rearranger/01\ -\ Another\ Tribe.mp3 > /dev/null; echo $?
cat: /mnt/cdrom/Led Zeppelin/172.19.7.113/Pub/Music/Led Zeppelin/Robert
Plant/2005 - Mighty Rearranger/01 - Another Tribe.mp3: Input/output error
1
$ 


Expected Results:  
No errors. 

I know the disk is OK. And this is easily proven by running (before the playback): 

$ cat /mnt/cdrom/Led\ Zeppelin/172.19.7.113/Pub/Music/Led\ Zeppelin/Robert\
Plant/2005\ -\ Mighty\ Rearranger/01\ -\ Another\ Tribe.mp3 > /dev/null; echo $?
0
$ 

And, by the way, rhythmbox doesn't hit the errors if it is run after the files
on the mounted DVD have been passed through `cat' like this before.

So, the kernel is able to read a file completely (as with `cat'), but not able
to read it in the way rhythmbox does this (perhaps, partially, with pauses
before reading the next part?).

Comment 1 Ivan Zakharyaschev 2008-02-05 22:52:11 MSK

I could reproduce it with a simpler program -- mpg123-0.59s-alt0.9:

# fgrep ' 22:4' -r /var/log/kernel/
/var/log/kernel/info:Feb  5 22:41:05 dell kernel: ISO 9660 Extensions: Microsoft
Joliet Level 3
/var/log/kernel/info:Feb  5 22:41:06 dell kernel: ISO 9660 Extensions: RRIP_1991A
/var/log/kernel/info:Feb  5 22:46:45 dell kernel: ISO 9660 Extensions: Microsoft
Joliet Level 3
/var/log/kernel/info:Feb  5 22:46:46 dell kernel: ISO 9660 Extensions: RRIP_1991A
/var/log/kernel/info:Feb  5 22:47:30 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 22:47:30 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 22:47:30 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/info:Feb  5 22:47:41 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 22:47:41 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 22:47:41 dell kernel:     Additional sense:
Unrecovered read error
/var/log/kernel/info:Feb  5 22:47:48 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 22:47:48 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 22:47:48 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/info:Feb  5 22:47:57 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 22:47:57 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 22:47:57 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/info:Feb  5 22:48:04 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 22:48:04 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 22:48:04 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/info:Feb  5 22:48:13 dell kernel: sr 1:0:0:0: SCSI error: return
code = 0x08000002
/var/log/kernel/info:Feb  5 22:48:13 dell kernel: sr0: Current: sense key:
Medium Error
/var/log/kernel/info:Feb  5 22:48:13 dell kernel:     Additional sense: No seek
complete
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603096
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603097
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603098
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603099
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603100
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603101
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603102
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603103
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603104
/var/log/kernel/errors:Feb  5 22:47:30 dell kernel: Buffer I/O error on device
sr0, logical block 1603105
/var/log/kernel/errors:Feb  5 22:47:41 dell kernel: Buffer I/O error on device
sr0, logical block 1603146
/var/log/kernel/errors:Feb  5 22:47:41 dell kernel: Buffer I/O error on device
sr0, logical block 1603147
/var/log/kernel/errors:Feb  5 22:47:48 dell kernel: Buffer I/O error on device
sr0, logical block 1603160
/var/log/kernel/errors:Feb  5 22:47:57 dell kernel: Buffer I/O error on device
sr0, logical block 1603210
/var/log/kernel/errors:Feb  5 22:47:57 dell kernel: Buffer I/O error on device
sr0, logical block 1603211
/var/log/kernel/errors:Feb  5 22:48:04 dell kernel: Buffer I/O error on device
sr0, logical block 1603096
/var/log/kernel/errors:Feb  5 22:48:13 dell kernel: Buffer I/O error on device
sr0, logical block 1603096
/var/log/kernel/errors:Feb  5 22:48:13 dell kernel: Buffer I/O error on device
sr0, logical block 1603097
/var/log/kernel/warnings:Feb  5 22:47:30 dell kernel: end_request: I/O error,
dev sr0, sector 6412384
/var/log/kernel/warnings:Feb  5 22:47:30 dell kernel: printk: 13 messages
suppressed.
/var/log/kernel/warnings:Feb  5 22:47:41 dell kernel: end_request: I/O error,
dev sr0, sector 6412584
/var/log/kernel/warnings:Feb  5 22:47:41 dell kernel: printk: 40 messages
suppressed.
/var/log/kernel/warnings:Feb  5 22:47:48 dell kernel: end_request: I/O error,
dev sr0, sector 6412640
/var/log/kernel/warnings:Feb  5 22:47:48 dell kernel: printk: 12 messages
suppressed.
/var/log/kernel/warnings:Feb  5 22:47:57 dell kernel: end_request: I/O error,
dev sr0, sector 6412840
/var/log/kernel/warnings:Feb  5 22:47:57 dell kernel: printk: 49 messages
suppressed.
/var/log/kernel/warnings:Feb  5 22:48:04 dell kernel: end_request: I/O error,
dev sr0, sector 6412384
/var/log/kernel/warnings:Feb  5 22:48:04 dell kernel: printk: 12 messages
suppressed.
/var/log/kernel/warnings:Feb  5 22:48:13 dell kernel: end_request: I/O error,
dev sr0, sector 6412384
/var/log/kernel/warnings:Feb  5 22:48:13 dell kernel: printk: 1 messages suppressed.
# 

The command was:
$ mpg123 /mnt/cdrom/Led\ Zeppelin/172.19.7.113/Pub/Music/Led\ Zeppelin/Robert\
Plant/2005\ -\ Mighty\ Rearranger/01\ -\ Another\ Tribe.mp3
High Performance MPEG 1.0/2.0/2.5 Audio Player for Layer 1, 2 and 3.
Version 0.59s-mh4 (2000/Oct/27). Written and copyrights by Michael Hipp.
Uses code from various people. See 'README' for more!
THIS SOFTWARE COMES WITH ABSOLUTELY NO WARRANTY! USE AT YOUR OWN RISK!
Title  : Another Tribe                   Artist: Plant, Robert & the Strange Se
Album  : Mighty Rearranger               Year  : 2005
Comment: Created by Grip                 Genre : Rock

Directory: /mnt/cdrom/Led Zeppelin/172.19.7.113/Pub/Music/Led Zeppelin/Robert
Plant/2005 - Mighty Rearranger/
Playing MPEG stream from 01 - Another Tribe.mp3 ...
Found new ID3 Header
MPEG 1.0 layer III, 256 kbit/s, 44100 Hz stereo

[0:24] Decoding of 01 - Another Tribe.mp3 finished.
$ 

It stopped before the end, waited, then exited.

Comment 2 Ivan Zakharyaschev 2008-02-05 23:01:18 MSK

But it's not reproducible with mpg123 every time.

Comment 3 Ivan Zakharyaschev 2008-02-05 23:18:34 MSK

It works OK on 2.6.18-std-smp-alt11 (tested with rhythmbox).
Thank you for the changes in the updated kernel!
Sorry I haven't tried the updated revision before posting the report.