Hi, I have an old P4-M based laptop with ICH4-M. It has rather new ATA disk and also DVD-DRIVE. The system was about 10 minutes uptime, maybe I was syncing portage(pakages) tree and doing some IO to the disk. Definitely not even having a CD/DVD-ROM meadia inserted. The syslog shows there was something going on with the CD/DVD drive. Any clues? I am not aware of any issues with any 2.6.x kernel, I am quite sure this was an unusual situation somehow. ata_piix 0000:00:1f.1: version 2.13 ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 3 PCI: setting IRQ 3 as level-triggered ata_piix 0000:00:1f.1: PCI INT A -> Link[LNKC] -> GSI 3 (level, low) -> IRQ 3 ata_piix 0000:00:1f.1: setting latency timer to 64 scsi0 : ata_piix scsi1 : ata_piix ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x8400 irq 14 ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x8408 irq 15 tun: Universal TUN/TAP device driver, 1.6 tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com> yenta_cardbus 0000:02:07.0: CardBus bridge found [1043:1624] ata2.01: ATAPI: Optiarc DVD RW AD-7590A, 1.05, max UDMA/33 ata2.01: configured for UDMA/33 ata1.00: ATA-8: WDC WD3200BEVE-00A0HT0, 11.01A11, max UDMA/100 ata1.00: 625142448 sectors, multi 16: LBA48 ata1.00: configured for UDMA/100 scsi 0:0:0:0: Direct-Access ATA WDC WD3200BEVE-0 11.0 PQ: 0 ANSI: 5 sd 0:0:0:0: [sda] 625142448 512-byte logical blocks: (320 GB/298 GiB) sd 0:0:0:0: [sda] Write Protect is off sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sda: sd 0:0:0:0: Attached scsi generic sg0 type 0 sda1 sda2 sda3 sda4 scsi 1:0:1:0: CD-ROM Optiarc DVD RW AD-7590A 1.05 PQ: 0 ANSI: 5 sd 0:0:0:0: [sda] Attached SCSI disk sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray Uniform CD-ROM driver Revision: 3.20 sr 1:0:1:0: Attached scsi CD-ROM sr0 sr 1:0:1:0: Attached scsi generic sg1 type 5 [cut] ata2: drained 32768 bytes to clear DRQ. ata2.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen ata2.01: ST_FIRST: !(DRQ|ERR|DF) ata2.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0 cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 res 58/58:58:58:00:00/00:00:00:00:00/b0 Emask 0x2 (HSM violation) ata2.01: status: { DRDY DRQ } ata2: soft resetting link ata2.01: configured for UDMA/33 ata2: EH complete ata2.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen ata2.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0 cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 res 51/24:24:00:00:00/00:00:00:00:00/b0 Emask 0x3 (HSM violation) ata2.01: status: { DRDY ERR } ata2: soft resetting link ata2.01: NODEV after polling detection ata2.01: revalidation failed (errno=-2) ata2: soft resetting link ata2.01: configured for UDMA/33 ata2: EH complete
Created attachment 28071 [details] dmesg
# lspci 00:00.0 Host bridge: Intel Corporation 82845 845 [Brookdale] Chipset Host Bridge (rev 04) 00:01.0 PCI bridge: Intel Corporation 82845 845 [Brookdale] Chipset AGP Bridge (rev 04) 00:1d.0 USB Controller: Intel Corporation 82801CA/CAM USB Controller #1 (rev 02) 00:1d.1 USB Controller: Intel Corporation 82801CA/CAM USB Controller #2 (rev 02) 00:1e.0 PCI bridge: Intel Corporation 82801 Mobile PCI Bridge (rev 42) 00:1f.0 ISA bridge: Intel Corporation 82801CAM ISA Bridge (LPC) (rev 02) 00:1f.1 IDE interface: Intel Corporation 82801CAM IDE U100 Controller (rev 02) 00:1f.3 SMBus: Intel Corporation 82801CA/CAM SMBus Controller (rev 02) 00:1f.5 Multimedia audio controller: Intel Corporation 82801CA/CAM AC'97 Audio Controller (rev 02) 00:1f.6 Modem: Intel Corporation 82801CA/CAM AC'97 Modem Controller (rev 02) 01:00.0 VGA compatible controller: ATI Technologies Inc Radeon Mobility M7 LW [Radeon Mobility 7500] 02:05.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL-8139/8139C/8139C+ (rev 10) 02:07.0 CardBus bridge: Ricoh Co Ltd RL5c476 II (rev a8) 02:07.1 CardBus bridge: Ricoh Co Ltd RL5c476 II (rev a8) 02:07.2 FireWire (IEEE 1394): Ricoh Co Ltd R5C552 IEEE 1394 Controller # While inferring some info from bug #9819 I can add that my hardware is ASUS L3C/S laptop lacking lapic. And you can find several bug reports faced on this good piece of hardware (in my eyes) in kernel bugzilla since 2002 (for some more details, especially acpi stuff).
The drive is choking on media presence polling. Does hal-disable-polling /dev/sr0 make any difference? Thanks.
I did the following but wonder if I can manage to reproduce that at all. For example, as I booted freshly today I do not see this error (well, with 2.6.36-rc2-git4 but as I said originally, I am using this for years and merely do not remember such issue, at least not "daily"). # hal-disable-polling --device /dev/sr0 Polling for drive /dev/sr0 have been disabled. The fdi file written was /etc/hal/fdi/information/media-check-disable-storage_model_DVD_RW_AD_7590A.fdi # I will try to do some IO stress.
I have just realized it happened again just after I booted up the laptop: Aug 31 13:35:47 vrapenec kernel: EXT3 FS on sda3, internal journal Aug 31 13:35:47 vrapenec kernel: Adding 2763172k swap on /dev/sda4. Priority:-1 extents:1 across:2763172k Aug 31 13:35:47 vrapenec acpid: starting up with proc fs Aug 31 13:35:47 vrapenec acpid: skipping conf file /etc/acpi/events/.. Aug 31 13:35:47 vrapenec acpid: skipping conf file /etc/acpi/events/. Aug 31 13:35:47 vrapenec acpid: 4 rules loaded Aug 31 13:35:47 vrapenec acpid: waiting for events: event logging is off Aug 31 13:35:47 vrapenec kernel: eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1 Aug 31 13:35:50 vrapenec rpcbind: cannot create socket for udp6 Aug 31 13:35:50 vrapenec rpcbind: cannot create socket for tcp6 Aug 31 13:35:50 vrapenec rpc.statd[2057]: Version 1.2.2 starting Aug 31 13:35:50 vrapenec rpc.statd[2057]: Flags: TI-RPC Aug 31 13:35:50 vrapenec rpc.statd[2057]: Running as root. chown /var/lib/nfs to choose different user Aug 31 13:35:53 vrapenec kernel: i2c /dev entries driver Aug 31 13:35:53 vrapenec kernel: i2c-core: driver [dev_driver] registered Aug 31 13:35:53 vrapenec kernel: i2c-dev: adapter [radeonfb monid] registered as minor 0 Aug 31 13:35:53 vrapenec kernel: i2c-dev: adapter [radeonfb dvi] registered as minor 1 Aug 31 13:35:53 vrapenec kernel: i2c-dev: adapter [radeonfb vga] registered as minor 2 Aug 31 13:35:53 vrapenec kernel: i2c-dev: adapter [radeonfb crt2] registered as minor 3 Aug 31 13:35:54 vrapenec cpufreqd: parse_config_general : Remote control enabled. Aug 31 13:35:54 vrapenec cpufreqd: parse_config_general : Remote controls will be r/w for group wheel (10). Aug 31 13:35:54 vrapenec acpid: client connected from 2144[0:0] Aug 31 13:35:54 vrapenec acpid: 1 client rule loaded Aug 31 13:35:55 vrapenec kernel: Clocksource tsc unstable (delta = -110640915 ns) Aug 31 13:35:57 vrapenec kernel: [drm] Initialized drm 1.1.0 20060810 Aug 31 13:35:58 vrapenec kernel: [drm] Initialized radeon 1.31.0 20080528 for 0000:01:00.0 on minor 0 Aug 31 13:35:59 vrapenec kernel: agpgart-intel 0000:00:00.0: AGP 2.0 bridge Aug 31 13:35:59 vrapenec kernel: agpgart-intel 0000:00:00.0: putting AGP V2 device into 4x mode Aug 31 13:35:59 vrapenec kernel: radeonfb 0000:01:00.0: putting AGP V2 device into 4x mode Aug 31 13:35:59 vrapenec kernel: [drm] Setting GART location based on new memory map Aug 31 13:35:59 vrapenec kernel: [drm] Loading R100 Microcode Aug 31 13:35:59 vrapenec kernel: [drm] writeback test succeeded in 1 usecs Aug 31 13:36:03 vrapenec kernel: ata2.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0 Aug 31 13:36:03 vrapenec kernel: ata2.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0 Aug 31 13:36:03 vrapenec kernel: cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Aug 31 13:36:03 vrapenec kernel: res 51/51:51:51:51:51/00:00:00:00:00/51 Emask 0x1 (device error) Aug 31 13:36:03 vrapenec kernel: ata2.01: status: { DRDY ERR } Aug 31 13:36:03 vrapenec kernel: ata2.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen Aug 31 13:36:03 vrapenec kernel: ata2.01: ST_FIRST: !(DRQ|ERR|DF) Aug 31 13:36:03 vrapenec kernel: ata2.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0 Aug 31 13:36:03 vrapenec kernel: cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Aug 31 13:36:03 vrapenec kernel: res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) Aug 31 13:36:03 vrapenec kernel: ata2: soft resetting link Aug 31 13:36:03 vrapenec kernel: ata2.01: configured for UDMA/33 Aug 31 13:36:03 vrapenec kernel: ata2.01: TEST_UNIT_READY failed (err_mask=0x100) Aug 31 13:36:03 vrapenec acpid: client connected from 2317[109:1009] Aug 31 13:36:03 vrapenec acpid: 1 client rule loaded Aug 31 13:36:08 vrapenec kernel: ata2: soft resetting link Aug 31 13:36:08 vrapenec kernel: ata2.01: configured for UDMA/33 Aug 31 13:36:08 vrapenec kernel: ata2: EH complete Aug 31 13:36:09 vrapenec kdc[2337]: label: default Aug 31 13:36:09 vrapenec kdc[2337]: dbname: /var/heimdal/heimdal Aug 31 13:36:09 vrapenec kdc[2337]: mkey_file: /var/heimdal/m-key Aug 31 13:36:09 vrapenec kdc[2337]: acl_file: /var/heimdal/kadmind.acl Aug 31 13:36:09 vrapenec kdc[2338]: listening on IPv4:127.0.0.1 port 88/udp Aug 31 13:36:09 vrapenec kdc[2338]: listening on IPv4:192.168.0.2 port 88/udp Aug 31 13:36:09 vrapenec kdc[2338]: listening on IPv4:127.0.0.1 port 88/tcp Aug 31 13:36:09 vrapenec kdc[2338]: listening on IPv4:192.168.0.2 port 88/tcp Aug 31 13:36:09 vrapenec kdc[2338]: KDC started Aug 31 13:36:09 vrapenec xdm[2318]: pam_krb5(xdm:auth): bad time value for renew_lifetime: Invalid format of Kerberos lifetime or clock skew string Aug 31 13:36:10 vrapenec kernel: microcode: CPU0 updated to revision 0x39, date = 2003-06-04
Yeah, the drive is choking on TEST_UNIT_READY. Nothing much can be done at this point. In the longer term, we're working on in-kernel media presence polling which won't use TUR and mimic the behavior of windows. Thanks.