9346 – cd/dvd inaccessible in 2.6.24-rc2

Bug 9346 - cd/dvd inaccessible in 2.6.24-rc2

Summary: cd/dvd inaccessible in 2.6.24-rc2

Status:	CLOSED CODE_FIX

Alias:	None

Product:	IO/Storage
Classification:	Unclassified
Component:	Other (show other bugs)
Hardware:	All Linux

Importance:	P1 normal
Assignee:	Tejun Heo

URL:
Keywords:

Depends on:
Blocks:	9243
	Show dependency tree

Reported:	2007-11-11 10:36 UTC by Rafael J. Wysocki
Modified:	2007-12-20 15:44 UTC (History)
CC List:	9 users (show)

See Also:
Kernel Version:	2.6.24-rc1
Subsystem:
Regression:	Yes
Bisected commit-id:

Attachments
atapi-drain.patch (4.40 KB, patch) 2007-11-28 00:47 UTC, Tejun Heo	Details \| Diff
improve-eh-reporting.patch (2.29 KB, patch) 2007-11-28 06:17 UTC, Tejun Heo	Details \| Diff
atapi-pio-debug.patch (1.53 KB, patch) 2007-11-29 19:01 UTC, Tejun Heo	Details \| Diff
bug9346-dbg.patch (6.96 KB, patch) 2007-12-03 22:19 UTC, Tejun Heo	Details \| Diff
bug9346-dbg1.patch (165.14 KB, patch) 2007-12-09 02:31 UTC, Tejun Heo	Details \| Diff
bug9346-dbg1.patch kernel.log.gz (9.63 KB, application/x-gzip) 2007-12-09 08:45 UTC, Yannick Dirou	Details
bug9346-dbg2.patch (5.35 KB, patch) 2007-12-09 09:03 UTC, Tejun Heo	Details \| Diff
kernel.log.gz bug9346-dbg1.patch (13.99 KB, application/x-gzip) 2007-12-09 09:07 UTC, Yannick Dirou	Details
kernel.log.gz bug9346-dbg2.patch (9.61 KB, application/x-gzip) 2007-12-09 10:53 UTC, Yannick Dirou	Details
kernel.log.gz bug9346-dbg.patch (5.34 KB, application/x-gzip) 2007-12-09 13:12 UTC, Yannick Dirou	Details
bug9346-blank-tout-debug.patch (641 bytes, patch) 2007-12-10 05:49 UTC, Tejun Heo	Details \| Diff
kernel.log.gz bug9346-dbg2.patch + bug9346-blank-tout-debug.patch (10.96 KB, application/x-gzip) 2007-12-10 10:37 UTC, Yannick Dirou	Details
bug9346-dbg2.patch (5.51 KB, patch) 2007-12-11 18:23 UTC, Tejun Heo	Details \| Diff
Show Obsolete (1) Add an attachment (proposed patch, testcase, etc.)

Description Rafael J. Wysocki 2007-11-11 10:36:32 UTC

Subject         : cd/dvd inaccessible in 2.6.24-rc2
Submitter       : Will Trives <will@trivescon.com.au>
References      : http://lkml.org/lkml/2007/11/9/290
Handled-By      : Alan Cox <alan@lxorguk.ukuu.org.uk>
                  Jeff Garzik <jeff@garzik.org>

Comment 1 Alan 2007-11-11 12:11:12 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)

Comment 2 Len Brown 2007-11-19 23:14:53 UTC

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

Comment 3 Will Trives 2007-11-20 01:26:30 UTC

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.

Comment 4 Len Brown 2007-11-20 13:39:12 UTC

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)

Comment 5 Yannick Dirou 2007-11-22 09:22:13 UTC

(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

Comment 6 Tejun Heo 2007-11-28 00:47:54 UTC

Created attachment 13775 [details]
atapi-drain.patch

Does this fix the problem?

Comment 7 Yannick Dirou 2007-11-28 04:32:45 UTC

(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

Comment 8 Tejun Heo 2007-11-28 06:17:54 UTC

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.

Comment 9 Yannick Dirou 2007-11-28 07:23:55 UTC

(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.

Comment 10 Tejun Heo 2007-11-28 17:18:31 UTC

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

Comment 11 Tejun Heo 2007-11-28 17:18:58 UTC

Eh... bugzilla broke the line "improve-ATAPI-data-transfer" part is the branch.  Thanks.

Comment 12 Will Trives 2007-11-28 18:00:18 UTC

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.
> 
>

Comment 13 Tejun Heo 2007-11-28 18:38:32 UTC

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).

Comment 14 Yannick Dirou 2007-11-28 21:24:21 UTC

(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

Comment 15 Tejun Heo 2007-11-28 22:00:25 UTC

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.

Comment 16 Tejun Heo 2007-11-29 07:02:52 UTC

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.

Comment 17 Yannick Dirou 2007-11-29 10:00:29 UTC

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

Comment 18 Will Trives 2007-11-29 13:31:38 UTC

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.
> 
>

Comment 19 Tejun Heo 2007-11-29 15:59:05 UTC

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.

Comment 20 Yannick Dirou 2007-11-29 18:27:11 UTC

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...)

Comment 21 Tejun Heo 2007-11-29 18:42:21 UTC

Yannick, please post the result of "lspci -nn" and kernel boot log.  I'll post a patch soon.

Comment 22 Tejun Heo 2007-11-29 19:01:44 UTC

Created attachment 13805 [details]
atapi-pio-debug.patch

Here you go.

Comment 23 Yannick Dirou 2007-11-29 19:08:16 UTC

(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

Comment 24 Yannick Dirou 2007-11-29 19:14:31 UTC

(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)

Comment 25 Tejun Heo 2007-11-29 19:35:12 UTC

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.

Comment 26 Yannick Dirou 2007-11-30 09:09:31 UTC

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 ?

Comment 27 Yannick Dirou 2007-12-03 11:38:45 UTC

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

Comment 28 Tejun Heo 2007-12-03 20:42:29 UTC

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?

Comment 29 Yannick Dirou 2007-12-03 22:02:29 UTC

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

Comment 30 Tejun Heo 2007-12-03 22:19:26 UTC

Created attachment 13844 [details]
bug9346-dbg.patch

Thanks.  Can you please apply the attached patch and report the same log?

Comment 31 Yannick Dirou 2007-12-04 00:10:05 UTC

(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

Comment 32 Rafael J. Wysocki 2007-12-07 17:24:56 UTC

Ping?

Comment 33 Yannick Dirou 2007-12-07 18:53:09 UTC

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

Comment 34 Tejun Heo 2007-12-09 02:31:10 UTC

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.

Comment 35 Yannick Dirou 2007-12-09 03:58:05 UTC

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

Comment 36 Tejun Heo 2007-12-09 07:24:07 UTC

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.

Comment 37 Yannick Dirou 2007-12-09 08:30:39 UTC

(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

Comment 38 Tejun Heo 2007-12-09 08:36:05 UTC

Please post the log and repeat the test with bug9346-dbg.patch.  Thanks.

Comment 39 Yannick Dirou 2007-12-09 08:45:20 UTC

Created attachment 13923 [details]
bug9346-dbg1.patch kernel.log.gz

Comment 40 Tejun Heo 2007-12-09 09:03:49 UTC

Created attachment 13924 [details]
bug9346-dbg2.patch

Also, does this patch work on top of clean 2.6.24-rc4?  Thanks.

Comment 41 Yannick Dirou 2007-12-09 09:06:19 UTC

too fast ;-) ,unfortunately i have bad news 

full erase bug

see the new kernel.log

Comment 42 Yannick Dirou 2007-12-09 09:07:16 UTC

Created attachment 13925 [details]
kernel.log.gz bug9346-dbg1.patch

Comment 43 Yannick Dirou 2007-12-09 10:53:10 UTC

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

Comment 44 Yannick Dirou 2007-12-09 13:12:34 UTC

Created attachment 13929 [details]
kernel.log.gz bug9346-dbg.patch

with this one
burn fail

Comment 45 Tejun Heo 2007-12-09 22:20:49 UTC

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.

Comment 46 Yannick Dirou 2007-12-09 22:34:16 UTC

(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

Comment 47 Tejun Heo 2007-12-09 22:56:54 UTC

(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.  :-)

Comment 48 Yannick Dirou 2007-12-09 23:30:44 UTC

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

Comment 49 Tejun Heo 2007-12-09 23:46:48 UTC

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.

Comment 50 Yannick Dirou 2007-12-10 00:28:32 UTC

(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)

Comment 51 Tejun Heo 2007-12-10 05:49:56 UTC

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.

Comment 52 Yannick Dirou 2007-12-10 10:37:45 UTC

Created attachment 13945 [details]
kernel.log.gz bug9346-dbg2.patch + bug9346-blank-tout-debug.patch

yep :

ata5.00: XXX BLANK issued, timeout=1010065ms

Comment 53 Ronald 2007-12-10 16:46:05 UTC

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 ?

Comment 54 Tejun Heo 2007-12-10 17:29:52 UTC

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.

Comment 55 Ronald 2007-12-10 18:03:37 UTC

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

Comment 56 Tejun Heo 2007-12-10 18:11:00 UTC

I was asking Yannick.  Ronald, can you roll your own kernel and apply the dbg2 patch?

Comment 57 Yannick Dirou 2007-12-10 18:40:37 UTC

(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)

Comment 58 Ronald 2007-12-10 18:53:35 UTC

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 ?

Comment 59 Tejun Heo 2007-12-10 19:33:57 UTC

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.

Comment 60 Yannick Dirou 2007-12-11 04:09:48 UTC

(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)

Comment 61 Yannick Dirou 2007-12-11 04:12:04 UTC

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

Comment 62 Ronald 2007-12-11 13:19:50 UTC

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.

Comment 63 Ronald 2007-12-11 14:53:12 UTC

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 ?

Comment 64 Tejun Heo 2007-12-11 17:42:16 UTC

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.

Comment 65 Tejun Heo 2007-12-11 18:23:10 UTC

Created attachment 13987 [details]
bug9346-dbg2.patch

Please apply this patch on top of -rc5 and see whether the problem is fixed.  Thanks.

Comment 66 Tejun Heo 2007-12-11 21:37:03 UTC

Okay, confirmed by Yannick.  Patches are posted.  Resolving as CODE_FIX.  Thanks.

Comment 67 Ronald 2007-12-11 22:10:59 UTC

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)

Comment 68 Tejun Heo 2007-12-11 22:44:08 UTC

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.

Comment 69 Ronald 2007-12-11 23:27:31 UTC

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)

Comment 70 Rafael J. Wysocki 2007-12-20 15:44:19 UTC

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

Note You need to log in before you can comment on or make changes to this bug.