Bug 9346
| Summary: | cd/dvd inaccessible in 2.6.24-rc2 | ||
|---|---|---|---|
| Product: | IO/Storage | Reporter: | Rafael J. Wysocki (rjwysocki) |
| Component: | Other | Assignee: | Tejun Heo (htejun) |
| Status: | CLOSED CODE_FIX | ||
| Severity: | normal | CC: | acpi-bugzilla, akpm, alan, greg, htejun, jgarzik, rwarsow, will, yannick.dirou |
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Kernel Version: | 2.6.24-rc1 | Subsystem: | |
| Regression: | Yes | Bisected commit-id: | |
| Bug Depends on: | |||
| Bug Blocks: | 9243 | ||
| Attachments: |
atapi-drain.patch
improve-eh-reporting.patch atapi-pio-debug.patch bug9346-dbg.patch bug9346-dbg1.patch bug9346-dbg1.patch kernel.log.gz bug9346-dbg2.patch kernel.log.gz bug9346-dbg1.patch kernel.log.gz bug9346-dbg2.patch kernel.log.gz bug9346-dbg.patch bug9346-blank-tout-debug.patch kernel.log.gz bug9346-dbg2.patch + bug9346-blank-tout-debug.patch bug9346-dbg2.patch |
||
|
Description
Rafael J. Wysocki
2007-11-11 10:36:32 UTC
Note that I've got several other reports for different controllers variously reporting no IDE IRQ being delivered or no IDE IRQ being available, all starting with 2.6.24-rc (and I think all -rc2) The ACPI interrupt routing on this board is simple.
in IOAPIC mode, all the wires are hard-coded.
So if we're getting the wrong IRQ for the device, then
it means we'd have to be confused about the pci seg/bus/fun
or something, because the pci-device->irq mapping is constant.
What did /proc/interrupts look like with working 2.6.23
and what do they look like with 2.6.24?
Do you see the same failure with acpi=off?
from the dmesg:
ata9.00: qc timeout (cmd 0xa0)
...
which is this guy (this is the 1st system i've seen reporting 11 ata controllerrs)
ata9: PATA max UDMA/100 cmd 0xc000 ctl 0xc100 bmdma 0xc400 irq 17
ata9.00: ATAPI: BENQ DVD DD DW1640, BSRB, max UDMA/33
ata9.00: configured for UDMA/33
we have some sharing on IRQ 17
ACPI: PCI Interrupt 0000:00:1c.1[B] -> GSI 17 (level, low) -> IRQ 17
ACPI: PCI Interrupt 0000:00:1c.5[B] -> GSI 17 (level, low) -> IRQ 17
Curiously, the lspci shows the controller at a different pci-id --
maybe there is some magic going on with the pci ids?
04:00.1 IDE interface: JMicron Technologies, Inc. JMicron 20360/20363 AHCI Controller (rev 02) (prog-if 85 [Master SecO PriO])
Interrupt: pin B routed to IRQ 17
I tried passing acpi=off in grub, it didn't make a difference. Interrupts also looked to be the same. I mistakenly said I could access the drive at all this is untrue. I am able to mount and transfer files, I can burn a disc with growisofs however wodim and k3b do not work. This is the problem, with wodim if I enter a command like wodim -blank=fast dev=/dev/sr0 With 2.6.23 this happens: wodim -blank=fast dev=/dev/sr0 Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' 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 real BLANK mode for single session. Last chance to quit, starting real write i 0 seconds. Operation starts. and it blanks a rewritable disc, if I do the same thing in 2.6.24rc* it never gets to the "Speed set to 5540 KB/s" and those kernel errors occur. I'm also unable to eject the disc from the drive. Same pattern with k3b, but just opening k3b causes the problem. Before there's any attempt to even burn a disc it's already jammed up. Hope this helps, I doubt I'll be the only person who runs into this problem. just to be sure this is not an interrupt assignment issue, can you paste the /proc/interrupts before and after here? (eg. 2.6.23 and 2.6.24 and 2.6.24 acpi=off) (In reply to comment #3) > I tried passing acpi=off in grub, it didn't make a difference. Interrupts > also > looked to be the same. > > I mistakenly said I could access the drive at all this is untrue. I am able > to > mount and transfer files, I can burn a disc with growisofs however wodim and > k3b do not work. > > This is the problem, with wodim if I enter a command like > > wodim -blank=fast dev=/dev/sr0 > > With 2.6.23 this happens: > > wodim -blank=fast dev=/dev/sr0 > Device type : Removable CD-ROM > Version : 5 > Response Format: 2 > Capabilities : > Vendor_info : 'BENQ ' > Identification : 'DVD DD DW1640 ' > Revision : 'BSRB' > 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 real BLANK mode for single > session. > Last chance to quit, starting real write i 0 seconds. Operation starts. > > and it blanks a rewritable disc, if I do the same thing in 2.6.24rc* it never > gets to the "Speed set to 5540 KB/s" and those kernel errors occur. I'm also > unable to eject the disc from the drive. tried the same and got a hang : wodim: Operation not permitted. Warning: Cannot raise RLIMIT_MEMLOCK limits.Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' Device seems to be: Generic mmc2 DVD-R/DVD-RW. Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr). Driver flags : MMC-3 SWABAUDIO BURNFREE Supported modes: wodim: Cannot load media. and this in syslog : Nov 22 18:14:18 localhost kernel: ata1.00: qc timeout (cmd 0xa0) Nov 22 18:14:18 localhost kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen Nov 22 18:14:18 localhost kernel: ata1.00: cmd a0/00:00:00:02:00/00:00:00:00:00/a0 tag 0 cdb 0x5a data 2 in Nov 22 18:14:18 localhost kernel: res 51/54:03:00:02:00/00:00:00:00:00/a0 Emask 0x5 (timeout) Nov 22 18:14:18 localhost kernel: ata1.00: status: { DRDY ERR } Nov 22 18:14:23 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x90) Nov 22 18:14:28 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 22 18:14:28 localhost kernel: ata1: soft resetting link Nov 22 18:14:28 localhost kernel: ata1.00: revalidation failed (errno=-2) Nov 22 18:14:28 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs Nov 22 18:14:33 localhost kernel: ata1: soft resetting link Nov 22 18:15:04 localhost kernel: ata1.00: qc timeout (cmd 0xa1) Nov 22 18:15:04 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4) Nov 22 18:15:04 localhost kernel: ata1.00: revalidation failed (errno=-5) Nov 22 18:15:04 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs Nov 22 18:15:14 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80) Nov 22 18:15:19 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 22 18:15:19 localhost kernel: ata1: soft resetting link Nov 22 18:15:49 localhost kernel: ata1.00: qc timeout (cmd 0xa1) Nov 22 18:15:49 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4) Nov 22 18:15:49 localhost kernel: ata1.00: revalidation failed (errno=-5) Nov 22 18:15:49 localhost kernel: ata1.00: disabled Nov 22 18:15:55 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80) Nov 22 18:16:00 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 22 18:16:00 localhost kernel: ata1: soft resetting link Nov 22 18:16:00 localhost kernel: ata1: EH complete Created attachment 13775 [details]
atapi-drain.patch
Does this fix the problem?
(In reply to comment #6) > Created an attachment (id=13775) [details] > atapi-drain.patch > > Does this fix the problem? > unfortunately not, but one thing better k3b does not hang at start, then it does that while trying to erase cd: kdecore (KAction): WARNING: KActionCollection::KActionCollection( QObject *parent, const char *name, KInstance *instance ) (K3bDevice::HalConnection) initializing HAL >= 0.5 Mapping udi /org/freedesktop/Hal/devices/storage_model_DVD_DD_DW1640 to device /dev/scd0 /dev/scd0 resolved to /dev/scd0 /dev/scd0 is block device (0) /dev/scd0 seems to be cdrom bus: 0, id: 0, lun: 0 (K3bDevice::Device) /dev/scd0: init() (K3bDevice::Device) /dev/scd0 feature: CD Mastering (K3bDevice::Device) /dev/scd0 feature: CD Track At Once (K3bDevice::Device) /dev/scd0 feature: DVD Read (MMC5) (K3bDevice::Device) /dev/scd0 feature: DVD+R (K3bDevice::Device) /dev/scd0 feature: DVD+RW (K3bDevice::Device) /dev/scd0 feature: DVD+R Double Layer (K3bDevice::Device) /dev/scd0 feature: DVD-R/-RW Write (K3bDevice::Device) /dev/scd0 feature: Rigid Restricted Overwrite (K3bDevice::Device) /dev/scd0 feature: Layer Jump Recording (K3bDevice::Device) /dev/scd0: dataLen: 60 (K3bDevice::Device) /dev/scd0: checking for TAO (K3bDevice::Device) /dev/scd0: checking for SAO (K3bDevice::Device) /dev/scd0: checking for SAO_R96P (K3bDevice::ScsiCommand) failed: command: MODE SELECT (55) errorcode: 70 sense key: ILLEGAL REQUEST (5) asc: 26 ascq: 0 (K3bDevice::Device) /dev/scd0: checking for SAO_R96R (K3bDevice::Device) /dev/scd0: checking for RAW_R16 (K3bDevice::Device) /dev/scd0: checking for RAW_R96P (K3bDevice::ScsiCommand) failed: command: MODE SELECT (55) errorcode: 70 sense key: ILLEGAL REQUEST (5) asc: 26 ascq: 0 (K3bDevice::Device) /dev/scd0: checking for RAW_R96R (K3bDevice::DeviceManager) setting current write speed of device /dev/scd0 to 706 /dev/scd0 resolved to /dev/scd0 (K3bDevice::DeviceManager) dev /dev/scd0 already found (K3bDevice::DeviceManager) found config entry for devicetype: BENQ DVD DD DW1640 DiskInfo: Mediatype: CD-RW Current Profile: CD-RW Disk state: incomplete Empty: 0 Rewritable: 1 Appendable: 1 Sessions: 1 Tracks: 1 Layers: 1 Capacity: 79:57:74 (LBA 359849) (736970752 Bytes) Remaining size: 19:27:33 (LBA 87558) (179318784 Bytes) Used Size: 60:30:41 (LBA 272291) (557651968 Bytes) Session | ADR | CONTROL| TNO | POINT | Min | Sec | Frame | Zero | PMIN | PSEC | PFRAME | 1 | 1 | 4 | 0 | a0 | 97 | 10 | 0 | 0 | 1 | 32 | 0 | 1 | 1 | 4 | 0 | a1 | 97 | 10 | 6 | 0 | 1 | 0 | 0 | 1 | 1 | 4 | 0 | a2 | 97 | 10 | 12 | 0 | 60 | 0 | 41 | 1 | 1 | 4 | 0 | 1 | 97 | 10 | 0 | 0 | 0 | 2 | 0 | 1 | 5 | 4 | 0 | b0 | 62 | 30 | 41 | 3 | 79 | 59 | 74 | 1 | 5 | 4 | 0 | c0 | 209 | 0 | 132 | 0 | 97 | 10 | 0 | 1 | 5 | 0 | 0 | c1 | 2 | 74 | 176 | 0 | 0 | 0 | 0 | (K3bDevice::Device) found invalid bcd values. No bcd toc. Devices: ------------------------------ Blockdevice: /dev/scd0 Generic device: Vendor: BENQ Description: DVD DD DW1640 Version: BSRB Write speed: 0 Profiles: DVD-ROM, DVD-R séquentiel, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+R double couche, CD-ROM, CD-R, CD-RW Read Cap: DVD-ROM, DVD-R, DVD-R séquentiel, DVD+R double couche, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD-RW, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+RW double couche, DVD+R double couche, CD-ROM, CD-R, CD-RW Write Cap: DVD-R, DVD-R séquentiel, DVD+R double couche, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD-RW, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+R double couche, CD-R, CD-RW Writing modes: SAO, TAO, RAW, SAO/R96R, RAW/R16, RAW/R96R, Réinscription restreinte, Saut de couche Reader aliases: /dev/scd0 ------------------------------ kdecore (KAction): WARNING: KActionCollection::operator+=(): function is severely deprecated. /dev/scd0: setting last sector of last track to 269890 (K3bDevice::Device) /dev/scd0: Number of supported write speeds via 2A: 1 (K3bDevice::Device) /dev/scd0 : 706 KB/s k3b: WARNING: Pixmap not found for mimetype inode/directory k3b: WARNING: Pixmap not found for mimetype inode/directory (K3bDevice::HalConnection) lock queued for /org/freedesktop/Hal/devices/storage_model_DVD_DD_DW1640 (K3bDevice::HalConnection) unlock queued for /org/freedesktop/Hal/devices/storage_model_DVD_DD_DW1640 Launched ok, pid = 4305 the syslog is : Nov 28 13:10:27 localhost kernel: ata1.00: qc timeout (cmd 0xa0) Nov 28 13:10:27 localhost kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen Nov 28 13:10:27 localhost kernel: ata1.00: cmd a0/00:00:00:02:00/00:00:00:00:00/a0 tag 0 cdb 0x5a data 2 in Nov 28 13:10:27 localhost kernel: res 51/54:03:00:02:00/00:00:00:00:00/a0 Emask 0x5 (timeout) Nov 28 13:10:27 localhost kernel: ata1.00: status: { DRDY ERR } Nov 28 13:10:32 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x90) Nov 28 13:10:37 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 28 13:10:37 localhost kernel: ata1: soft resetting link Nov 28 13:10:37 localhost kernel: ata1.00: revalidation failed (errno=-2) Nov 28 13:10:37 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs Nov 28 13:10:42 localhost kernel: ata1: soft resetting link Nov 28 13:11:13 localhost kernel: ata1.00: qc timeout (cmd 0xa1) Nov 28 13:11:13 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4) Nov 28 13:11:13 localhost kernel: ata1.00: revalidation failed (errno=-5) Nov 28 13:11:13 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs Nov 28 13:11:23 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80) Nov 28 13:11:28 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 28 13:11:28 localhost kernel: ata1: soft resetting link Nov 28 13:11:57 localhost ntpd[3755]: synchronized to 91.189.94.4, stratum 2 Nov 28 13:11:57 localhost ntpd[3755]: kernel time sync status change 0001 Nov 28 13:11:58 localhost kernel: ata1.00: qc timeout (cmd 0xa1) Nov 28 13:11:58 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4) Nov 28 13:11:58 localhost kernel: ata1.00: revalidation failed (errno=-5) Nov 28 13:11:58 localhost kernel: ata1.00: disabled thanks anyway Created attachment 13779 [details]
improve-eh-reporting.patch
Ah.. okay, so that wasn't enough. Can you please apply the attached patch on top of atapi-drain.patch and report the result. Thanks.
(In reply to comment #8) > Created an attachment (id=13779) [details] > improve-eh-reporting.patch > > Ah.. okay, so that wasn't enough. Can you please apply the attached patch on > top of atapi-drain.patch and report the result. Thanks. > (In reply to comment #8) > Created an attachment (id=13779) [details] > improve-eh-reporting.patch > > Ah.. okay, so that wasn't enough. Can you please apply the attached patch on > top of atapi-drain.patch and report the result. Thanks. > ok, k3b output : kdecore (KAction): WARNING: KActionCollection::KActionCollection( QObject *parent, const char *name, KInstance *instance ) (K3bDevice::HalConnection) initializing HAL >= 0.5 Mapping udi /org/freedesktop/Hal/devices/storage_model_DVD_DD_DW1640 to device /dev/scd0 /dev/scd0 resolved to /dev/scd0 /dev/scd0 is block device (0) /dev/scd0 seems to be cdrom bus: 0, id: 0, lun: 0 (K3bDevice::Device) /dev/scd0: init() (K3bDevice::Device) /dev/scd0 feature: CD Mastering (K3bDevice::Device) /dev/scd0 feature: CD Track At Once (K3bDevice::Device) /dev/scd0 feature: DVD Read (MMC5) (K3bDevice::Device) /dev/scd0 feature: DVD+R (K3bDevice::Device) /dev/scd0 feature: DVD+RW (K3bDevice::Device) /dev/scd0 feature: DVD+R Double Layer (K3bDevice::Device) /dev/scd0 feature: DVD-R/-RW Write (K3bDevice::Device) /dev/scd0 feature: Rigid Restricted Overwrite (K3bDevice::Device) /dev/scd0 feature: Layer Jump Recording (K3bDevice::Device) /dev/scd0: dataLen: 60 (K3bDevice::Device) /dev/scd0: checking for TAO (K3bDevice::Device) /dev/scd0: checking for SAO (K3bDevice::Device) /dev/scd0: checking for SAO_R96P (K3bDevice::ScsiCommand) failed: command: MODE SELECT (55) errorcode: 70 sense key: ILLEGAL REQUEST (5) asc: 26 ascq: 0 (K3bDevice::Device) /dev/scd0: checking for SAO_R96R (K3bDevice::Device) /dev/scd0: checking for RAW_R16 (K3bDevice::Device) /dev/scd0: checking for RAW_R96P (K3bDevice::ScsiCommand) failed: command: MODE SELECT (55) errorcode: 70 sense key: ILLEGAL REQUEST (5) asc: 26 ascq: 0 (K3bDevice::Device) /dev/scd0: checking for RAW_R96R (K3bDevice::Device) /dev/scd0: GET PERFORMANCE dataLen = 120 (K3bDevice::Device) /dev/scd0: GET PERFORMANCE successful with reported length: 116 (K3bDevice::Device) /dev/scd0: Number of supported write speeds via GET PERFORMANCE: 7 (K3bDevice::Device) /dev/scd0 : 8466 KB/s (K3bDevice::Device) /dev/scd0 : 7056 KB/s (K3bDevice::Device) /dev/scd0 : 5645 KB/s (K3bDevice::Device) /dev/scd0 : 4234 KB/s (K3bDevice::Device) /dev/scd0 : 2822 KB/s (K3bDevice::Device) /dev/scd0 : 2117 KB/s (K3bDevice::Device) /dev/scd0 : 1411 KB/s (K3bDevice::DeviceManager) setting current write speed of device /dev/scd0 to 3324 /dev/scd0 resolved to /dev/scd0 (K3bDevice::DeviceManager) dev /dev/scd0 already found (K3bDevice::DeviceManager) found config entry for devicetype: BENQ DVD DD DW1640 Devices: ------------------------------ Blockdevice: /dev/scd0 Generic device: Vendor: BENQ Description: DVD DD DW1640 Version: BSRB Write speed: 0 Profiles: DVD-ROM, DVD-R séquentiel, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+R double couche, CD-ROM, CD-R, CD-RW Read Cap: DVD-ROM, DVD-R, DVD-R séquentiel, DVD+R double couche, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD-RW, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+RW double couche, DVD+R double couche, CD-ROM, CD-R, CD-RW Write Cap: DVD-R, DVD-R séquentiel, DVD+R double couche, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD-RW, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+R double couche, CD-R, CD-RW Writing modes: SAO, TAO, RAW, SAO/R96R, RAW/R16, RAW/R96R, Réinscription restreinte, Saut de couche Reader aliases: /dev/scd0 ------------------------------ kdecore (KAction): WARNING: KActionCollection::operator+=(): function is severely deprecated. k3b: WARNING: Pixmap not found for mimetype inode/directory k3b: WARNING: Pixmap not found for mimetype inode/directory DiskInfo: Mediatype: CD-RW Current Profile: CD-RW Disk state: incomplete Empty: 0 Rewritable: 1 Appendable: 1 Sessions: 1 Tracks: 1 Layers: 1 Capacity: 79:57:74 (LBA 359849) (736970752 Bytes) Remaining size: 19:27:33 (LBA 87558) (179318784 Bytes) Used Size: 60:30:41 (LBA 272291) (557651968 Bytes) Session | ADR | CONTROL| TNO | POINT | Min | Sec | Frame | Zero | PMIN | PSEC | PFRAME | 1 | 1 | 4 | 0 | a0 | 97 | 10 | 0 | 0 | 1 | 32 | 0 | 1 | 1 | 4 | 0 | a1 | 97 | 10 | 6 | 0 | 1 | 0 | 0 | 1 | 1 | 4 | 0 | a2 | 97 | 10 | 12 | 0 | 60 | 0 | 41 | 1 | 1 | 4 | 0 | 1 | 97 | 10 | 0 | 0 | 0 | 2 | 0 | 1 | 5 | 4 | 0 | b0 | 62 | 30 | 41 | 3 | 79 | 59 | 74 | 1 | 5 | 4 | 0 | c0 | 209 | 0 | 132 | 0 | 97 | 10 | 0 | 1 | 5 | 0 | 0 | c1 | 2 | 74 | 176 | 0 | 0 | 0 | 0 | (K3bDevice::Device) found invalid bcd values. No bcd toc. /dev/scd0: setting last sector of last track to 269890 (K3bDevice::Device) /dev/scd0: Number of supported write speeds via 2A: 1 (K3bDevice::Device) /dev/scd0 : 706 KB/s (K3bDevice::HalConnection) lock queued for /org/freedesktop/Hal/devices/storage_model_DVD_DD_DW1640 (K3bDevice::HalConnection) unlock queued for /org/freedesktop/Hal/devices/storage_model_DVD_DD_DW1640 syslog: Nov 28 16:10:44 localhost kernel: ata1.00: qc timeout (cmd 0xa0) Nov 28 16:10:44 localhost kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen Nov 28 16:10:44 localhost kernel: ata1.00: cmd a0/00:00:00:02:00/00:00:00:00:00/a0 tag 0 pio 2 in Nov 28 16:10:44 localhost kernel: cdb 5a 00 30 00 00 00 00 00 02 00 00 00 00 00 00 00 Nov 28 16:10:44 localhost kernel: res 51/54:03:00:02:00/00:00:00:00:00/a0 Emask 0x5 (timeout) Nov 28 16:10:44 localhost kernel: ata1.00: status: { DRDY ERR } Nov 28 16:10:49 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x90) Nov 28 16:10:54 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 28 16:10:54 localhost kernel: ata1: soft resetting link Nov 28 16:10:54 localhost kernel: ata1.00: revalidation failed (errno=-2) Nov 28 16:10:54 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs Nov 28 16:10:59 localhost kernel: ata1: soft resetting link Nov 28 16:11:30 localhost kernel: ata1.00: qc timeout (cmd 0xa1) Nov 28 16:11:30 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4) Nov 28 16:11:30 localhost kernel: ata1.00: revalidation failed (errno=-5) Nov 28 16:11:30 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs Nov 28 16:11:40 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80) Nov 28 16:11:45 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 28 16:11:45 localhost kernel: ata1: soft resetting link Nov 28 16:12:15 localhost kernel: ata1.00: qc timeout (cmd 0xa1) Nov 28 16:12:15 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4) Nov 28 16:12:15 localhost kernel: ata1.00: revalidation failed (errno=-5) Nov 28 16:12:15 localhost kernel: ata1.00: disabled Nov 28 16:12:21 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80) Nov 28 16:12:26 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset Nov 28 16:12:26 localhost kernel: ata1: soft resetting link Nov 28 16:12:26 localhost kernel: ata1: EH complete k3b log : ystem ----------------------- K3b Version: 1.0.4 KDE Version: 3.5.8 QT Version: 3.3.7 Kernel: 2.6.24-rc3-yann96 Devices ----------------------- BENQ DVD DD DW1640 BSRB (/dev/scd0, ) [CD-R, CD-RW, CD-ROM, DVD-ROM, DVD-R, DVD-RW, DVD-R DL, DVD+R, DVD+RW, DVD+R DL] [DVD-ROM, DVD-R séquentiel, DVD-R double couche séquentiel, DVD+R double couche à saut, DVD RW à réinscription limitée, DVD-RW séquentiel, DVD+RW, DVD+R, DVD+R double couche, CD-ROM, CD-R, CD-RW] [SAO, TAO, RAW, SAO/R96R, RAW/R16, RAW/R96R, Réinscription restreinte, Saut de couche] Used versions ----------------------- cdrecord: 1.1.6 cdrecord command: ----------------------- /usr/bin/wodim -v gracetime=2 dev=/dev/scd0 speed=4 -tao driveropts=burnfree -eject blank=fast -force cdrecord ----------------------- /usr/bin/wodim: Operation not permitted. Warning: Cannot raise RLIMIT_MEMLOCK limits.scsidev: '/dev/scd0' devname: '/dev/scd0' scsibus: -2 target: -2 lun: -2 Linux sg driver version: 3.5.27 Wodim version: 1.1.6 SCSI buffer size: 64512 Beginning DMA speed test. Set CDR_NODMATEST environment variable if device communication breaks or freezes immediately after that. TOC Type: 1 = CD-ROM Driveropts: 'burnfree' Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' Device seems to be: Generic mmc2 DVD-R/DVD-RW. Current: 0x000A (CD-RW) Profile: 0x002B (DVD+R/DL) Profile: 0x001B (DVD+R) Profile: 0x001A (DVD+RW) Profile: 0x0016 (DVD-R/DL layer jump recording) Profile: 0x0015 (DVD-R/DL sequential recording) Profile: 0x0014 (DVD-RW sequential recording) Profile: 0x0013 (DVD-RW restricted overwrite) Profile: 0x0011 (DVD-R sequential recording) Profile: 0x0010 (DVD-ROM) Profile: 0x000A (CD-RW) (current) Profile: 0x0009 (CD-R) Profile: 0x0008 (CD-ROM) Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr). Driver flags : MMC-3 SWABAUDIO BURNFREE Supported modes: Current Secsize: 0 Errno: 5 (Input/output error), read disk info scsi sendcmd: fatal error CDB: 51 00 00 00 00 00 00 00 04 00 cmd finished after 0.000s timeout 240s /usr/bin/wodim: Cannot get disk type. /usr/bin/wodim: Cannot init drive. /usr/bin/wodim: Cannot eject media. Thanks, can you please give a shot at the following git tree? If you can't, I can provide a tarball. Just lemme know. git://git.kernel.org/pub/scm/linux/kernel/git/tj/libata-dev.git improve-ATAPI-data-transfer Eh... bugzilla broke the line "improve-ATAPI-data-transfer" part is the branch. Thanks. Hello TJ, Exactly how do I checkout the source ? I can get the main one with .... git clone git://git.kernel.org/pub/scm/linux/kernel/git/tj/libata-dev.git But when I do "git show-branch" there are no branches listed. Regards, Will On Wed, 2007-11-28 at 17:18 -0800, bugme-daemon@bugzilla.kernel.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=9346 > > > > > > ------- Comment #11 from htejun@gmail.com 2007-11-28 17:18 ------- > Eh... bugzilla broke the line "improve-ATAPI-data-transfer" part is the > branch. > Thanks. > > Hmmm... it should have brought it. You can fetch and checkout the branch by... $ git fetch git://git.kernel.org/pub/scm/linux/kernel/git/tj/libata-dev.git improve-ATAPI-data-transfer:improve-ATAPI-data-transfer $ git checkout improve-ATAPI-data-transfer (again, w/o the line break). (In reply to comment #13) > Hmmm... it should have brought it. You can fetch and checkout the branch > by... > > $ git fetch git://git.kernel.org/pub/scm/linux/kernel/git/tj/libata-dev.git > improve-ATAPI-data-transfer:improve-ATAPI-data-transfer > $ git checkout improve-ATAPI-data-transfer > > (again, w/o the line break). > good news Tejun, i can erase and burn a cdrw seems to work ok except for end of end of burn reporting in k3b (had to "cancel" the burn even if i was done) and it did not recognize the cd in gnome after that and closing k3b then, reboot and it saw the cd, and i could play a video on it nothing interesting in the logs as far as i can find. Now i have to find out how to use git branches to get back to linus rc*** ;-) thanks a lot You probably need to eject and reload the media. Some drives get confused after burning a media. Also, we're not done yet, we need to find fix for 2.6.24-rcX. I'll post a patch soon. Thanks. Hmmm... weird. I can't reproduce your problem here. Can you hook your dvd driver to SATA controller w/ SFF interface - for example, ata_piix or sata_sil? I wanna see how the drive handles 2 byte data transfer. Thanks. uh ??? my lsmod is like this with a cd in : Module Size Used by nls_utf8 2560 1 isofs 30756 1 zlib_inflate 15872 1 isofs udf 78628 0 binfmt_misc 9352 1 radeon 119840 2 drm 67860 3 radeon battery 11524 0 video 17936 0 backlight 4740 1 video output 3584 1 video container 4608 0 ac 5380 0 nls_iso8859_1 4736 2 nls_cp437 6400 2 vfat 10880 2 fat 43548 1 vfat snd_hda_intel 75932 1 snd_pcm 58244 1 snd_hda_intel evdev 9344 3 snd_seq 43984 0 snd_timer 18692 2 snd_pcm,snd_seq snd_seq_device 7052 1 snd_seq snd 37496 7 snd_hda_intel,snd_pcm,snd_seq,snd_timer,snd_seq_device soundcore 6880 1 snd snd_page_alloc 8328 2 snd_hda_intel,snd_pcm intel_agp 21780 0 button 7312 0 rtc 7700 0 pcspkr 3200 0 ext3 110216 2 jbd 42516 1 ext3 mbcache 7296 1 ext3 sd_mod 23680 8 sr_mod 13860 1 cdrom 33184 1 sr_mod usbhid 25728 0 hid 32640 1 usbhid usb_storage 34304 0 ehci_hcd 29452 0 e100 31500 0 mii 5376 1 e100 ahci 23300 6 ata_piix 14468 1 uhci_hcd 22028 0 usbcore 109112 4 usbhid,usb_storage,ehci_hcd,uhci_hcd unix 22832 755 thermal 16028 0 processor 36168 1 thermal fan 4228 0 fuse 39700 3 ata_piix seems to be in use Hello TJ, Just to state the obvious. There are two of us with this problem, and what is common in both situations is we have the exact same DVD burner with exactly the same firmware version. I'm no expert but i'd assume then that the problem might be specific to the drive. Regards, Will On Thu, 2007-11-29 at 07:02 -0800, bugme-daemon@bugzilla.kernel.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=9346 > > > > > > ------- Comment #16 from htejun@gmail.com 2007-11-29 07:02 ------- > Hmmm... weird. I can't reproduce your problem here. Can you hook your dvd > driver to SATA controller w/ SFF interface - for example, ata_piix or > sata_sil? > I wanna see how the drive handles 2 byte data transfer. > > Thanks. > > Yeah, that's what I'm thinking too and I wanna find out how the device behaves. AHCI interface implements PIO HSM in hardware and I can't tell much about what's going on. SFF compliant controllers like ata_piix or sata_sil use software PIO HSM implementation so by sprinkling printks properly we can see what's going on. If you're on intel ICHs, put the controller into native IDE mode in BIOS will give you ata_piix ports instead of ahcis. If your drive is connected to an add-on card like JMicrons, you'll need to move it to the port coming out of ICHs. Please lemme know if you can make such configuration. I'll post a debug patch. Thanks. ah ok, i can disable ahci in bios and i did $ lsmod | grep ata_piix ata_piix 14468 6 Now ready to test your patch (even if the problem is specific to the drive, maybe buggy, but quite common, it worked with 2.6.23 so it is a kind of regression...) Yannick, please post the result of "lspci -nn" and kernel boot log. I'll post a patch soon. Created attachment 13805 [details]
atapi-pio-debug.patch
Here you go.
(In reply to comment #21) > Yannick, please post the result of "lspci -nn" and kernel boot log. I'll > post > a patch soon. > here it is : ~$ lspci -nn 00:00.0 Host bridge [0600]: Intel Corporation 82945G/GZ/P/PL Memory Controller Hub [8086:2770] (rev 02) 00:01.0 PCI bridge [0604]: Intel Corporation 82945G/GZ/P/PL PCI Express Root Port [8086:2771] (rev 02) 00:1b.0 Audio device [0403]: Intel Corporation 82801G (ICH7 Family) High Definition Audio Controller [8086:27d8] (rev 01) 00:1c.0 PCI bridge [0604]: Intel Corporation 82801G (ICH7 Family) PCI Express Port 1 [8086:27d0] (rev 01) 00:1d.0 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #1 [8086:27c8] (rev 01) 00:1d.1 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #2 [8086:27c9] (rev 01) 00:1d.2 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #3 [8086:27ca] (rev 01) 00:1d.3 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #4 [8086:27cb] (rev 01) 00:1d.7 USB Controller [0c03]: Intel Corporation 82801G (ICH7 Family) USB2 EHCI Controller [8086:27cc] (rev 01) 00:1e.0 PCI bridge [0604]: Intel Corporation 82801 PCI Bridge [8086:244e] (rev e1) 00:1f.0 ISA bridge [0601]: Intel Corporation 82801GB/GR (ICH7 Family) LPC Interface Bridge [8086:27b8] (rev 01) 00:1f.1 IDE interface [0101]: Intel Corporation 82801G (ICH7 Family) IDE Controller [8086:27df] (rev 01) 00:1f.2 IDE interface [0101]: Intel Corporation 82801GB/GR/GH (ICH7 Family) SATA IDE Controller [8086:27c0] (rev 01) 00:1f.3 SMBus [0c05]: Intel Corporation 82801G (ICH7 Family) SMBus Controller [8086:27da] (rev 01) 01:00.0 VGA compatible controller [0300]: ATI Technologies Inc RV370 5B60 [Radeon X300 (PCIE)] [1002:5b60] 01:00.1 Display controller [0380]: ATI Technologies Inc RV370 [Radeon X300SE] [1002:5b70] 03:08.0 Ethernet controller [0200]: Intel Corporation 82801G (ICH7 Family) LAN Controller [8086:27dc] (rev 01) and $ dmesg Table [SSDT](id 0004) - 5 Objects with 0 Devices 3 Methods 0 Regions Parsing all Control Methods: Table [SSDT](id 0005) - 10 Objects with 0 Devices 4 Methods 0 Regions tbxface-0598 [00] tb_load_namespace : ACPI Tables successfully acquired evxfevnt-0091 [00] enable : Transition to ACPI mode successful CPU0: Intel(R) Pentium(R) 4 CPU 3.20GHz stepping 03 SMP alternatives: switching to SMP code Booting processor 1/1 eip 3000 Initializing CPU#1 Calibrating delay using timer specific routine.. 6383.99 BogoMIPS (lpj=3191998) CPU: After generic identify, caps: bfebfbff 20100000 00000000 00000000 0000649d 00000000 00000000 00000000 monitor/mwait feature present. CPU: Trace cache: 12K uops, L1 D cache: 16K CPU: L2 cache: 2048K CPU: Physical Processor ID: 0 CPU: After all inits, caps: bfebfbff 20100000 00000000 0000b180 0000649d 00000000 00000000 00000000 Intel machine check architecture supported. Intel machine check reporting enabled on CPU#1. CPU1: Intel P4/Xeon Extended MCE MSRs (24) available CPU1: Thermal monitoring enabled CPU1: Intel(R) Pentium(R) 4 CPU 3.20GHz stepping 03 Total of 2 processors activated (12772.29 BogoMIPS). ENABLING IO-APIC IRQs ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1 checking TSC synchronization [CPU#0 -> CPU#1]: passed. Brought up 2 CPUs net_namespace: 64 bytes NET: Registered protocol family 16 ACPI: bus type pci registered PCI: Found Intel Corporation 945G/GZ/P/PL Express Memory Controller Hub without MMCONFIG support. PCI: PCI BIOS revision 2.10 entry at 0xfb93c, last bus=3 PCI: Using configuration type 1 Setting up standard PCI resources evgpeblk-0956 [00] ev_create_gpe_block : GPE 00 to 1F [_GPE] 4 regs on int 0x9 evgpeblk-1052 [00] ev_initialize_gpe_bloc: Found 11 Wake, Enabled 1 Runtime GPEs in this block ACPI: EC: Look up EC in DSDT Completing Region/Field/Buffer/Package initialization:..................................................... Initialized 21/25 Regions 0/0 Fields 8/8 Buffers 24/36 Packages (425 nodes) Initializing Device/Processor/Thermal objects by executing _INI methods:.<4>ACPI: System BIOS is requesting _OSI(Linux) ACPI: If "acpi_osi=Linux" works better, Please send dmidecode to linux-acpi@vger.kernel.org .... Executed 5 _INI methods requiring 4 _STA executions (examined 40 objects) ACPI: Interpreter enabled ACPI: (supports S0 S1 S3 S4 S5) ACPI: Using IOAPIC for interrupt routing ACPI: PCI Root Bridge [PCI0] (0000:00) PCI quirk: region 0800-087f claimed by ICH6 ACPI/GPIO/TCO PCI quirk: region 0880-08bf claimed by ICH6 GPIO PCI: Transparent bridge - 0000:00:1e.0 ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI4._PRT] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI2._PRT] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI1._PRT] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 10 *11 12 15) ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 *9 10 11 12 15) ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 *5 6 7 9 10 11 12 15) ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 11 12 15) *0, disabled. ACPI: PCI Interrupt Link [LNKE] (IRQs *3 4 5 6 7 9 10 11 12 15) ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 *10 11 12 15) ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 *9 10 11 12 15) ACPI: PCI Interrupt Link [LNKH] (IRQs 3 *4 5 6 7 9 10 11 12 15) Linux Plug and Play Support v0.97 (c) Adam Belay pnp: PnP ACPI init ACPI: bus type pnp registered pnp: PnP ACPI: found 8 devices ACPI: ACPI bus type pnp unregistered SCSI subsystem initialized libata version 3.00 loaded. PCI: Using ACPI for IRQ routing PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 hpet0: 3 64-bit timers, 14318180 Hz Time: tsc clocksource has been installed. Switched to high resolution mode on CPU 0 Switched to high resolution mode on CPU 1 system 00:01: ioport range 0x800-0x85f has been reserved system 00:01: ioport range 0xc00-0xc7f has been reserved system 00:01: ioport range 0x860-0x8ff could not be reserved system 00:06: iomem range 0x0-0x9ffff could not be reserved system 00:06: iomem range 0x100000-0xffffff could not be reserved system 00:06: iomem range 0x1000000-0x3fe88bff could not be reserved system 00:06: iomem range 0xf0000-0xfffff could not be reserved system 00:07: ioport range 0x100-0x1fe could not be reserved system 00:07: ioport range 0x200-0x277 has been reserved system 00:07: ioport range 0x280-0x2e7 has been reserved system 00:07: ioport range 0x2e8-0x2ef has been reserved system 00:07: ioport range 0x2f0-0x2f7 has been reserved system 00:07: ioport range 0x2f8-0x2ff has been reserved system 00:07: ioport range 0x300-0x377 could not be reserved system 00:07: ioport range 0x380-0x3bb has been reserved system 00:07: iomem range 0xf0000000-0xf3ffffff could not be reserved system 00:07: iomem range 0xfeda0000-0xfedacfff has been reserved PCI: Bridge: 0000:00:01.0 IO window: d000-dfff MEM window: efd00000-efefffff PREFETCH window: ec000000-edffffff PCI: Bridge: 0000:00:1c.0 IO window: disabled. MEM window: efc00000-efcfffff PREFETCH window: disabled. PCI: Bridge: 0000:00:1e.0 IO window: c000-cfff MEM window: efb00000-efbfffff PREFETCH window: disabled. ACPI: PCI Interrupt 0000:00:01.0[A] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:01.0 to 64 ACPI: PCI Interrupt 0000:00:1c.0[A] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:1c.0 to 64 PCI: Setting latency timer of device 0000:00:1e.0 to 64 NET: Registered protocol family 2 IP route cache hash table entries: 32768 (order: 5, 131072 bytes) TCP established hash table entries: 131072 (order: 8, 1048576 bytes) TCP bind hash table entries: 65536 (order: 7, 786432 bytes) TCP: Hash tables configured (established 131072 bind 65536) TCP reno registered Unpacking initramfs... done Freeing initrd memory: 2915k freed Simple Boot Flag at 0x7a set to 0x1 Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254) io scheduler noop registered io scheduler cfq registered (default) Boot video device is 0000:01:00.0 PCI: Firmware left 0000:03:08.0 e100 interrupts enabled, disabling PCI: Setting latency timer of device 0000:00:01.0 to 64 assign_interrupt_mode Found MSI capability Allocate Port Service[0000:00:01.0:pcie00] PCI: Setting latency timer of device 0000:00:1c.0 to 64 assign_interrupt_mode Found MSI capability Allocate Port Service[0000:00:1c.0:pcie00] Allocate Port Service[0000:00:1c.0:pcie02] Linux agpgart interface v0.102 PNP: No PS/2 controller found. Probing ports directly. serio: i8042 KBD port at 0x60,0x64 irq 1 serio: i8042 AUX port at 0x60,0x64 irq 12 mice: PS/2 mouse device common for all mice TCP cubic registered Using IPI No-Shortcut mode Freeing unused kernel memory: 184k freed fuse init (API version 7.9) ACPI Exception (processor_core-0816): AE_NOT_FOUND, Processor Device is not present [20070126] ACPI Exception (processor_core-0816): AE_NOT_FOUND, Processor Device is not present [20070126] NET: Registered protocol family 1 usbcore: registered new interface driver usbfs usbcore: registered new interface driver hub usbcore: registered new device driver usb USB Universal Host Controller Interface driver v3.0 ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 21 (level, low) -> IRQ 17 PCI: Setting latency timer of device 0000:00:1d.0 to 64 uhci_hcd 0000:00:1d.0: UHCI Host Controller uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 1 uhci_hcd 0000:00:1d.0: irq 17, io base 0x0000ff80 usb usb1: configuration #1 chosen from 1 choice hub 1-0:1.0: USB hub found hub 1-0:1.0: 2 ports detected e100: Intel(R) PRO/100 Network Driver, 3.5.23-k4-NAPI e100: Copyright(c) 1999-2006 Intel Corporation ACPI: PCI Interrupt 0000:00:1d.1[B] -> GSI 22 (level, low) -> IRQ 18 PCI: Setting latency timer of device 0000:00:1d.1 to 64 uhci_hcd 0000:00:1d.1: UHCI Host Controller uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 2 uhci_hcd 0000:00:1d.1: irq 18, io base 0x0000ff60 usb usb2: configuration #1 chosen from 1 choice hub 2-0:1.0: USB hub found hub 2-0:1.0: 2 ports detected ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 19 PCI: Setting latency timer of device 0000:00:1d.2 to 64 uhci_hcd 0000:00:1d.2: UHCI Host Controller uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 3 uhci_hcd 0000:00:1d.2: irq 19, io base 0x0000ff40 usb usb3: configuration #1 chosen from 1 choice hub 3-0:1.0: USB hub found hub 3-0:1.0: 2 ports detected ACPI: PCI Interrupt 0000:00:1d.3[D] -> GSI 23 (level, low) -> IRQ 20 PCI: Setting latency timer of device 0000:00:1d.3 to 64 uhci_hcd 0000:00:1d.3: UHCI Host Controller uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 4 uhci_hcd 0000:00:1d.3: irq 20, io base 0x0000ff20 usb usb4: configuration #1 chosen from 1 choice hub 4-0:1.0: USB hub found hub 4-0:1.0: 2 ports detected ACPI: PCI Interrupt 0000:00:1d.7[A] -> GSI 21 (level, low) -> IRQ 17 PCI: Setting latency timer of device 0000:00:1d.7 to 64 ehci_hcd 0000:00:1d.7: EHCI Host Controller ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 5 ehci_hcd 0000:00:1d.7: debug port 1 PCI: cache line size of 128 is not supported by device 0000:00:1d.7 ehci_hcd 0000:00:1d.7: irq 17, io mem 0xffa80800 usb 2-1: new full speed USB device using uhci_hcd and address 2 ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004 usb usb5: configuration #1 chosen from 1 choice hub 5-0:1.0: USB hub found hub 5-0:1.0: 8 ports detected ata_piix 0000:00:1f.1: version 2.12 ACPI: PCI Interrupt 0000:00:1f.1[A] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:1f.1 to 64 scsi0 : ata_piix scsi1 : ata_piix ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xffa0 irq 14 ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xffa8 irq 15 usb 5-3: new high speed USB device using ehci_hcd and address 2 ata1.00: ATAPI: BENQ DVD DD DW1640, BSRB, max UDMA/33 usb 5-3: configuration #1 chosen from 1 choice Initializing USB Mass Storage driver... ata1.00: configured for UDMA/33 ata2: port disabled. ignoring. scsi 0:0:0:0: CD-ROM BENQ DVD DD DW1640 BSRB PQ: 0 ANSI: 5 scsi 0:0:0:0: Attached scsi generic sg0 type 5 ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ] ACPI: PCI Interrupt 0000:00:1f.2[C] -> GSI 20 (level, low) -> IRQ 21 PCI: Setting latency timer of device 0000:00:1f.2 to 64 scsi2 : ata_piix scsi3 : ata_piix ata3: SATA max UDMA/133 cmd 0xfe00 ctl 0xfe10 bmdma 0xfea0 irq 21 ata4: SATA max UDMA/133 cmd 0xfe20 ctl 0xfe30 bmdma 0xfea8 irq 21 scsi4 : SCSI emulation for USB Mass Storage devices usbcore: registered new interface driver usb-storage USB Mass Storage support registered. usb-storage: device found at 2 usb-storage: waiting for device to settle before scanning ata3.00: ATA-7: MAXTOR STM3250820AS, 3.AAE, max UDMA/133 ata3.00: 488397168 sectors, multi 8: LBA48 NCQ (depth 0/32) ata3.01: ATA-7: ST3160828AS, 8.04, max UDMA/133 ata3.01: 312500000 sectors, multi 8: LBA48 NCQ (depth 0/32) ata3.00: configured for UDMA/133 ata3.01: configured for UDMA/133 usb 3-1: new low speed USB device using uhci_hcd and address 2 scsi 2:0:0:0: Direct-Access ATA MAXTOR STM325082 3.AA PQ: 0 ANSI: 5 scsi 2:0:0:0: Attached scsi generic sg1 type 0 scsi 2:0:1:0: Direct-Access ATA ST3160828AS 8.04 PQ: 0 ANSI: 5 scsi 2:0:1:0: Attached scsi generic sg2 type 0 ACPI: PCI Interrupt 0000:03:08.0[A] -> GSI 20 (level, low) -> IRQ 21 sr0: scsi3-mmc drive: 48x/48x writer cd/rw xa/form2 cdda tray Uniform CD-ROM driver Revision: 3.20 sr 0:0:0:0: Attached scsi CD-ROM sr0 sd 2:0:0:0: [sda] 488397168 512-byte hardware sectors (250059 MB) sd 2:0:0:0: [sda] Write Protect is off sd 2:0:0:0: [sda] Mode Sense: 00 3a 00 00 sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sd 2:0:0:0: [sda] 488397168 512-byte hardware sectors (250059 MB) sd 2:0:0:0: [sda] Write Protect is off sd 2:0:0:0: [sda] Mode Sense: 00 3a 00 00 sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sda:<6>e100: eth0: e100_probe: addr 0xefbff000, irq 21, MAC addr 00:12:3f:c9:ba:0b usb 3-1: configuration #1 chosen from 1 choice sda1 sda2 sda3 sd 2:0:0:0: [sda] Attached SCSI disk sd 2:0:1:0: [sdb] 312500000 512-byte hardware sectors (160000 MB) sd 2:0:1:0: [sdb] Write Protect is off sd 2:0:1:0: [sdb] Mode Sense: 00 3a 00 00 sd 2:0:1:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sd 2:0:1:0: [sdb] 312500000 512-byte hardware sectors (160000 MB) sd 2:0:1:0: [sdb] Write Protect is off sd 2:0:1:0: [sdb] Mode Sense: 00 3a 00 00 sd 2:0:1:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sdb: sdb1 sdb2 sdb3 sd 2:0:1:0: [sdb] Attached SCSI disk usb 3-2: new low speed USB device using uhci_hcd and address 3 usb 3-2: configuration #1 chosen from 1 choice usbcore: registered new interface driver hiddev input: Dell Dell USB Mouse as /devices/pci0000:00/0000:00:1d.2/usb3/3-1/3-1:1.0/input/input0 input,hidraw0: USB HID v1.10 Mouse [Dell Dell USB Mouse] on usb-0000:00:1d.2-1 input: Dell Dell USB Keyboard as /devices/pci0000:00/0000:00:1d.2/usb3/3-2/3-2:1.0/input/input1 input,hidraw1: USB HID v1.10 Keyboard [Dell Dell USB Keyboard] on usb-0000:00:1d.2-2 usbcore: registered new interface driver usbhid drivers/hid/usbhid/hid-core.c: v2.6:USB HID core driver kjournald starting. Commit interval 5 seconds EXT3-fs: mounted filesystem with ordered data mode. usb-storage: device scan complete scsi 4:0:0:0: Direct-Access TEAC USB HS-CF Card 4.00 PQ: 0 ANSI: 0 scsi 4:0:0:1: Direct-Access TEAC USB HS-xD/SM 4.00 PQ: 0 ANSI: 0 scsi 4:0:0:2: Direct-Access TEAC USB HS-MS Card 4.00 PQ: 0 ANSI: 0 scsi 4:0:0:3: Direct-Access TEAC USB HS-SD Card 4.00 PQ: 0 ANSI: 0 sd 4:0:0:0: [sdc] Attached SCSI removable disk sd 4:0:0:0: Attached scsi generic sg3 type 0 sd 4:0:0:1: [sdd] Attached SCSI removable disk sd 4:0:0:1: Attached scsi generic sg4 type 0 sd 4:0:0:2: [sde] Attached SCSI removable disk sd 4:0:0:2: Attached scsi generic sg5 type 0 sd 4:0:0:3: [sdf] Attached SCSI removable disk sd 4:0:0:3: Attached scsi generic sg6 type 0 input: PC Speaker as /devices/platform/pcspkr/input/input2 intel_rng: Firmware space is locked read-only. If you can't or intel_rng: don't want to disable this in firmware setup, and if intel_rng: you are certain that your system has a functional intel_rng: RNG, try using the 'no_fwh_detect' option. input: Power Button (FF) as /devices/virtual/input/input3 ACPI: Power Button (FF) [PWRF] input: Power Button (CM) as /devices/virtual/input/input4 ACPI: Power Button (CM) [VBTN] Real Time Clock Driver v1.12ac e100: eth0: e100_watchdog: link up, 100Mbps, full-duplex ACPI: PCI Interrupt 0000:00:1b.0[A] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:1b.0 to 64 Adding 4088532k swap on /dev/sda2. Priority:-1 extents:1 across:4088532k EXT3 FS on sda1, internal journal kjournald starting. Commit interval 5 seconds EXT3 FS on sda3, internal journal EXT3-fs: mounted filesystem with ordered data mode. [drm] Initialized drm 1.1.0 20060810 ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 16 [drm] Initialized radeon 1.28.0 20060524 on minor 0 [drm] Setting GART location based on new memory map [drm] Loading R300 Microcode [drm] writeback test succeeded in 1 usecs (In reply to comment #22) > Created an attachment (id=13805) [details] > atapi-pio-debug.patch > > Here you go. > on top of which kernel i can apply your patch ? thank you (by the way need to sleep a little now) Ah.. okay, the device is PATA. You can leave SATA part in ahci mode then. It doesn't matter. I thought the drive was connected to SATA port for some reason - ah okay someone posted partial log above which suggests that the controller was JMB AHCI. Anyways, please apply the patch on top of both previous patches. Thanks. hum on top of linus master git branch yannick@tiyann:~/src/kernel/linux$ patch -p1 < ../atapi-pio-debug.patch patching file drivers/ata/libata-core.c Hunk #1 FAILED at 5153. Hunk #2 FAILED at 5162. Hunk #3 FAILED at 5188. Hunk #4 succeeded at 5280 with fuzz 1 (offset 39 lines). 3 out of 4 hunks FAILED -- saving rejects to file drivers/ata/libata-core.c.rej and at compile time : CC drivers/ata/libata-core.o drivers/ata/libata-core.c: In function «__atapi_pio_bytes": drivers/ata/libata-core.c:5276: erreur: «dev" undeclared (first use in this function) drivers/ata/libata-core.c:5276: erreur: (Each undeclared identifier is reported only once drivers/ata/libata-core.c:5276: erreur: for each function it appears in.) drivers/ata/libata-core.c:5276: erreur: «no_more_sg" undeclared (first use in this function) make[3]: *** [drivers/ata/libata-core.o] Erreur 1 make[2]: *** [drivers/ata] Erreur 2 make[1]: *** [drivers] Erreur 2 make[1]: quittant le répertoire « /home/yannick/src/kernel/linux-2.6.git » make: *** [debian/stamp-build-kernel] Erreur 2 must i do it on top of improve-ATAPI-data-transfer branch ? last git pull unpatched :
Dec 3 20:30:08 localhost kernel: ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Dec 3 20:30:08 localhost kernel: ata5.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 8 in
Dec 3 20:30:08 localhost kernel: cdb ac 00 00 00 00 00 00 00 00 01 03 00 00 00 00 00
Dec 3 20:30:08 localhost kernel: res 58/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x2 (HSM violation)
Dec 3 20:30:08 localhost kernel: ata5.00: status: { DRDY DRQ }
Dec 3 20:30:08 localhost kernel: ata5: soft resetting link
Dec 3 20:30:39 localhost kernel: ata5.00: qc timeout (cmd 0xa1)
Dec 3 20:30:39 localhost kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 3 20:30:39 localhost kernel: ata5.00: revalidation failed (errno=-5)
Dec 3 20:30:39 localhost kernel: ata5: failed to recover some devices, retrying in 5 secs
Dec 3 20:30:49 localhost kernel: ata5: port is slow to respond, please be patient (Status 0x80)
Dec 3 20:30:54 localhost kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 3 20:30:54 localhost kernel: ata5: soft resetting link
Dec 3 20:31:24 localhost kernel: ata5.00: qc timeout (cmd 0xa1)
Dec 3 20:31:24 localhost kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 3 20:31:24 localhost kernel: ata5.00: revalidation failed (errno=-5)
Dec 3 20:31:24 localhost kernel: ata5: failed to recover some devices, retrying in 5 secs
Dec 3 20:31:34 localhost kernel: ata5: port is slow to respond, please be patient (Status 0x80)
Dec 3 20:31:39 localhost kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 3 20:31:39 localhost kernel: ata5: soft resetting link
Dec 3 20:32:10 localhost kernel: ata5.00: qc timeout (cmd 0xa1)
Dec 3 20:32:10 localhost kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 3 20:32:10 localhost kernel: ata5.00: revalidation failed (errno=-5)
Dec 3 20:32:10 localhost kernel: ata5.00: disabled
Dec 3 20:32:15 localhost kernel: ata5: port is slow to respond, please be patient (Status 0x80)
Dec 3 20:32:20 localhost kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 3 20:32:20 localhost kernel: ata5: soft resetting link
Dec 3 20:32:21 localhost kernel: ata5: EH complete
Strange, it applies fine on today's git #master. tj@htj:~/os/linux-2.6> git-cat-file commit HEAD tree 78e6687f31a1ee2d61f879d8aa335361e3f8b66c parent 1a2edea9aff48c31302e07100ddbaba358596cd7 author Ralf Baechle <ralf@linux-mips.org> 1196597351 +0000 committer Ralf Baechle <ralf@linux-mips.org> 1196710826 +0000 [MIPS] BCM1480: Fix interrupt routing. The old code did did only work as long as CFE and the kernel were using the same interrupt numbering ... Signed-off-by: Ralf Baechle <ralf@linux-mips.org> tj@htj:~/os/linux-2.6> patch -p1 < ~/tmp/atapi-pio-debug.patch patching file drivers/ata/libata-core.c Hunk #1 succeeded at 5156 (offset 3 lines). Hunk #2 succeeded at 5165 (offset 3 lines). Hunk #3 succeeded at 5191 (offset 3 lines). Hunk #4 succeeded at 5244 (offset 3 lines). Can you please checkout a clean tree and try again? ok clean tree + atapi-pio-debug.patch
k3b launch syslog:
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost last message repeated 5 times
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=36 requested=36 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=36 requested=36 transferred=36 curbytes=36 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost last message repeated 11 times
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=36 requested=36 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=36 requested=36 transferred=36 curbytes=36 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=40 requested=8 transferred=8 curbytes=8 no_more_sg=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=12 requested=12 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=12 requested=12 transferred=12 curbytes=12 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=12 requested=12 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=12 requested=12 transferred=12 curbytes=12 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=8 requested=8 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost last message repeated 5 times
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=60 requested=60 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost last message repeated 5 times
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=8 requested=8 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 no_more_sg=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI EOF nbytes=8 requested=8 curbytes=0
Dec 4 06:54:22 localhost kernel: ata1.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 no_more_sg=1
Dec 4 06:54:22 localhost kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Dec 4 06:54:22 localhost kernel: ata1.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 8 in
Dec 4 06:54:22 localhost kernel: cdb ac 00 00 00 00 00 00 00 00 01 03 00 00 00 00 00
Dec 4 06:54:22 localhost kernel: res 58/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x2 (HSM violation)
Dec 4 06:54:22 localhost kernel: ata1.00: status: { DRDY DRQ }
Dec 4 06:54:22 localhost kernel: ata1: soft resetting link
Dec 4 06:54:53 localhost kernel: ata1.00: qc timeout (cmd 0xa1)
Dec 4 06:54:53 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 4 06:54:53 localhost kernel: ata1.00: revalidation failed (errno=-5)
Dec 4 06:54:53 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs
Dec 4 06:55:03 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80)
Dec 4 06:55:08 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset
Dec 4 06:55:08 localhost kernel: ata1: soft resetting link
Dec 4 06:55:38 localhost kernel: ata1.00: qc timeout (cmd 0xa1)
Dec 4 06:55:38 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 4 06:55:38 localhost kernel: ata1.00: revalidation failed (errno=-5)
Dec 4 06:55:38 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs
Dec 4 06:55:48 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80)
Dec 4 06:55:53 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset
Dec 4 06:55:53 localhost kernel: ata1: soft resetting link
Dec 4 06:56:24 localhost kernel: ata1.00: qc timeout (cmd 0xa1)
Dec 4 06:56:24 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 4 06:56:24 localhost kernel: ata1.00: revalidation failed (errno=-5)
Dec 4 06:56:24 localhost kernel: ata1.00: disabled
Dec 4 06:56:29 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80)
Dec 4 06:56:34 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset
Dec 4 06:56:34 localhost kernel: ata1: soft resetting link
Dec 4 06:56:34 localhost kernel: ata1: EH complete
Created attachment 13844 [details] bug9346-dbg.patch Thanks. Can you please apply the attached patch and report the same log? (In reply to comment #30) here it is k3b start without hang : now flood for start ;-) Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=36 requested=36 transferred=36 curbytes=36 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 36 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=36 requested=36 transferred=36 curbytes=36 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 36 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=40 requested=8 transferred=8 curbytes=8 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 8 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=12 requested=12 transferred=12 curbytes=12 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 12 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=12 requested=12 transferred=12 curbytes=12 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 12 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 8 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 60 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 8 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_DRAIN: drained 8 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_DRAIN: drained 8 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 24 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=120 requested=120 transferred=120 curbytes=120 EOS=1 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 120 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:44 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:45 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:47 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:49 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:51 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:53 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:55 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:57 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:00:59 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:01 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:01:03 localhost kernel: ata5.00: ATAPI EOF after 26 bytes but trying to erase cdrw : Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=2 requested=2 transferred=2 curbytes=2 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 2 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=44 requested=44 transferred=44 curbytes=44 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 44 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=44 requested=44 transferred=44 curbytes=44 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 44 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 8 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 8 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=296 requested=296 transferred=296 curbytes=296 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 296 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=96 requested=26 transferred=26 curbytes=26 EOS=0 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 26 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=2 requested=2 transferred=2 curbytes=2 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 2 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=44 requested=44 transferred=44 curbytes=44 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 44 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=44 requested=44 transferred=44 curbytes=44 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 44 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=2 requested=2 transferred=2 curbytes=2 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 2 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=44 requested=44 transferred=44 curbytes=44 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 44 bytes Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI_XFER: nbytes=44 requested=44 transferred=44 curbytes=44 EOS=1 Dec 4 09:06:07 localhost kernel: ata5.00: ATAPI EOF after 44 bytes Dec 4 09:06:37 localhost kernel: ata5.00: qc timeout (cmd 0xa0) Dec 4 09:06:37 localhost kernel: ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen Dec 4 09:06:37 localhost kernel: ata5.00: cmd a0/00:00:00:02:00/00:00:00:00:00/a0 tag 0 pio 2 in Dec 4 09:06:37 localhost kernel: cdb 5a 00 30 00 00 00 00 00 02 00 00 00 00 00 00 00 Dec 4 09:06:37 localhost kernel: res 51/54:03:00:02:00/00:00:00:00:00/a0 Emask 0x5 (timeout) Dec 4 09:06:37 localhost kernel: ata5.00: status: { DRDY ERR } Dec 4 09:06:42 localhost kernel: ata5: port is slow to respond, please be patient (Status 0x90) Dec 4 09:06:47 localhost kernel: ata5: device not ready (errno=-16), forcing hardreset Dec 4 09:06:47 localhost kernel: ata5: soft resetting link Dec 4 09:06:48 localhost kernel: ata5.00: revalidation failed (errno=-2) Dec 4 09:06:48 localhost kernel: ata5: failed to recover some devices, retrying in 5 secs Dec 4 09:06:53 localhost kernel: ata5: soft resetting link Dec 4 09:07:23 localhost kernel: ata5.00: qc timeout (cmd 0xa1) Dec 4 09:07:23 localhost kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4) Dec 4 09:07:23 localhost kernel: ata5.00: revalidation failed (errno=-5) Dec 4 09:07:23 localhost kernel: ata5: failed to recover some devices, retrying in 5 secs Dec 4 09:07:33 localhost kernel: ata5: port is slow to respond, please be patient (Status 0x80) Dec 4 09:07:38 localhost kernel: ata5: device not ready (errno=-16), forcing hardreset Dec 4 09:07:38 localhost kernel: ata5: soft resetting link Dec 4 09:08:09 localhost kernel: ata5.00: qc timeout (cmd 0xa1) Dec 4 09:08:09 localhost kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4) Dec 4 09:08:09 localhost kernel: ata5.00: revalidation failed (errno=-5) Dec 4 09:08:09 localhost kernel: ata5.00: disabled Dec 4 09:08:14 localhost kernel: ata5: port is slow to respond, please be patient (Status 0x80) Dec 4 09:08:19 localhost kernel: ata5: device not ready (errno=-16), forcing hardreset Dec 4 09:08:19 localhost kernel: ata5: soft resetting link Dec 4 09:08:20 localhost kernel: ata5: EH complete Ping? here am i ;-)
In Britanny, France, we say :
"No News, Good News !"
But unfortunately this isn't the case:
Syslog with latest git pull (rc4*) unpatched at k3b start:
Dec 8 03:48:47 localhost kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Dec 8 03:48:47 localhost kernel: ata1.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 8 in
Dec 8 03:48:47 localhost kernel: cdb ac 00 00 00 00 00 00 00 00 01 03 00 00 00 00 00
Dec 8 03:48:47 localhost kernel: res 58/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x2 (HSM violation)
Dec 8 03:48:47 localhost kernel: ata1.00: status: { DRDY DRQ }
Dec 8 03:48:47 localhost kernel: ata1: soft resetting link
Dec 8 03:49:18 localhost kernel: ata1.00: qc timeout (cmd 0xa1)
Dec 8 03:49:18 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 8 03:49:18 localhost kernel: ata1.00: revalidation failed (errno=-5)
Dec 8 03:49:18 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs
Dec 8 03:49:28 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80)
Dec 8 03:49:33 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset
Dec 8 03:49:33 localhost kernel: ata1: soft resetting link
Dec 8 03:50:03 localhost kernel: ata1.00: qc timeout (cmd 0xa1)
Dec 8 03:50:03 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 8 03:50:03 localhost kernel: ata1.00: revalidation failed (errno=-5)
Dec 8 03:50:03 localhost kernel: ata1: failed to recover some devices, retrying in 5 secs
Dec 8 03:50:13 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80)
Dec 8 03:50:18 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset
Dec 8 03:50:18 localhost kernel: ata1: soft resetting link
Dec 8 03:50:49 localhost kernel: ata1.00: qc timeout (cmd 0xa1)
Dec 8 03:50:49 localhost kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 8 03:50:49 localhost kernel: ata1.00: revalidation failed (errno=-5)
Dec 8 03:50:49 localhost kernel: ata1.00: disabled
Dec 8 03:50:54 localhost kernel: ata1: port is slow to respond, please be patient (Status 0x80)
Dec 8 03:50:59 localhost kernel: ata1: device not ready (errno=-16), forcing hardreset
Dec 8 03:50:59 localhost kernel: ata1: soft resetting link
Dec 8 03:50:59 localhost kernel: ata1: EH complete
Created attachment 13920 [details] bug9346-dbg1.patch That ping was for me, I think. I still can't tell why the improve-ATAPI-data-transfer branch succeeds while the dbg patch fails. There shouldn't be much difference. Can you please apply the attached patch and report the result? Thanks. here it is, after applying the patch (with some rejects)
and compiling the kernel
k3b start fast but during erase error:
System
-----------------------
K3b Version: 1.0.3
KDE Version: 3.5.8
QT Version: 3.3.7
Kernel: 2.6.24-rc4-yann8
Devices
-----------------------
BENQ DVD DD DW1640 BSRB (/dev/scd0, ) [CD-R, CD-RW, CD-ROM, DVD-ROM, DVD-R, DVD-RW, DVD-R DL, DVD+R, DVD+RW, DVD+R DL] [DVD-ROM, DVD-R Sequential, DVD-R Dual Layer Sequential, DVD-R Dual Layer Jump, DVD-RW Restricted Overwrite, DVD-RW Sequential, DVD+RW, DVD+R, DVD+R Dual Layer, CD-ROM, CD-R, CD-RW] [SAO, TAO, RAW, SAO/R96R, RAW/R16, RAW/R96R, Restricted Overwrite, Layer Jump]
Used versions
-----------------------
cdrecord: 1.1.6
cdrecord command:
-----------------------
/usr/bin/wodim -v gracetime=2 dev=/dev/scd0 speed=4 -tao driveropts=burnfree -eject blank=all -force
cdrecord
-----------------------
/usr/bin/wodim: Operation not permitted. Warning: Cannot raise RLIMIT_MEMLOCK limits.
scsidev: '/dev/scd0'
devname: '/dev/scd0'
scsibus: -2 target: -2 lun: -2
Linux sg driver version: 3.5.27
Wodim version: 1.1.6
SCSI buffer size: 64512
Beginning DMA speed test. Set CDR_NODMATEST environment variable if device
communication breaks or freezes immediately after that.
TOC Type: 1 = CD-ROM
Driveropts: 'burnfree'
Device type : Removable CD-ROM
Version : 5
Response Format: 2
Capabilities :
Vendor_info : 'BENQ '
Identification : 'DVD DD DW1640 '
Revision : 'BSRB'
Device seems to be: Generic mmc2 DVD-R/DVD-RW.
Current: 0x000A (CD-RW)
Profile: 0x002B (DVD+R/DL)
Profile: 0x001B (DVD+R)
Profile: 0x001A (DVD+RW)
Profile: 0x0016 (DVD-R/DL layer jump recording)
Profile: 0x0015 (DVD-R/DL sequential recording)
Profile: 0x0014 (DVD-RW sequential recording)
Profile: 0x0013 (DVD-RW restricted overwrite)
Profile: 0x0011 (DVD-R sequential recording)
Profile: 0x0010 (DVD-ROM)
Profile: 0x000A (CD-RW) (current)
Profile: 0x0009 (CD-R)
Profile: 0x0008 (CD-ROM)
Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr).
Driver flags : MMC-3 SWABAUDIO BURNFREE
Supported modes: TAO PACKET SAO SAO/R96R RAW/R16 RAW/R96R
Drive buf size : 1073152 = 1048 KB
Speed set to 706 KB/s
Current Secsize: 2048
ATIP info from disk:
Indicated writing power: 5
Reference speed: 2
Is not unrestricted
Is erasable
ATIP start of lead in: -12900 (97:10/00)
ATIP start of lead out: 359849 (79:59/74)
1T speed low: 0 (reserved val 0) 1T speed high: 4
2T speed low: 0 (reserved val 5) 2T speed high: 0 (reserved val 12)
power mult factor: 4 5
recommended erase/write power: 3
A1 values: 02 4A B0
A2 values: 5C C6 26
Disk type: unknown dye (reserved id code)
Manuf. index: -1
Manufacturer: unknown (not in table)
Manufacturer is unknown because of the orange forum embargo.
As the orange forum likes to get money for recent information,
it may be that this media does not use illegal manufacturer coding.
Waiting for drive to calm down.
Starting to write CD/DVD at speed 4.0 in real force BLANK mode for single session.
Last chance to quit, starting real write in 2 seconds.
1 seconds.
0 seconds. Operation starts.
Errno: 5 (Input/output error), blank unit scsi sendcmd: no error
CDB: A1 00 00 00 00 00 00 00 00 00 00 00
status: 0x2 (CHECK CONDITION)
Sense Bytes: 72 0B 00 00 00 00 00 0E 09 0C 00 00 00 02 00 00
Sense Key: 0x0 No Additional Sense, Segment 11
Sense Code: 0x00 Qual 0x02 (end-of-partition/medium detected) Fru 0x0
Sense flags: Blk 0 (not valid)
cmd finished after 1152.493s timeout 9600s
Starting to write CD/DVD at speed 4.0 in real force BLANK mode for single session.
No chance to quit anymore. Operation starts.
Performing OPC...
/usr/bin/wodim: OPC failed.
/usr/bin/wodim: Cannot blank disk, aborting.
This drive or media does not support the 'BLANK media' command
Errno: 5 (Input/output error), prevent/allow medium removal scsi sendcmd: fatal error
CDB: 1E 00 00 00 00 00
cmd finished after 0.000s timeout 40s
Errno: 5 (Input/output error), start/stop unit scsi sendcmd: fatal error
CDB: 1B 00 00 00 02 00
cmd finished after 0.000s timeout 40s
/usr/bin/wodim: Cannot eject media.
syslog :
Dec 9 12:47:14 tiyann kernel: ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Dec 9 12:47:14 tiyann kernel: ata5.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
Dec 9 12:47:14 tiyann kernel: cdb a1 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Dec 9 12:47:14 tiyann kernel: res 40/00:02:00:2c:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
Dec 9 12:47:14 tiyann kernel: ata5.00: status: { DRDY }
Dec 9 12:47:19 tiyann kernel: ata5: port is slow to respond, please be patient (Status 0x90)
Dec 9 12:47:24 tiyann kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 9 12:47:24 tiyann kernel: ata5: soft resetting link
Dec 9 12:47:55 tiyann kernel: ata5.00: qc timeout (cmd 0xa1)
Dec 9 12:47:55 tiyann kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 9 12:47:55 tiyann kernel: ata5.00: revalidation failed (errno=-5)
Dec 9 12:47:55 tiyann kernel: ata5: failed to recover some devices, retrying in 5 secs
Dec 9 12:48:05 tiyann kernel: ata5: port is slow to respond, please be patient (Status 0x80)
Dec 9 12:48:10 tiyann kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 9 12:48:10 tiyann kernel: ata5: soft resetting link
Dec 9 12:48:40 tiyann kernel: ata5.00: qc timeout (cmd 0xa1)
Dec 9 12:48:40 tiyann kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 9 12:48:40 tiyann kernel: ata5.00: revalidation failed (errno=-5)
Dec 9 12:48:40 tiyann kernel: ata5: failed to recover some devices, retrying in 5 secs
Dec 9 12:48:50 tiyann kernel: ata5: port is slow to respond, please be patient (Status 0x80)
Dec 9 12:48:55 tiyann kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 9 12:48:55 tiyann kernel: ata5: soft resetting link
Dec 9 12:49:26 tiyann kernel: ata5.00: qc timeout (cmd 0xa1)
Dec 9 12:49:26 tiyann kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 9 12:49:26 tiyann kernel: ata5.00: revalidation failed (errno=-5)
Dec 9 12:49:26 tiyann kernel: ata5.00: disabled
Dec 9 12:49:31 tiyann kernel: ata5: port is slow to respond, please be patient (Status 0x80)
Dec 9 12:49:36 tiyann kernel: ata5: device not ready (errno=-16), forcing hardreset
Dec 9 12:49:36 tiyann kernel: ata5: soft resetting link
Dec 9 12:49:37 tiyann kernel: ata5: EH complete
Hmmm... The patch is supposed to apply cleanly on -rc4. Maybe I screwed up somewhere. Nope, it applies fine here. Anyways, the last patch was basically improve-ATAPI-data-transfer + debug messages. Interestingly, it passes the two byte MODE SENSE the upstream fix patch fails. Can you please... 1. Please double check that you have clean 2.6.24-rc4 and re-apply the patch. 2. Post full kernel log leading to the failure. I wanna compare the difference between the previous patch and the one before that one. Please attach as text/plain instead of pasting in-line. (In reply to comment #36) > Hmmm... The patch is supposed to apply cleanly on -rc4. Maybe I screwed up > somewhere. Nope, it applies fine here. Anyways, the last patch was > basically > improve-ATAPI-data-transfer + debug messages. Interestingly, it passes the > two > byte MODE SENSE the upstream fix patch fails. Can you please... > > 1. Please double check that you have clean 2.6.24-rc4 and re-apply the patch. ah i was on 2.6.24-rc4 + new bits on linus tree ... ok done > > 2. Post full kernel log leading to the failure. I wanna compare the > difference this worked right , i did fast erase + burn with k3b and i worked ok do i need to attach my kernel.log ? thanks anyway i'll try with a full erase and report and post the log if any Please post the log and repeat the test with bug9346-dbg.patch. Thanks. Created attachment 13923 [details] bug9346-dbg1.patch kernel.log.gz Created attachment 13924 [details] bug9346-dbg2.patch Also, does this patch work on top of clean 2.6.24-rc4? Thanks. too fast ;-) ,unfortunately i have bad news full erase bug see the new kernel.log Created attachment 13925 [details] kernel.log.gz bug9346-dbg1.patch Created attachment 13926 [details] kernel.log.gz bug9346-dbg2.patch rc4 with bug9346-dbg2.patch : burn ok, fast erase ok, burn ok complete erase -> bug Created attachment 13929 [details] kernel.log.gz bug9346-dbg.patch with this one burn fail Okay, so, to recap. Everything except for full erase works fine with improve-ATAPI-data-xfer branch (or dbg1) and dbg2. On dbg1, burn fails. Right? I think now I know what's going on. Can you please test full blank on 2.6.23? Thanks. (In reply to comment #45) > Okay, so, to recap. > > Everything except for full erase works fine with improve-ATAPI-data-xfer > branch > (or dbg1) and dbg2. On dbg1, burn fails. Right? it's on dbg that burn fail beside that you're right > > I think now I know what's going on. Can you please test full blank on > 2.6.23? I'll do (In reply to comment #46) > (In reply to comment #45) > > Okay, so, to recap. > > > > Everything except for full erase works fine with improve-ATAPI-data-xfer > branch > > (or dbg1) and dbg2. On dbg1, burn fails. Right? > > it's on dbg that burn fail beside that you're right Right, that's exactly what I meant. :-) i tried the full erase on 2.6.22-14-generic (it's ubuntu gutsy kernel) and uses libata and ata_piix i know not good but have to go to work soon. It works, if you want i'll test 2.6.23 tonight Yannick, thanks a lot for all the testing. How long does full erase take? I'm thinking the problem is caused by k3b not setting enough timeout. The blank is non-data command and there shouldn't be any difference among 2.6.22, 23, -rc4 and improve-ATAPI-data-transfer. (In reply to comment #49) > How long does full erase take? I'm > thinking the problem is caused by k3b not setting enough timeout. The blank > is > non-data command and there shouldn't be any difference among 2.6.22, 23, -rc4 > and improve-ATAPI-data-transfer. > the cdrw is 4X max, and i would say that the blanking last a long time and is done at 2X (i'm not a home and won't be able to time it precisely) Created attachment 13944 [details] bug9346-blank-tout-debug.patch Can you please apply the attached patch to 2.6.23 and 2.6.24-rc4+dbg2 and report the result? It will print when BLANK is issued with what timeout. Thanks. Created attachment 13945 [details] kernel.log.gz bug9346-dbg2.patch + bug9346-blank-tout-debug.patch yep : ata5.00: XXX BLANK issued, timeout=1010065ms I'm also a owner of this device "DVD DD DW1640", hangs on an pata_amd. I quick test with a Fedora kernel-2.6.24-0.79.rc4.git5.fc9 shows the same as in Comment #5 running wodim blank=all If can do some testing, esp. with Fedora Kernels (cause I'm not very used with git, patch, etc.) ask ! add myself to CC list. okay ? Dec 10 18:56:28 tiyann kernel: ata5.00: XXX BLANK issued, timeout=1010065ms Dec 10 19:13:18 tiyann kernel: ata5.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen Dec 10 19:13:18 tiyann kernel: ata5.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0 Dec 10 19:13:18 tiyann kernel: cdb a1 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Dec 10 19:13:18 tiyann kernel: res 40/00:02:00:2c:00/00:00:00:00:00/a0 Emask 0x4 (timeout) Okay, the timeout is set to around 17mins and correctly times out. Two questions. 1. How long does full blanking take on working setup? You were using the the same program and driver, right? 2. Does the drive look like performing blanking during that 17mins? Thanks. I'm not sure who is asked, but I answer (Fedora kernel-2.6.23.8-63.fc8): [root@obelix ~]# time wodim blank=all Device was not specified. Trying to find an appropriate drive... Detected CD-R drive: /dev/cdrw Using /dev/cdrom of unknown capabilities Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' Device seems to be: Generic mmc2 DVD-R/DVD-RW. Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr). Driver flags : MMC-3 SWABAUDIO BURNFREE Supported modes: TAO PACKET SAO SAO/R96R RAW/R16 RAW/R96R Speed set to 1764 KB/s Starting to write CD/DVD at speed 10.0 in real BLANK mode for single session. Last chance to quit, starting real write in 0 seconds. Operation starts. real 9m15.900s user 0m0.018s sys 0m0.032s I was asking Yannick. Ronald, can you roll your own kernel and apply the dbg2 patch? (In reply to comment #54) > > 1. How long does full blanking take on working setup? You were using the the > same program and driver, right? kind of weird : it last 45 mn (auto mode) , and yes same program and driver k3b / ata_piix > 2. Does the drive look like performing blanking during that 17mins? It looks like (led blinking slowly) sorry for the noise. Yes I can do that, but let me do it tomorrow/today (in germany it's now 3:47 am) okay ? give me the instruction to do so. I need some info's: - this kernel/from here: http://www.kernel.org/pub/linux/kernel/v2.6/testing/linux-2.6.24-rc4.tar.bz2 - patch is on this page, comment #40, right ? - question: how do I apply this patch (full comand line please, to exclude mistakes) - tasks to do/report here: - blank/writing a disk: cd ?; dvd ? - log/times from that - what else ? I wonder what makes timeouts differ between 2.6.23 and 2.6.24-rcX but dbg2 seems to fix all the ATAPI PIO data transfer issues. I'll look into it. Ronald, the command is "patch -p1 < patch-file" in the source directory. (In reply to comment #59) > I wonder what makes timeouts differ between 2.6.23 and 2.6.24-rcX but dbg2 > seems to fix all the ATAPI PIO data transfer issues. I'll look into it. by the way - i tried the full blank with dbg2 and cdrdao : no pb done in 21mn it's maybe a bug in k3b or wodim (i think k3b uses it) more info with wodim : wodim -blank all wodim: Operation not permitted. Warning: Cannot raise RLIMIT_MEMLOCK limits.Device was not specified. Trying to find an appropriate drive... Detected CD-R drive: /dev/cdrw Using /dev/cdrom of unknown capabilities Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' Device seems to be: Generic mmc2 DVD-R/DVD-RW. Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr). Driver flags : MMC-3 SWABAUDIO BURNFREE Supported modes: TAO PACKET SAO SAO/R96R RAW/R16 RAW/R96R Speed set to 706 KB/s Starting to write CD/DVD at speed 4.0 in real BLANK mode for single session. Last chance to quit, starting real write i 0 seconds. Operation starts. Errno: 5 (Input/output error), blank unit scsi sendcmd: no error CDB: A1 00 00 00 00 00 00 00 00 00 00 00 status: 0x2 (CHECK CONDITION) Sense Bytes: 72 0B 00 00 00 00 00 0E 09 0C 00 00 00 02 00 00 Sense Key: 0x0 No Additional Sense, Segment 11 Sense Code: 0x00 Qual 0x02 (end-of-partition/medium detected) Fru 0x0 Sense flags: Blk 0 (not valid) cmd finished after 1152.384s timeout 9600s wodim: Cannot blank disk, aborting. Errno: 5 (Input/output error), prevent/allow medium removal scsi sendcmd: fatal error CDB: 1E 00 00 00 00 00 cmd finished after 0.000s timeout 40s A linux-2.6.24-rc5 is patches and currently compiles. Was it the right choice ? or should I go back to rc4 ? any instructions ?, esp. to configure the kernel by deselecting devices, etc. I don't have in my box. this is after a "make install" (maybe I disabeld to much, but the box is running as usual): sh /opt/prog/kernel/linux-2.6.24-rc5/arch/x86/boot/install.sh 2.6.24-rc5 arch/x86/boot/bzImage System.map "/boot" WARNING: No module uhci-hcd found for kernel 2.6.24-rc5, continuing anyway WARNING: No module libata found for kernel 2.6.24-rc5, continuing anyway WARNING: No module uhci-hcd found for kernel 2.6.24-rc5, continuing anyway ========================================================== log's after inserting a CD and umounting the by hal mounted CD: Dec 11 22:28:14 obelix kernel: [ 132.771896] ata4.00: ATAPI_XFER: nbytes=12 requested=12 transferred=12 curbytes=12 EOS=1 Dec 11 22:28:14 obelix kernel: [ 132.772020] ata4.00: ATAPI EOF after 12 bytes Dec 11 22:28:16 obelix hald: mounted /dev/sr0 on behalf of uid 500 Dec 11 22:28:16 obelix gnome-keyring-daemon[2259]: adding removable location: volume_label_FreeBSD_bootonly at /media/FreeBSD_bootonly Dec 11 22:28:16 obelix kernel: [ 133.898163] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:28:16 obelix kernel: [ 133.898294] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:28:18 obelix kernel: [ 135.797805] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:28:18 obelix kernel: [ 135.798121] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:28:20 obelix kernel: [ 136.965798] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:28:20 obelix kernel: [ 136.965923] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:28:22 obelix kernel: [ 137.733495] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:06 obelix kernel: [ 185.067028] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:06 obelix kernel: [ 185.067148] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:30:08 obelix kernel: [ 185.837243] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:08 obelix kernel: [ 185.837366] ata4.00: ATAPI EOF after 8 bytes ... Dec 11 22:30:09 obelix gnome-keyring-daemon[2259]: removing removable location: volume_label_FreeBSD_bootonly Dec 11 22:30:10 obelix kernel: [ 186.605256] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:10 obelix kernel: [ 186.605384] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:30:12 obelix kernel: [ 187.372664] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:12 obelix kernel: [ 187.372786] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:30:14 obelix kernel: [ 188.142102] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:14 obelix kernel: [ 188.142223] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:30:16 obelix kernel: [ 188.911173] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:16 obelix kernel: [ 188.911296] ata4.00: ATAPI EOF after 8 bytes Dec 11 22:30:18 obelix kernel: [ 189.680602] ata4.00: ATAPI_XFER: nbytes=8 requested=8 transferred=8 curbytes=8 EOS=1 Dec 11 22:30:18 obelix kernel: [ 189.680722] ata4.00: ATAPI EOF after 8 bytes ============================================================================== wodim blank=all: Device was not specified. Trying to find an appropriate drive... Detected CD-R drive: /dev/cdrw Using /dev/cdrom of unknown capabilities Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' Device seems to be: Generic mmc2 DVD-R/DVD-RW. Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr). Driver flags : MMC-3 SWABAUDIO BURNFREE Supported modes: TAO PACKET SAO SAO/R96R RAW/R16 RAW/R96R Speed set to 1764 KB/s Starting to write CD/DVD at speed 10.0 in real BLANK mode for single session. Last chance to quit, starting real write in 0 seconds. Operation starts. real 9m21.348s user 0m0.018s sys 0m0.055s the above log entries stop, after that I shot that command and starts again after wodim has finished. (maybe I got to much debug options enabled) ==================================================================================================== wodim Fedora-8-i386-rescuecd.iso: wodim: No write mode specified. wodim: Asuming -tao mode. wodim: Future versions of wodim may have different drive dependent defaults. Device was not specified. Trying to find an appropriate drive... Looking for a CD-R drive to store 102.84 MiB... Detected CD-R drive: /dev/cdrw Using /dev/cdrom of unknown capabilities Device type : Removable CD-ROM Version : 5 Response Format: 2 Capabilities : Vendor_info : 'BENQ ' Identification : 'DVD DD DW1640 ' Revision : 'BSRB' Device seems to be: Generic mmc2 DVD-R/DVD-RW. Using generic SCSI-3/mmc CD-R/CD-RW driver (mmc_cdr). Driver flags : MMC-3 SWABAUDIO BURNFREE Supported modes: TAO PACKET SAO SAO/R96R RAW/R16 RAW/R96R Speed set to 1764 KB/s Starting to write CD/DVD at speed 10.0 in real TAO mode for single session. Last chance to quit, starting real write in 0 seconds. Operation starts. Track 01: Total bytes read/written: 107833344/107833344 (52653 sectors). this above log-lines temporally. were changed during the write into: ATAPI_XFER: nbytes=60 requested=60 transferred=60 curbytes=60 EOS=1 now I roll a new one with "CONFIG_DEBUG_KOBJECT is not set" ! something I can do else/better ? Yannick, yeah, it seems somehow wodim uses too short timeout value. Dunno why it works in 2.6.23 tho. Ronald, full blanking takes a lot of time. Yours seems fine now. I'll forward fixes collected till now upstream and keep digging the timeout. Thanks. Created attachment 13987 [details] bug9346-dbg2.patch Please apply this patch on top of -rc5 and see whether the problem is fixed. Thanks. Okay, confirmed by Yannick. Patches are posted. Resolving as CODE_FIX. Thanks. okay, a new kernel, patched on a clean rc5 with your last patch. now I get by blanking/writing no logs, but this lines: wodim: Operation not permitted. Warning: Cannot raise RLIMIT_MEMLOCK limits.Device was not specified. Trying to find an appropriate drive... times blank=full: real 9m21.181s user 0m0.020s sys 0m0.048s Times haven't changed, (should they ?, I got no experiences regarding times for full blanking, I always do a blank=fast) You can ignore the RLIMIT warning. It will go away if you run it as root but you won't really need it. And, yes, yours works fine with or without the timeout fix patch because your drive blanks fast enough to finish blanking before the truncated timeout expires. 2.6.24 will work fine for your device. Good to know. Thanks ! and Happy hacking (as a developer I currently can't recall his name (Canada, French, WLAN ? ...) used to greet/end in his mails) Fixed by: commit ededa4d396b15c282aa60d6aacddfc07f0142dbf Merge: 64396ac... 140b5e5... Author: Linus Torvalds <torvalds@woody.linux-foundation.org> Date: Mon Dec 17 19:29:32 2007 -0800 Merge branch 'upstream-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jgarzik/libata-dev http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=ededa4d396b15c282aa60d6aacddfc07f0142dbf |