Bug 577196

If I setup utelnetd to access the system and watch the logs before the hang occurs, I see the following information...


13:04:57,084 ERR kernel:end_request: I/O error, dev sr0, sector 181068
13:04:57,086 INFO kernel:sr 1:0:0:0: [sr0] Device not ready
13:04:57,086 INFO kernel:sr 1:0:0:0: [sr0] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
13:04:57,086 INFO kernel:sr 1:0:0:0: [sr0] Sense Key : Not Ready [current] 
13:04:57,086 WARN kernel:Info fld=0x0
13:04:57,086 INFO kernel:sr 1:0:0:0: [sr0] Add. Sense: Medium not present
13:04:57,086 INFO kernel:sr 1:0:0:0: [sr0] CDB: Read(10): 28 00 00 00 b0 d5 00 00 02 00
13:04:57,086 ERR kernel:end_request: I/O error, dev sr0, sector 181076
13:04:57,089 INFO kernel:sr 1:0:0:0: [sr0] Device not ready
13:04:57,089 INFO kernel:sr 1:0:0:0: [sr0] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
13:04:57,089 INFO kernel:sr 1:0:0:0: [sr0] Sense Key : Not Ready [current] 
13:04:57,089 WARN kernel:Info fld=0x0
13:04:57,089 INFO kernel:sr 1:0:0:0: [sr0] Add. Sense: Medium not present
13:04:57,089 INFO kernel:sr 1:0:0:0: [sr0] CDB: Read(10): 28 00 00 00 b0 d5 00 00 02 00
13:04:57,089 ERR kernel:end_request: I/O error, dev sr0, sector 181076
13:04:57,091 INFO kernel:sr 1:0:0:0: [sr0] Device not ready
13:04:57,091 INFO kernel:sr 1:0:0:0: [sr0] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
13:04:57,091 INFO kernel:sr 1:0:0:0: [sr0] Sense Key : Not Ready [current] 
13:04:57,091 WARN kernel:Info fld=0x0
13:04:57,091 INFO kernel:sr 1:0:0:0: [sr0] Add. Sense: Medium not present
13:04:57,091 INFO kernel:sr 1:0:0:0: [sr0] CDB: Read(10): 28 00 00 00 b0 d5 00 00 02 00
13:04:57,091 ERR kernel:end_request: I/O error, dev sr0, sector 181076
13:04:57,094 INFO kernel:sr 1:0:0:0: [sr0] Device not ready
13:04:57,094 INFO kernel:sr 1:0:0:0: [sr0] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
13:04:57,094 INFO kernel:sr 1:0:0:0: [sr0] Sense Key : Not Ready [current] 
13:04:57,094 WARN kernel:Info fld=0x0
13:04:57,094 INFO kernel:sr 1:0:0:0: [sr0] Add. Sense: Medium not present
13:04:57,094 INFO kernel:sr 1:0:0:0: [sr0] CDB: Read(10): 28 00 00 00 b0 d5 00 00 02 00
13:04:57,094 ERR kernel:end_request: I/O error, dev sr0, sector 181076
13:04:57,098 INFO kernel:sr 1:0:0:0: [sr0] Device not ready
13:04:57,098 INFO kernel:sr 1:0:0:0: [sr0] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
13:04:57,098 INFO kernel:sr 1:0:0:0: [sr0] Sense Key : Not Ready [current] 
13:04:57,098 WARN kernel:Info fld=0x0
13:04:57,098 INFO kernel:sr 1:0:0:0: [sr0] Add. Sense: Medium not present
13:04:57,098 INFO kernel:sr 1:0:0:0: [sr0] CDB: Read(10): 28 00 00 00 b0 a5 00 00 02 00
13:04:57,098 ERR kernel:end_request: I/O error, dev sr0, sector 180884
13:04:57,098 ERR kernel:SQUASHFS error: squashfs_read_data failed to read block 0x35a53b8
13:04:57,098 ERR kernel:SQUASHFS error: Unable to read data cache entry [35a53b8]
13:04:57,098 ERR kernel:SQUASHFS error: Unable to read page, block 35a53b8, size a9b3

Could this be a problem introduced by the fix for bug#569377?

When I install from netinst.iso from HTTP or NFS repo, no freezes occur.

Well, the netinst.iso is a completely different image, with much less data, on a completely different piece of physical media.  Did you run media check on the original DVD before installation?

(In reply to comment #3)
> Well, the netinst.iso is a completely different image, with much less data, on
> a completely different piece of physical media.  Did you run media check on the
> original DVD before installation?    

Yeah, the DVD passed media check.

Created attachment 402862 [details]
anaconda-logs.tgz

-rw-rw-r-- jlaska/jlaska 27721 2010-03-26 09:21 tmp/minimon/anaconda.log
-rw-rw-r-- jlaska/jlaska  7903 2010-03-26 09:21 tmp/minimon/install.log
-rw-rw-r-- jlaska/jlaska 39675 2010-03-26 09:21 tmp/minimon/program.log
-rw-rw-r-- jlaska/jlaska 180088 2010-03-26 09:21 tmp/minimon/storage.log
-rw-rw-r-- jlaska/jlaska 134937 2010-03-26 09:25 tmp/minimon/syslog
-rw-rw-r-- jlaska/jlaska  26577 2010-03-26 09:21 tmp/minimon/X.log
-rw-rw-r-- jlaska/jlaska  25341 2010-03-26 09:17 tmp/minimon/yum.log

Created attachment 402867 [details]
anaconda-logs.tgz

in storage.log:
11:20:29,077 DEBUG storage: looking for device 'sr0'...
11:20:29,082 DEBUG storage:                 OpticalDevice.mediaPresent: sr0 ; status: True ;
11:20:29,089 DEBUG storage:                 Iso9660FS.supported: supported: True ;
11:20:29,089 DEBUG storage: found OpticalDevice instance (0x7ffb548544d0) --
  name = sr0  status = True  parents = []
  kids = 0
  id = 2 
  uuid = None  format = <storage.formats.fs.Iso9660FS object at 0x7ffb54854390>  size = 3606.58203125
  major = 11  minor = 0  exists = True
  sysfs path = /devices/pci0000:00/0000:00:01.1/host1/target1:0:0/1:0:0:0/block/sr0  partedDevice = <parted.device.Device object at 0x7ffb3e682250>
  target size = 0  path = /dev/sr0 
  format args = []  originalFormat = Iso9660FS instance (0x7ffb54854390) --
  type = iso9660  name = iso9660  status = True
  device = /dev/sr0  uuid = None  exists = True
  options = ro  supported = True  formattable = False  resizable = False
  mountpoint = None  mountopts = None
  label = Fedora_13-Beta_x86_64_DVD  size = 0  targetSize = 0
  
11:20:29,092 DEBUG storage:            OpticalDevice.eject: sr0 ; status: True ;
11:20:29,094 DEBUG storage:             OpticalDevice.teardown: sr0 ; status: True ;

And at the same time (GMT though) in syslog:
15:20:29,282 ERR kernel:ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 
15:20:29,282 ERR kernel:ata2.00: BMDMA stat 0x5 
15:20:29,282 INFO kernel:sr 1:0:0:0: [sr0] CDB: Read(10): 28 00 00 00 eb 75 00 00 02 00
15:20:29,283 ERR kernel:ata2.00: cmd a0/01:00:00:00:10/00:00:00:00:00/a0 tag 0 dma 4096 in
15:20:29,283 ERR kernel:         res 01/60:00:00:00:10/00:00:00:00:00/a0 Emask 0x3 (HSM violation)
15:20:29,283 ERR kernel:ata2.00: status: { ERR }
15:20:29,283 INFO kernel:ata2: soft resetting link
15:20:29,435 DEBUG kernel:ata2.01: NODEV after polling detection
15:20:29,436 INFO kernel:ata2.00: configured for MWDMA2
15:20:29,439 INFO kernel:ata2: EH complete
15:20:29,439 INFO kernel:sr 1:0:0:0: [sr0] Device not ready
15:20:29,440 INFO kernel:sr 1:0:0:0: [sr0] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
15:20:29,440 INFO kernel:sr 1:0:0:0: [sr0] Sense Key : Not Ready [current]

So, that definitely looks like we wouldn't see it without the eject fix, but it doesn't look like the eject fix is the actual /cause/ of the problem. It merely enables the real bug to show through.

This was reported from a virt install (disks in storage.log are vda, vdb). The original eject bug (bug 569377) did not even manifest in virt. We should find out if this happens on real hardware.

So we've been doing some real hardware tests. Seems sometimes we can reproduce, sometimes not.

Here's my result:

I tested installing to a 4GB USB stick, to save messing up my real disk at all. So at the disk selection stage, I picked only the USB drive. I then picked 'use entire disk', but also 'review and modify layout'. The layout it chose was a 500MB /boot, with the rest of the disk as an LVM, with a 2GB swap partition and the rest - 1.5GB -as / . I changed this to be just a 400GB /boot partition and the rest of the disk as a / partition: no LVM, no swap partition.

I chose the minimal package set, to make sure it'd fit on the stick and to make the install process quicker.

This test succeeded: it didn't hit the bug. The install process completed, ejected the DVD, and displayed the 'yay we're done' screen. The installed system on the USB stick boots fine. I can provide anaconda logs from the stick if desired.

Jesse's been testing also, if he could add his results on this thread it'd be great.



-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

I've discovered a pattern.

If the install either involves installing to LVM or the disks were part of a pre-existing LVM I get the hang at the end.

If the disks were not involved in a previous LVM, and if the install is to a non-LVM setup, there is no hang at the end.

My conclusion is that the existence of LVM is what's causing this to fall over.

Further data, I've been doing all this testing with bios raid, so it's not device-mapper.

as discussed on IRC, I just tested - again installing to my 4GB USB key - using auto-partitioning. I zero'ed the key before doing the install. Auto-partitioning definitely set up an LVM, I checked that at the console. Again the install completed successfully, no bug. I was using the minimal package set again. I'll try doing an install over the now-LVM'ed stick and see what happens with that.



-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

I did some tests on this issue using F13-beta-rc1-x86_64-DVD.iso.

1. In virt-install, it hanged at installing bootloader and was 100% reproducible no matter it's minimal or graphical, lvm or no lvm...

2. On bare metal, the screen hanged after it ejected the DVD and the screen(tty6) hanged with black screen. As far as I tested, it didn't happen in minimal install. Then I used the same ext4 partitions(/ and /boot) to install it only with package differences:

a. Minimal install - pass.
b. gnome + office + base + xwindow - pass
c. graphical default - fail
 
The failure info on tty3:
...
INFO anaconda: leaving (1) step dopostaction
INFO anaconda: moving (1) to step complete
WARNING anaconda: /usr/lib/anaconda/gui.py:1533: GTKWarning: Error loading theme icon 'gtk-quit' for stock: Error reading from file: Input/output error 
_

Info on tty5 :
...
GNU GRUB version 0.97 (640K lower / 3072K upper memory)

[ Minimal BASH-like line editing is supported. For the first word, TAB lists possible command completions. Anywhere else TAB lists the possible completions of a device/filename.]

grub> root (hd0,4)
Filesystem type is ext2fs, partition type 0x83
grub> install --stage2=/boot/grub/stage2 /grub/stage1 d (hd0) /grub/stage2 p (hd0,4)/grub/grub.conf
grub>
Backtrace:

anaconda-13.37.1-1.fc13 has been submitted as an update for Fedora 13.
http://admin.fedoraproject.org/updates/anaconda-13.37.1-1.fc13

I tested on anaconda 13.37.1, it has been fixed.

Closing this issue based on feedback from Liam (comment#16) and additional F-13-Beta-RC2 test results

anaconda-13.37.2-1.fc13 has been submitted as an update for Fedora 13.
http://admin.fedoraproject.org/updates/anaconda-13.37.2-1.fc13

anaconda-13.37.2-1.fc13 has been pushed to the Fedora 13 stable repository.  If problems still persist, please make note of it in this bug report.