Bug 835466

(In reply to comment #0)
> 2) only mount guest image once when injecting files (attached Pádraig's
> workaround patch)

In openstack-nova-2012.1-13.el6

Duplicate of bug 832511 ?

Note the sleep(3) also works for the very similar upstream issue seen on RH 6.1

Note there are 2 issues really in the upstream https://bugs.launchpad.net/nova/+bug/1013689. The unsynchronised guest issue is very similar and
also addressed with a sleep(3). However my "inject_once" patch attached
here does not address their issue, which is not that surprising
since it was only minimising traversal of the problematic code path.

Verified openstack-nova-2012.1-13.el6


# for i in {1..10}; do nova boot test$i --flavor 1 --image 7e04542d-d996-43bb-bdec-f05d27d0df61 --file '/root/david2=/root/test' --security_groups 'allow-icmp-and-ssh' --key_name david; sleep 1 ; done

#for ip in `nova list |awk '/demonet/{print $8}'| sed -e s/demonet=//g`; do ssh -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no -i david.priv root@$ip md5sum /root/.ssh/authorized_keys /root/david2 ; done

Warning: Permanently added '192.168.1.163' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.158' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.159' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.161' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.156' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.165' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.162' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.157' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.160' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2
Warning: Permanently added '192.168.1.164' (RSA) to the list of known hosts.
b58e9c494f6ea298d17e70a845277066  /root/.ssh/authorized_keys
35f19e72dd33950659c0222922fc046a  /root/david2

Created attachment 596883 [details]
mount once patch to avoid issue

So this patch is only avoiding the issue.
Richard Jones fix some sync issues with libguestfs recently that may well be the root cause. For details of the sync issues addressed see:
https://www.redhat.com/archives/libguestfs/2012-July/msg00020.html

It would be great to reproduce this issue by using an earlier version of nova, or just:

(cd /usr/lib/python2.6/site-packages/nova && patch -R -p1 < $this_patch)

and then updating libguestfs to see is the issue addressed directly.

Richard has released Fedora RPMs though I don't notice RHEL rpms at present.
So this is just a reminder note for when they become available.

cheers.

(In reply to comment #6)
> Created attachment 596883 [details]
> mount once patch to avoid issue
> 
> So this patch is only avoiding the issue.
> Richard Jones fix some sync issues with libguestfs recently that may well be
> the root cause. For details of the sync issues addressed see:
> https://www.redhat.com/archives/libguestfs/2012-July/msg00020.html

Unless you can prove that qemu is segfaulting, this is not the
same thing.  Read the conditions (a) through (d) in the above
email message carefully.

We can't get any further on this bug until someone captures
the debug information from libguestfs:

http://libguestfs.org/guestfs-faq.1.html#debugging_libguestfs

I'm sorry, but everything written about this bug so far
has been broad speculation.  We need facts.

Created attachment 597041 [details]
compute.log with guestmount --verbose

(In reply to comment #7)
> We can't get any further on this bug until someone captures
> the debug information from libguestfs:
> 
> http://libguestfs.org/guestfs-faq.1.html#debugging_libguestfs


Added --verbose to guestmount and logged STDERR to compute.log (Attached)

Thanks to some discussion with David on IRC we have a
plausible cause for this:

(1) When Nova has finished with the mountpoint, it calls
fusermount -u /tmp/mpXX

(2) fusermount informs the kernel which begins the process
of guestmount exiting, but it doesn't wait for guestmount
to actually exit (ie. finish writing and closing the disk
image, shutting down qemu etc)

(3) Nova immediately continues by launching the guest.

(4) Since guestmount hasn't exited, another qemu instance
runs using probably the old copy of the disk image.

(5) For some reason all hell *doesn't* break loose at this
point.  I'm not clear why that is.  But anyway it's not good.

The only way to fix this properly I can see is to use the mount-local
API.

However an interim workaround would be to spin on
'pgrep guestmount' just after calling fusermount and wait
for the guestmount process to exit (for the hack it doesn't
matter which one exits, as long as none are running before
we proceed).

David is going to collect the output of 'pgrep fusermount'
before and after fusermount to see if the situation above
is likely.

I mean 'pgrep guestmount' in that last paragraph.

Created attachment 597068 [details]
rhbz835466.sh

Standalone reproducer for this bug.  This requires guestmount, guestfish,
qemu-img and fusermount programs and nothing else.

To run it:

  chmod +x rhbz835466.sh
  ./rhbz835466.sh

There are various possible outputs:

(1)

  No conclusion.  You must do
    fusermount -u /tmp/testmp
  and rerun the test.

means that fusermount failed because something jumped
into the mountpoint.  Follow the instructions and rerun
the test.

(2) "rhbz 835466 was reproduced"

means that the bug was reproduced.  A file was written to
the mountpoint, but the underlying disk file was not
finalized before we managed to copy it away.

(3)

  RHBZ#835466 could not be reproduced.  This might be luck
  or you might not be affected by it.

Also try uncommenting the "sleep 10" line, to make the
bug go away.  This indicates that the magical fix that
went upstream just changed the timing of things as I predicted.

As Richard suspected guestmount is running before and after fusermount

2012-07-09 15:59:16 DEBUG nova.utils [req-cb983e39-61a1-4774-9249-cddef6ae3dad 29af43364ced4611bf6e093a04d4c144 3f1e394b238d4f26b742e9685a9a1a57] Running cmd (subprocess): sudo nova-rootwrap pgrep guestmount from (pid=8472) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
2012-07-09 15:59:16 DEBUG nova.utils [req-cb983e39-61a1-4774-9249-cddef6ae3dad 29af43364ced4611bf6e093a04d4c144 3f1e394b238d4f26b742e9685a9a1a57] STDOUT=8717
, STDERR= from (pid=8472) execute /usr/lib/python2.6/site-packages/nova/utils.py:235
2012-07-09 15:59:16 DEBUG nova.utils [req-cb983e39-61a1-4774-9249-cddef6ae3dad 29af43364ced4611bf6e093a04d4c144 3f1e394b238d4f26b742e9685a9a1a57] Running cmd (subprocess): sudo nova-rootwrap fusermount -u /tmp/tmpEZz4xc from (pid=8472) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
2012-07-09 15:59:16 DEBUG nova.utils [req-cb983e39-61a1-4774-9249-cddef6ae3dad 29af43364ced4611bf6e093a04d4c144 3f1e394b238d4f26b742e9685a9a1a57] STDOUT=, STDERR= from (pid=8472) execute /usr/lib/python2.6/site-packages/nova/utils.py:235
2012-07-09 15:59:16 DEBUG nova.utils [req-cb983e39-61a1-4774-9249-cddef6ae3dad 29af43364ced4611bf6e093a04d4c144 3f1e394b238d4f26b742e9685a9a1a57] Running cmd (subprocess): sudo nova-rootwrap pgrep guestmount from (pid=8472) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
2012-07-09 15:59:16 DEBUG nova.utils [req-cb983e39-61a1-4774-9249-cddef6ae3dad 29af43364ced4611bf6e093a04d4c144 3f1e394b238d4f26b742e9685a9a1a57] STDOUT=8717
, STDERR= from (pid=8472) execute /usr/lib/python2.6/site-packages/nova/utils.py:235

For completeness re attachment 597041 [details], disregard the guestmount commands returning with 247. They were manually killed due to --trace causing them to hang.

Search instead for the two "guestmount --verbose --rw" commands run in sequence. David confirms that the ssh keys injected in the first run are not present.

So `fusermount -u` is asynchronous. That's unexpected.
I don't suppose there's an easy way to get fuse to
wait for guestmount to exit? Is there ever a case you wouldn't want that?

I wondered could we wait until the mount_dir was unused,
though since we can already os.rmdir(self.mount_dir),
I guess that's immediately released, but guestmount is left running?

Manually waiting for guestmount to return wouldn't be too bad,
though it's awkward to get the pid of the actual guestmount process at present.

(In reply to comment #14)
> I don't suppose there's an easy way to get fuse to
> wait for guestmount to exit? Is there ever a case you wouldn't want that?

Still investigating the fuse & guestmount code to see if this
is possible.

> I wondered could we wait until the mount_dir was unused,
> though since we can already os.rmdir(self.mount_dir),
> I guess that's immediately released, but guestmount is left running?

Yes, I don't think this would ever be possible.  After all
we *have* to release the mountpoint before closing libguestfs,
because if we closed libguestfs first then how would we handle
the FUSE requests that Nova is making on the mountpoint?

The only question is whether we can make fusermount hang
synchronously until guestmount has completely finished, which
is what I'm looking at.

In any case, mount-local solves this properly since Nova would
wait for g.mount_local_run to return and it gets to close the
libguestfs handle itself.

(In reply to comment #15)
> (In reply to comment #14)
> > I don't suppose there's an easy way to get fuse to
> > wait for guestmount to exit? Is there ever a case you wouldn't want that?
> 
> Still investigating the fuse & guestmount code to see if this
> is possible.

I don't think so.

fusermount calls the umount2 syscall, which eventually gets us to
fuse_abort_conn in the kernel, which as far as I can tell simply
sends a close message to the userspace process but doesn't wait
for any answer.

Filed a bug to add guestmount --pid-file:
https://bugzilla.redhat.com/show_bug.cgi?id=838592

I think David is going to work up a Nova patch which will
wait for the guestmount process to exit after the fusermount.

Created attachment 597371 [details]
A more direct workaround

I think this should address the issue more directly.
To verify it does it needs the "mount once" patch backed out of course,
but there are benefits to both, so I'll propose both upstream.

Note on the folsom branch I'll also remove the sync as part of the same patch.

Patch looks good to me.