yahoo-eng-team team mailing list archive
-
yahoo-eng-team team
-
Mailing list archive
-
Message #68905
[Bug 1728563] [NEW] Live snapshot cannot lock .delta (regression with apparmor)
Public bug reported:
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
** Affects: nova
Importance: Undecided
Status: New
** Description changed:
- When live snapshot is enabled in nova via `[workarounds]
+ 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.
+ 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
+ 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`
+ 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 working well.
+ live snapshot is now working well for that instance.
- But this is only hotfix and there must be updated libvirt apparmor
+ 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:
+ 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=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
--
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):
New
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
Follow ups