Created attachment 751952 [details]
anaconda.log

Created attachment 751953 [details]
program.log

Created attachment 751954 [details]
storage.log

Created attachment 751955 [details]
syslog

Created attachment 751956 [details]
ifcfg.log

Created attachment 751957 [details]
packaging.log

Created attachment 751958 [details]
X.log

My 6 virtual disks are LVM volumes on the host system, so they may contain stale data from previous installations for the F19 Test Day.

https://fedoraproject.org/wiki/Test_Day:2013-05-21_AnacondaNewUI_Followup

18:42:42,504 INFO program: Running... mdadm --create /dev/md/pv00 --run --level=1 --raid-devices=2 --metadata=default --bitmap=internal /dev/vda2 /dev/vdb1
18:42:42,755 INFO program: mdadm: array /dev/md/pv00 started.
18:42:42,756 DEBUG program: Return code: 0

18:42:42,862 INFO program: Running... lvm pvcreate --config  devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|","r|/vdc$|","r|/vdd$|","r|/vde$|","r|/vdf$|"] }  --dataalignment 1024k /dev/md/pv00
18:42:42,883 INFO program:   Physical volume "/dev/md/pv00" successfully created
18:42:42,884 DEBUG program: Return code: 0

18:42:42,949 INFO program: Running... lvm vgcreate -s 4m --config  devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|","r|/vdc$|","r|/vdd$|","r|/vde$|","r|/vdf$|"] }  fedora /dev/md/pv00
18:42:42,978 INFO program:   Volume group "fedora" successfully created
18:42:42,979 DEBUG program: Return code: 0

18:42:43,011 INFO program: Running... lvm lvcreate -L 13792m -n root --config  devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|","r|/vdc$|","r|/vdd$|","r|/vde$|","r|/vdf$|"] }  fedora
18:42:43,048 INFO program:   device-mapper: create ioctl on fedora-root failed: Device or resource busy
18:42:43,048 INFO program:   Failed to activate new LV.
18:42:43,048 DEBUG program: Return code: 5


Reassigning to lvm to get input on possible causes, although I am wondering if this is related to the md mirror resync. Adding the mdadm maintainer in case he has input.

(In reply to David Lehman from comment #9)

> 18:42:43,011 INFO program: Running... lvm lvcreate -L 13792m -n root
> --config  devices {
> filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|","r|/
> vdc$|","r|/vdd$|","r|/vde$|","r|/vdf$|"] }  fedora
> 18:42:43,048 INFO program:   device-mapper: create ioctl on fedora-root
> failed: Device or resource busy
> 18:42:43,048 INFO program:   Failed to activate new LV.
> 18:42:43,048 DEBUG program: Return code: 5
> 
> 
> Reassigning to lvm to get input on possible causes, although I am wondering
> if this is related to the md mirror resync. Adding the mdadm maintainer in
> case he has input.


Can we get full trace of  'lvm lvcreate -L 13792m -n root -vvvv .....'

It's probably worth to run 'dmsetup table' before failing command.

This kernel trace looks weird:

23:42:42,697 ERR kernel:[   76.697116] device-mapper: table: 253:1: linear: dm-linear: Device lookup failed
23:42:42,697 WARNING kernel:[   76.697119] device-mapper: ioctl: error adding target to table
23:42:42,698 ERR kernel:[   76.698254] device-mapper: table: 253:2: linear: dm-linear: Device lookup failed
23:42:42,698 WARNING kernel:[   76.698256] device-mapper: ioctl: error adding target to table

Created attachment 760839 [details]
strace of lvm

I think I managed to reproduce it again with Fedora 19 TC3 and anaconda-19.30.5-1

[anaconda root@localhost tmp]# dmsetup table
fedora-swap: 
fedora-root: 0 16351232 linear 9:127 2048
fedora-rootfs: 
live-rw: 0 2097152 snapshot 7:1 7:2 P 8
fedora-home: 0 2048000 linear 9:127 16353280

[anaconda root@localhost tmp]# strace -f -tt -o /tmp/lvm.trace lvm lvcreate -L 2080m -n swap --config 'devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|"] }' fedora


See the attached lvm.trace output.

Created attachment 760840 [details]
lvm -vvvv output

The lvm command run again with -vvvv flags

And the traceback just to be complete:

anaconda 19.30.5-1 exception report
Traceback (most recent call first):
  File "/usr/lib/python2.7/site-packages/blivet/devices.py", line 789, in create
    raise DeviceCreateError(str(e), self.name)
  File "/usr/lib/python2.7/site-packages/blivet/deviceaction.py", line 272, in execute
    self.device.create()
  File "/usr/lib/python2.7/site-packages/blivet/devicetree.py", line 237, in processActions
    action.execute()
  File "/usr/lib/python2.7/site-packages/blivet/__init__.py", line 310, in doIt
    self.devicetree.processActions()
  File "/usr/lib/python2.7/site-packages/blivet/__init__.py", line 169, in turnOnFilesystems
    storage.doIt()
  File "/usr/lib64/python2.7/site-packages/pyanaconda/install.py", line 138, in doInstall
    turnOnFilesystems(storage, mountOnly=flags.flags.dirInstall)
  File "/usr/lib64/python2.7/threading.py", line 764, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/threads.py", line 168, in run
    threading.Thread.run(self, *args, **kwargs)
DeviceCreateError: ('lvcreate failed for fedora/swap: running lvm lvcreate -L 2080m -n swap --config  devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|"] }  fedora failed', 'fedora-swap')

Local variables in innermost frame:
self: non-existent 2080MB lvmlv fedora-swap (24) with non-existent swap
e: lvcreate failed for fedora/swap: running lvm lvcreate -L 2080m -n swap --config  devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|"] }  fedora failed




And the syslog shows similar errors from device-mapper:
16:53:04,311 ERR kernel:[  406.850454] device-mapper: table: 253:1: linear: dm-linear: Device lookup failed
16:53:04,311 WARNING kernel:[  406.850457] device-mapper: ioctl: error adding target to table
16:53:04,312 ERR kernel:[  406.851650] device-mapper: table: 253:2: linear: dm-linear: Device lookup failed
16:53:04,312 WARNING kernel:[  406.851651] device-mapper: ioctl: error adding target to table

#libdm-deptree.c:1798     Creating fedora-swap
#ioctl/libdm-iface.c:1724         dm create fedora-swap LVM-FF1ysA4X2Sx1FYWK3w8BfEmnI4a4K4HUkUg4mckqenX8aRy00JG87yu4UddmM6Db NF   [16384] (*1)
#ioctl/libdm-iface.c:1742   device-mapper: create ioctl on fedora-swap failed: Device or resource busy

Is that the true output from the run that failed, or is it output from a different run afterwards showing a different (consequential) problem and not relevant to the original problem?

Sorry, I should have clarified

That's the output from a later run.

When anaconda crashed with the traceback seen in comment 13, I hit CTRL-ALT-F2 to get a shell and then I ran the failed lvm command manually through strace, and then I ran it a 3rd time with the -vvvv flag.

If you want to get the -vvvv output from when anaconda tries to run it, I guess we'll need to patch anaconda with an updates.img

Running some command afterwards isn't going to help us see how it got into that state unless you manage to put the system back into the same state as it was when the failing command ran so you can accurately reproduce it.  For that you'd need at least 'dmsetup remove fedora-swap' and fedora-rootfs and possibly more depending on what other incorrect states 'dmsetup info -c' shows.

I think it might be easier to use an Anaconda updates.img to add the -vvvv flag.  (Easier for me, anyway, since I'm not a device-mapper expert.)

The python-blivet library runs the lvcreate command now, so I think this is what I need to patch:
https://git.fedorahosted.org/cgit/blivet.git/tree/blivet/devicelibs/lvm.py#n353

blivet has scripts/makeupdates which creates an updates image usable by anaconda

Thanks!  Between that script and a quick git branch, I made an updates.img with this patch:

diff --git a/blivet/devicelibs/lvm.py b/blivet/devicelibs/lvm.py
index eaafad1..decdcb1 100644
--- a/blivet/devicelibs/lvm.py
+++ b/blivet/devicelibs/lvm.py
@@ -354,10 +354,12 @@ def lvcreate(vg_name, lv_name, size, pvs=[]):
     args = ["lvcreate"] + \
             ["-L", "%dm" % size] + \
             ["-n", lv_name] + \
+            ["-vvvv"] + \
             _getConfigArgs() + \
             [vg_name] + pvs
 
     try:
+        util.run_program(["dmsetup", "table"])
         lvm(args)
     except LVMError as msg:
         raise LVMError("lvcreate failed for %s/%s: %s" % (vg_name, lv_name, msg

Created attachment 760906 [details]
anaconda traceback with blivet -vvvv patch

The 'dmsetup table' and 'lvcreate -vvvv' output starts on line 10577:

13:45:59,332 INFO program: Running... dmsetup table
13:45:59,348 INFO program: fedora-root: 
13:45:59,349 INFO program: live-rw: 0 2097152 snapshot 7:1 7:2 P 8
13:45:59,349 INFO program: fedora-home: 
13:45:59,350 DEBUG program: Return code: 0
13:45:59,350 INFO program: Running... lvm lvcreate -L 12876m -n root -vvvv --config  devices { filter=["r|/loop3$|","r|/loop4$|","r|/loop5$|","r|/loop6$|","r|/loop7$|"] }  fedora
...

I've been able to pretty consistently hit this bug with a slightly different set of steps.

Steps to Reproduce:
0. First run only: Create 6 LVM volumes on the host to use as virtual disks:
  for x in a b c d e f ; do
    lvcreate -L16G -n f19tc3_sd${x} /dev/vg_gecko_data
  done

  Change vg_gecko_data to your volume group name!

1. Clear existing LVM and MDRAID metadata on all 6 virtual disks:
  for x in a b c d e f ; do
    dd if=/dev/zero of=/dev/mapper/vg_gecko_data-f19tc3_sd${x} bs=1M count=100
  done

2. Start the virtual machine
  virt-install --name=test-machine101 --ram=1024 --vcpus=2 \
    --graphics=vnc \
    --os-type=linux --os-variant=fedora18 \
    --network=network=default,model=virtio \
    --cdrom=/var/lib/libvirt/images/Fedora-19-TC3-x86_64-netinst.iso \
    --disk=/dev/mapper/vg_gecko_data-f19tc3_sda,bus=virtio \
    --disk=/dev/mapper/vg_gecko_data-f19tc3_sdb,bus=virtio \
    --disk=/dev/mapper/vg_gecko_data-f19tc3_sdc,bus=virtio \
    --disk=/dev/mapper/vg_gecko_data-f19tc3_sdd,bus=virtio \
    --disk=/dev/mapper/vg_gecko_data-f19tc3_sde,bus=virtio \
    --disk=/dev/mapper/vg_gecko_data-f19tc3_sdf,bus=virtio

  NOTE: I'm using VNC instead of Spice due to bug 974198

3. Select Install Fedora 19-TC3 and hit TAB to add
      updates=http://server/updates.img
   to the command line.

   It may also be useful to add
      drm_kms_helper.edid_firmware=edid/1024x768.bin
   See bug 966226

4. Set Date & Time and NTP servers

5. Change Software Selection to Minimal Install

6. In the Storage spoke, select all 6 disks and hit Done
   - choose "I want to review" and hit Continue
   - Click the link to create mount points automatically
   - Change /home to 2GB and hit Update Settings
   - Change swap to 1GB and hit Update Settings
   - Select / and hit Modify button for the Volume Group
     - Change RAID level to RAID1 and hit Save
     - Hit Update Settings again (I tend to forget this step!)
   - Hit Done and Accept Changes to return to hub

7. Begin Installation

After a few minutes anaconda should crash when "Creating mdmember on /dev/..."

Well again, the lvcreate failure is correct because 'fedora-root' is shown in the dmsetup table command to exist in the kernel already *prior* to the lvcreate command that is supposedly creating it!  lvcreate correctly refuses to create a new LV with a name that is already in use in the kernel.

13:45:59,332 INFO program: Running... dmsetup table
13:45:59,348 INFO program: fedora-root: 
13:45:59,349 INFO program: live-rw: 0 2097152 snapshot 7:1 7:2 P 8
13:45:59,349 INFO program: fedora-home: 
13:45:59,350 DEBUG program: Return code: 0
13:45:59,350 INFO program: Running... lvm lvcreate -L 12876m -n root -vvvv 

How did it get there?

You might need to try putting some more 'dmsetup info -c' and 'dmsetup table' commands earlier on to see if you can work out how 'fedora-root' got there *before* it was meant to be created!

(1) Are you certain this is running in a clean kernel environment?
(2) If so, could something outside anaconda possibly be attempting to set up dm devices?  (Any udev rules firing?)
(3) Or could some earlier anaconda code be incidentally using VG fedora LV root in some temporary way and not cleaning up properly afterwards?

I should make it clear that we do NOT believe that these messages:

23:42:42,697 ERR kernel:[   76.697116] device-mapper: table: 253:1: linear: dm-linear: Device lookup failed
23:42:42,697 WARNING kernel:[   76.697119] device-mapper: ioctl: error adding target to table
23:42:42,698 ERR kernel:[   76.698254] device-mapper: table: 253:2: linear: dm-linear: Device lookup failed
23:42:42,698 WARNING kernel:[   76.698256] device-mapper: ioctl: error adding target to table

correspond to the -vvvv trace we are being presented with.

This is because these kernel error messages come from a "load" ioctl system call, but the userspace trace does not show that ioctl being issued!

(Do the time stamps give any clues?)


I also notice this error in the last trace:

18:42:50,025 ERR systemd: /usr/lib/systemd/system-generators/lvm2-activation-generator exited with exit status 127.

Could there be pre-existing metadata on the device?  Some part of systemd/udev tries to activate this but fails; anaconda comes along and doesn't clean up sufficiently from the failed activation attempt before reusing the devices?

I'm manually zeroing the first 100MiB of each disk before running virt-install (as seen in comment 2).  I guess I could try wiping the end of the disk too and see if that "fixes" this problem.

(In reply to Jeff Bastian from comment #26)
> (as seen in comment 2).

That was supposed to be comment 22

(In reply to Jeff Bastian from comment #22)
> 1. Clear existing LVM and MDRAID metadata on all 6 virtual disks:
>   for x in a b c d e f ; do
>     dd if=/dev/zero of=/dev/mapper/vg_gecko_data-f19tc3_sd${x} bs=1M
> count=100
>   done

This is only clearing all metadata from the virtual disks if either a) they are only 100 blocks in size or b) none of them were partitioned inside the virt install. Otherwise, this is leaving all of the metadata in each partition, and also on any devices build on top of the partitions. Anaconda does not randomize partition sectors, so partition layouts are generally reproducible to the sector. We take great pains to prevent stale metadata from jamming up the works, but there may be gaps.

David, this seems to be incarnation of bug #882341 which we haven't covered yet. Would it be possible for you to define an lvm.conf with activation/auto_activation_volume_list=[]. But not passing it as <lvm_command> --config passing as the configuration needs to be read from global config that the pvscan --cache -aay in 69-dm-lvm-metad.rules would honour (I'd backport the patch from bug #882341 comment #3 as it's not in F19 yet).

Otherwise, if using the lvm.conf is problematic (I think you mentioned some cases once), I could add the test for ANACONDA=1 and then I can call "pvscan --cache" instead of "pvscan --cache -aay", so the lvmetad is still updated, but there would be no volume autoactivation.

Thing is that this is not an upstream solution and so this would always need to be added as an extra patch for Fedora (RHEL 7+) which is not quite nice... If you could define the lvm.conf - that would be much better.

We are actually using lvmetad in f19 intentionally. We no longer set ANACONDA in the udev environment, so there is no need to backport that patch.

Are you saying we should disable auto-activation of lvm completely because of the possibility that something like this will happen? We just switched to allowing all storage devices to get activated by systemd/udev/whatever during boot so turning back now is not really an option -- especially just for this bug.

(In reply to David Lehman from comment #28)
> (In reply to Jeff Bastian from comment #22)
> >     dd if=/dev/zero of=/dev/mapper/vg_gecko_data-f19tc3_sd${x} bs=1M
> > count=100
> 
> This is only clearing all metadata from the virtual disks if either a) they
> are only 100 blocks in size or b) none of them were partitioned inside the
> virt install.


I had a block size of 1 MiB (bs=1M) so it was 100 MiB, not 100 blocks.

In any case, I just realized that's not enough since /boot is 500 MiB and the RAID metadata comes after that.

So, I just modified it to zero out the first 1 GiB of the disk, and the last 100 MiB of the disk:

  # wipe any mdraid and lvm metadata first
  for x in a b c d e f ; do
    # /sys/block/DEVICE/size is 512-byte units
    # 100MiB = 204800 blocks of 512-bytes
    DMDEV=$(lvdisplay /dev/vg_gecko_data/f19tc3_sd${x} | awk '/Block device/{d=$NF; sub(".*:","dm-",d); print d}')
    DMSKIP=$(( $( cat /sys/block/${DMDEV}/size ) - 204800 ))
    date
    # wipe 1 GiB from front of disk
    dd if=/dev/zero of=/dev/${DMDEV} bs=512 count=2097152
    # wipe 100 MiB from end of disk
    dd if=/dev/zero of=/dev/${DMDEV} bs=512 count=204800 skip=${DMSKIP}
    echo "$x done"
  done
  virt-install ....


I tried this 3 times in a row and Anaconda succeeded every time.  This seems to indicate something in the system is seeing the stale metadata on the disk and activating old devices.

(In reply to Jeff Bastian from comment #31)
>     # wipe 100 MiB from end of disk
>     dd if=/dev/zero of=/dev/${DMDEV} bs=512 count=204800 skip=${DMSKIP}


Oops, that should have been "seek", not "skip".  I guess the end of the disk didn't matter then.

(In reply to David Lehman from comment #30)
> We are actually using lvmetad in f19 intentionally. We no longer set
> ANACONDA in the udev environment, so there is no need to backport that patch.
> 

Aha, ok then. Sorry, I didn't know - I'll close the bug #882341 then.

> Are you saying we should disable auto-activation of lvm completely because
> of the possibility that something like this will happen? We just switched to
> allowing all storage devices to get activated by systemd/udev/whatever
> during boot so turning back now is not really an option -- especially just
> for this bug.

I don't think We need to disable the lvmetad and accompanying auto-activation. However, in that case, the LVM error message is correct then (comment #23 - #25). To avoid this problem, we either need to provide the activation/auto_activation_volume_list lvm configuration and activate only volumes needed or there needs to be a complete wipe of stale metadata on existing disks...

...or adding a better check for existing volumes? Why does anaconda try to create a volume that already exists?

(In reply to Zdenek Kabelac from comment #10)
> 23:42:42,697 ERR kernel:[   76.697116] device-mapper: table: 253:1: linear:
> dm-linear: Device lookup failed
> 23:42:42,697 WARNING kernel:[   76.697119] device-mapper: ioctl: error
> adding target to table
> 23:42:42,698 ERR kernel:[   76.698254] device-mapper: table: 253:2: linear:
> dm-linear: Device lookup failed
> 23:42:42,698 WARNING kernel:[   76.698256] device-mapper: ioctl: error
> adding target to table

Bug #985638 comment #13 might be related or even the same...

Anaconda never sees any indication that a fedora-root lv exists, so it uses that name when creating a new lv. There are no active lvs when anaconda scans storage. There are no block devices reported as lvm pvs by udev/blkid. I'm not sure what else we think anaconda should be doing in this case. It seems to me like if lvm fails to activate a vg then it should clean up by removing the maps. No?

Peter, it's not possible to know a list of the lvs that "need" to be activated since we're installing an OS and therefore any existing lv could be needed or not, depending on the user's plan for the system configuration.

Created attachment 791134 [details]
anaconda-traceback from ppc64 install

I just hit this error when installing a ppc64 Fedora 19 guest
under qemu-system-ppc64.

We've improved the lvcreate code here to wipe any stale signatures before finishing the lvcreate operation and also properly directing udev to not interfere (by temporarily flagging the LV for udev to skip the scanning/autoactivation). Also, we're using libblkid now by default to detect the signatures so that should provide much more coverage now (see blkid -k) than the native lvm2 signature detection code (which was used for pvcreate originally, but not for lvcreate).

However, this functionality will be available in F21+ (maybe a separate update for F20, but that's going to be after the release).

I'm closing this bug with NEXTRELEASE (meaning F21+ here).

(See also bug #997223)