PVE7 / PBS2 / backup is running since

[ChristophGoth]

Using above Versions, the check_mk State remains in "backup is running since: ..." after the Backup is done.

This only occures for LXC Backups, QEMU are shown correctly.

Sample Output for a lxc job:

/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Starting Backup of VM 800 (lxc)
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: status = running
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: CT Name: lnx-router
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: including mount point rootfs ('/') in backup
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: backup mode: snapshot
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: ionice priority: 7
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK: backup-start snapshot 800
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK-ENV: vmtype=lxc;storeid=PVE01-PBS;hostname=lnx-router;target=ct/800/2021-08-26T23:12:56Z
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK: pre-stop snapshot 800
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK-ENV: vmtype=lxc;storeid=PVE01-PBS;hostname=lnx-router;target=ct/800/2021-08-26T23:12:56Z
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: create storage snapshot 'vzdump'
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK: pre-restart snapshot 800
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK-ENV: vmtype=lxc;storeid=PVE01-PBS;hostname=lnx-router;target=ct/800/2021-08-26T23:12:56Z
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK: post-restart snapshot 800
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: HOOK-ENV: vmtype=lxc;storeid=PVE01-PBS;hostname=lnx-router;target=ct/800/2021-08-26T23:12:56Z
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: creating Proxmox Backup Server archive 'ct/800/2021-08-26T23:12:56Z'
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: run: lxc-usernsexec -m u:0:100000:65536 -m g:0:100000:65536 -- /usr/bin/proxmox-backup-client backup --crypt-mode=none pct.conf:/var/tmp/vzdumptmp2008121_800/etc/vzdump/pct.conf root.pxar:/mnt/vzsnap0 --include-dev /mnt/vzsnap0/./ --skip-lost-and-found --exclude=/tmp/?* --exclude=/var/tmp/?* --exclude=/var/run/?*.pid --backup-type ct --backup-id 800 --backup-time 1630019576 --repository root@pam@pve01.2-cpu.local:Backup
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Starting backup: ct/800/2021-08-26T23:12:56Z
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Client name: pve01
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Starting backup protocol: Fri Aug 27 01:12:56 2021
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Downloading previous manifest (Thu Aug 26 09:31:31 2021)
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Upload config file '/var/tmp/vzdumptmp2008121_800/etc/vzdump/pct.conf' to 'root@pam@pve01.2-cpu.local:8007:Backup' as pct.conf.blob
/var/log/vzdump/lxc-800.log 2021-08-27 01:12:56 INFO: Upload directory '/mnt/vzsnap0' to 'root@pam@pve01.2-cpu.local:8007:Backup' as root.pxar.didx
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: root.pxar: had to backup 323.36 MiB of 5.10 GiB (compressed 61.34 MiB) in 15.04s
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: root.pxar: average backup speed: 21.49 MiB/s
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: root.pxar: backup was done incrementally, reused 4.79 GiB (93.8%)
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: Uploaded backup catalog (892.03 KiB)
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: Duration: 15.25s
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: End Time: Fri Aug 27 01:13:11 2021
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: HOOK: backup-end snapshot 800
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:11 INFO: HOOK-ENV: vmtype=lxc;storeid=PVE01-PBS;hostname=lnx-router;target=ct/800/2021-08-26T23:12:56Z
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:12 INFO: cleanup temporary 'vzdump' snapshot
/var/log/vzdump/lxc-800.log 2021-08-27 01:13:12 INFO: Finished Backup of VM 800 (00:00:16)

And for qemu:

/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: Starting Backup of VM 503 (qemu)
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: status = stopped
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: backup mode: stop
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: ionice priority: 7
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: VM Name: esx03
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: include disk 'sata0' 'local-zfs-nvme2:vm-503-disk-0' 32G
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: HOOK: backup-start stop 503
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: HOOK-ENV: vmtype=qemu;storeid=PVE01-PBS;hostname=esx03;target=vm/503/2021-08-26T23:12:12Z
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: creating Proxmox Backup Server archive 'vm/503/2021-08-26T23:12:12Z'
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:12 INFO: starting kvm to execute backup task
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:13 INFO: started backup task 'c5c00529-1fc8-47f3-a7c6-923e14059cf5'
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:13 INFO: sata0: dirty-bitmap status: created new
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:16 INFO: 25% (8.2 GiB of 32.0 GiB) in 3s, read: 2.7 GiB/s, write: 0 B/s
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:19 INFO: 48% (15.4 GiB of 32.0 GiB) in 6s, read: 2.4 GiB/s, write: 0 B/s
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:22 INFO: 76% (24.6 GiB of 32.0 GiB) in 9s, read: 3.1 GiB/s, write: 0 B/s
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:25 INFO: 100% (32.0 GiB of 32.0 GiB) in 12s, read: 2.5 GiB/s, write: 0 B/s
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:25 INFO: backup is sparse: 30.66 GiB (95%) total zero data
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:25 INFO: backup was done incrementally, reused 32.00 GiB (100%)
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:25 INFO: transferred 32.00 GiB in 12 seconds (2.7 GiB/s)
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:25 INFO: stopping kvm after backup task
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:26 INFO: HOOK: backup-end stop 503
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:26 INFO: HOOK-ENV: vmtype=qemu;storeid=PVE01-PBS;hostname=esx03;target=vm/503/2021-08-26T23:12:12Z
/var/log/vzdump/qemu-503.log 2021-08-27 01:12:26 INFO: Finished Backup of VM 503 (00:00:14)

[ChristophGoth]

Seems to be Line 111 in proxmox_lxc_backup, it searches for "had to upload" but now it is "had to backup"

[ChristophGoth]

After replacing 111, 169 and 211 it's working for backups containing data.
LXC without any change (2021-08-27 01:08:24 INFO: root.pxar: had to backup 0 B of 4.59 GiB (compressed 0 B) in 47.22s) runs into exception:

Exception

ValueError (could not convert string to float: '')

Traceback

File "/omd/sites/mysite/lib/python3/cmk/base/checking.py", line 582, in get_aggregated_result
result = _aggregate_results(check_function(**kwargs))
File "/omd/sites/mysite/lib/python3/cmk/base/checking.py", line 813, in _aggregate_results
perfdata, results = _consume_and_dispatch_result_types(subresults)
File "/omd/sites/mysite/lib/python3/cmk/base/checking.py", line 857, in _consume_and_dispatch_result_types
for subr in subresults:
File "/omd/sites/mysite/lib/python3/cmk/base/api/agent_based/register/check_plugins.py", line 89, in filtered_generator
for element in generator(*args, **kwargs):
File "/omd/sites/mysite/lib/python3/cmk/base/api/agent_based/register/check_plugins_legacy.py", line 183, in check_result_generator
for subresult in subresults:
File "/omd/sites/mysite/local/share/check_mk/checks/proxmox_lxc_backup", line 172, in check_lxc_backup
size_numbers = float(size[:len(size)-2])

[ChristophGoth]

After changing "size_numbers = float(size[:len(size)-2])" to "size_numbers = float(size[:len(size)-0])" (not nice but a try) the Crash for Backups with "0 B of" is gone. Maybe there is a cleaner solution.