Bug 855444

Summary: RHEL6.4 builds hang
Product: Red Hat Enterprise Linux 6 Reporter: Scott Poore <spoore>
Component: lvm2Assignee: Peter Rajnoha <prajnoha>
Status: CLOSED ERRATA QA Contact: Cluster QE <mspqa-list>
Severity: unspecified Docs Contact:
Priority: high    
Version: 6.4CC: agk, coughlan, dwysocha, heinzm, jbrassow, jstodola, msnitzer, nperic, prajnoha, prockai, thornber, zkabelac
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: lvm2-2.02.97-3.el6 Doc Type: Bug Fix
Doc Text:
This bug was introduced between releases and never appeared in an actual LVM release, RHEL or otherwise. No documentation needed.
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-21 08:13:34 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 841211    

Description Scott Poore 2012-09-07 18:54:20 UTC
Description of problem:

RHEL6.4 test builds hang in beaker causing jobs to abort.  Looking through some of the logs, it may be hanging on an lvcreate?

Version-Release number of selected component (if applicable):
RHEL6.4-20120904.n.0

How reproducible:
Always.  Seems to have happened on every 6.4 beaker job I've tried to run including simple reservations.

Steps to Reproduce:
1.  Reservce a system in beaker selecting RHEL6.4-20120904.n.0 build/distro
  
Actual results:
hangs/aborts

Expected results:
builds server successfully

Additional info:

end of anaconda.log:
22:20:08,196 DEBUG   : enablefilesystems is a direct step
22:20:09,026 DEBUG   : notifying kernel of 'change' event on device /sys/class/block/sdb1
22:20:09,892 DEBUG   : notifying kernel of 'change' event on device /sys/class/block/sda2
22:20:13,300 DEBUG   : notifying kernel of 'change' event on device /sys/class/block/sda1
22:20:14,699 DEBUG   : notifying kernel of 'change' event on device /sys/class/block/sda2
22:20:15,974 DEBUG   : notifying kernel of 'change' event on device /sys/class/block/sdb1

end of program.log:

22:20:14,325 INFO    : Running... ['lvm', 'pvcreate', '--dataalignment', '1024k', '/dev/sda2']
22:20:14,669 INFO    :   Physical volume "/dev/sda2" successfully created
22:20:14,699 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:14,780 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:14,855 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:15,287 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:15,593 INFO    : Running... ['lvm', 'pvcreate', '--dataalignment', '1024k', '/dev/sdb1']
22:20:15,940 INFO    :   Physical volume "/dev/sdb1" successfully created
22:20:15,975 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:16,057 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:16,105 INFO    : Running... ['lvm', 'vgcreate', '-s', '4m', 'vg_nightcrawler', '/dev/sda2', '/dev/sdb1']
22:20:16,439 INFO    :   Volume group "vg_nightcrawler" successfully created
22:20:16,480 INFO    : Running... ['udevadm', 'settle', '--timeout=300']
22:20:16,522 INFO    : Running... ['lvm', 'lvcreate', '-L', '51200m', '-n', 'lv_root', 'vg_nightcrawler']


end of storage.log relating to sdb1:

22:20:14,806 INFO    : executing action: Create Device partition sdb1 (id 7)
22:20:14,808 DEBUG   :            PartitionDevice.create: sdb1 ; status: False ;
22:20:14,808 INFO    : NOTE: recursive device creation disabled
22:20:14,810 DEBUG   :             PartitionDevice.setupParents: kids: 1 ; name: sdb1 ; orig: False ;
22:20:14,811 DEBUG   :              DiskDevice.setup: sdb ; status: True ; orig: False ;
22:20:14,815 DEBUG   :             DiskLabel.commit: device: /dev/sdb ; numparts: 1 ;
22:20:15,136 DEBUG   :             DeviceFormat.destroy: device: /dev/sdb1 ; status: False ; type: None ;
22:20:15,136 DEBUG   : zeroing out beginning and end of /dev/sdb1...
22:20:15,279 DEBUG   :              PartitionDevice._setPartedPartition: sdb1 ;
22:20:15,279 DEBUG   : device sdb1 new partedPartition parted.Partition instance --
  disk: <parted.disk.Disk object at 0x7fa5d2bd4d90>  fileSystem: None
  number: 1  path: /dev/sdb1  type: 0
  name: None  active: True  busy: False
  geometry: <parted.geometry.Geometry object at 0x7fa5ca2529d0>  PedPartition: <_ped.Partition object at 0x7fa5ca247a70> has path /dev/sdb1
22:20:15,281 DEBUG   :             PartitionDevice.setup: sdb1 ; status: True ; orig: False ;
22:20:15,283 DEBUG   :              PartitionDevice.setupParents: kids: 1 ; name: sdb1 ; orig: False ;
22:20:15,284 DEBUG   :               DiskDevice.setup: sdb ; status: True ; orig: False ;
22:20:15,286 DEBUG   :              DiskLabel.setup: device: /dev/sdb ; status: False ; type: disklabel ;
22:20:15,287 DEBUG   :               DiskLabel.setup: device: /dev/sdb ; status: False ; type: disklabel ;
22:20:15,413 INFO    : executing action: Create Format lvmpv on partition sdb1 (id 7)
22:20:15,415 DEBUG   :            PartitionDevice.setup: sdb1 ; status: True ; orig: False ;
22:20:15,416 DEBUG   :             PartitionDevice.setupParents: kids: 1 ; name: sdb1 ; orig: False ;
22:20:15,417 DEBUG   :              DiskDevice.setup: sdb ; status: True ; orig: False ;
22:20:15,419 DEBUG   :             DiskLabel.setup: device: /dev/sdb ; status: False ; type: disklabel ;
22:20:15,420 DEBUG   :              DiskLabel.setup: device: /dev/sdb ; status: False ; type: disklabel ;
22:20:15,422 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 1 ;
22:20:15,423 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 1 ;
22:20:15,424 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 2 ;
22:20:15,426 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 2 ;
22:20:15,427 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 3 ;
22:20:15,428 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 3 ;
22:20:15,430 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 4 ;
22:20:15,431 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 4 ;
22:20:15,432 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 5 ;
22:20:15,434 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 5 ;
22:20:15,435 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 8 ;
22:20:15,436 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 8 ;
22:20:15,438 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 9 ;
22:20:15,439 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 9 ;
22:20:15,440 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 10 ;
22:20:15,442 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 10 ;
22:20:15,443 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 11 ;
22:20:15,444 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 11 ;
22:20:15,446 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 12 ;
22:20:15,447 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 12 ;
22:20:15,448 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 13 ;
22:20:15,449 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 13 ;
22:20:15,451 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 14 ;
22:20:15,452 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 14 ;
22:20:15,453 DEBUG   :            PartitionDevice.unsetFlag: path: /dev/sdb1 ; flag: 15 ;
22:20:15,455 DEBUG   :             PartitionDevice.flagAvailable: path: /dev/sdb1 ; flag: 15 ;
22:20:15,456 DEBUG   :            PartitionDevice.setFlag: path: /dev/sdb1 ; flag: 6 ;
22:20:15,459 DEBUG   :            DiskLabel.commitToDisk: device: /dev/sdb ; numparts: 1 ;
22:20:15,464 DEBUG   :            LVMPhysicalVolume.create: device: /dev/sdb1 ; status: None ; type: lvmpv ;
22:20:15,466 DEBUG   :             LVMPhysicalVolume.create: device: /dev/sdb1 ; status: None ; type: lvmpv ;
22:20:15,469 DEBUG   :             LVMPhysicalVolume.destroy: device: /dev/sdb1 ; status: None ; type: lvmpv ;
22:20:15,469 DEBUG   : zeroing out beginning and end of /dev/sdb1...
22:20:15,973 DEBUG   :             LVMPhysicalVolume.notifyKernel: device: /dev/sdb1 ; type: lvmpv ;
22:20:16,054 DEBUG   :            PartitionDevice.updateSysfsPath: sdb1 ; status: True ;
22:20:16,055 DEBUG   :             PartitionDevice.updateSysfsPath: sdb1 ; status: True ;
22:20:16,056 DEBUG   : sdb1 sysfsPath set to /devices/pci0000:00/0000:00:08.0/host3/target3:0:0/3:0:0:0/block/sdb/sdb1
22:20:16,082 INFO    : executing action: Create Device lvmvg vg_nightcrawler (id 9)
22:20:16,084 DEBUG   :            LVMVolumeGroupDevice.create: vg_nightcrawler ; status: False ;
22:20:16,086 INFO    : NOTE: recursive device creation disabled
22:20:16,087 DEBUG   :             LVMVolumeGroupDevice.setupParents: kids: 3 ; name: vg_nightcrawler ; orig: False ;
22:20:16,088 DEBUG   :              PartitionDevice.setup: sda2 ; status: True ; orig: False ;
22:20:16,090 DEBUG   :               PartitionDevice.setupParents: kids: 1 ; name: sda2 ; orig: False ;
22:20:16,093 DEBUG   :                DiskDevice.setup: sda ; status: True ; orig: False ;
22:20:16,095 DEBUG   :               DiskLabel.setup: device: /dev/sda ; status: False ; type: disklabel ;
22:20:16,097 DEBUG   :                DiskLabel.setup: device: /dev/sda ; status: False ; type: disklabel ;
22:20:16,098 DEBUG   :              PartitionDevice.setup: sdb1 ; status: True ; orig: False ;
22:20:16,100 DEBUG   :               PartitionDevice.setupParents: kids: 1 ; name: sdb1 ; orig: False ;
22:20:16,101 DEBUG   :                DiskDevice.setup: sdb ; status: True ; orig: False ;
22:20:16,103 DEBUG   :               DiskLabel.setup: device: /dev/sdb ; status: False ; type: disklabel ;
22:20:16,104 DEBUG   :                DiskLabel.setup: device: /dev/sdb ; status: False ; type: disklabel ;
22:20:16,479 DEBUG   :             LVMVolumeGroupDevice.setup: vg_nightcrawler ; status: True ; orig: False ;
22:20:16,515 INFO    : executing action: Create Device lvmlv vg_nightcrawler-lv_root (id 10)
22:20:16,517 DEBUG   :            LVMLogicalVolumeDevice.create: vg_nightcrawler-lv_root ; status: False ;
22:20:16,518 INFO    : NOTE: recursive device creation disabled
22:20:16,520 DEBUG   :             LVMLogicalVolumeDevice.setupParents: kids: 0 ; name: vg_nightcrawler-lv_root ; orig: False ;
22:20:16,521 DEBUG   :              LVMVolumeGroupDevice.setup: vg_nightcrawler ; status: True ; orig: False ;

Comment 3 Scott Poore 2012-09-07 19:53:41 UTC
Note that when I ran the beaker job with ks_meta="partitions=yes" to prevent using LVM for the partitioning, it worked fine.

So is this an anaconda issue or LVM?

Comment 4 Peter Rajnoha 2012-09-11 09:05:24 UTC
Yes, I've reproduced with latest 6.4 nighlty build as well (RHEL6.4-20120910.n.0).

We've changed udev rules upstream to not detect the path for dmsetup/lvm binary and we firmly use the path that is set during "configure" (which is /sbin by default in 6.4).

But we still need to detect the binary path in 6.4 as anaconda places these binaries in /usr/sbin. If the path is wrong, the binaries called in /lib/udev/rules.d/[0-9]*-dm* udev rules are not found and so the notification through dmsetup call in 95-dm-notify.rules is not done, therefore the hang!

This just needs the extra "configure --enable-udev-rules-exec-path-detection" in the spec file. I'll do a new build right away...

Comment 6 Nenad Peric 2012-09-12 10:41:14 UTC
I have reproduced the issue with RHEL6.4-20120910.n.0 as well. 


But the newest nightly build (RHEL6.4-20120912.n.0) started without any problems (ran into some package installation problem during installation later, but that is another story completely.)

Marking this bug as verified as far as the problems with lvcreate goes: 

========= snip ===========

Running anaconda 13.21.176, the Red Hat Enterprise Linux system installer - please wait.
Examining storage devices
In progress

Creating device /dev/vda1
Creating ext4 filesystem on /dev/vda1
In progress

Creating device /dev/vda2
Creating physical volume (LVM) on /dev/vda2
In progress

Creating device /dev/mapper/VolGroup
In progress

Creating device /dev/mapper/VolGroup-lv_root
In progress

Creating ext4 filesystem on /dev/mapper/VolGroup-lv_root
In progress

Creating device /dev/mapper/VolGroup-lv_swap
In progress

Creating swap on /dev/mapper/VolGroup-lv_swap
In progress

Retrieving installation information for Red Hat Enterprise Linux.
In progress

Retrieving installation information for Client.
In progress

Retrieving installation information for Client-optional.
In progress

Retrieving installation information for Red Hat Enterprise Linux.
Retrieving installation information for Client.
Retrieving installation information for Client-optional.
Checking dependencies in packages selected for installation
In progress
Completed

=========== /snip ===========

Comment 7 errata-xmlrpc 2013-02-21 08:13:34 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2013-0501.html