yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1728563] Re: Live snapshot cannot lock .delta (regression with apparmor)

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Thu, 15 Mar 2018 21:39:18 -0000
Reply-to: Bug 1728563 <1728563@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
This needs to get routed to ubuntu or elsewhere as this isn't something
directly in nova's control.

** Changed in: nova
       Status: New => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1728563

Title:
  Live snapshot cannot lock .delta (regression with apparmor)

Status in OpenStack Compute (nova):
  Invalid

Bug description:
  When live snapshot is enabled in Nova via `[workarounds]
  disable_libvirt_livesnapshot = False`, it fails after done using
  Horizon or CLI with error `unable to execute QEMU command 'drive-
  mirror': Failed to lock byte 100`.

  Non live snapshot is working fine both in Horizon and CLI.

  I traced what cause this error thanks to this bug report
  `https://bugs.launchpad.net/nova/+bug/1244694`. The reason of that old
  bug was wrong Apparmor config. This bug report was solved fine, but
  currently with live snapshot I have an issue with libvirt trying to
  lock file in
  `/var/lib/nova/instances/snapshots/<TMP_DIR>/<UUID>.delta` which fails
  according to Apparmor log below.

  I hotfixed this issue by updating
  `/etc/apparmor.d/libvirt/libvirt-${UUID}` for specific instance's
  UUID. I appended following line `/var/lib/nova/instances/snapshots/**
  k,` and live snapshot is now working well for that instance.

  But this is only hotfix and there must be updated Libvirt Apparmor
  template to allow using snapshots subdirectories, or there must be
  temporary created rule that allows it before live snapshot is made and
  deleted after it is done.

  Nova log:

  ERROR oslo_messaging.rpc.server [req-ae5933d6-a603-48ab-8d53-a4ebdc57ebdc 82fb7a159550424098f2addf3c30461a 971a410f32a6446c95f73819bf4eaebc - default default] Exception during message handling: libvirtError:
  internal error: unable to execute QEMU command 'drive-mirror': Failed to lock byte 100
  ERROR oslo_messaging.rpc.server Traceback (most recent call last):
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 160, in _process_incoming
  ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 213, in dispatch
  ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 183, in _do_dispatch
  ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/exception_wrapper.py", line 76, in wrapped
  ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  ERROR oslo_messaging.rpc.server     self.force_reraise()
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/exception_wrapper.py", line 67, in wrapped
  ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 190, in decorated_function
  ERROR oslo_messaging.rpc.server     "Error: %s", e, instance=instance)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  ERROR oslo_messaging.rpc.server     self.force_reraise()
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 160, in decorated_function
  ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 218, in decorated_function
  ERROR oslo_messaging.rpc.server     kwargs['instance'], e, sys.exc_info())
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  ERROR oslo_messaging.rpc.server     self.force_reraise()
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 206, in decorated_function
  ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 247, in decorated_function
  ERROR oslo_messaging.rpc.server     image_id, instance=instance)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  ERROR oslo_messaging.rpc.server     self.force_reraise()
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 234, in decorated_function
  ERROR oslo_messaging.rpc.server     *args, **kwargs)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 3201, in snapshot_instance
  ERROR oslo_messaging.rpc.server     task_states.IMAGE_SNAPSHOT)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/compute/manager.py", line 3233, in _snapshot_instance
  ERROR oslo_messaging.rpc.server     update_task_state)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1732, in snapshot
  ERROR oslo_messaging.rpc.server     image_format, instance.image_meta)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1906, in _live_snapshot
  ERROR oslo_messaging.rpc.server     dev.rebase(disk_delta, copy=True, reuse_ext=True, shallow=True)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/nova/virt/libvirt/guest.py", line 784, in rebase
  ERROR oslo_messaging.rpc.server     self._disk, base, self.REBASE_DEFAULT_BANDWIDTH, flags=flags)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/eventlet/tpool.py", line 186, in doit
  ERROR oslo_messaging.rpc.server     result = proxy_call(self._autowrap, f, *args, **kwargs)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/eventlet/tpool.py", line 144, in proxy_call
  ERROR oslo_messaging.rpc.server     rv = execute(f, *args, **kwargs)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/eventlet/tpool.py", line 125, in execute
  ERROR oslo_messaging.rpc.server     six.reraise(c, e, tb)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/eventlet/tpool.py", line 83, in tworker
  ERROR oslo_messaging.rpc.server     rv = meth(*args, **kwargs)
  ERROR oslo_messaging.rpc.server   File "/openstack/venvs/nova-16.0.1/lib/python2.7/site-packages/libvirt.py", line 957, in blockRebase
  ERROR oslo_messaging.rpc.server     if ret == -1: raise libvirtError ('virDomainBlockRebase() failed', dom=self)
  ERROR oslo_messaging.rpc.server libvirtError: internal error: unable to execute QEMU command 'drive-mirror': Failed to lock byte 100

  Apparmor log after live-snapshot is started:

  type=VIRT_RESOURCE msg=audit(1509111601.674:659): pid=10277 uid=0 auid=4294967295 ses=4294967295 msg='virt=kvm resrc=cgroup reason=allow vm="instance-00000016" uuid=b1c155b1-1521-4979-998d-1d5c82d9ba7a cgroup="/sys/fs/cgroup/devices/machine/qemu-1-instance-00000016.libvirt-qemu/" class=path path="/var/lib/nova/instances/snapshots/tmpFIdRtb/f10c5e8ede994246966d8d1a0e89cc09.delta" rdev=? acl=rw exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
  type=USER_ACCT msg=audit(1509111601.730:660): pid=13830 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=CRED_ACQ msg=audit(1509111601.730:661): pid=13830 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=USER_ACCT msg=audit(1509111601.730:662): pid=13831 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=CRED_ACQ msg=audit(1509111601.730:663): pid=13831 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=LOGIN msg=audit(1509111601.730:664): pid=13830 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=15 res=1
  type=LOGIN msg=audit(1509111601.730:665): pid=13831 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=16 res=1
  type=USER_START msg=audit(1509111601.730:666): pid=13831 uid=0 auid=0 ses=16 msg='op=PAM:session_open acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=USER_START msg=audit(1509111601.730:667): pid=13830 uid=0 auid=0 ses=15 msg='op=PAM:session_open acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=USER_CMD msg=audit(1509111601.738:668): pid=13834 uid=0 auid=0 ses=16 msg='cwd="/root" cmd=2F6F70742F766E782D6661756C74792D6465766963652D636C65616E75702F6661756C74795F6465766963655F636C65616E75702E7079202D2D636F6E6669672D66696C65202F6574632F6E6F76612F6E6F76612E636F6E66202D2D646574656374696F6E2D6F6E6C79 terminal=? res=failed'
  type=CRED_DISP msg=audit(1509111601.738:669): pid=13831 uid=0 auid=0 ses=16 msg='op=PAM:setcred acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=USER_END msg=audit(1509111601.738:670): pid=13831 uid=0 auid=0 ses=16 msg='op=PAM:session_close acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=CRED_DISP msg=audit(1509111601.874:671): pid=13830 uid=0 auid=0 ses=15 msg='op=PAM:setcred acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=USER_END msg=audit(1509111601.874:672): pid=13830 uid=0 auid=0 ses=15 msg='op=PAM:session_close acct="root" exe="/usr/sbin/cron" hostname=? addr=? terminal=cron res=success'
  type=AVC msg=audit(1509111601.878:673): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="libvirt-b1c155b1-1521-4979-998d-1d5c82d9ba7a" pid=13829 comm="apparmor_parser"
  type=SYSCALL msg=audit(1509111601.878:673): arch=c000003e syscall=1 success=yes exit=52193 a0=5 a1=116c7a0 a2=cbe1 a3=0 items=0 ppid=13828 pid=13829 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="apparmor_parser" exe="/sbin/apparmor_parser" key=(null)
  type=PROCTITLE msg=audit(1509111601.878:673): proctitle=2F7362696E2F61707061726D6F725F706172736572002D72002F6574632F61707061726D6F722E642F6C6962766972742F6C6962766972742D62316331353562312D313532312D343937392D393938642D316435633832643962613761
  type=AVC msg=audit(1509111601.890:674): apparmor="DENIED" operation="file_lock" profile="libvirt-b1c155b1-1521-4979-998d-1d5c82d9ba7a" name="/var/lib/nova/instances/snapshots/tmpFIdRtb/f10c5e8ede994246966d8d1a0e89cc09.delta" pid=12194 comm="qemu-system-x86" requested_mask="k" denied_mask="k" fsuid=64055 ouid=64055
  type=SYSCALL msg=audit(1509111601.890:674): arch=c000003e syscall=72 success=no exit=-13 a0=66 a1=25 a2=7fff60854b00 a3=7f5198729b78 items=0 ppid=1 pid=12194 auid=4294967295 uid=64055 gid=115 euid=64055 suid=64055 fsuid=64055 egid=115 sgid=115 fsgid=115 tty=(none) ses=4294967295 comm="qemu-system-x86" exe="/usr/bin/qemu-system-x86_64" key=(null)
  type=PROCTITLE msg=audit(1509111601.890:674): proctitle=2F7573722F62696E2F71656D752D73797374656D2D7838365F3634002D6E616D650067756573743D696E7374616E63652D30303030303031362C64656275672D746872656164733D6F6E002D53002D6F626A656374007365637265742C69643D6D61737465724B6579302C666F726D61743D7261772C66696C653D2F7661722F
  type=AVC msg=audit(1509111601.890:675): apparmor="DENIED" operation="file_lock" profile="libvirt-b1c155b1-1521-4979-998d-1d5c82d9ba7a" name="/var/lib/nova/instances/snapshots/tmpFIdRtb/f10c5e8ede994246966d8d1a0e89cc09.delta" pid=12194 comm="qemu-system-x86" requested_mask="k" denied_mask="k" fsuid=64055 ouid=64055
  type=SYSCALL msg=audit(1509111601.890:675): arch=c000003e syscall=72 success=no exit=-13 a0=66 a1=25 a2=7fff60854b00 a3=0 items=0 ppid=1 pid=12194 auid=4294967295 uid=64055 gid=115 euid=64055 suid=64055 fsuid=64055 egid=115 sgid=115 fsgid=115 tty=(none) ses=4294967295 comm="qemu-system-x86" exe="/usr/bin/qemu-system-x86_64" key=(null)
  type=PROCTITLE msg=audit(1509111601.890:675): proctitle=2F7573722F62696E2F71656D752D73797374656D2D7838365F3634002D6E616D650067756573743D696E7374616E63652D30303030303031362C64656275672D746872656164733D6F6E002D53002D6F626A656374007365637265742C69643D6D61737465724B6579302C666F726D61743D7261772C66696C653D2F7661722F
  type=AVC msg=audit(1509111601.890:676): apparmor="DENIED" operation="file_lock" profile="libvirt-b1c155b1-1521-4979-998d-1d5c82d9ba7a" name="/var/lib/nova/instances/snapshots/tmpFIdRtb/f10c5e8ede994246966d8d1a0e89cc09.delta" pid=12194 comm="qemu-system-x86" requested_mask="k" denied_mask="k" fsuid=64055 ouid=64055
  type=SYSCALL msg=audit(1509111601.890:676): arch=c000003e syscall=72 success=no exit=-13 a0=66 a1=25 a2=7fff60854b80 a3=7f519d32dc00 items=0 ppid=1 pid=12194 auid=4294967295 uid=64055 gid=115 euid=64055 suid=64055 fsuid=64055 egid=115 sgid=115 fsgid=115 tty=(none) ses=4294967295 comm="qemu-system-x86" exe="/usr/bin/qemu-system-x86_64" key=(null)
  type=PROCTITLE msg=audit(1509111601.890:676): proctitle=2F7573722F62696E2F71656D752D73797374656D2D7838365F3634002D6E616D650067756573743D696E7374616E63652D30303030303031362C64656275672D746872656164733D6F6E002D53002D6F626A656374007365637265742C69643D6D61737465724B6579302C666F726D61743D7261772C66696C653D2F7661722F
  type=VIRT_RESOURCE msg=audit(1509111601.890:677): pid=10277 uid=0 auid=4294967295 ses=4294967295 msg='virt=kvm resrc=disk reason=mirror vm="instance-00000016" uuid=b1c155b1-1521-4979-998d-1d5c82d9ba7a old-disk="?" new-disk="/var/lib/nova/instances/snapshots/tmpFIdRtb/f10c5e8ede994246966d8d1a0e89cc09.delta" exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=failed'
  type=VIRT_RESOURCE msg=audit(1509111601.890:678): pid=10277 uid=0 auid=4294967295 ses=4294967295 msg='virt=kvm resrc=cgroup reason=deny vm="instance-00000016" uuid=b1c155b1-1521-4979-998d-1d5c82d9ba7a cgroup="/sys/fs/cgroup/devices/machine/qemu-1-instance-00000016.libvirt-qemu/" class=path path="/var/lib/nova/instances/snapshots/tmpFIdRtb/f10c5e8ede994246966d8d1a0e89cc09.delta" rdev=? acl=rwm exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
  type=AVC msg=audit(1509111602.086:679): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="libvirt-b1c155b1-1521-4979-998d-1d5c82d9ba7a" pid=13838 comm="apparmor_parser"
  type=SYSCALL msg=audit(1509111602.086:679): arch=c000003e syscall=1 success=yes exit=51169 a0=5 a1=2436900 a2=c7e1 a3=0 items=0 ppid=13837 pid=13838 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="apparmor_parser" exe="/sbin/apparmor_parser" key=(null)
  type=PROCTITLE msg=audit(1509111602.086:679): proctitle=2F7362696E2F61707061726D6F725F706172736572002D72002F6574632F61707061726D6F722E642F6C6962766972742F6C6962766972742D62316331353562312D313532312D343937392D393938642D316435633832643962613761

  Versions used:

  Installation via Openstack ansible pike stable
  Virtualization: Libvirt + KVM
  Storage: NFS storage with files mounted on /var/lib/nova/instances
  Networking: Neutron with linuxbridge
  OS: Ubuntu 16.04
  libvirt: 3.6.0-1ubuntu5~cloud0
  qemu: 1:2.10+dfsg-0ubuntu1~cloud0
  Openstack: Pike
  Nova: commit a2e45404d9b7fdf350b494d5fb53f94c616f39ee

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1728563/+subscriptions
References

[Bug 1728563] [NEW] Live snapshot cannot lock .delta (regression with apparmor)
From: Ondrej Vasko, 2017-10-30