Discussion:
Bug#932456: libvirt-daemon-system: blockcommit => permission denied
(too old to reply)
Benoit Panizzon
2019-07-19 16:00:02 UTC
Permalink
Package: libvirt-daemon-system
Version: 5.0.0-4
Severity: important

Dear Maintainer,

After upgrading my virtual 'hosting' machine to Buster, I snapshoted a first guest.

Now I am not able to blockcommit the snapshot back to the backing image
to be able to grow the FS.
Also the snapshot is quickly growing.

I am pretty at a loss about the cause. Google found a couple of hints
that apparmor is the culpit. So I did try to run everything under
aa-complaint with no success.

I did try to disable apparmor or the libvirtd profile on apparmor as well, no joy!

I did a chmod 777 on the directory with the images and a chmod 666
in the images themself. So I'm pretty sure it's not a file
permission issue.

# virsh blockcommit hathi vda --active --verbose --pivot
error: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied

Jul 19 17:33:08 pulsar kernel: [ 1904.061499] audit: type=1400 audit(1563550388.502:120): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="libvirt-402562bd-e0cd-9bcd-7455-4c3833e60907" pid=5933 comm="apparmor_parser"
Jul 19 17:33:08 pulsar libvirtd[3145]: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied
Jul 19 17:33:08 pulsar kernel: [ 1904.202315] audit: type=1400 audit(1563550388.642:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="libvirt-402562bd-e0cd-9bcd-7455-4c3833e60907" pid=5937 comm="apparmor_parser"

Any hints on how to solve the issue are greatly appreciated.

-Benoit-

-- System Information:
Debian Release: 10.0
APT prefers stable
APT policy: (500, 'stable')
Architecture: amd64 (x86_64)

Kernel: Linux 4.19.0-5-amd64 (SMP w/4 CPU cores)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=de_CH.UTF-8, LC_CTYPE=de_CH.UTF-8 (charmap=UTF-8), LANGUAGE=de_CH:de (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages libvirt-daemon-system depends on:
ii adduser 3.118
ii debconf [debconf-2.0] 1.5.71
ii gettext-base 0.19.8.1-9
ii iptables 1.8.2-4
ii libacl1 2.2.53-4
ii libapparmor1 2.13.2-10
ii libaudit1 1:2.8.4-3
ii libblkid1 2.33.1-0.1
ii libc6 2.28-10
ii libcap-ng0 0.7.9-2
ii libdbus-1-3 1.12.16-1
ii libdevmapper1.02.1 2:1.02.155-3
ii libgnutls30 3.6.7-4
ii libnl-3-200 3.4.0-1
ii libnl-route-3-200 3.4.0-1
ii libnuma1 2.0.12-1
ii libselinux1 2.8-1+b1
ii libvirt-clients 5.0.0-4
ii libvirt-daemon 5.0.0-4
ii libvirt0 5.0.0-4
ii libxml2 2.9.4+dfsg1-7+b3
ii libyajl2 2.1.0-3
ii logrotate 3.14.0-4
ii lsb-base 10.2019051400
ii policykit-1 0.105-25

Versions of packages libvirt-daemon-system recommends:
ii dmidecode 3.2-1
ii dnsmasq-base [dnsmasq-base] 2.80-1
ii iproute2 4.20.0-2
ii parted 3.2-25

Versions of packages libvirt-daemon-system suggests:
ii apparmor 2.13.2-10
pn auditd <none>
ii nfs-common 1:1.3.4-2.5
pn open-iscsi <none>
pn pm-utils <none>
pn radvd <none>
ii systemd 241-5
pn systemtap <none>
pn zfsutils <none>

-- Configuration Files:
/etc/apparmor.d/usr.sbin.libvirtd changed:
@{LIBVIRT}="libvirt"
/usr/sbin/libvirtd flags=(attach_disconnected, complain) {
#include <abstractions/base>
#include <abstractions/dbus>
capability kill,
capability net_admin,
capability net_raw,
capability setgid,
capability sys_admin,
capability sys_module,
capability sys_ptrace,
capability sys_pacct,
capability sys_nice,
capability sys_chroot,
capability setuid,
capability dac_override,
capability dac_read_search,
capability fowner,
capability chown,
capability setpcap,
capability mknod,
capability fsetid,
capability audit_write,
capability ipc_lock,
# Needed for vfio
capability sys_resource,
mount options=(rw,rslave) -> /,
mount options=(rw, nosuid) -> /{var/,}run/libvirt/qemu/*.dev/,
# libvirt provides any mounts under /dev to qemu namespaces
mount options=(rw, move) /dev/ -> /{,var/}run/libvirt/qemu/*.dev/,
mount options=(rw, move) /dev/** -> /{,var/}run/libvirt/qemu/*{,/},
mount options=(rw, move) /{,var/}run/libvirt/qemu/*.dev/ -> /dev/,
mount options=(rw, move) /{,var/}run/libvirt/qemu/*{,/} -> /dev/**,
network inet stream,
network inet dgram,
network inet6 stream,
network inet6 dgram,
network netlink raw,
network packet dgram,
network packet raw,
# for --p2p migrations
unix (send, receive) type=stream addr=none peer=(label=unconfined addr=none),
ptrace (read,trace) peer=unconfined,
ptrace (read,trace) peer=/usr/sbin/libvirtd,
ptrace (read,trace) peer=/usr/sbin/dnsmasq,
ptrace (read,trace) peer=libvirt-*,
signal (send) peer=/usr/sbin/dnsmasq,
signal (read, send) peer=libvirt-*,
signal (send) set=("kill", "term") peer=unconfined,
# For communication/control to qemu-bridge-helper
unix (send, receive) type=stream addr=none peer=(label=/usr/sbin/libvirtd//qemu_bridge_helper),
signal (send) set=("term") peer=/usr/sbin/libvirtd//qemu_bridge_helper,
# allow connect with openGraphicsFD, direction reversed in newer versions
unix (send, receive) type=stream addr=none peer=(label=libvirt-[0-9a-f]*-[0-9a-f]*-[0-9a-f]*-[0-9a-f]*-[0-9a-f]*),
# unconfined also required if guests run without security module
unix (send, receive) type=stream addr=none peer=(label=unconfined),
# required if guests run unconfined seclabel type='none' but libvirtd is confined
signal (read, send) peer=unconfined,
# Very lenient profile for libvirtd since we want to first focus on confining
# the guests. Guests will have a very restricted profile.
/ r,
/** rwmkl,
/bin/* PUx,
/sbin/* PUx,
/usr/bin/* PUx,
/usr/sbin/virtlogd pix,
/usr/sbin/* PUx,
/{usr/,}lib/udev/scsi_id PUx,
/usr/{lib,lib64}/xen-common/bin/xen-toolstack PUx,
/usr/{lib,lib64}/xen/bin/* Ux,
/usr/lib/xen-*/bin/libxl-save-helper PUx,
# Required by nwfilter_ebiptables_driver.c:ebiptablesWriteToTempFile() to
# read and run an ebtables script.
/var/lib/libvirt/virtd* ixr,
# force the use of virt-aa-helper
audit deny /{usr/,}sbin/apparmor_parser rwxl,
audit deny /etc/apparmor.d/libvirt/** wxl,
audit deny /sys/kernel/security/apparmor/features rwxl,
audit deny /sys/kernel/security/apparmor/matching rwxl,
audit deny /sys/kernel/security/apparmor/.* rwxl,
/sys/kernel/security/apparmor/profiles r,
/usr/{lib,lib64}/libvirt/* PUxr,
/usr/{lib,lib64}/libvirt/libvirt_parthelper ix,
/usr/{lib,lib64}/libvirt/libvirt_iohelper ix,
/etc/libvirt/hooks/** rmix,
/etc/xen/scripts/** rmix,
# allow changing to our UUID-based named profiles
change_profile -> @{LIBVIRT}-[0-9a-f]*-[0-9a-f]*-[0-9a-f]*-[0-9a-f]*-[0-9a-f]*,
/usr/{lib,lib64,lib/qemu,libexec}/qemu-bridge-helper Cx -> qemu_bridge_helper,
# child profile for bridge helper process
profile qemu_bridge_helper {
#include <abstractions/base>
capability setuid,
capability setgid,
capability setpcap,
capability net_admin,
network inet stream,
# For communication/control from libvirtd
unix (send, receive) type=stream addr=none peer=(label=/usr/sbin/libvirtd),
signal (receive) set=("term") peer=/usr/sbin/libvirtd,
/dev/net/tun rw,
/etc/qemu/** r,
owner @{PROC}/*/status r,
/usr/{lib,lib64,lib/qemu,libexec}/qemu-bridge-helper rmix,
}

# Site-specific additions and overrides. See local/README for details.
#include <local/usr.sbin.libvirtd>
}

/etc/default/libvirt-guests changed:
ON_BOOT=start
START_DELAY=10
ON_SHUTDOWN=susped
PARALLEL_SHUTDOWN=3

/etc/default/libvirtd changed:
start_libvirtd="yes"
libvirtd_opts="-l"

/etc/init.d/libvirtd changed:
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
export PATH
DAEMON=/usr/sbin/libvirtd
NAME=libvirtd
DESC="libvirt management daemon"
cgroups="cpuset cpu cpuacct devices freezer net_cls blkio perf_event"
! grep -qs cgroup_enable=memory /proc/cmdline || cgroups="$cgroups memory"
test -x $DAEMON || exit 0
echo TEST2
. /lib/lsb/init-functions
echo TEST
PIDFILE=/var/run/$NAME.pid
DODTIME=1 # Time to wait for the server to die, in seconds
if [ -f /etc/default/libvirtd ] ; then
. /etc/default/libvirtd
fi
check_start_libvirtd_option() {
if [ ! "$start_libvirtd" = "yes" ]; then
log_warning_msg "Not starting libvirt management daemon libvirtd, disabled via /etc/default/libvirtd"
return 1
else
return 0
fi
}
running_pid()
{
# Check if a given process pid's cmdline matches a given name
pid=$1
name=$2
[ -z "$pid" ] && return 1
[ ! -d /proc/$pid ] && return 1
cmd=`cat /proc/$pid/cmdline | tr "\000" "\n"|head -n 1 |cut -d : -f 1`
# Is this the expected child?
[ "$cmd" != "$name" ] && return 1
return 0
}
running()
{
# No pidfile, probably no daemon present
[ ! -f "$PIDFILE" ] && return 1
# Obtain the pid and check it against the binary name
pid=`cat $PIDFILE`
running_pid $pid $DAEMON || return 1
return 0
}
systemd_running()
{
if [ -d /run/systemd/system ] ; then
return 0
fi
return 1
}
mount_cgroups()
{
if ! systemd_running
then
mount -t tmpfs cgroup_root /sys/fs/cgroup || return 1
for M in $cgroups; do
mkdir /sys/fs/cgroup/$M || return 1
mount -t cgroup -o rw,nosuid,nodev,noexec,relatime,$M "cgroup_${M}" "/sys/fs/cgroup/${M}" || return 1
done
else
log_warning_msg "Systemd running, skipping cgroup mount."
fi
}
umount_cgroups()
{
if ! systemd_running
then
for M in $cgroups; do
umount "cgroup_${M}"
rmdir /sys/fs/cgroup/$M
done
umount cgroup_root
else
log_warning_msg "Systemd running, skipping cgroup mount."
fi
}
check_mount_cgroup_options() {
if [ ! "$mount_cgroups" = "yes" ]; then
return 1
else
return 0
fi
}
force_stop() {
[ ! -f "$PIDFILE" ] && return
if running ; then
kill -15 $pid
# Is it really dead?
[ -n "$DODTIME" ] && sleep "$DODTIME"s
if running ; then
kill -9 $pid
[ -n "$DODTIME" ] && sleep "$DODTIME"s
if running ; then
echo "Cannot kill $LABEL (pid=$pid)!"
exit 1
fi
fi
fi
rm -f $PIDFILE
return 0
}
case "$1" in
start)
if check_start_libvirtd_option; then
log_daemon_msg "Starting $DESC" "$NAME"
if running ; then
log_progress_msg "already running"
log_end_msg 0
exit 0
fi
rm -f /var/run/libvirtd.pid
if check_mount_cgroup_options; then
if ! mount_cgroups;then
log_warning_msg "Can not mount cgroups layout"
exit 1
fi
fi
start-stop-daemon --start --quiet --pidfile $PIDFILE \
--exec $DAEMON -- -d $libvirtd_opts
if running; then
log_end_msg 0
else
log_end_msg 1
fi
fi
;;
stop)
log_daemon_msg "Stopping $DESC" "$NAME"
if ! running ; then
log_progress_msg "not running"
log_end_msg 0
exit 0
fi
if check_mount_cgroup_options; then
umount_cgroups
fi
start-stop-daemon --stop --quiet --pidfile $PIDFILE \
--exec $DAEMON
log_end_msg 0
;;
force-stop)
log_daemon_msg "Forcefully stopping $DESC" "$NAME"
force_stop
if ! running; then
log_end_msg 0
else
log_end_msg 1
fi
;;
restart)
if check_start_libvirtd_option; then
log_daemon_msg "Restarting $DESC" "$DAEMON"
start-stop-daemon --oknodo --stop --quiet --pidfile \
/var/run/$NAME.pid --exec $DAEMON
[ -n "$DODTIME" ] && sleep $DODTIME
start-stop-daemon --start --quiet --pidfile \
/var/run/$NAME.pid --exec $DAEMON -- -d $libvirtd_opts
if running; then
log_end_msg 0
else
log_end_msg 1
fi
fi
;;
reload|force-reload)
if running; then
log_daemon_msg "Reloading configuration of $DESC" "$NAME"
start-stop-daemon --stop --signal 1 --quiet --pidfile \
/var/run/$NAME.pid --exec $DAEMON
log_end_msg 0
else
log_warning_msg "libvirtd not running, doing nothing."
fi
;;
status)
log_daemon_msg "Checking status of $DESC" "$NAME"
if running ; then
log_progress_msg "running"
log_end_msg 0
else
log_progress_msg "not running"
log_end_msg 1
if [ -f "$PIDFILE" ] ; then
exit 1
else
exit 3
fi
fi
;;
*)
N=/etc/init.d/libvirtd
echo "Usage: $N {start|stop|restart|reload|force-reload|status|force-stop}" >&2
exit 1
;;
esac
exit 0

/etc/libvirt/libvirtd.conf changed:
listen_tls = 0
listen_tcp = 1
unix_sock_group = "libvirt"
unix_sock_ro_perms = "0777"
unix_sock_rw_perms = "0770"
unix_sock_dir = "/var/run/libvirt"
auth_unix_ro = "none"
auth_unix_rw = "none"
auth_tcp = "sasl"

/etc/libvirt/nwfilter/allow-arp.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit allow-arp
or other application using the libvirt API.
-->
<filter name='allow-arp' chain='arp' priority='-500'>
<uuid>d0abceab-e2b4-4cc3-93d6-dc3ea426edf3</uuid>
<rule action='accept' direction='inout' priority='500'/>
</filter>

/etc/libvirt/nwfilter/allow-dhcp-server.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit allow-dhcp-server
or other application using the libvirt API.
-->
<filter name='allow-dhcp-server' chain='ipv4' priority='-700'>
<uuid>6fccac6f-0f2e-4e6a-93c7-a9d523bc4dab</uuid>
<rule action='accept' direction='out' priority='100'>
<ip srcipaddr='0.0.0.0' dstipaddr='255.255.255.255' protocol='udp' srcportstart='68' dstportstart='67'/>
</rule>
<rule action='accept' direction='in' priority='100'>
<ip srcipaddr='$DHCPSERVER' protocol='udp' srcportstart='67' dstportstart='68'/>
</rule>
</filter>

/etc/libvirt/nwfilter/allow-dhcp.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit allow-dhcp
or other application using the libvirt API.
-->
<filter name='allow-dhcp' chain='ipv4' priority='-700'>
<uuid>5a543ad3-1b04-498f-a52e-23a538040e58</uuid>
<rule action='accept' direction='out' priority='100'>
<ip srcipaddr='0.0.0.0' dstipaddr='255.255.255.255' protocol='udp' srcportstart='68' dstportstart='67'/>
</rule>
<rule action='accept' direction='in' priority='100'>
<ip protocol='udp' srcportstart='67' dstportstart='68'/>
</rule>
</filter>

/etc/libvirt/nwfilter/allow-incoming-ipv4.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit allow-incoming-ipv4
or other application using the libvirt API.
-->
<filter name='allow-incoming-ipv4' chain='ipv4' priority='-700'>
<uuid>1950e05d-12e5-4f06-a3ef-23f9dae8141a</uuid>
<rule action='accept' direction='in' priority='500'/>
</filter>

/etc/libvirt/nwfilter/allow-ipv4.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit allow-ipv4
or other application using the libvirt API.
-->
<filter name='allow-ipv4' chain='ipv4' priority='-700'>
<uuid>ff143dbd-a11b-4dbc-81fd-397c87ce1a94</uuid>
<rule action='accept' direction='inout' priority='500'/>
</filter>

/etc/libvirt/nwfilter/clean-traffic-gateway.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit clean-traffic-gateway
or other application using the libvirt API.
-->
<filter name='clean-traffic-gateway' chain='root'>
<uuid>9b94ec17-4ae0-4222-8783-77f1aefe66c2</uuid>
<filterref filter='no-mac-spoofing'/>
<filterref filter='no-ip-spoofing'/>
<filterref filter='no-arp-spoofing'/>
<rule action='accept' direction='inout' priority='-500'>
<mac protocolid='arp'/>
</rule>
<rule action='accept' direction='in' priority='500'>
<mac srcmacaddr='$GATEWAY_MAC'/>
</rule>
<rule action='accept' direction='out' priority='500'>
<mac dstmacaddr='$GATEWAY_MAC'/>
</rule>
<filterref filter='no-other-l2-traffic'/>
<filterref filter='qemu-announce-self'/>
</filter>

/etc/libvirt/nwfilter/clean-traffic.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit clean-traffic
or other application using the libvirt API.
-->
<filter name='clean-traffic' chain='root'>
<uuid>b28d72d9-1c54-463d-bb09-ae2fb40554ec</uuid>
<filterref filter='no-mac-spoofing'/>
<filterref filter='no-ip-spoofing'/>
<rule action='accept' direction='out' priority='-650'>
<mac protocolid='ipv4'/>
</rule>
<filterref filter='allow-incoming-ipv4'/>
<filterref filter='no-arp-spoofing'/>
<rule action='accept' direction='inout' priority='-500'>
<mac protocolid='arp'/>
</rule>
<filterref filter='no-other-l2-traffic'/>
<filterref filter='qemu-announce-self'/>
</filter>

/etc/libvirt/nwfilter/no-arp-ip-spoofing.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-arp-ip-spoofing
or other application using the libvirt API.
-->
<filter name='no-arp-ip-spoofing' chain='arp-ip' priority='-510'>
<uuid>53a5762e-5ef0-4830-8032-2290974116c5</uuid>
<rule action='return' direction='out' priority='400'>
<arp arpsrcipaddr='$IP'/>
</rule>
<rule action='drop' direction='out' priority='1000'/>
</filter>

/etc/libvirt/nwfilter/no-arp-mac-spoofing.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-arp-mac-spoofing
or other application using the libvirt API.
-->
<filter name='no-arp-mac-spoofing' chain='arp-mac' priority='-520'>
<uuid>183a713b-d051-4613-9d33-ecc67f5b22c9</uuid>
<rule action='return' direction='out' priority='350'>
<arp arpsrcmacaddr='$MAC'/>
</rule>
<rule action='drop' direction='out' priority='1000'/>
</filter>

/etc/libvirt/nwfilter/no-arp-spoofing.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-arp-spoofing
or other application using the libvirt API.
-->
<filter name='no-arp-spoofing' chain='root'>
<uuid>d0c1b728-0074-4b70-9fb9-c149736ce06e</uuid>
<filterref filter='no-arp-mac-spoofing'/>
<filterref filter='no-arp-ip-spoofing'/>
</filter>

/etc/libvirt/nwfilter/no-ip-multicast.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-ip-multicast
or other application using the libvirt API.
-->
<filter name='no-ip-multicast' chain='ipv4' priority='-700'>
<uuid>9f588e1a-3f48-49ab-b928-c89701ac6373</uuid>
<rule action='drop' direction='out' priority='500'>
<ip dstipaddr='224.0.0.0' dstipmask='4'/>
</rule>
</filter>

/etc/libvirt/nwfilter/no-ip-spoofing.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-ip-spoofing
or other application using the libvirt API.
-->
<filter name='no-ip-spoofing' chain='ipv4-ip' priority='-710'>
<uuid>b9a96e04-51c9-49ab-8ea8-2bfbff0d8a28</uuid>
<rule action='return' direction='out' priority='100'>
<ip srcipaddr='0.0.0.0' protocol='udp'/>
</rule>
<rule action='return' direction='out' priority='500'>
<ip srcipaddr='$IP'/>
</rule>
<rule action='drop' direction='out' priority='1000'/>
</filter>

/etc/libvirt/nwfilter/no-mac-broadcast.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-mac-broadcast
or other application using the libvirt API.
-->
<filter name='no-mac-broadcast' chain='ipv4' priority='-700'>
<uuid>c619f93f-868c-4fb5-9482-d9ea3d294929</uuid>
<rule action='drop' direction='out' priority='500'>
<mac dstmacaddr='ff:ff:ff:ff:ff:ff'/>
</rule>
</filter>

/etc/libvirt/nwfilter/no-mac-spoofing.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-mac-spoofing
or other application using the libvirt API.
-->
<filter name='no-mac-spoofing' chain='mac' priority='-800'>
<uuid>b89e855e-ed41-4276-917d-72462a07002e</uuid>
<rule action='return' direction='out' priority='500'>
<mac srcmacaddr='$MAC'/>
</rule>
<rule action='drop' direction='out' priority='500'>
<mac/>
</rule>
</filter>

/etc/libvirt/nwfilter/no-other-l2-traffic.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-other-l2-traffic
or other application using the libvirt API.
-->
<filter name='no-other-l2-traffic' chain='root'>
<uuid>69a49398-75d7-4f3c-8484-45bed1c723a5</uuid>
<rule action='drop' direction='inout' priority='1000'/>
</filter>

/etc/libvirt/nwfilter/no-other-rarp-traffic.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit no-other-rarp-traffic
or other application using the libvirt API.
-->
<filter name='no-other-rarp-traffic' chain='rarp' priority='-400'>
<uuid>9798add2-28b8-45e2-bb52-8a9e213201b3</uuid>
<rule action='drop' direction='inout' priority='1000'/>
</filter>

/etc/libvirt/nwfilter/qemu-announce-self-rarp.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit qemu-announce-self-rarp
or other application using the libvirt API.
-->
<filter name='qemu-announce-self-rarp' chain='rarp' priority='-400'>
<uuid>fe544f26-bd73-44f8-8255-cec766f24322</uuid>
<rule action='accept' direction='out' priority='500'>
<rarp srcmacaddr='$MAC' dstmacaddr='ff:ff:ff:ff:ff:ff' opcode='Request_Reverse' arpsrcmacaddr='$MAC' arpdstmacaddr='$MAC' arpsrcipaddr='0.0.0.0' arpdstipaddr='0.0.0.0'/>
</rule>
<rule action='accept' direction='in' priority='500'>
<rarp dstmacaddr='ff:ff:ff:ff:ff:ff' opcode='Request_Reverse' arpsrcmacaddr='$MAC' arpdstmacaddr='$MAC' arpsrcipaddr='0.0.0.0' arpdstipaddr='0.0.0.0'/>
</rule>
</filter>

/etc/libvirt/nwfilter/qemu-announce-self.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh nwfilter-edit qemu-announce-self
or other application using the libvirt API.
-->
<filter name='qemu-announce-self' chain='root'>
<uuid>6a702d98-c092-4172-a16f-cf27fd1fae7e</uuid>
<rule action='accept' direction='out' priority='500'>
<mac protocolid='0x835'/>
</rule>
<filterref filter='qemu-announce-self-rarp'/>
<filterref filter='no-other-rarp-traffic'/>
</filter>

/etc/libvirt/qemu/networks/default.xml changed:
<!--
WARNING: THIS IS AN AUTO-GENERATED FILE. CHANGES TO IT ARE LIKELY TO BE
OVERWRITTEN AND LOST. Changes to this xml configuration should be made using:
virsh net-edit default
or other application using the libvirt API.
-->
<network>
<name>default</name>
<uuid>966b4956-62e6-49ea-9883-57caa0107927</uuid>
<forward mode='nat'/>
<bridge name='virbr0' stp='on' delay='0'/>
<mac address='52:54:00:29:52:56'/>
<ip address='192.168.122.1' netmask='255.255.255.0'>
<dhcp>
<range start='192.168.122.2' end='192.168.122.254'/>
</dhcp>
</ip>
</network>


-- debconf information:
libvirt-daemon-system/id_warning: true
Benoit Panizzon
2019-07-19 17:30:02 UTC
Permalink
libvirt debug output:

Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=3 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38e86f0 classname=virNetSocket
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SOCKET_NEW: sock=0x5606e38e86f0 fd=40 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38e37d0 classname=virNetServerClient
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_ADD_TIMEOUT: timer=7 frequency=-1 cb=0x7f25acaf1550 opaque=0x5606e38e37d0 ff=(nil)
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_NEW: client=0x5606e38e37d0 sock=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_ADD_HANDLE: watch=30 fd=40 events=1 cb=0x7f25acae6470 opaque=0x5606e38e86f0 ff=0x7f25acae6420
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: Re-enabling services
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=3 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=4 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=6 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=7 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38f30b0 classname=virKeepAlive
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_KEEPALIVE_NEW: ka=0x5606e38f30b0 client=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x7f25a00030b0 classname=virIdentity
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=36 prog=536903814 vers=1 proc=66 type=1 status=0 serial=0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_KEEPALIVE_START: ka=0x5606e38f30b0 client=0x5606e38e37d0 interval=0 count=0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_ADD_TIMEOUT: timer=8 frequency=5000 cb=0x7f25acaea5a0 opaque=0x5606e38f30b0 ff=0x7f25ac9f8bf0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38f30b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=40 prog=536903814 vers=1 proc=1 type=0 status=0 serial=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x7f2598005430 classname=virConnect
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=1 type=1 status=0 serial=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=110 type=0 status=0 serial=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=48 prog=536903814 vers=1 proc=110 type=1 status=0 serial=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=4
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=4
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=5
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=5
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=360 type=0 status=0 serial=6
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=360 type=1 status=0 serial=6
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=40 prog=536903814 vers=1 proc=23 type=0 status=0 serial=7
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2554292fd0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x7f25980048f0 classname=virDomain
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2554292fd0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25980048f0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x7f25980048f0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=60 prog=536903814 vers=1 proc=23 type=1 status=0 serial=7
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virFileClose:113 : Closed fd 41
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: info : virSecurityDACSetOwnership:780 : Setting DAC user and group on '/var/lib/libvirt/images/hathi.img' to '106:118'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virFileFindResourceFull:1793 : Resolved 'fs' to '/usr/lib/libvirt/storage-file/libvirt_storage_file_fs.so'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virModuleLoadFile:47 : Load module file '/usr/lib/libvirt/storage-file/libvirt_storage_file_fs.so'
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=68 prog=536903814 vers=1 proc=316 type=0 status=0 serial=8
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virModuleLoadFunc:68 : Lookup function 'virStorageFileFsRegister'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virStorageFileBackendRegister:93 : Registering storage file backend 'file' protocol 'none'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virStorageFileBackendRegister:93 : Registering storage file backend 'block' protocol 'none'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virStorageFileBackendRegister:93 : Registering storage file backend 'dir' protocol 'none'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virFileFindResourceFull:1793 : Resolved 'gluster' to '/usr/lib/libvirt/storage-file/libvirt_storage_file_gluster.so'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: info : virModuleLoad:112 : Module '/usr/lib/libvirt/storage-file/libvirt_storage_file_gluster.so' does not exist
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virFileClose:113 : Closed fd 3
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.582+0000: 12870: debug : virFileClose:113 : Closed fd 42
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x7f2590005940 classname=virDomain
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_ADD_TIMEOUT: timer=9 frequency=-1 cb=0x7f25aca84bf0 opaque=0x7f2554120790 ff=0x7f25ac9f8bf0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2554120790
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2590005940
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x7f2590005940
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=316 type=1 status=0 serial=8
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4982
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4982
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=68 prog=536903814 vers=1 proc=316 type=0 status=0 serial=9
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x7f2588005140 classname=virDomain
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2554120790
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2588005140
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x7f2588005140
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=316 type=1 status=0 serial=9
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=88 prog=536903814 vers=1 proc=290 type=0 status=0 serial=10
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x7f25a0006f70 classname=virDomain
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2554292fd0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2554152260
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2554152260
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=15
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_SEND_MSG: mon=0x7f252c001be0 msg={"execute":"query-block","id":"libvirt-20"}#015#012 fd=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4997
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_IO_WRITE: mon=0x7f252c001be0 buf={"execute":"query-block","id":"libvirt-20"}#015#012 len=45 ret=45 errno=0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4997
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virFileClose:113 : Closed fd 41
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: info : virSecurityDACSetOwnership:780 : Setting DAC user and group on '/var/lib/libvirt/images/hathi.img' to '106:118'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virFileFindResourceFull:1793 : Resolved 'fs' to '/usr/lib/libvirt/storage-file/libvirt_storage_file_fs.so'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virModuleLoadFile:47 : Load module file '/usr/lib/libvirt/storage-file/libvirt_storage_file_fs.so'
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4996
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virModuleLoadFunc:68 : Lookup function 'virStorageFileFsRegister'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virStorageFileBackendRegister:93 : Registering storage file backend 'file' protocol 'none'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virStorageFileBackendRegister:93 : Registering storage file backend 'block' protocol 'none'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virStorageFileBackendRegister:93 : Registering storage file backend 'dir' protocol 'none'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virFileFindResourceFull:1793 : Resolved 'gluster' to '/usr/lib/libvirt/storage-file/libvirt_storage_file_gluster.so'
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: info : virModuleLoad:112 : Module '/usr/lib/libvirt/storage-file/libvirt_storage_file_gluster.so' does not exist
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virFileClose:113 : Closed fd 3
Jul 19 19:07:25 pulsar libvirtd[12365]: 2019-07-19 17:07:25.592+0000: 12871: debug : virFileClose:113 : Closed fd 42
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_RECV_REPLY: mon=0x7f252c001be0 reply={"return": [{"io-status": "ok", "device": "drive-virtio-disk0", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"backing-image": {"virtual-size": 10005037056, "filename": "/var/lib/libvirt/images/hathi.img", "format": "raw", "actual-size": 10005041152, "dirty-flag": false}, "backing-filename-format": "raw", "virtual-size": 10005037056, "filename": "/var/lib/libvirt/images/hathi.snap1", "cluster-size": 65536, "format": "qcow2", "actual-size": 2174361600, "format-specific": {"type": "qcow2", "data": {"compat": "1.1", "lazy-refcounts": false, "refcount-bits": 16, "corrupt": false}}, "full-backing-filename": "/var/lib/libvirt/images/hathi.img", "backing-filename": "/var/lib/libvirt/images/hathi.img", "dirty-flag": false}, "iops_wr": 0, "ro": false, "node-name": "#block103", "backing_file_depth": 1, "drv": "qcow2", "iops": 0, "bps_wr": 0, "wr!
ite_threshold": 0, "backing_file": "/var/lib/libvirt/images/hathi.img", "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/var/lib/libvirt/images/hathi.snap1", "encryption_key_missing": false}, "qdev": "/machine/peripheral/virtio-disk0/virtio-backend", "type": "unknown"}], "id": "libvirt-20"}
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=15
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4995
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_SEND_MSG: mon=0x7f252c001be0 msg={"execute":"query-block","id":"libvirt-21"}#015#012 fd=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4995
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_IO_WRITE: mon=0x7f252c001be0 buf={"execute":"query-block","id":"libvirt-21"}#015#012 len=45 ret=45 errno=0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4995
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4994
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_RECV_REPLY: mon=0x7f252c001be0 reply={"return": [{"io-status": "ok", "device": "drive-virtio-disk0", "locked": false, "removable": false, "inserted": {"iops_rd": 0, "detect_zeroes": "off", "image": {"backing-image": {"virtual-size": 10005037056, "filename": "/var/lib/libvirt/images/hathi.img", "format": "raw", "actual-size": 10005041152, "dirty-flag": false}, "backing-filename-format": "raw", "virtual-size": 10005037056, "filename": "/var/lib/libvirt/images/hathi.snap1", "cluster-size": 65536, "format": "qcow2", "actual-size": 2174361600, "format-specific": {"type": "qcow2", "data": {"compat": "1.1", "lazy-refcounts": false, "refcount-bits": 16, "corrupt": false}}, "full-backing-filename": "/var/lib/libvirt/images/hathi.img", "backing-filename": "/var/lib/libvirt/images/hathi.img", "dirty-flag": false}, "iops_wr": 0, "ro": false, "node-name": "#block103", "backing_file_depth": 1, "drv": "qcow2", "iops": 0, "bps_wr": 0, "wr!
ite_threshold": 0, "backing_file": "/var/lib/libvirt/images/hathi.img", "encrypted": false, "bps": 0, "bps_rd": 0, "cache": {"no-flush": false, "direct": false, "writeback": true}, "file": "/var/lib/libvirt/images/hathi.snap1", "encryption_key_missing": false}, "qdev": "/machine/peripheral/virtio-disk0/virtio-backend", "type": "unknown"}], "id": "libvirt-21"}
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=15
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4994
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_SEND_MSG: mon=0x7f252c001be0 msg={"execute":"block-commit","arguments":{"device":"drive-virtio-disk0","top":"/var/lib/libvirt/images/hathi.snap1","base":"/var/lib/libvirt/images/hathi.img"},"id":"libvirt-22"}#015#012 fd=-1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4994
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_IO_WRITE: mon=0x7f252c001be0 buf={"execute":"block-commit","arguments":{"device":"drive-virtio-disk0","top":"/var/lib/libvirt/images/hathi.snap1","base":"/var/lib/libvirt/images/hathi.img"},"id":"libvirt-22"}#015#012 len=177 ret=177 errno=0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4990
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=20 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: QEMU_MONITOR_RECV_REPLY: mon=0x7f252c001be0 reply={"id": "libvirt-22", "error": {"class": "GenericError", "desc": "Could not reopen file: Permission denied"}}
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=20 events=13
Jul 19 19:07:25 pulsar libvirtd[12365]: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f252c001be0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4990
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2554152260
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2554152260
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25541187c0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2554292fd0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a0006f70
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x7f25a0006f70
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=296 prog=536903814 vers=1 proc=290 type=1 status=1 serial=10
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4987
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4986
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=317 type=0 status=0 serial=11
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=317 type=1 status=0 serial=11
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=32 prog=536903814 vers=1 proc=317 type=0 status=0 serial=12
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389ec50
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_REMOVE_TIMEOUT: timer=9
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=317 type=1 status=0 serial=12
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_PURGE_TIMEOUT: timer=9
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2554120790
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=4999
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=361 type=0 status=0 serial=13
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=361 type=1 status=0 serial=13
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=3
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_RX: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=2 type=0 status=0 serial=14
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_TIMEOUT: timer=8 frequency=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e389f8d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x5606e38e37d0 len=28 prog=536903814 vers=1 proc=2 type=1 status=0 serial=14
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38b55a0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=27 timeout=5000
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=30 events=2
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=30 events=0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_KEEPALIVE_STOP: ka=0x5606e38f30b0 client=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_REMOVE_TIMEOUT: timer=8
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38f30b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38f5580 classname=virIdentity
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_REF: obj=0x5606e38f5580
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38f5580
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38f5580
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38f5580
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_REMOVE_HANDLE: watch=30
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: Re-enabling services
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=3 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=4 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=6 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=7 events=1
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_PURGE_TIMEOUT: timer=8
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38f30b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38f30b0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_KEEPALIVE_DISPOSE: ka=0x5606e38f30b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_PURGE_HANDLE: watch=30
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SERVER_CLIENT_DISPOSE: client=0x5606e38e37d0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x7f2598005430
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x7f25a00030b0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_REMOVE_TIMEOUT: timer=7
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: RPC_SOCKET_DISPOSE: sock=0x5606e38e86f0
Jul 19 19:07:25 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=26 timeout=-1
Jul 19 19:07:40 pulsar snmpd[712]: error on subcontainer 'ia_addr' insert (-1)
Jul 19 19:07:45 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=19 events=1
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2538001be0
Jul 19 19:07:45 pulsar libvirtd[12365]: QEMU_MONITOR_RECV_EVENT: mon=0x7f2538001be0 event={"timestamp": {"seconds": 1563556065, "microseconds": 368644}, "event": "VNC_CONNECTED", "data": {"server": {"auth": "vnc", "family": "ipv4", "service": "5907", "host": "0.0.0.0", "websocket": false}, "client": {"family": "ipv4", "service": "42158", "host": "173.72.101.149", "websocket": false}}}
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2538001be0
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38bd750 classname=virDomainQemuMonitorEvent
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38bd750
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38bd750
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2538001be0
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2538001be0
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38d5050 classname=virDomainEventGraphics
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38d5050
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38d5050
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2538001be0
Jul 19 19:07:45 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=19 events=13
Jul 19 19:07:45 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2538001be0
Jul 19 19:07:45 pulsar libvirtd[12365]: EVENT_POLL_PURGE_TIMEOUT: timer=7
Jul 19 19:07:45 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=26 timeout=-1
Jul 19 19:07:46 pulsar libvirtd[12365]: EVENT_POLL_DISPATCH_HANDLE: watch=19 events=1
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2538001be0
Jul 19 19:07:46 pulsar libvirtd[12365]: QEMU_MONITOR_RECV_EVENT: mon=0x7f2538001be0 event={"timestamp": {"seconds": 1563556066, "microseconds": 879038}, "event": "VNC_DISCONNECTED", "data": {"server": {"auth": "vnc", "family": "ipv4", "service": "5907", "host": "0.0.0.0", "websocket": false}, "client": {"family": "ipv4", "service": "42158", "host": "173.72.101.149", "websocket": false}}}
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2538001be0
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38de4b0 classname=virDomainQemuMonitorEvent
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38de4b0
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38de4b0
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2538001be0
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_REF: obj=0x7f2538001be0
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_NEW: obj=0x5606e38f0e40 classname=virDomainEventGraphics
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x5606e38f0e40
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_DISPOSE: obj=0x5606e38f0e40
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2538001be0
Jul 19 19:07:46 pulsar libvirtd[12365]: EVENT_POLL_UPDATE_HANDLE: watch=19 events=13
Jul 19 19:07:46 pulsar libvirtd[12365]: OBJECT_UNREF: obj=0x7f2538001be0
Jul 19 19:07:46 pulsar libvirtd[12365]: EVENT_POLL_RUN: nhandles=26
timeout=-1
Sebastian Kiesel
2019-07-21 20:40:01 UTC
Permalink
Hi,

I'm having the same problem and indeed it seems to be related to apparmor.
My system is using the same library version numbers as Benoit's system.

As a workaround I set set security_driver = "none"
in in /etc/libvirt/qemu.conf and rebooted:

--- /etc/libvirt/qemu.conf 2019/07/21 19:33:30 1.1
+++ /etc/libvirt/qemu.conf 2019/07/21 19:35:54 1.3
@@ -414,6 +414,7 @@
# isolation, but it cannot appear in a list of drivers.
#
#security_driver = "selinux"
+security_driver = "none"

# If set to non-zero, then the default security labeling
# will make guests confined. If set to zero, then guests


This seems to work for me but I suspect that this is not how it is
supposed to be from a security perspective. When explicitly setting
security_driver = "apparmor" I had the same problems as in the
default configuration, when security_driver is completely commented out.

-----

Here the result of some experiments I did *before* changing anything in
/etc/libvirt/qemu.conf - maybe this is helpful for finding the bug
or giving advice how to properly configure our systems:


After host boot, before any VM is started:

$ ls -l /etc/apparmor.d/libvirt
total 8
-rw-r--r-- 1 root root 342 Jun 17 19:05 TEMPLATE.lxc
-rw-r--r-- 1 root root 192 Jun 17 19:05 TEMPLATE.qemu

Start a VM:

virsh # start buster5
Domain buster5 started

$ ls -l /etc/apparmor.d/libvirt
total 16
-rw-r--r-- 1 root root 342 Jun 17 19:05 TEMPLATE.lxc
-rw-r--r-- 1 root root 192 Jun 17 19:05 TEMPLATE.qemu
-rw-r--r-- 1 root root 293 Jul 21 21:07 libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5
-rw-r--r-- 1 root root 649 Jul 21 21:07 libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files

$ cat /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
"/var/log/libvirt/**/buster5.log" w,
"/var/lib/libvirt/qemu/domain-buster5/monitor.sock" rw,
"/var/lib/libvirt/qemu/domain-1-buster5/*" rw,
"/var/run/libvirt/**/buster5.pid" rwk,
"/run/libvirt/**/buster5.pid" rwk,
"/var/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/var/lib/libvirt/images/buster5.qcow2" rwk,
"/var/lib/libvirt/qemu/domain-1-buster5/{,**}" rwk,
"/var/lib/libvirt/qemu/channel/target/domain-1-buster5/{,**}" rwk,
"/var/lib/libvirt/qemu/domain-1-buster5/master-key.aes" rwk,
"/dev/net/tun" rwk,

$ cp /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.1

create a snapshot

virsh # domblklist buster5 --details
Type Device Target Source
-----------------------------------------------------------------
file disk hda /var/lib/libvirt/images/buster5.qcow2
file cdrom hdb -

virsh # snapshot-create-as --domain buster5 --name backup_overlay --disk-only --atomic --no-metadata
Domain snapshot backup_overlay created
virsh # domblklist buster5 --details
Type Device Target Source
--------------------------------------------------------------------------
file disk hda /var/lib/libvirt/images/buster5.backup_overlay
file cdrom hdb -

$ ls -l /etc/apparmor.d/libvirt
total 16
-rw-r--r-- 1 root root 342 Jun 17 19:05 TEMPLATE.lxc
-rw-r--r-- 1 root root 192 Jun 17 19:05 TEMPLATE.qemu
-rw-r--r-- 1 root root 293 Jul 21 21:07 libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5
-rw-r--r-- 1 root root 535 Jul 21 21:13 libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files

$ cat /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
"/var/log/libvirt/**/buster5.log" w,
"/var/lib/libvirt/qemu/domain-buster5/monitor.sock" rw,
"/var/lib/libvirt/qemu/domain-1-buster5/*" rw,
"/var/run/libvirt/**/buster5.pid" rwk,
"/run/libvirt/**/buster5.pid" rwk,
"/var/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/var/lib/libvirt/images/buster5.qcow2" rwk,
"/dev/pts/5" rw,
"/dev/pts/5" rw,
"/var/lib/libvirt/images/buster5.backup_overlay" rwk,

$ cp /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.2

$ diff -u /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.{1,2}
--- /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.1 2019-07-21 21:11:55.637296657 +0200
+++ /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.2 2019-07-21 21:14:59.759204162 +0200
@@ -7,7 +7,6 @@
"/var/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/var/lib/libvirt/images/buster5.qcow2" rwk,
- "/var/lib/libvirt/qemu/domain-1-buster5/{,**}" rwk,
- "/var/lib/libvirt/qemu/channel/target/domain-1-buster5/{,**}" rwk,
- "/var/lib/libvirt/qemu/domain-1-buster5/master-key.aes" rwk,
- "/dev/net/tun" rwk,
+ "/dev/pts/5" rw,
+ "/dev/pts/5" rw,
+ "/var/lib/libvirt/images/buster5.backup_overlay" rwk,


cp /var/lib/libvirt/images/buster5.qcow2 /backups/buster5-20190721.qcow2

try blockcommit

virsh # blockcommit --domain buster5 --path hda --pivot
error: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied

syslog says:

Jul 21 21:16:13 virthost kernel: [20738.344485] audit: type=1400 audit(1563736573.754:28): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5" pid=12452 comm="apparmor_parser"
Jul 21 21:16:13 virthost kernel: [20738.472223] audit: type=1400 audit(1563736573.882:29): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5" pid=12456 comm="apparmor_parser"

$ ls -l /etc/apparmor.d/libvirt
total 16
-rw-r--r-- 1 root root 342 Jun 17 19:05 TEMPLATE.lxc
-rw-r--r-- 1 root root 192 Jun 17 19:05 TEMPLATE.qemu
-rw-r--r-- 1 root root 293 Jul 21 21:07 libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5
-rw-r--r-- 1 root root 672 Jul 21 21:16 libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files

$ cat /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
"/var/log/libvirt/**/buster5.log" w,
"/var/lib/libvirt/qemu/domain-buster5/monitor.sock" rw,
"/var/lib/libvirt/qemu/domain-1-buster5/*" rw,
"/var/run/libvirt/**/buster5.pid" rwk,
"/run/libvirt/**/buster5.pid" rwk,
"/var/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/var/lib/libvirt/images/buster5.backup_overlay" rwk,
"/var/lib/libvirt/images/buster5.qcow2" rk,
# don't audit writes to readonly files
deny "/var/lib/libvirt/images/buster5.qcow2" w,
"/dev/pts/5" rw,
"/dev/pts/5" rw,
"/var/lib/libvirt/images/buster5.qcow2" rwk,

$ cp /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.3

$ diff -u /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.{2,3}
--- /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.2 2019-07-21 21:14:59.759204162 +0200
+++ /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.3 2019-07-21 21:17:51.601252623 +0200
@@ -6,7 +6,10 @@
"/run/libvirt/**/buster5.pid" rwk,
"/var/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.buster5" rw,
- "/var/lib/libvirt/images/buster5.qcow2" rwk,
+ "/var/lib/libvirt/images/buster5.backup_overlay" rwk,
+ "/var/lib/libvirt/images/buster5.qcow2" rk,
+ # don't audit writes to readonly files
+ deny "/var/lib/libvirt/images/buster5.qcow2" w,
"/dev/pts/5" rw,
"/dev/pts/5" rw,
- "/var/lib/libvirt/images/buster5.backup_overlay" rwk,
+ "/var/lib/libvirt/images/buster5.qcow2" rwk,




stopping apparmor allows me to do the blockcommit

$ sudo aa-teardown
Unloading AppArmor profiles

virsh # blockcommit --domain buster5 --path hda --pivot
Successfully pivoted

$ sudo rm /var/lib/libvirt/images/buster5.backup_overlay

$ cp /etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.4
$ diff -u /tmp/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files.{3,4}

(unchanged)


Maybe the "deny ..." line causes the problems?

$ sudo grep -r 'DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.' /etc /usr
/etc/apparmor.d/libvirt/libvirt-089ee8b3-5793-4ef6-900f-46f6a62769d5.files:# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
Binary file /usr/lib/libvirt/virt-aa-helper matches

So /usr/lib/libvirt/virt-aa-helper or its configuration will probably
need further examination.


Thanks
Sebastian
Robert Niederreiter
2019-10-13 17:10:02 UTC
Permalink
Hi,

I encountered the same problem.

It looks like libvirt denies write access to guest base image by
modifying the guest related apparmor profile once the guest runs on a
snapshot referring to this base image.

Here's what i tried:

Guest runs on base image:

***@host/storage/vm# virsh domblklist test
Target Source
--------------------------------
vda /storage/vm/test.img

Generated aa profile not contains deny rule for base image:

***@host/storage/vm# cat /etc/apparmor.d/libvirt/libvirt-<uuid>.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
"/var/log/libvirt/**/test.log" w,
"/var/lib/libvirt/qemu/domain-test/monitor.sock" rw,
"/var/lib/libvirt/qemu/domain-8-test/*" rw,
"/var/run/libvirt/**/test.pid" rwk,
"/run/libvirt/**/test.pid" rwk,
"/var/run/libvirt/**/*.tunnelmigrate.dest.test" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.test" rw,
"/storage/vm/test.img" rwk, <---------------------------------------
"/dev/vhost-net" rw,
"/var/lib/libvirt/qemu/domain-8-test/{,**}" rwk,
"/var/lib/libvirt/qemu/channel/target/domain-8-test/{,**}" rwk,
"/var/lib/libvirt/qemu/domain-8-test/master-key.aes" rwk,
"/dev/net/tun" rwk,

After generating the snapshot, there's still no deny rule (but we also not tried to merge back to base image yet):

***@host/storage/vm# virsh snapshot-create-as --domain test --name backup_overlay --no-metadata --atomic --disk-only --diskspec vda,snapshot=external
Domain snapshot backup_overlay created

***@host/storage/vm# cat /etc/apparmor.d/libvirt/libvirt-<uuid>.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
"/var/log/libvirt/**/test.log" w,
"/var/lib/libvirt/qemu/domain-test/monitor.sock" rw,
"/var/lib/libvirt/qemu/domain-8-test/*" rw,
"/var/run/libvirt/**/test.pid" rwk,
"/run/libvirt/**/test.pid" rwk,
"/var/run/libvirt/**/*.tunnelmigrate.dest.test" rw,
"/run/libvirt/**/*.tunnelmigrate.dest.test" rw,
"/storage/vm/test.img" rwk, <---------------------------------------
"/dev/pts/2" rw,
"/dev/pts/2" rw,
"/var/lib/libvirt/qemu/channel/target/domain-8-test/org.qemu.guest_agent.0" rw,
"/dev/vhost-net" rw,
"/storage/vm/test.backup_overlay" rwk,

When shutting down and starting guest again, host specific aa profile gets regenerated.
Now the deny rule is present. Note that guest runs on snapshot:

***@host/storage/vm# virsh domblklist test
Target Source
-------------------------------------------
vda /storage/vm/test.backup_overlay

***@host/storage/vm# virsh shutdown test
Domain test is being shutdown

***@host/storage/vm# virsh start test
Domain test started

***@host/storage/vm# cat /etc/apparmor.d/libvirt/libvirt-<uuid>.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
...
"/storage/vm/test.img" rk, <-------------------------------------------
# don't audit writes to readonly files
deny "/storage/vm/test.img" w, <----------------------------------------
"/dev/vhost-net" rw,
...

And it seems like this rule prevents us from merging snapshot back to base image:

***@host/storage/vm# virsh blockcommit test vda --active --pivoterror: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied

As soon as the guest aa profile gets disabled, blockcommit works as expected:

***@host/storage/vm# aa-disable /etc/apparmor.d/libvirt/libvirt-<uuid>
Disabling /etc/apparmor.d/libvirt/libvirt-<uuid>.

***@host/storage/vm# virsh blockcommit test vda --active --pivot
Successfully pivoted

After merge, stop and start guest, the deny rule is gone again:

***@host/storage/vm# virsh shutdown test
Domain test is being shutdown

***@host/storage/vm# virsh start test
Domain test started

***@host/storage/vm# cat /etc/apparmor.d/libvirt/libvirt-<uuid>.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
...
"/storage/vm/test.img" rwk,
"/dev/vhost-net" rw,
...

***@host/storage/vm# virsh domblklist test
Target Source
--------------------------------
vda /storage/vm/test.img

As stated above, the deny rule is not created immediately when creating the snapshot
if guest not gets stopped/started. But it gets added as soon as we try to merge back
to the base image:

***@host/storage/vm# virsh snapshot-create-as --domain test --name backup_overlay --no-metadata --atomic --disk-only --diskspec vda,snapshot=external
Domain snapshot backup_overlay created

***@host/storage/vm# cat /etc/apparmor.d/libvirt/libvirt-<uuid>.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
...
"/storage/vm/test.img" rwk,
...

***@host/storage/vm# virsh blockcommit test vda --active --pivoterror: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied

***@host/storage/vm# cat /etc/apparmor.d/libvirt/libvirt-<uuid>.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
...
"/storage/vm/test.img" rk,
# don't audit writes to readonly files
deny "/storage/vm/test.img" w, <--------------------------------------------
"/dev/pts/2" rw,
"/dev/pts/2" rw,
"/var/lib/libvirt/qemu/channel/target/domain-10-test/org.qemu.guest_agent.0" rw,
"/dev/vhost-net" rw,
"/storage/vm/test.img" rwk,

I fear this is not solvable by just fixing some apparmor base profiles because libvirt creates and modifies aa profiles on the fly via virt-aa-helper.
Would be good to know if this procedure fails as well on other distros if apparmor is enabled, then it's probably a general problem with libvirt and apparmor.

Thanks,

Kind Regards,

Robert

Loading...