Bug#494822: linux-image-2.6.25-2-686: DVD-writing with VIA IDE controller produce kernel error hdd: status timeout
Package: linux-image-2.6.25-2-686
Version: 2.6.25-7
Severity: normal
When I use the writing-capabilities (in simulation!), after a while, the
(simulated) writing process will terminate and my syslog begins to get
filled with plenty of repeated kernel error messages related to my
DVD-writer. My DVD-writer, from that time on, is unusable until
the next reboot. The only thing I found to stop kernel error logging is
to unload the ide_cd_mod module.
Here attached, you will find my setup and what I exactly did to
produce the problem. Please note that the first DVD-writing attempt did
NOT trigger the error, thus I guess there is some randomness included.
But I got the problem each time I tried to write at speed=1 (I guess,
because the time to terminate the process is longer so more chance to
trigger the problem).
-- Package-specific info:
** Version:
Linux version 2.6.25-2-686 (Debian 2.6.25-6) (maks@debian.org) (gcc version 4.1.3 20080623 (prerelease) (Debian 4.1.2-23)) #1 SMP Fri Jun 27 03:23:20 UTC 2008
** Command line:
BOOT_IMAGE=Linux-2.6.25-2 ro root=301
** Not tainted
-- System Information:
Debian Release: lenny/sid
APT prefers testing
APT policy: (990, 'testing'), (500, 'unstable')
Architecture: i386 (i686)
Kernel: Linux 2.6.25-2-686 (SMP w/2 CPU cores)
Locale: LANG=fr_BE.UTF-8, LC_CTYPE=fr_BE.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/bash
Versions of packages linux-image-2.6.25-2-686 depends on:
ii debconf [debconf-2.0] 1.5.22 Debian configuration management sy
ii initramfs-tools [linux-initra 0.92e tools for generating an initramfs
ii module-init-tools 3.4-1 tools for managing Linux kernel mo
Versions of packages linux-image-2.6.25-2-686 recommends:
ii libc6-i686 2.7-10 GNU C Library: Shared libraries [i
Versions of packages linux-image-2.6.25-2-686 suggests:
ii lilo 1:22.8-5 LInux LOader - The Classic OS load
pn linux-doc-2.6.25 <none> (no description available)
-----
setup and bug triggering, 23 juil, 18h
-----
~#uname -a
Linux Olivier 2.6.25-2-686 #1 SMP Fri Jun 27 03:23:20 UTC 2008 i686 GNU/Linux
/var/log#apt-show-versions | grep image-2.6.25
linux-image-2.6.25-2-686/testing uptodate 2.6.25-6
~#lsmod | grep ide_
ide_disk 13952 3
ide_cd_mod 32864 0
cdrom 31872 1 ide_cd_mod
ide_pci_generic 4228 0 [permanent]
ide_core 100312 4 ide_disk,ide_cd_mod,via82cxxx,ide_pci_generic
~#lspci | grep IDE
00:0f.1 IDE interface: VIA Technologies, Inc. VT82C586A/B/VT82C686/A/B/VT823x/A/C PIPC Bus Master IDE (rev 06)
~#wodim --devices
wodim: Overview of accessible drives (2 found) :
-------------------------------------------------------------------------
0 dev='/dev/hdc' rwrw-- : 'SAMSUNG' 'DVD-ROM SD-616Q'
1 dev='/dev/hdd' rwrw-- : 'PLEXTOR' 'DVDR PX-708A'
-------------------------------------------------------------------------
mounting a CD with mount /dev/hdc and mount /dev/hdd: works (I can read the content). Then I unmount and load an empty DVD in the Plextor drive.
~#hdparm /dev/hdd
/dev/hdd:
IO_support = 1 (32-bit)
unmaskirq = 1 (on)
using_dma = 1 (on)
keepsettings = 0 (off)
readonly = 0 (off)
readahead = 256 (on)
HDIO_GETGEO failed: Inappropriate ioctl for device
~#dvd+rw-mediainfo /dev/hdd
INQUIRY: [PLEXTOR ][DVDR PX-708A ][1.02]
GET [CURRENT] CONFIGURATION:
Mounted Media: 11h, DVD-R Sequential
Current Write Speed: 4.0x1385=5540KB/s
Write Speed #0: 4.0x1385=5540KB/s
Write Speed #1: 2.0x1385=2770KB/s
Write Speed #2: 1.0x1385=1385KB/s
GET [CURRENT] PERFORMANCE:
Write Performance: 4.0x1385=5540KB/s@[0 -> 2294911]
Speed Descriptor#0: 02/2298495 R@8.0x1385=11080KB/s W@4.0x1385=5540KB/s
Speed Descriptor#1: 02/2298495 R@8.0x1385=11080KB/s W@2.0x1385=2770KB/s
Speed Descriptor#2: 02/2298495 R@8.0x1385=11080KB/s W@1.0x1385=1385KB/s
READ DVD STRUCTURE[#0h]:
Media Book Type: 00h, DVD-ROM book [revision 0]
Legacy lead-out at: 2298496*2KB=4707319808
READ DISC INFORMATION:
Disc status: blank
Number of Sessions: 1
State of Last Session: empty
"Next" Track: 1
Number of Tracks: 1
READ TRACK INFORMATION[#1]:
Track State: invisible incremental
Track Start Address: 0*2KB
Next Writable Address: 0*2KB
Free Blocks: 2297888*2KB
Track Size: 2297888*2KB
READ CAPACITY: 0*2048=0
~#wodim dev=/dev/hdd -dummy Fedora-9-x86_64-DVD.iso
wodim: No write mode specified.
wodim: Asuming -tao mode.
wodim: Future versions of wodim may have different drive dependent defaults.
Device type : Removable CD-ROM
Version : 0
Response Format: 1
Vendor_info : 'PLEXTOR '
Identification : 'DVDR PX-708A '
Revision : '1.02'
Device seems to be: Generic mmc2 DVD-R/DVD-RW.
Using generic SCSI-3/mmc DVD-R(W) driver (mmc_mdvd).
Driver flags : SWABAUDIO BURNFREE
Supported modes: PACKET SAO
HINT: use dvd+rw-mediainfo from dvd+rw-tools for information extraction.
Speed set to 5540 KB/s
Starting to write CD/DVD at speed 4.0 in dummy unknown mode for single session.
Last chance to quit, starting dummy write in 0 seconds. Operation starts.
Track 01: Total bytes read/written: 4163696640/4163696640 (2033055 sectors).
~#wodim dev=/dev/hdd -dummy -speed=1 -v Fedora-9-x86_64-DVD.iso
wodim: No write mode specified.
wodim: Asuming -tao mode.
wodim: Future versions of wodim may have different drive dependent defaults.
TOC Type: 1 = CD-ROM
scsidev: '/dev/hdd'
devname: '/dev/hdd'
scsibus: -2 target: -2 lun: -2
Linux sg driver version: 3.5.27
Wodim version: 1.1.8
SCSI buffer size: 64512
Device type : Removable CD-ROM
Version : 0
Response Format: 1
Vendor_info : 'PLEXTOR '
Identification : 'DVDR PX-708A '
Revision : '1.02'
Device seems to be: Generic mmc2 DVD-R/DVD-RW.
Current: 0x0011 (DVD-R sequential recording)
Profile: 0x001B (DVD+R)
Profile: 0x001A (DVD+RW)
Profile: 0x0014 (DVD-RW sequential recording)
Profile: 0x0013 (DVD-RW restricted overwrite)
Profile: 0x0011 (DVD-R sequential recording) (current)
Profile: 0x0010 (DVD-ROM)
Profile: 0x000A (CD-RW)
Profile: 0x0009 (CD-R)
Profile: 0x0008 (CD-ROM)
Using generic SCSI-3/mmc DVD-R(W) driver (mmc_mdvd).
Driver flags : SWABAUDIO BURNFREE
Supported modes: PACKET SAO
Drive buf size : 1036288 = 1012 KB
Beginning DMA speed test. Set CDR_NODMATEST environment variable if device
communication breaks or freezes immediately after that.
Drive DMA Speed: 26439 kB/s 150x CD 19x DVD
FIFO size : 12582912 = 12288 KB
Track 01: data 3970 MB
Total size: 4560 MB (451:47.40) = 2033055 sectors
Lout start: 4560 MB (451:49/30) = 2033055 sectors
Current Secsize: 2048
HINT: use dvd+rw-mediainfo from dvd+rw-tools for information extraction.
Blocks total: 2298496 Blocks current: 2298496 Blocks remaining: 265441
Speed set to 1385 KB/s
Starting to write CD/DVD at speed 1.0 in dummy unknown mode for single session.
Last chance to quit, starting dummy write in 0 seconds. Operation starts.
Waiting for reader process to fill input buffer ... input buffer ready.
Starting new track at sector: 0
Track 01: 0 of 3970 MB written.Errno: 0 (Success), write_g1 scsi sendcmd: no error
CDB: 2A 00 00 00 00 00 00 00 1F 00
status: 0x7f (Reserved)
Sense Bytes:
Sense Key: 0xFFFFFFFF [], Segment 0
Sense Code: 0x00 Qual 0x00 (no additional sense information) Fru 0x0
Sense flags: Blk 0 (not valid)
resid: 63488
cmd finished after 1.499s timeout 40s
write track data: error after 0 bytes
wodim: A write error occured.
wodim: Please properly read the error message above.
Errno: 0 (Success), test unit ready scsi sendcmd: no error
CDB: 00 00 00 00 00 00
status: 0x7f (Reserved)
Sense Bytes:
Sense Key: 0xFFFFFFFF [], Segment 0
Sense Code: 0x00 Qual 0x00 (no additional sense information) Fru 0x0
Sense flags: Blk 0 (not valid)
cmd finished after 0.199s timeout 40s
Errno: 0 (Success), test unit ready scsi sendcmd: no error
CDB: 00 00 00 00 00 00
status: 0x7f (Reserved)
Sense Bytes:
Sense Key: 0xFFFFFFFF [], Segment 0
Sense Code: 0x00 Qual 0x00 (no additional sense information) Fru 0x0
Sense flags: Blk 0 (not valid)
cmd finished after 0.000s timeout 40s
Writing time: 83.845s
Average write speed 35.9x.
Fixating...
Errno: 0 (Success), flush cache scsi sendcmd: no error
CDB: 35 00 00 00 00 00 00 00 00 00
status: 0x7f (Reserved)
Sense Bytes:
Sense Key: 0xFFFFFFFF [], Segment 0
Sense Code: 0x00 Qual 0x00 (no additional sense information) Fru 0x0
Sense flags: Blk 0 (not valid)
cmd finished after 0.000s timeout 120s
Trouble flushing the cache
Fixating time: 0.000s
Errno: 0 (Success), prevent/allow medium removal scsi sendcmd: no error
CDB: 1E 00 00 00 00 00
status: 0x7f (Reserved)
Sense Bytes:
Sense Key: 0xFFFFFFFF [], Segment 0
Sense Code: 0x00 Qual 0x00 (no additional sense information) Fru 0x0
Sense flags: Blk 0 (not valid)
cmd finished after 0.000s timeout 40s
wodim: fifo had 196 puts and 5 gets.
wodim: fifo was 0 times empty and 4 times full, min fill was 99%.
~#cat /var/log/syslog | grep "Jul 23 18:3.:.. Olivier kernel" | head -n 40
Jul 23 18:30:46 Olivier kernel: [626344.006911] hdd: DMA timeout retry
Jul 23 18:30:46 Olivier kernel: [626344.006921] hdd: timeout waiting for DMA
Jul 23 18:30:51 Olivier kernel: [626344.206645] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:30:51 Olivier kernel: [626344.206645] ide: failed opcode was: unknown
Jul 23 18:30:51 Olivier kernel: [626344.206645] hdd: drive not ready for command
Jul 23 18:30:51 Olivier kernel: [626344.206645] Clocksource tsc unstable (delta = 4686793483 ns)
Jul 23 18:30:56 Olivier kernel: [626354.433190] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:30:56 Olivier kernel: [626354.433204] ide: failed opcode was: unknown
Jul 23 18:30:56 Olivier kernel: [626354.433217] hdd: drive not ready for command
Jul 23 18:31:02 Olivier kernel: [626359.557505] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:31:02 Olivier kernel: [626359.557505] ide: failed opcode was: unknown
Jul 23 18:31:02 Olivier kernel: [626359.557505] hdd: drive not ready for command
Jul 23 18:31:07 Olivier kernel: [626369.978204] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:31:07 Olivier kernel: [626369.978216] ide: failed opcode was: unknown
Jul 23 18:31:07 Olivier kernel: [626369.978225] hdd: drive not ready for command
Jul 23 18:31:12 Olivier kernel: [626370.173894] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:31:12 Olivier kernel: [626370.173894] ide: failed opcode was: unknown
Jul 23 18:31:12 Olivier kernel: [626370.173894] hdd: drive not ready for command
Jul 23 18:31:17 Olivier kernel: [626375.462320] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:31:17 Olivier kernel: [626375.462320] ide: failed opcode was: unknown
Jul 23 18:31:17 Olivier kernel: [626375.462320] hdd: drive not ready for command
Jul 23 18:31:23 Olivier kernel: [626385.686618] hdd: status timeout: status=0xd0 { Busy }
Jul 23 18:31:23 Olivier kernel: [626385.686631] ide: failed opcode was: unknown
Jul 23 18:31:23 Olivier kernel: [626385.686655] hdd: drive not ready for command
Jul 23 18:31:24 Olivier kernel: [626385.766789] hdd: status error: status=0x7f { DriveReady DeviceFault SeekComplete DataRequest CorrectedError Index Error }
Jul 23 18:31:24 Olivier kernel: [626385.766789] hdd: status error: error=0x7f { IllegalLengthIndication EndOfMedia AbortedCommand MediaChangeRequested LastFailedSense=0x07 }
Jul 23 18:31:24 Olivier kernel: [626385.766789] ide: failed opcode was: unknown
Jul 23 18:31:24 Olivier kernel: [626385.766789] hdd: drive not ready for command
Jul 23 18:31:24 Olivier kernel: [626385.766789] hdc: status error: status=0x58 { DriveReady SeekComplete DataRequest }
Jul 23 18:31:24 Olivier kernel: [626385.766789] ide: failed opcode was: unknown
Jul 23 18:31:24 Olivier kernel: [626385.766789] hdc: drive not ready for command
Jul 23 18:31:24 Olivier kernel: [626387.074141] hdd: status error: status=0x7f { DriveReady DeviceFault SeekComplete DataRequest CorrectedError Index Error }
Jul 23 18:31:24 Olivier kernel: [626387.074160] hdd: status error: error=0x7f { IllegalLengthIndication EndOfMedia AbortedCommand MediaChangeRequested LastFailedSense=0x07 }
Jul 23 18:31:24 Olivier kernel: [626387.074169] ide: failed opcode was: unknown
Jul 23 18:31:24 Olivier kernel: [626387.074190] hdd: drive not ready for command
Jul 23 18:31:24 Olivier kernel: [626387.074218] hdc: status error: status=0x58 { DriveReady SeekComplete DataRequest }
Jul 23 18:31:24 Olivier kernel: [626387.074227] ide: failed opcode was: unknown
Jul 23 18:31:24 Olivier kernel: [626387.074239] hdc: drive not ready for command
Jul 23 18:31:24 Olivier kernel: [626387.262548] hdd: status error: status=0x7f { DriveReady DeviceFault SeekComplete DataRequest CorrectedError Index Error }
Jul 23 18:31:24 Olivier kernel: [626387.262566] hdd: status error: error=0x7f { IllegalLengthIndication EndOfMedia AbortedCommand MediaChangeRequested LastFailedSense=0x07 }
(after waiting 10 minutes)
~#tail /var/log/syslog
Jul 23 18:41:14 Olivier kernel: [626984.377825] ide: failed opcode was: unknown
Jul 23 18:41:14 Olivier kernel: [626984.377834] hdd: drive not ready for command
Jul 23 18:41:15 Olivier kernel: [630450.744579] hdd: status error: status=0x7f { DriveReady DeviceFault SeekComplete DataRequest CorrectedError Index Error }
Jul 23 18:41:15 Olivier kernel: [630450.744595] hdd: status error: error=0x7f { IllegalLengthIndication EndOfMedia AbortedCommand MediaChangeRequested LastFailedSense=0x07 }
Jul 23 18:41:15 Olivier kernel: [630450.744605] ide: failed opcode was: unknown
Jul 23 18:41:15 Olivier kernel: [630450.744614] hdd: drive not ready for command
Jul 23 18:41:15 Olivier kernel: [626985.707836] hdd: status error: status=0x7f { DriveReady DeviceFault SeekComplete DataRequest CorrectedError Index Error }
Jul 23 18:41:15 Olivier kernel: [626985.707854] hdd: status error: error=0x7f { IllegalLengthIndication EndOfMedia AbortedCommand MediaChangeRequested LastFailedSense=0x07 }
Jul 23 18:41:15 Olivier kernel: [626985.707863] ide: failed opcode was: unknown
Jul 23 18:41:15 Olivier kernel: [626985.707874] hdd: drive not ready for command
~#rmmod ide_cd_mod
(stops logging kernel errors)
~#lsmod | grep ide_
ide_disk 13952 3
ide_pci_generic 4228 0 [permanent]
ide_core 100312 3 ide_disk,via82cxxx,ide_pci_generic
~#modprobe ide_cd_mod
(begins to log again kernel errors)
~#lsmod | grep ide_
ide_cd_mod 32864 0
ide_disk 13952 3
cdrom 31872 1 ide_cd_mod
ide_pci_generic 4228 0 [permanent]
ide_core 100312 4 ide_cd_mod,ide_disk,via82cxxx,ide_pci_generic
~#eject /dev/hdd
(nothing happens)
The DVD-writer led stays lit. Nothing happens when I press the "eject" button on the drive.
Reply to: