search

abbbi / virtnbdbackup

Backup utility for Libvirt / qemu / kvm supporting incremental and differential backups + instant recovery (agentless).
http://libvirtbackup.grinser.de/
GNU General Public License v3.0
330 stars 46 forks source link

Incremental Backup hangs on large qcow2 images #59

Closed mrickl closed 2 years ago

mrickl commented 2 years ago

I have a web server running that has a qcow2 image with the maximum size of 600GB. Of this, about 380GB are currently used. I have the problem that during the backup job incremental the process hangs at the following point. 

`root@hv01 ~ # virtnbdbackup -d Webserver -l inc -o /mnt/storage01/vm-backups/Webserver --checkpointdir /mnt/storage01/checkpoints/Webserver -w 500 -v
[2022-07-11 21:34:33] INFO common - printVersion [MainThread]: Version: 0.72 Arguments: /usr/local/bin/virtnbdbackup -d Webserver -l inc -o /mnt/storage01/vm-backups/Webserver --checkpointdir /mnt/storage01/checkpoints/Webserver -w 500 -v
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Backup level: [inc]
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Store checkpoints in: /mnt/storage01/checkpoints/Webserver
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Libvirt library version: 7000000
[2022-07-11 21:34:33] DEBUG libvirthelper - hasforeignCheckpoint [MainThread]: Found checkpoint: [virtnbdbackup.1]
[2022-07-11 21:34:33] DEBUG libvirthelper - hasforeignCheckpoint [MainThread]: Found checkpoint: [virtnbdbackup.2]
[2022-07-11 21:34:33] DEBUG libvirthelper - hasforeignCheckpoint [MainThread]: Found checkpoint: [virtnbdbackup.4]
[2022-07-11 21:34:33] DEBUG libvirthelper - hasforeignCheckpoint [MainThread]: Found checkpoint: [virtnbdbackup.0]
[2022-07-11 21:34:33] DEBUG libvirthelper - hasforeignCheckpoint [MainThread]: Found checkpoint: [virtnbdbackup.3]
[2022-07-11 21:34:33] DEBUG libvirthelper - domainOffline [MainThread]: Domain state returned by libvirt: [1]
[2022-07-11 21:34:33] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [loader] found: 'NoneType' object has no attribute 'text'
[2022-07-11 21:34:33] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [nvram] found: 'NoneType' object has no attribute 'text'
[2022-07-11 21:34:33] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [kernel] found: 'NoneType' object has no attribute 'text'
[2022-07-11 21:34:33] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [initrd] found: 'NoneType' object has no attribute 'text'
[2022-07-11 21:34:33] DEBUG libvirthelper - getDomainInfo [MainThread]: Domain Info: [{'loader': None, 'nvram': None, 'kernel': None, 'initrd': None}]
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Domain has 1 disks attached which support changed block tracking.
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Concurrent backup processes: [500]
[2022-07-11 21:34:33] INFO libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint list from: [/mnt/storage01/checkpoints/Webserver]
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint config from: [/mnt/storage01/checkpoints/Webserver/virtnbdbackup.0.xml]
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Checkpoint [virtnbdbackup.0] found
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint config from: [/mnt/storage01/checkpoints/Webserver/virtnbdbackup.1.xml]
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Checkpoint [virtnbdbackup.1] found
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint config from: [/mnt/storage01/checkpoints/Webserver/virtnbdbackup.2.xml]
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Checkpoint [virtnbdbackup.2] found
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint config from: [/mnt/storage01/checkpoints/Webserver/virtnbdbackup.3.xml]
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Checkpoint [virtnbdbackup.3] found
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint config from: [/mnt/storage01/checkpoints/Webserver/virtnbdbackup.4.xml]
[2022-07-11 21:34:33] DEBUG libvirthelper - redefineCheckpoints [MainThread]: Checkpoint [virtnbdbackup.4] found
[2022-07-11 21:34:33] INFO virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint handling.
[2022-07-11 21:34:33] INFO virtnbdbackup - handleCheckpoints [MainThread]: Next checkpoint id: [5].
[2022-07-11 21:34:33] INFO virtnbdbackup - handleCheckpoints [MainThread]: Parent checkpoint name [virtnbdbackup.4].
[2022-07-11 21:34:33] INFO virtnbdbackup - handleCheckpoints [MainThread]: Using checkpoint name: [virtnbdbackup.5].
[2022-07-11 21:34:33] DEBUG virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint info: [{'name': 'virtnbdbackup.5', 'parent': 'virtnbdbackup.4', 'file': '/mnt/storage01/vm-backups/Webserver/Webserver.cpt'}].
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Temporary scratch file target directory: /var/tmp
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: NDB Endpoint socket: /var/tmp/virtnbdbackup.3007943
[2022-07-11 21:34:33] INFO virtnbdbackup - main [MainThread]: Starting backup job.
[2022-07-11 21:34:33] DEBUG libvirthelper - _createBackupXml [MainThread]: Using scratch file: /var/tmp/backup.V4S3X.vda
[2022-07-11 21:34:33] DEBUG libvirthelper - _indentXml [MainThread]: 
<domainbackup mode="pull">
  <server transport="unix" socket="/var/tmp/virtnbdbackup.3007943"/>
  <disks>
    <disk name="vda">
      <scratch file="/var/tmp/backup.V4S3X.vda"/>
    </disk>
  </disks>
  <incremental>virtnbdbackup.4</incremental>
</domainbackup>
[2022-07-11 21:34:33] DEBUG libvirthelper - _indentXml [MainThread]: 
<domaincheckpoint>
  <description>Backup checkpoint</description>
  <name>virtnbdbackup.5</name>
  <parent>
    <name>virtnbdbackup.4</name>
  </parent>
  <disks>
    <disk name="vda"/>
  </disks>
</domaincheckpoint>
^C[2022-07-11 21:39:15] ERROR virtnbdbackup - handleSignal [MainThread]: Caught signal: 2
[2022-07-11 21:39:15] ERROR virtnbdbackup - handleSignal [MainThread]: Cleanup: Stopping backup job
[2022-07-11 21:39:16] WARNING libvirthelper - stopBackup [MainThread]: Unable to stop backup job: [Angeforderte Operation ist nicht gültig: Domain läuft nicht]
[2022-07-11 21:39:16] ERROR virtnbdbackup - main [MainThread]: <built-in function virDomainFSFreeze> returned a result with an error set
[2022-07-11 21:39:16] ERROR virtnbdbackup - main [MainThread]: <built-in function virDomainFSFreeze> returned a result with an error set`

The error that comes at the end is from "virsh destroy" because the webserver is not responding and there is no other solution. I had run the process for a maximum of 15 minutes before I aborted the process. If I append "-v" this usually works but not always. So far I make a full backup only once a week, which I would like to change. With the incremental backups there are 24 hours in between, but there is not much changes inside the image. At most a handful of logs but that's it. One day it works but the next day it doesn't work.

Gladly I help debugging the problem if I know what to do. As additional info I used the version v0.72 here.

abbbi commented 2 years ago

It appears to me that it already fails to start the backup job. what is tracked in the qemu logfiles for this virtual machine? It seems there is an issue on libvirt/qemu side to start he backup job. Is /var/tmp/ maybe running out of space because of the created scratch file becoming too big?

I assume it hangs right here which would indicate some issue on libvirt/qemu side:

https://github.com/abbbi/virtnbdbackup/blob/master/libvirtnbdbackup/libvirthelper/libvirthelper.py#L391

because if this action would be successful on libvirt/qemu side, you would see this log message, which is missing in our output:

https://github.com/abbbi/virtnbdbackup/blob/master/virtnbdbackup#L518

Check the logfiles for the virtual machine in /var/log/libvirt/qemu

Additionally i see that you use the -w option with 500 concurrent processes, that doesnt make sense if the virtual machine has only one disk, it would make sense if it had 500 attached disks (one backup connection for each disk, then). But it shouldnt cause this error, because setting up the workers happens after issuing the backup job operation on libvirt side.

mrickl commented 2 years ago

Unfortunately, there is nothing in the libvirt logs. I have set the debug level to 1 and try to reproduce the problem, because it currently runs without problems. I will report back as soon as I have been able to reproduce this.

2022-07-11T07:00:24.255536Z qemu-system-x86_64: warning: Spice: reds.c:2342:reds_handle_link_error: Connection reset by peer
2022-07-11T07:37:44.323779Z qemu-system-x86_64: warning: Spice: reds.c:2342:reds_handle_link_error: Connection reset by peer
2022-07-11T19:32:39.209134Z qemu-system-x86_64: warning: Spice: reds.c:2342:reds_handle_link_error: Connection reset by peer
2022-07-11T19:39:15.379588Z qemu-system-x86_64: terminating on signal 15 from pid 1297855 (/usr/sbin/libvirtd)
2022-07-11 19:39:15.780+0000: shutting down, reason=destroyed
2022-07-11 19:40:36.821+0000: starting up libvirt version: 7.0.0, package: 3 (Andrea Bolognani <eof@kiyuko.org> Fri, 26 Feb 2021 16:46:34 +0100), qemu version: 5.2.0Debian 1:5.2+dfsg-11+deb11u2, kernel: 5.10.0-15-amd64, hostname:

So the scratch file was about 14Gb in size and has not grown in that time. So there were at this time on the volume-root where also "/var/tmp" is still about 50Gb free. Because the servers are on a separate lvm volume.

Oh well, I guess I misunderstood or maybe didn't read the Workers part correctly.

abbbi commented 2 years ago

Unfortunately, there is nothing in the libvirt logs. I have set the debug level to 1 and try to reproduce the problem, because it currently runs without problems. I will report back as soon as I have been able to reproduce this.

thats unfortunate.. maybe journalctl -u libvirtd -f shows something strange going on too, what about dmesg?

So the scratch file was about 14Gb in size and has not grown in that time. So there were at this time on the volume-root where also "/var/tmp" is still about 50Gb free. Because the servers are on a separate lvm volume.

just a guess of mine, because qemu usually "stalls" if there is some filesystem running out of space.

Oh well, I guess I misunderstood or maybe didn't read the Workers part correctly.

nm, just fixed this in the latest release, it defaults to the amount of disks now if an value is specified which is higher than the amount of disks found for backup.

abbbi commented 2 years ago

If the situation appears again, it would be useful to know the state of the job, you may want to check wether if libvirt acutally manages to start the backup job (while backup operation hanging) via virsh, like so:


virsh domjobinfo vm1
Job type:         Unbounded   
Operation:        Backup      
Time elapsed:     8934         ms
Temporary disk space use: 0.000 B
Temporary disk space total: 50.000 MiB
abbbi commented 2 years ago

Further thinking about the problem, it might also be the case that it hangs during filesystem freeze, the VM you are backing up appears to have the qemu agent running! That might also be the reason why the system becomes unusable then: the filesystem freeze action via the qemu agent somehow succeeds but never returns, filesystems are left in freezed state but backup job operation is never started! Ive just added some more debug messages in the latest version, so it reports on entering the freeze function and leaving. You might also want to check the qemu agent logfiles for possible issues during filesytem freeze ( journalctl -u qemu-guest-agent)

mrickl commented 2 years ago

first thank you for the input of the last three messages. I will get back to you as soon as I have the info together, if I could reproduce the problem again.

mrickl commented 2 years ago

So I just had the problem again

[2022-07-12 22:43:38] INFO common - printVersion [MainThread]: Version: 0.75 Arguments: /usr/local/bin/virtnbdbackup -d Webserver -l inc -o /mnt/storage01/vm-backups/Webserver --checkpointdir /mnt/storage01/checkpoints/Webserver -n
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Backup level: [inc]
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Store checkpoints in: /mnt/storage01/checkpoints/Webserver
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Libvirt library version: 7000000
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Domain has 1 disks attached which support changed block tracking.
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Concurrent backup processes: [1]
[2022-07-12 22:43:38] INFO libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint list from: [/mnt/storage01/checkpoints/Webserver]
[2022-07-12 22:43:38] INFO virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint handling.
[2022-07-12 22:43:38] INFO virtnbdbackup - handleCheckpoints [MainThread]: Next checkpoint id: [5].
[2022-07-12 22:43:38] INFO virtnbdbackup - handleCheckpoints [MainThread]: Parent checkpoint name [virtnbdbackup.4].
[2022-07-12 22:43:38] INFO virtnbdbackup - handleCheckpoints [MainThread]: Using checkpoint name: [virtnbdbackup.5].
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Temporary scratch file target directory: /var/tmp
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: NDB Endpoint socket: /var/tmp/virtnbdbackup.77422
[2022-07-12 22:43:38] INFO virtnbdbackup - main [MainThread]: Starting backup job.
[2022-07-12 22:55:03] WARNING libvirthelper - fsFreeze [MainThread]: Gast-Agent antwortet nicht: Guest agent disappeared while executing command
[2022-07-12 22:55:03] ERROR virtnbdbackup - main [MainThread]: Operation ist nicht unterstützt: cannot perform disk backup for inactive domain
[2022-07-12 22:55:03] ERROR virtnbdbackup - main [MainThread]: Operation ist nicht unterstützt: cannot perform disk backup for inactive domain

According to virsh there is no running job for the domain name

root@hv01 ~ # virsh domjobinfo Webserver
Job-Typ:          Kein

Here is once the journalctl output of libvirtd in the second where it wanted to start the backup

Jul 12 22:43:38 hv01 libvirtd[77423]: 2022-07-12 20:43:38.035+0000: 77423: info : virSecurityDACRestoreFileLabelInternal:878 : Restoring DAC user and group on '/var/tmp/backup.ER2T6.vda' to 0:0
Jul 12 22:43:38 hv01 libvirtd[3123143]: Interner Fehler: child reported (status=125): Benutzer und Gruppe konnten nicht auf '0:0' in '/var/tmp/backup.ER2T6.vda' gesetzt werden: Datei oder Verzeichnis nicht gefunden
Jul 12 22:43:38 hv01 libvirtd[3123143]: Benutzer und Gruppe konnten nicht auf '0:0' in '/var/tmp/backup.ER2T6.vda' gesetzt werden: Datei oder Verzeichnis nicht gefunden
Jul 12 22:43:38 hv01 libvirtd[77424]: 2022-07-12 20:43:38.046+0000: 77424: info : virSecurityDACRestoreFileLabelInternal:878 : Restoring DAC user and group on '/var/tmp/backup.ER2T6.vda' to 0:0
Jul 12 22:43:38 hv01 libvirtd[3123143]: Interner Fehler: child reported (status=125): Benutzer und Gruppe konnten nicht auf '0:0' in '/var/tmp/backup.ER2T6.vda' gesetzt werden: Datei oder Verzeichnis nicht gefunden
Jul 12 22:43:38 hv01 libvirtd[3123143]: Benutzer und Gruppe konnten nicht auf '0:0' in '/var/tmp/backup.ER2T6.vda' gesetzt werden: Datei oder Verzeichnis nicht gefunden
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f047813db40
Jul 12 22:43:38 hv01 libvirtd[3123143]: Unable to restore security label on /var/tmp/backup.ER2T6.vda
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f0478022e40 classname=virDomainEventBlockJob
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f0478022e40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0478022e40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f0478022e40 classname=virDomainEventBlockJob
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f0478022e40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0478022e40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b44e7290
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b44e7290
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f047812c020
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b44e7290
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f047812e200
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04a8477bf0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8477bf0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b44e7290
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=2 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c0f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x561d8aa8c6f0 classname=virNetSocket
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SOCKET_NEW: sock=0x561d8aa8c6f0 fd=57 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x561d8aa93580 classname=virNetServerClient
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_ADD_TIMEOUT: timer=142 interval=-1 cb=0x7f04c9886180 opaque=0x561d8aa93580 ff=(nil)
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_NEW: client=0x561d8aa93580 sock=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_ADD_HANDLE: watch=98 fd=57 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0 ff=0x7f04c9875870
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: Re-enabling services
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=2 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=3 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f0448013540 classname=virKeepAlive
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_KEEPALIVE_NEW: ka=0x7f0448013540 client=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: Bypass polkit auth for privileged client pid:77422,uid:0
Jul 12 22:43:38 hv01 libvirtd[3123143]: Re-enabling services
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=2 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=3 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=36 prog=536903814 vers=1 proc=66 type=1 status=0 serial=0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=56 prog=536903814 vers=1 proc=1 type=0 status=0 serial=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04c0663340 classname=virConnect
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=28 prog=536903814 vers=1 proc=1 type=1 status=0 serial=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=2
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=2
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=28 prog=536903814 vers=1 proc=157 type=0 status=0 serial=4
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=36 prog=536903814 vers=1 proc=157 type=1 status=0 serial=4
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=44 prog=536903814 vers=1 proc=23 type=0 status=0 serial=5
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04c0004df0 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04c0004df0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0004df0
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=64 prog=536903814 vers=1 proc=23 type=1 status=0 serial=5
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=68 prog=536903814 vers=1 proc=14 type=0 status=0 serial=6
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b80050b0 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b80050b0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b80050b0
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=5416 prog=536903814 vers=1 proc=14 type=1 status=0 serial=6
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=72 prog=536903814 vers=1 proc=413 type=0 status=0 serial=7
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04a8001810 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f045c007190 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f045c0071d0 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f041400a2d0 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b8007790 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f0464008450 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f045c007190
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f045c007190
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f045c0071d0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f045c0071d0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f041400a2d0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f041400a2d0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b8007790
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b8007790
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f0464008450
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04a8001810
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0464008450
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=316 prog=536903814 vers=1 proc=413 type=1 status=0 serial=7
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=68 prog=536903814 vers=1 proc=212 type=0 status=0 serial=8
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b0001860 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b0001860
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b0001860
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=36 prog=536903814 vers=1 proc=212 type=1 status=0 serial=8
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=68 prog=536903814 vers=1 proc=14 type=0 status=0 serial=9
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b40031a0 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b40031a0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b40031a0
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=5416 prog=536903814 vers=1 proc=14 type=1 status=0 serial=9
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=88 prog=536903814 vers=1 proc=415 type=0 status=0 serial=10
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04c0004e90 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f041400a390 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0004e90
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0004e90
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f041400a390
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04c0004e90
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0004e90
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f041400a390
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=84 prog=536903814 vers=1 proc=415 type=1 status=0 serial=10
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=88 prog=536903814 vers=1 proc=415 type=0 status=0 serial=11
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b8005150 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b8007c50 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04b8005150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b8005150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b8007c50
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b8005150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b8005150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b8007c50
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=84 prog=536903814 vers=1 proc=415 type=1 status=0 serial=11
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=88 prog=536903814 vers=1 proc=415 type=0 status=0 serial=12
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f047801fe40 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f0424009e10 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f047801fe40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f047801fe40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f0424009e10
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f047801fe40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f047801fe40
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0424009e10
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=84 prog=536903814 vers=1 proc=415 type=1 status=0 serial=12
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=88 prog=536903814 vers=1 proc=415 type=0 status=0 serial=13
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b00018b0 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b063bd10 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04b00018b0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b00018b0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b063bd10
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b00018b0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b00018b0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b063bd10
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=84 prog=536903814 vers=1 proc=415 type=1 status=0 serial=13
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=88 prog=536903814 vers=1 proc=415 type=0 status=0 serial=14
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04b4003150 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f041400a010 classname=virDomainCheckpoint
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04b4003150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b4003150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f041400a010
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_DISPOSE: obj=0x7f04b4003150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f04b4003150
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f041400a010
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561d8aa93580 len=84 prog=536903814 vers=1 proc=415 type=1 status=0 serial=14
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=3
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=2 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_DISPATCH_HANDLE: watch=98 events=1 cb=0x7f04c98758c0 opaque=0x561d8aa8c6f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: RPC_SERVER_CLIENT_MSG_RX: client=0x561d8aa93580 len=72 prog=536903814 vers=1 proc=335 type=0 status=0 serial=15
Jul 12 22:43:38 hv01 libvirtd[3123143]: EVENT_GLIB_UPDATE_HANDLE: watch=98 events=1
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa93580
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa86410
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa72880
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_NEW: obj=0x7f04c0004ee0 classname=virDomain
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f04c0663340
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa72ea0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x561d8aa5a5f0
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f0478126260
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f046400ec30
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f046400ec30
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f046400ec30
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f046400ec30
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_REF: obj=0x7f046400ec30
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f046400ec30
Jul 12 22:43:38 hv01 libvirtd[3123143]: OBJECT_UNREF: obj=0x7f046400ec30

The qemu-guest-agent runs in the VM. It has also received the guest-fsfreeze call. In all tests today as you can see here it also worked. Until the time 22:43:38

root@web ~ # journalctl -u qemu-guest-agent --since 18:00
-- Journal begins at Fri 2022-05-06 10:54:32 CEST, ends at Tue 2022-07-12 23:02:22 CEST. --
Jul 12 20:57:07 web qemu-ga[446]: info: guest-fsfreeze called
Jul 12 21:29:48 web qemu-ga[446]: info: guest-fsfreeze called
Jul 12 21:30:52 web qemu-ga[446]: info: guest-fsfreeze called
Jul 12 21:34:31 web qemu-ga[446]: info: guest-fsfreeze called
Jul 12 22:43:38 web qemu-ga[446]: info: guest-fsfreeze called
-- Boot a1342dd98fc7420b8f7843d2a2c76aa8 --
Jul 12 22:55:26 web systemd[1]: Started QEMU Guest Agent.
abbbi commented 2 years ago

i really guess it is the qemu agent /freezing action that triggers the issue, this message suggests so:

WARNING libvirthelper - fsFreeze [MainThread]: Gast-Agent antwortet nicht: Guest agent disappeared while executing command

Unfortunately it you didnt pass -v option so we cant see wetherif freezing action returned or not. As virsh command shows, the backup job was never created.

Try to disable qemu agent, otherwise i have no idea and you probably have to reach out to the llibvirt/qemu folks in order to debug this issue further, or enable qemu debug logging that logs to /var/log/libvirt/qemu/ and shows more information whats happening on qemu side. Maybe its also an qemu agent <-> qemu version type issue. Cant spot any obvious reason in the libvirt logs: all work related to this is qemu stuff anyway, i dont think libvirt is at fault here.

You could also try the "-s" and "-k" options to reproduce the issue without making an actual backup, example:

this command freezes/thaws FS and starts the backup job:

virtnbdbackup -d testvm_saveme -v -o $(mktemp -d) -s

this command kills the backup job:

virtnbdbackup -d testvm_saveme -v -o $(mktemp -d) -k

I tried on my test setup with an loop and was not able to reproduce the issue. So it must be an environment specific issue or maybe based on the qemu agent version.

for I in $(seq 1 200); do sudo ./virtnbdbackup -d testvm_saveme -o $(mktemp -d) -s; sudo ./virtnbdbackup -d testvm_saveme -o $(mktemp -d) -k; done > test.log 2>&1

mrickl commented 2 years ago

I tried it now with the option "-s" on a clone of the original VM.

Once with running qemu-guest-agent

root@hv01 /var/lib/vservers # virtnbdbackup -d webserver-test -o /mnt/storage01/vm-backups/webserver-test --checkpointdir /mnt/storage01/checkpoints/webserver-test -n -v -s
[2022-07-13 22:32:59] INFO common - printVersion [MainThread]: Version: 0.75 Arguments: /usr/local/bin/virtnbdbackup -d webserver-test -o /mnt/storage01/vm-backups/webserver-test --checkpointdir /mnt/storage01/checkpoints/webserver-test -n -v -s
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Backup level: [copy]
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Store checkpoints in: /mnt/storage01/checkpoints/webserver-test
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Libvirt library version: 7000000
[2022-07-13 22:32:59] DEBUG libvirthelper - domainOffline [MainThread]: Domain state returned by libvirt: [1]
[2022-07-13 22:32:59] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [loader] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:32:59] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [nvram] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:32:59] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [kernel] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:32:59] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [initrd] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:32:59] DEBUG libvirthelper - getDomainInfo [MainThread]: Domain Info: [{'loader': None, 'nvram': None, 'kernel': None, 'initrd': None}]
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Domain has 1 disks attached which support changed block tracking.
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Concurrent backup processes: [1]
[2022-07-13 22:32:59] INFO libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint list from: [/mnt/storage01/checkpoints/webserver-test]
[2022-07-13 22:32:59] INFO virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint handling.
[2022-07-13 22:32:59] DEBUG virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint info: [{'name': 'virtnbdbackup.0', 'parent': False, 'file': '/mnt/storage01/vm-backups/webserver-test/webserver-test.cpt'}].
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Temporary scratch file target directory: /var/tmp
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: NDB Endpoint socket: /var/tmp/virtnbdbackup.1260997
[2022-07-13 22:32:59] INFO virtnbdbackup - main [MainThread]: Starting backup job.
[2022-07-13 22:32:59] DEBUG libvirthelper - _createBackupXml [MainThread]: Using scratch file: /var/tmp/backup.HXB34.vda
[2022-07-13 22:32:59] DEBUG libvirthelper - _indentXml [MainThread]: 
<domainbackup mode="pull">
  <server transport="unix" socket="/var/tmp/virtnbdbackup.1260997"/>
  <disks>
    <disk name="vda">
      <scratch file="/var/tmp/backup.HXB34.vda"/>
    </disk>
  </disks>
</domainbackup>
[2022-07-13 22:32:59] DEBUG libvirthelper - fsFreeze [MainThread]: Attempting to freeze filesystems.
[2022-07-13 22:33:00] INFO libvirthelper - fsFreeze [MainThread]: Freezed [1] filesystems.
[2022-07-13 22:33:00] DEBUG libvirthelper - startBackup [MainThread]: Starting backup job via libvirt API.
[2022-07-13 22:33:30] DEBUG libvirthelper - fsThaw [MainThread]: Attempting to thaw filesystems.
[2022-07-13 22:33:30] INFO libvirthelper - fsThaw [MainThread]: Thawed [1] filesystems.
[2022-07-13 22:33:30] ERROR virtnbdbackup - main [MainThread]: Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)
[2022-07-13 22:33:30] ERROR virtnbdbackup - main [MainThread]: Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/virtnbdbackup-0.75-py3.9.egg/EGG-INFO/scripts/virtnbdbackup", line 513, in main
  File "/usr/local/lib/python3.9/dist-packages/virtnbdbackup-0.75-py3.9.egg/libvirtnbdbackup/libvirthelper/libvirthelper.py", line 403, in startBackup
    raise errmsg
  File "/usr/local/lib/python3.9/dist-packages/virtnbdbackup-0.75-py3.9.egg/libvirtnbdbackup/libvirthelper/libvirthelper.py", line 394, in startBackup
    domObj.backupBegin(backupXml, checkpointXml)
  File "/usr/lib/python3/dist-packages/libvirt.py", line 797, in backupBegin
    raise libvirtError('virDomainBackupBegin() failed')
libvirt.libvirtError: Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)

and once without running qemu-guest-agent

root@hv01 /var/lib/vservers # virtnbdbackup -d webserver-test -o /mnt/storage01/vm-backups/webserver-test --checkpointdir /mnt/storage01/checkpoints/webserver-test -n -v -s
[2022-07-13 22:33:37] INFO common - printVersion [MainThread]: Version: 0.75 Arguments: /usr/local/bin/virtnbdbackup -d webserver-test -o /mnt/storage01/vm-backups/webserver-test --checkpointdir /mnt/storage01/checkpoints/webserver-test -n -v -s
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Backup level: [copy]
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Store checkpoints in: /mnt/storage01/checkpoints/webserver-test
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Libvirt library version: 7000000
[2022-07-13 22:33:37] DEBUG libvirthelper - domainOffline [MainThread]: Domain state returned by libvirt: [1]
[2022-07-13 22:33:37] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [loader] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:33:37] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [nvram] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:33:37] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [kernel] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:33:37] DEBUG libvirthelper - getDomainInfo [MainThread]: No setting [initrd] found: 'NoneType' object has no attribute 'text'
[2022-07-13 22:33:37] DEBUG libvirthelper - getDomainInfo [MainThread]: Domain Info: [{'loader': None, 'nvram': None, 'kernel': None, 'initrd': None}]
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Domain has 1 disks attached which support changed block tracking.
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Concurrent backup processes: [1]
[2022-07-13 22:33:37] INFO libvirthelper - redefineCheckpoints [MainThread]: Loading checkpoint list from: [/mnt/storage01/checkpoints/webserver-test]
[2022-07-13 22:33:37] INFO virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint handling.
[2022-07-13 22:33:37] DEBUG virtnbdbackup - handleCheckpoints [MainThread]: Checkpoint info: [{'name': 'virtnbdbackup.0', 'parent': False, 'file': '/mnt/storage01/vm-backups/webserver-test/webserver-test.cpt'}].
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Temporary scratch file target directory: /var/tmp
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: NDB Endpoint socket: /var/tmp/virtnbdbackup.1261790
[2022-07-13 22:33:37] INFO virtnbdbackup - main [MainThread]: Starting backup job.
[2022-07-13 22:33:37] DEBUG libvirthelper - _createBackupXml [MainThread]: Using scratch file: /var/tmp/backup.KPXQP.vda
[2022-07-13 22:33:37] DEBUG libvirthelper - _indentXml [MainThread]: 
<domainbackup mode="pull">
  <server transport="unix" socket="/var/tmp/virtnbdbackup.1261790"/>
  <disks>
    <disk name="vda">
      <scratch file="/var/tmp/backup.KPXQP.vda"/>
    </disk>
  </disks>
</domainbackup>
[2022-07-13 22:33:37] DEBUG libvirthelper - fsFreeze [MainThread]: Attempting to freeze filesystems.
[2022-07-13 22:33:37] WARNING libvirthelper - fsFreeze [MainThread]: Gast-Agent antwortet nicht: QEMU guest agent is not connected
[2022-07-13 22:33:37] DEBUG libvirthelper - startBackup [MainThread]: Starting backup job via libvirt API.
[2022-07-13 22:34:07] ERROR virtnbdbackup - main [MainThread]: Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)
[2022-07-13 22:34:07] ERROR virtnbdbackup - main [MainThread]: Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/virtnbdbackup-0.75-py3.9.egg/EGG-INFO/scripts/virtnbdbackup", line 513, in main
  File "/usr/local/lib/python3.9/dist-packages/virtnbdbackup-0.75-py3.9.egg/libvirtnbdbackup/libvirthelper/libvirthelper.py", line 403, in startBackup
    raise errmsg
  File "/usr/local/lib/python3.9/dist-packages/virtnbdbackup-0.75-py3.9.egg/libvirtnbdbackup/libvirthelper/libvirthelper.py", line 394, in startBackup
    domObj.backupBegin(backupXml, checkpointXml)
  File "/usr/lib/python3/dist-packages/libvirt.py", line 797, in backupBegin
    raise libvirtError('virDomainBackupBegin() failed')
libvirt.libvirtError: Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)

If you don't mind me asking, what version are you running in the test environment?

With me it is the following

libvirt=7.0.0-3 qemu=1:5.2+dfsg-11+deb11u2

qemu-quest-agent=1:5.2+dfsg-11+deb11u2

abbbi commented 2 years ago

the test didnt reproduce the situation of a hanging backup. It clearly catches another exception from the libvirt api:

Cannot acquire state change lock (held by monitor=remoteDispatchDomainBackupBegin)

I can reproduce THIS situation if i start a backup job twice. If you start an backup job, you must KILL IT with the -k option, as i have described in my initial post.

you have to:

1) start the backup job with option -s 2) kill the backup job with option -k ... repeat step 1&2

abbbi commented 2 years ago

any news on this? Otherwise ill close issue as im unable to reproduce.

mrickl commented 2 years ago

Sorry that I have not reported for a long time. I have in the meantime always had another version of qemu tried. But the error still exists. On the part of the qemu-ga is a bit difficult to log because he disabled the logging with the call fsfreeze. But in the meantime I could detect the following in the libvirtd log on the host system 

2022-08-02 15:48:05.700+0000: 2373: warning : qemuDomainObjBeginJobInternal:934 : Cannot start job (none, modify, none) for domain Webserver; current job is (none, modify, none) owned by (0 <null>, 2371 remoteDispatchDomainFSFreeze, 0 <null> (flags=0x0)) for (0s, 169s, 0s)
2022-08-02 15:48:05.700+0000: 2373: error : qemuDomainObjBeginJobInternal:973 : Zeit abgelaufen während der Aktion: cannot acquire state change lock (held by agent=remoteDispatchDomainFSFreeze)

I assume that this is now more a case to open an issue directly at qemu or?

abbbi commented 2 years ago

I wonder if there can be an race condition between calling fsFreeze and backupBegin. I would assume (and python-libvirt documentation doesnt tell otherwise) that if fsFreeze returns as it has finished operation on all volumes. The message looks like the backup job cannot be started because the Freeze action is still active? But for sure this looks more like an issue with Qemu-QA or qemu internals messing up something during filesystem freeze.

mrickl commented 2 years ago

First of all, thanks for helping. I have looked at the issues at qemu and also found the following:

https://gitlab.com/qemu-project/qemu/-/issues/881 https://jira.mariadb.org/browse/MDEV-27196

This concerns Proxmox and their backup server but also the qemu-ga is mentioned. I will test this now if this really has to do with the MariaDB version or not. But because of this it is not really a bug on the part of virtndbbackup. Feel free to close the issue here.

mrickl commented 2 years ago

A short feedback. Since I have now downgraded from MariaDB 10.8 to 10.5, I had no problems running virtnbdbackup on my webserver. So the case can really be closed.