Comment 7 for bug 1845506

logs:

2 disks:
Oct 15 13:14:07 e libvirtd[612]: internal error: unable to execute QEMU command 'transaction': Could not create file: Permission denied
Oct 15 13:14:08 e libvirtd[612]: Path '/var/lib/libvirt/images/eoan-disk1.snapshot1.qcow' is not accessible: No such file or directory
Oct 15 13:14:08 e libvirtd[612]: Unable to tear down cgroup access on /var/lib/libvirt/images/eoan-disk1.snapshot1.qcow
Oct 15 13:14:08 e libvirtd[612]: internal error: child reported (status=125): unable to set user and group to '0:0' on '/var/lib/libvirt/images/eoan-disk1.snapshot1.qcow': No such file or directory
Oct 15 13:14:08 e libvirtd[612]: Unable to restore security label on /var/lib/libvirt/images/eoan-disk1.snapshot1.qcow
Oct 15 13:14:08 e libvirtd[612]: Path '/var/lib/libvirt/images/eoan-disk2.snapshot1.qcow' is not accessible: No such file or directory
Oct 15 13:14:08 e libvirtd[612]: Unable to tear down cgroup access on /var/lib/libvirt/images/eoan-disk2.snapshot1.qcow
Oct 15 13:14:08 e libvirtd[612]: internal error: child reported (status=125): unable to set user and group to '0:0' on '/var/lib/libvirt/images/eoan-disk2.snapshot1.qcow': No such file or directory
Oct 15 13:14:08 e libvirtd[612]: Unable to restore security label on /var/lib/libvirt/images/eoan-disk2.snapshot1.qcow

One disk:
- no message
- new rule
  "/var/lib/libvirt/images/eoan-disk1.snapshot1.qcow" rwk,

This looks like a late call from labelling (comes with rwk by default).

Check what we get with one disk and two disks in GDB:
Num Type Disp Enb Address What
3 breakpoint keep y 0x00007f92474dacd0 in load_profile at ../../../src/security/security_apparmor.c:166
        silent
        if fn == 0
          cont
        p fn
        end

(gdb) bt
#0 load_profile (profile=0x7f9224049f10 "libvirt-2370eae2-cc9a-493c-b502-d2d64e2ee1d1", def=def@entry=0x7f92380e9190,
    fn=0x7f92180be390 "/var/lib/libvirt/images/eoan-disk1.snapshot2.qcow", append=append@entry=false, mgr=<optimized out>) at ../../../src/security/security_apparmor.c:166
#1 0x00007f92474db08b in AppArmorSetSecurityImageLabel (mgr=<optimized out>, def=0x7f92380e9190, src=0x7f92181f9930, flags=<optimized out>) at ../../../src/security/security_apparmor.c:830
#2 0x00007f92474d1ebe in virSecurityManagerSetImageLabel (mgr=0x7f91f401d0b0, vm=vm@entry=0x7f92380e9190, src=src@entry=0x7f92181f9930, flags=flags@entry=(unknown: 0))
    at ../../../src/security/security_manager.c:506
#3 0x00007f92474cd9a9 in virSecurityStackSetImageLabel (mgr=<optimized out>, vm=0x7f92380e9190, src=0x7f92181f9930, flags=(unknown: 0)) at ../../../src/security/security_stack.c:575
#4 0x00007f92474d1ebe in virSecurityManagerSetImageLabel (mgr=0x7f91f401b920, vm=0x7f92380e9190, src=src@entry=0x7f92181f9930, flags=flags@entry=(unknown: 0))
    at ../../../src/security/security_manager.c:506
#5 0x00007f923c27a014 in qemuSecuritySetImageLabel (driver=driver@entry=0x7f91f400f880, vm=vm@entry=0x7f92240444b0, src=src@entry=0x7f92181f9930, backingChain=backingChain@entry=false)
    at ../../../src/qemu/qemu_security.c:115
#6 0x00007f923c1dccad in qemuDomainStorageSourceAccessModify (driver=0x7f91f400f880, vm=0x7f92240444b0, src=0x7f92181f9930, flags=QEMU_DOMAIN_STORAGE_SOURCE_ACCESS_SKIP_REVOKE)
    at ../../../src/qemu/qemu_domain.c:9350
#7 0x00007f923c275473 in qemuDomainSnapshotCreateSingleDiskActive (reuse=false, actions=<optimized out>, dd=0x7f92181f98c0, vm=<optimized out>, driver=0x7f91f400f880)
    at ../../../src/qemu/qemu_driver.c:15216
#8 qemuDomainSnapshotCreateDiskActive (asyncJob=QEMU_ASYNC_JOB_SNAPSHOT, flags=144, snap=<optimized out>, vm=<optimized out>, driver=0x7f91f400f880)
    at ../../../src/qemu/qemu_driver.c:15269
#9 qemuDomainSnapshotCreateActiveExternal (flags=144, snap=<optimized out>, vm=<optimized out>, driver=0x7f91f400f880) at ../../../src/qemu/qemu_driver.c:15476
#10 qemuDomainSnapshotCreateXML (domain=<optimized out>, xmlDesc=<optimized out>, flags=144) at ../../../src/qemu/qemu_driver.c:15773
#11 0x00007f92475ed698 in virDomainSnapshotCreateXML (domain=domain@entry=0x7f92180f3100,
    xmlDesc=0x7f92183119a0 "<domainsnapshot>\n <disks>\n <disk name='vda' snapshot='no'/>\n <disk name='vdb' snapshot='no'/>\n <disk name='vdc' snapshot='external'>\n <source file='/var/lib/libvirt/images/eoan-disk1.sn"..., flags=144) at ../../../src/libvirt-domain-snapshot.c:241
#12 0x0000561722d17ddc in remoteDispatchDomainSnapshotCreateXML (server=0x56172369bed0, msg=0x56172371b300, ret=0x7f921830c9e0, args=0x7f921803a160, rerr=0x7f9241fce9a0,
    client=<optimized out>) at ../../../src/remote/remote_daemon_dispatch_stubs.h:11744
#13 remoteDispatchDomainSnapshotCreateXMLHelper (server=0x56172369bed0, client=<optimized out>, msg=0x56172371b300, rerr=0x7f9241fce9a0, args=0x7f921803a160, ret=0x7f921830c9e0)
    at ../../../src/remote/remote_daemon_dispatch_stubs.h:11718
#14 0x00007f92474fbcb1 in virNetServerProgramDispatchCall (msg=0x56172371b300, client=0x5617236f00e0, server=0x56172369bed0, prog=0x5617236e5550)
    at ../../../src/rpc/virnetserverprogram.c:435
#15 virNetServerProgramDispatch (prog=0x5617236e5550, server=server@entry=0x56172369bed0, client=0x5617236f00e0, msg=0x56172371b300) at ../../../src/rpc/virnetserverprogram.c:302
#16 0x00007f92475022bc in virNetServerProcessMsg (msg=<optimized out>, prog=<optimized out>, client=<optimized out>, srv=0x56172369bed0) at ../../../src/rpc/virnetserver.c:142
#17 virNetServerHandleJob (jobOpaque=<optimized out>, opaque=0x56172369bed0) at ../../../src/rpc/virnetserver.c:163
#18 0x00007f924742860f in virThreadPoolWorker (opaque=opaque@entry=0x56172368a580) at ../../../src/util/virthreadpool.c:163
#19 0x00007f92474278fc in virThreadHelper (data=<optimized out>) at ../../../src/util/virthread.c:206
#20 0x00007f9247299669 in start_thread (arg=<optimized out>) at pthread_create.c:479
#21 0x00007f92471c1323 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

This effectively calls
$9 = 0x7f92180f6520 "LIBVIRT_LOG_OUTPUTS=3:stderr /usr/lib/libvirt/virt-aa-helper -r -u libvirt-2370eae2-cc9a-493c-b502-d2d64e2ee1d1 -f /var/lib/libvirt/images/eoan-disk1.snapshot2.qcow"

Which seems right to me ...

And after this I see in the profile it is added:

  "/var/lib/libvirt/images/eoan-disk1.snapshot2.qcow" rwk,

I see those calls for both paths:
Thread 4 "libvirtd" hit Breakpoint 5, load_profile (profile=0x7f9224049f10 "libvirt-2370eae2-cc9a-493c-b502-d2d64e2ee1d1", def=def@entry=0x7f92380e9190,
    fn=0x7f9210007be0 "/var/lib/libvirt/images/eoan-disk1.snapshot2.qcow", append=append@entry=false, mgr=<optimized out>) at ../../../src/security/security_apparmor.c:166
166 load_profile(virSecurityManagerPtr mgr ATTRIBUTE_UNUSED,
$17 = 0x7f9210007be0 "/var/lib/libvirt/images/eoan-disk1.snapshot2.qcow"
(gdb) c
Continuing.
[Detaching after fork from child process 21613]
[Detaching after fork from child process 21616]

Thread 4 "libvirtd" hit Breakpoint 5, load_profile (profile=0x7f9224049f10 "libvirt-2370eae2-cc9a-493c-b502-d2d64e2ee1d1", def=def@entry=0x7f92380e9190,
    fn=0x7f9210009f10 "/var/lib/libvirt/images/eoan-disk2.snapshot1.qcow", append=append@entry=false, mgr=<optimized out>) at ../../../src/security/security_apparmor.c:166
166 load_profile(virSecurityManagerPtr mgr ATTRIBUTE_UNUSED,
$18 = 0x7f9210009f10 "/var/lib/libvirt/images/eoan-disk2.snapshot1.qcow"

$29 = 0x7f92300055a0 "LIBVIRT_LOG_OUTPUTS=3:stderr /usr/lib/libvirt/virt-aa-helper -r -u libvirt-2370eae2-cc9a-493c-b502-d2d64e2ee1d1 -f /var/lib/libvirt/images/eoan-disk2.snapshot1.qcow"

So surely both file labelling calls happen.