Backup fails after a migration and a new destination directory is selected

[dcskinner]

I've run into an issue. I have a wrapper script that creates a new backup directory based on a hash of the VM name to spread Full backups over the course of a month. This is working well for the most part.

If I migrate a VM between hosts, the checkpoints are lost. If the backup directory remains the same, it will recreate the checkpoints and then perform the backup as expected.

The problem is if a VM has checkpoints, is migrated, and then a new backup directory is created to start a new checkpoint chain. virtnbdbackup doesn't think there are any checkpoints to cleanup and it just tries to start a new chain, but the checkpoints exist in the disk image files. When this happens, the backup dies, leaves the nbd port open, and leaves a state change lock on the VM. Running the backup with -k does not remove the lock. I have to shutdown the VM (which frees up the nbd port), restart libvirtd (clears the lock), and then power the VM back up.

At this point, it appears my options are to point the backup at the old directory to recreate the checkpoints and then use the new dir to start a new chain, or shutdown the VM and remove the bitmap checkpoints from the volume file(s).

Any thoughts on how to deal with this situation? I'm thinking my wrapper could, if it creates a new directory, look for an empty checkpoint list and try to run an estimate using the prev directory first (assuming there is one). That should handle most of the situations unless the prev dir is not available for some reason. Any better way to handle this?

Thanks!

If folks are interested, I will share my wrapper once I get this (hopefully) last failure situation ironed out and I make my code a little more readable.

Here is the failure (the first 6 lines and the last line are my wrapper):

$ /opt/bckuser/etc/runscripts/kvm-backup.sh vm01
[2024-10-14 15:06:01] INFO: /data/KVM/vm01/20240815 is a month or more old, creating new dir: /data/KVM/vm01/20241026
[2024-10-14 15:06:01] INFO: Output directory is: /data/KVM/vm01/20241026
[2024-10-14 15:06:05] INFO: Attempting lock for host kvmhost03. Will wait for 28800 seconds.
[2024-10-14 15:06:05] INFO: Host kvmhost03 locked for backup.
[2024-10-14 15:06:05] INFO: Found VM vm01 on host kvmhost03
[2024-10-14 15:06:05] INFO: Ready to run the backup. Handing off to virtnbdbackup... 

[2024-10-14 15:06:06] INFO lib common - printVersion [main]: Version: 2.12 Arguments: /usr/bin/virtnbdbackup -U qemu+ssh://[email protected]/system --ssh-user bckuser --tls -l auto -S -n --nocolor -d vm01 -o /data/KVM/vm01/20241026
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: Backup level: [auto]
[2024-10-14 15:06:06] INFO virt client - _connect [main]: Connected to remote host: [kvmhost03.example.com]
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: Libvirt library version: [10000000]
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: NBD library version: [1.18.1]
[2024-10-14 15:06:06] INFO root check - targetDir [main]: Backup mode auto, target folder is empty: executing full backup.
[2024-10-14 15:06:06] INFO root disktype - Optical [main]: Skipping attached [cdrom] device: [sda].
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: Backup will save [1] attached disks.
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: Concurrent backup processes: [1]
[2024-10-14 15:06:06] INFO root checkpoint - create [main]: Loading checkpoints from: [/data/KVM/vm01/20241026/vm01.cpt]
[2024-10-14 15:06:06] INFO root checkpoint - redefine [main]: Loading checkpoint list from: [/data/KVM/vm01/20241026/checkpoints]
[2024-10-14 15:06:06] INFO root checkpoint - create [main]: Checkpoint handling.
[2024-10-14 15:06:06] INFO root checkpoint - create [main]: Using checkpoint name: [virtnbdbackup.0].
[2024-10-14 15:06:06] INFO ssh client - connect [main]: Connecting remote system [kvmhost03.example.com] via ssh, username: [bckuser]
[2024-10-14 15:06:06] INFO paramiko.transport transport - _log [Thread-1]: Connected (version 2.0, client OpenSSH_8.7)
[2024-10-14 15:06:06] INFO paramiko.transport transport - _log [Thread-1]: Auth banner: b'\\S\nKernel \\r on an \\m\n\n'
[2024-10-14 15:06:06] INFO paramiko.transport transport - _log [Thread-1]: Authentication (publickey) successful!
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: Remote NBD Endpoint host: [kvmhost03.example.com]
[2024-10-14 15:06:06] INFO root virtnbdbackup - main [main]: Temporary scratch file target directory: [/var/tmp]
[2024-10-14 15:06:06] INFO root job - start [main]: Starting backup job.
[2024-10-14 15:06:07] INFO fs fs - freeze [main]: Freezed [2] filesystems.
[2024-10-14 15:06:15] WARNING fs fs - thaw [main]: internal error: client socket is closed
[2024-10-14 15:06:15] ERROR root job - start [main]: Failed to start backup: [End of file while reading data: \S
Kernel \r on an \m                                                     

virt-ssh-helper: could not proxy traffic: End of file while reading data: Input/output error: Input/output error]
[2024-10-14 15:06:15] INFO: Host kvmhost03 unlocked for backup.

[abbbi]

[2024-10-14 15:06:15] ERROR root job - start [main]: Failed to start backup: [End of file while reading data: \S
Kernel \r on an \m                                                     
virt-ssh-helper: could not proxy traffic: End of file while reading data: Input/output error: Input/output error]

huh, that looks pretty strange to me.
Why does the virt-ssh-helper return the ssh auth banner information during an error here?

I have not yet seen a backup fail in this situation, it seems somehow its attempting to start the backup job, but then the
ssh connection to the libvirt daemon drops:

virt-ssh-helper: could not proxy traffic: End of file while reading data: Input/output error: Input/output error

it also seems to be unable to thaw the filesystems (that results in the vm beeing freezed as filesystems are not
thawed):

[2024-10-14 15:06:07] INFO fs fs - freeze [main]: Freezed [2] filesystems.
[2024-10-14 15:06:15] WARNING fs fs - thaw [main]: internal error: client socket is closed

That looks to me as if the complete VM crashes? There have been similar issues in the past related to mysql running within
the VM and crashing during freeze using the qemu agent, see:

#102

Maybe it helps if you try to backup without the qemu agent running to see if its the same problem?

As you tell, the NBD Service seems to be running after this action, so it somehow at least managed to start the backup
job but then communication drops for whatever reason.. You would have to check the libvirt and qemu logfiles what
happens with the VM here.

Also, the latest virtnbdbackup version has seen some improvements and attempts to reconnect the libvirt daemon in case
an error happens that is related to the connection and attempts to cleanup, but i dont know if that helps in your situation.

Have you considered using the external checkpoint directory for storing checkpoint information like described here?

https://github.com/abbbi/virtnbdbackup?tab=readme-ov-file#transient-virtual-machines-checkpoint-persistency-on-clusters

[dcskinner]

The VM doesn't crash, but it is unhappy. I will test again without the agent running. I think the backup process still crashes. More details on that in a bit after some more testing.

I read the transient VM doc but didn't think it applied b/c I am always backing up from the same remote machine, but you are right that is a better way to handle my situation. If I move the checkpoint dir one level higher, it stays the same even when I create a new directory to force a new Full backup. That is a MUCH better way to handle it and probably solves that problem. THANK YOU!

It looks like the checkpoint directory is created if it doesn't exist (perhaps add to the doc and --help).

[dcskinner]

Ok, some more testing. I set up the same scenario. I backed up the VM a couple times to create some checkpoints. I migrated the VM between hosts, which caused libvirt to lose the checkpoint info. Then I ran the backup using a new directory and did not use the common checkpoint dir as we discussed above. Basically the same thing happened. The output was the same (including the virsh-ssh-helper) except for:

[2024-10-15 12:33:46] WARNING fs fs - freeze [main]: Guest agent is not responding: QEMU guest agent is not connected

This time, the VM itself did not seem to become unhappy and appeared to be running normally. The nbd port was still left open and I had to shutdown the VM again to clear that. The state change lock was still there and needed to be cleared with a libvirtd restart while the VM was down.

When the backup happens in this state, libvirtd apparently crashes and restarts (timestamp doesn't match the guest agent line above b/c they were 2 different tests, but the same thing happened):

Oct 15 12:37:42 kvmhost03 libvirtd[475573]: internal error: unable to execute QEMU command 'transaction': Bitmap already exists: virtnbdbackup.0
Oct 15 12:37:42 kvmhost03 libvirtd[475573]: This thread seems to be the async job owner; entering monitor without asking for a nested job is dangerous
Oct 15 12:37:42 kvmhost03 libvirtd[475573]: internal error: Missing monitor reply object
Oct 15 12:37:42 kvmhost03 kernel: rpc-libvirtd[475581]: segfault at 20 ip 00007f74b5d1bf17 sp 00007f74bfdfd5d0 error 4 in libvirt_driver_qemu.so[7f74b5c48000+12f000] likely on CPU 38 (core 12, socket 0)
Oct 15 12:37:42 kvmhost03 kernel: Code: 85 36 01 00 00 48 8d 5d 18 eb 18 0f 1f 84 00 00 00 00 00 48 8d 7d 40 48 89 de e8 64 da f3 ff 85 c0 78 50 48 8b 85 a8 00 00 00 <80> 78 20 00 74 e3 44 8b b5 c8 00 00 00 45 85 f6 0f 85 8b 00 00 00
Oct 15 12:37:43 kvmhost03 systemd[1]: libvirtd.service: Main process exited, code=killed, status=11/SEGV
Oct 15 12:37:43 kvmhost03 systemd[1]: libvirtd.service: Failed with result 'signal'.
Oct 15 12:37:43 kvmhost03 systemd[1]: libvirtd.service: Consumed 9.019s CPU time.
Oct 15 12:37:43 kvmhost03 systemd[1]: libvirtd.service: Scheduled restart job, restart counter is at 1.
Oct 15 12:37:43 kvmhost03 systemd[1]: Stopped libvirt legacy monolithic daemon.
Oct 15 12:37:43 kvmhost03 systemd[1]: libvirtd.service: Consumed 9.019s CPU time.
Oct 15 12:37:43 kvmhost03 systemd[1]: Starting libvirt legacy monolithic daemon...
Oct 15 12:37:43 kvmhost03 systemd[1]: Started libvirt legacy monolithic daemon.
Oct 15 12:37:49 kvmhost03 libvirtd[476225]: libvirt version: 10.0.0, package: 6.7.el9_4 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2024-09-12-06:48:10, )
Oct 15 12:37:49 kvmhost03 libvirtd[476225]: hostname: kvmhost03.example.com
Oct 15 12:37:49 kvmhost03 libvirtd[476225]: dropping blockjob 'backup-vda-libvirt-2-format' untracked by qemu

I think changing the checkpoint dir will prevent this situation in my case, but hopefully this testing will help if someone else runs into this. I'd be curious if other folks can replicate the issue. It seems like libvirtd shouldn't be crashing, so maybe there is a bug somewhere that needs to be addressed. Let me know if you want any more info. I will have this host in a state where I can do more testing probably through the rest of the week.

Thanks again!

[abbbi]

rpc-libvirtd[475581]: segfault [..]

is most probably cause of the issue...
I would suggest forwarding this issue to your distribution vendor.