Bug 885385 - Strange race in livecd creation
Summary: Strange race in livecd creation
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: livecd-tools
Version: 18
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Brian Lane
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: AcceptedNTH RejectedBlocker
Depends On:
Blocks: F18-accepted, F18FinalFreezeExcept
TreeView+ depends on / blocked
 
Reported: 2012-12-09 00:30 UTC by Kevin Fenzi
Modified: 2012-12-18 17:00 UTC (History)
22 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-12-18 06:55:57 UTC
Type: Bug


Attachments (Terms of Use)

Description Kevin Fenzi 2012-12-09 00:30:28 UTC
Some livecd creation runs in koji are failing with: 

...
Checking filesystem /var/tmp/imgcreate-CZ5ZI7/tmp-hSrKND/ext3fs.img
e2fsck 1.42.5 (29-Jul-2012)
Pass 1: Checking inodes, blocks, and sizes
Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Pass 4: Checking reference counts
Pass 5: Checking group summary information
_Fedora-18-Night: 78920/262144 files (0.1% non-contiguous), 588108/1048576 blocks

Losetup add /dev/loop0 mapping to /var/tmp/imgcreate-CZ5ZI7/tmp-hSrKND/ext3fs.img
Extending sparse file /var/tmp/imgcreate-CZ5ZI7/iso-NzgYzH/LiveOS/osmin to 67108864
Losetup add /dev/loop1 mapping to /var/tmp/imgcreate-CZ5ZI7/iso-NzgYzH/LiveOS/osmin
Checking filesystem /dev/mapper/imgcreate-20183-47010
e2fsck 1.42.5 (29-Jul-2012)
/sbin/e2fsck: No such file or directory while trying to open /dev/mapper/imgcreate-20183-47010
Possibly non-existent device?

resizing /dev/mapper/imgcreate-20183-47010
resize2fs 1.42.5 (29-Jul-2012)
open: No such file or directory while opening /dev/mapper/imgcreate-20183-47010

Losetup remove /dev/loop1
Losetup remove /dev/loop0
Error creating Live CD : resize2fs returned an error (1)!
...

I can't find anything wrong with builders and indeed the same builder will build the same image on later tries. 

http://koji.fedoraproject.org/koji/taskinfo?taskID=4768309

http://koji.fedoraproject.org/koji/taskinfo?taskID=4768310

are two examples of failures, while (using the same ks and versions of everything): 

http://koji.fedoraproject.org/koji/taskinfo?taskID=4769643

http://koji.fedoraproject.org/koji/taskinfo?taskID=4769644

So, it seems to me like some kind of race in making the image loop setup?

Happy to try and redirect or debug... this is a weird one. ;(

Comment 1 Brian Lane 2012-12-10 17:21:12 UTC
I don't know if it means anything, but the ones that fail are starting at loop1 instead of loop0. Maybe something else on the build host is stomping on the loop files while they are in use?

Comment 2 Matthew Miller 2012-12-14 17:58:15 UTC
Similar problem with appliance-creator (used currently for cloud image creation): 

http://koji.fedoraproject.org/koji/taskinfo?taskID=4788741


Fails like this:

Adding disk sda as /var/tmp/imgcreate-OfMOoK/tmp-K91PfH/Fedora-18-TC2-ec2-20121213-x86_64-sda.raw
Extending sparse file /var/tmp/imgcreate-OfMOoK/tmp-K91PfH/Fedora-18-TC2-ec2-20121213-x86_64-sda.raw to 10485760000
Losetup add /dev/loop0 mapping to /var/tmp/imgcreate-OfMOoK/tmp-K91PfH/Fedora-18-TC2-ec2-20121213-x86_64-sda.raw
Formatting disks
Initializing partition table for /dev/loop0 with msdos layout
Assigning partitions to disks
Assigned / to sda1 at 0 at size 10000
Creating partitions
Add primary part at 0 of size 10000
Dev loop0p1: /dev/loop01 -> /dev/mapper/loop0p1
Creating symlink from /dev/loop01 to /dev/mapper/loop0p1
Adding partx mapping for /dev/loop0
Formating ext4 filesystem on /dev/loop01
mke2fs 1.42.5 (29-Jul-2012)
mkfs.ext4: No such file or directory while trying to determine filesystem size

Unable to create appliance : Failed mount disks : Error creating ext4 filesystem

Comment 3 Kevin Fenzi 2012-12-14 18:24:29 UTC
We have traced this to the change in bug 864368
and specifically this kpartx update: 

* Wed Oct 24 2012 Benjamin Marzinski <bmarizns@redhat.com> 0.4.9-35
- Add 0022-RHBZ-864368-disable-libdm-failback.patch
  * make kpartx and multiapthd disable libdm failback device creation

Adding lvm-team here for comment. Is there something we can do so mock chroot's work as they did before? Or do we need to adjust livecd-tools and appliance-creator? or mock? 

Many thanks to agrimm for debugging this and tracking down the issue.

Comment 4 Matthew Miller 2012-12-14 19:01:42 UTC
I'm proposing this as a F18 blocker. I'm unable to point to a specific criterion which is violated by not being able to make live images, but a large number of criteria assume that they exist, so....

Comment 5 Brian Lane 2012-12-14 19:04:24 UTC
livecd-creator is using dmsetup create to create the minimized image. It looks like dmsetup is not synchronizing with whatever creates the device node (udev I think) before it returns, so we have a race on the device node.

The dmsetup manpage seems to indicate that it should be synchronized with udev but I also see a --addnodeoncreate option. Should we be passing this to make sure the node exists before dmsetup create exits?

Comment 6 Alasdair Kergon 2012-12-14 19:38:53 UTC
If this dmsetup command is running in a chroot, we probably need to see the relevant configuration of that to understand what is going on.  E.g. is udev running inside/outside?  What is /dev and how is it updated etc.?

Meanwhile see if adding --verifyudev to any dmsetup commands helps.

Comment 7 Alasdair Kergon 2012-12-14 19:43:42 UTC
Another possible workaround - if the problem is an in-chroot kpartx/multipath command and there's no udev daemon running to update /dev inside the chroot - might be to set DM_DISABLE_UDEV environment variable before running those commands.  I need more details of what you're actually running to be more specific, really.

Comment 8 Kevin Fenzi 2012-12-14 19:47:17 UTC
It's a RHEL6 host, running mock, running livecd-creator in that mock. 

mock bind mounts /dev from the host. 

udev is not running in the chroot that I know of. 

Note that it also does not fail everytime, it's sporadic (perhaps udev in the host adds the node in time sometimes and not in others?)

Also note that the appliance creator issue we thought was this same thing may not be. 
It's got a seperate bug now in bug 887357

Comment 9 Alasdair Kergon 2012-12-15 00:33:07 UTC
So bug 887357 covers a workaround (reinstating old behaviour).

If I've follow this correctly, the long-term fix needs libdm code running *inside* a chroot to sync against the udev rules running *outside* that chroot.  We need to find out exactly what's happening with the cookies/udev detection checks at the moment to see why that is not already happening.

Are /sys and /proc present inside the chroot too?  (I think the relevant code paths try to use them.)

Can you point us to the relevant part of the script(s)?


NB The last comment says this is RHEL6 not Fedora!

Are the commands running inside the chroot also RHEL6, or are they from rawhide?
If they are rawhide, then this means we need to support a mixed configuration where two different versions of the same package are running side-by-side and interacting with each other!

So what are the relevant package N-V-Rs?  I.e. device-mapper, device-mapper-multipath, inside and outside the chroot.

Comment 10 Fedora Update System 2012-12-15 00:49:03 UTC
livecd-tools-18.14-1.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/livecd-tools-18.14-1.fc18

Comment 11 Andy Grimm 2012-12-15 00:56:29 UTC
I can't answer for koji, but for the environment where I reproduced both issues:

Outside (EL6):
* device-mapper-1.02.74-10.el6.x86_64
* device-mapper-multipath not installed
* udev-147-2.41.el6.x86_64
* kernel-2.6.32-279.el6.x86_64

Inside (F18):
* device-mapper-1.02.77-4.fc18.x86_64
* kpartx / device-mapper-multipath-libs-0.4.9-35.fc18.x86_64

Comment 12 Alasdair Kergon 2012-12-15 01:11:12 UTC
OK, thanks.  We'll work on a permanent solution.  Please keep one of the bugs open to track that.

For information, what was driving this particular change was the rule that only udev should be touching device nodes and links in /dev nowadays.  The workaround reinstates reliance on code that violates that.

Comment 13 Fedora Update System 2012-12-15 21:14:51 UTC
Package livecd-tools-18.14-1.fc18:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing livecd-tools-18.14-1.fc18'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-20467/livecd-tools-18.14-1.fc18
then log in and leave karma (feedback).

Comment 14 Adam Williamson 2012-12-17 17:47:48 UTC
Discussed at 2012-12-17 blocker review meeting: http://meetbot.fedoraproject.org/fedora-bugzappers/2012-12-17/f18final-blocker-review-5.2012-12-17-16.40.log.txt . Rejected as a blocker: as we can just keep re-spinning the images till we get a success, it doesn't make sense to block on this - imagine if it were the last bug, it'd make zero sense to delay release a week to fix a bug in image creation when we had releaseable images. But accepted as NTH, as this can delay TC/RC creation and frustrate the releng team.

Comment 15 Alasdair Kergon 2012-12-17 20:22:45 UTC
Peter Rajnoha and I now have a theory of what happened that seems consistent with the evidence reported here.  We're working through all the combinations (i.e. not just the specific circumstances on this bug), but a likely answer will be to disable the 'Is udev running?' check that the code does and replace it with something that tells the code to assume udev is running.

Comment 16 Fedora Update System 2012-12-18 06:56:00 UTC
livecd-tools-18.14-1.fc18 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 17 Peter Rajnoha 2012-12-18 12:24:57 UTC
Just to make things clear where the origin of the problem is...

In the situation described in this bug report where the running system is RHEL6 and inside chroot we have rawhide, the real origin of the problem is in libudev's "udev_queue_get_udev_is_active" function that returns the udev state.

We use this function inside libdevmapper code to check whether udev is running or not. This is to prevent a hang that would occur in case udev is not running and we'd end up waiting forever for udev to complete the processing of an event.

This function simply checks udev's queue file existence and returns 1 if it exists and 0 if it does not.

Now, the problem is that RHEL6 versions of udev use /dev/.udev/queue.bin existence. The rawhide version of udev/systemd checks /run/udev/queue.bin. In both cases, the queue.bin path is *hardcoded*.

So the problem that arises is straightforward - running RHEL6 version of udev has /dev/.udev/queue.bin which is bind-mounted into the rawhide in chroot. After chroot, the rawhide's version of libudev is used, which checks /run/udev/queue.bin. This causes the libudev function to report that udev is not active! Libdevmapper (using libudev) then automatically disables synchronization with udev (to prevent a hang from infinite waiting for udev rule completion as udev is considered to be "not running").

Without udev synchronization, the udev event can still be processed (and so the /dev content is incomplete) while the command that is the origin of the event is already finished (e.g. by creating/removing a device-mapper device). And so we can end up with the mkfs trying to open a /dev path that does not exist yet!


So probably libudev should also be prepared for such situations like described here (so different libudev versions checking the active state of udev). It's also arguable whether mixing environments this way is correct at all.

Harald, Kay, what do you think? Shouldn't there be another instance of udev running inside chroot if possible?

Comment 18 Kay Sievers 2012-12-18 12:59:58 UTC
A mismatch between a running udev daemon and the used libudev cannot reliably
be supported. Returning udev-is-not-active sounds like the right thing here,
as udev has really no idea what is running in that environment and what data
will be passed from udev to libudev. The versions of the daemon and the library
need to match.

If it should be possible to run multiple udev daemons at the same time, I'm
really not sure about. Udev is bound to devtmpfs, it will not work anywhere
else really, so this doesn't sound like something that would really work out.

Comment 19 Peter Rajnoha 2012-12-18 13:19:24 UTC
Then I guess we're bound to using chroot environments with compatible host system (possibly equal). But yes, also mixing RHEL kernel with rawhide userspace does not seem to be the best idea...

Comment 20 Kevin Fenzi 2012-12-18 16:50:28 UTC
Not being able to build Fedora live media in our buildsystem will also be less than ideal. ;(

Comment 21 Dennis Gilmore 2012-12-18 17:00:39 UTC
we have to support running fedora compose tools in chroots of the target Fedora release on hosts running the latest version of RHEL. it is the way Release engineering has always worked. it is also how building works so any test suites run at build time need to support the same principles. however we explictly bind mount /dev into the chroot for image creation. where mock uses a dummy /dev on builds.


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