Proxmox not restarting VM after backup

[xFede46]

Hi,
I have PVE 7.4-3 installed on my server, when the backup job (that backup every VM on a PBS in stop mode) starts every machine come back online except one (VM 102) that i need to start manually.
Until one week ago everything was working flawlessly, the only modification i did was to install a couple of new VMs.
Thanks in advice for your help.
Syslog attached

qm.conf:

agent: 1
bios: ovmf
boot: order=scsi0
cores: 6
cpu: host
efidisk0: VM_Pool1:vm-102-disk-0,efitype=4m,pre-enrolled-keys=1,size=1M
machine: pc-q35-7.2
memory: 65536
meta: creation-qemu=7.2.0,ctime=1687274110
name: xxxxxxxxxxxxxxxxxxx
net0: virtio=1E:29:19:94:17:06,bridge=vmbr0,firewall=1
numa: 0
onboot: 1
ostype: win11
scsi0: VM_Pool1:vm-102-disk-1,cache=writeback,discard=on,iothread=1,size=100G,ssd=1
scsi1: VM_Pool1:vm-102-disk-3,cache=writeback,discard=on,iothread=1,size=500G,ssd=1
scsi2: xxxxxxxxxxxxxxxxxxx:0.0.1.scsi-xxxxxxxxxxxxxxxxxxx,backup=0,cache=writeback,discard=on,iothread=1,size=1T
scsihw: virtio-scsi-single
smbios1: uuid=ac98e8ce-fcfe-492e-a601-6af7a6c67e2d
sockets: 1
tpmstate0: VM_Pool1:vm-102-disk-2,size=4M,version=v2.0
vga: virtio
vmgenid: eb852b6c-55a7-4e2e-96d6-0af5107ff783

PVEVersion:

proxmox-ve: 7.4-1 (running kernel: 5.15.107-2-pve)
pve-manager: 7.4-3 (running version: 7.4-3/9002ab8a)
pve-kernel-5.15: 7.4-3
pve-kernel-5.15.107-2-pve: 5.15.107-2
pve-kernel-5.15.102-1-pve: 5.15.102-1
ceph-fuse: 15.2.17-pve1
corosync: 3.1.7-pve1
criu: 3.15-1+pve-1
glusterfs-client: 9.2-1
ifupdown2: 3.1.0-1+pmx4
ksm-control-daemon: 1.4-1
libjs-extjs: 7.0.0-1
libknet1: 1.24-pve2
libproxmox-acme-perl: 1.4.4
libproxmox-backup-qemu0: 1.3.1-1
libproxmox-rs-perl: 0.2.1
libpve-access-control: 7.4-3
libpve-apiclient-perl: 3.2-1
libpve-common-perl: 7.4-1
libpve-guest-common-perl: 4.2-4
libpve-http-server-perl: 4.2-3
libpve-rs-perl: 0.7.6
libpve-storage-perl: 7.4-2
libspice-server1: 0.14.3-2.1
lvm2: 2.03.11-2.1
lxc-pve: 5.0.2-2
lxcfs: 5.0.3-pve1
novnc-pve: 1.4.0-1
proxmox-backup-client: 2.4.2-1
proxmox-backup-file-restore: 2.4.2-1
proxmox-kernel-helper: 7.4-1
proxmox-mail-forward: 0.1.1-1
proxmox-mini-journalreader: 1.3-1
proxmox-widget-toolkit: 3.7.0
pve-cluster: 7.3-3
pve-container: 4.4-3
pve-docs: 7.4-2
pve-edk2-firmware: 3.20230228-2
pve-firewall: 4.3-2
pve-firmware: 3.6-5
pve-ha-manager: 3.6.1
pve-i18n: 2.12-1
pve-qemu-kvm: 7.2.0-8
pve-xtermjs: 4.16.0-1
qemu-server: 7.4-3
smartmontools: 7.2-pve3
spiceterm: 3.2-2
swtpm: 0.8.0~bpo11+3
vncterm: 1.7-1
zfsutils-linux: 2.1.11-pve1

 

[fiona]

Hi,
please share the backup task log (at least the part concerning VM 102). You can find it in the Task History in the UI.

 

[xFede46]

Thanks for the support.
Backup task log:

INFO: Starting Backup of VM 102 (qemu)
INFO: Backup started at 2023-10-10 00:05:45
INFO: status = running
INFO: backup mode: stop
INFO: ionice priority: 7
INFO: VM Name: vm_name
INFO: include disk 'scsi0' 'VM_Pool1:vm-102-disk-1' 100G
INFO: include disk 'scsi1' 'VM_Pool1:vm-102-disk-3' 500G
INFO: exclude disk 'scsi2' 'Backup:0.0.1.scsi-asd8656asd334asd3335353asd9393asd16' (backup=no)
INFO: include disk 'efidisk0' 'VM_Pool1:vm-102-disk-0' 1M
INFO: include disk 'tpmstate0' 'VM_Pool1:vm-102-disk-2' 4M
INFO: stopping virtual guest
INFO: creating Proxmox Backup Server archive 'vm/102/2023-10-09T22:05:45Z'
INFO: starting kvm to execute backup task
swtpm_setup: Not overwriting existing state file.
INFO: attaching TPM drive to QEMU for backup
INFO: started backup task '096edce7-4d2e-4f7e-a8b2-18ec623e45c8'
INFO: resuming VM again after 21 seconds
INFO: efidisk0: dirty-bitmap status: created new
INFO: scsi0: dirty-bitmap status: created new
INFO: scsi1: dirty-bitmap status: created new
INFO: tpmstate0-backup: dirty-bitmap status: created new
INFO:   0% (540.0 MiB of 600.0 GiB) in 3s, read: 180.0 MiB/s, write: 36.0 MiB/s
INFO:   1% (6.3 GiB of 600.0 GiB) in 20s, read: 348.0 MiB/s, write: 9.9 MiB/s
INFO:   2% (12.0 GiB of 600.0 GiB) in 30s, read: 586.4 MiB/s, write: 1.2 MiB/s
INFO:   3% (18.3 GiB of 600.0 GiB) in 48s, read: 354.2 MiB/s, write: 25.8 MiB/s
INFO:   4% (24.3 GiB of 600.0 GiB) in 59s, read: 566.9 MiB/s, write: 45.5 MiB/s
INFO:   5% (30.9 GiB of 600.0 GiB) in 1m 4s, read: 1.3 GiB/s, write: 6.4 MiB/s
INFO:   6% (36.2 GiB of 600.0 GiB) in 1m 23s, read: 286.1 MiB/s, write: 35.8 MiB/s
INFO:   7% (42.2 GiB of 600.0 GiB) in 1m 39s, read: 387.2 MiB/s, write: 2.2 MiB/s
INFO:   8% (48.2 GiB of 600.0 GiB) in 1m 53s, read: 438.0 MiB/s, write: 19.1 MiB/s
INFO:   9% (54.3 GiB of 600.0 GiB) in 2m 18s, read: 248.3 MiB/s, write: 34.1 MiB/s
INFO:  10% (60.5 GiB of 600.0 GiB) in 2m 34s, read: 395.2 MiB/s, write: 18.5 MiB/s
INFO:  11% (66.3 GiB of 600.0 GiB) in 2m 41s, read: 857.7 MiB/s, write: 13.7 MiB/s
INFO:  12% (74.4 GiB of 600.0 GiB) in 2m 44s, read: 2.7 GiB/s, write: 21.3 MiB/s
INFO:  13% (78.1 GiB of 600.0 GiB) in 2m 51s, read: 542.3 MiB/s, write: 26.9 MiB/s
INFO:  14% (84.2 GiB of 600.0 GiB) in 3m 9s, read: 347.6 MiB/s, write: 22.7 MiB/s
INFO:  15% (90.4 GiB of 600.0 GiB) in 3m 25s, read: 396.8 MiB/s, write: 43.5 MiB/s
INFO:  16% (99.3 GiB of 600.0 GiB) in 3m 28s, read: 3.0 GiB/s, write: 12.0 MiB/s
INFO:  18% (111.5 GiB of 600.0 GiB) in 3m 31s, read: 4.1 GiB/s, write: 0 B/s
INFO:  20% (123.7 GiB of 600.0 GiB) in 3m 34s, read: 4.1 GiB/s, write: 2.7 MiB/s
INFO:  21% (126.3 GiB of 600.0 GiB) in 3m 50s, read: 170.5 MiB/s, write: 56.5 MiB/s
INFO:  22% (133.5 GiB of 600.0 GiB) in 3m 59s, read: 820.4 MiB/s, write: 68.4 MiB/s
INFO:  23% (138.0 GiB of 600.0 GiB) in 4m 6s, read: 655.4 MiB/s, write: 57.1 MiB/s
INFO:  24% (144.3 GiB of 600.0 GiB) in 4m 17s, read: 580.7 MiB/s, write: 74.2 MiB/s
INFO:  25% (150.0 GiB of 600.0 GiB) in 4m 30s, read: 453.8 MiB/s, write: 71.7 MiB/s
INFO:  26% (156.0 GiB of 600.0 GiB) in 4m 40s, read: 613.6 MiB/s, write: 87.6 MiB/s
INFO:  27% (162.1 GiB of 600.0 GiB) in 4m 55s, read: 415.2 MiB/s, write: 61.3 MiB/s
INFO:  28% (168.5 GiB of 600.0 GiB) in 5m 8s, read: 502.2 MiB/s, write: 76.0 MiB/s
INFO:  29% (174.0 GiB of 600.0 GiB) in 5m 17s, read: 632.9 MiB/s, write: 91.1 MiB/s
INFO:  30% (180.5 GiB of 600.0 GiB) in 5m 29s, read: 548.3 MiB/s, write: 80.3 MiB/s
INFO:  31% (186.3 GiB of 600.0 GiB) in 5m 40s, read: 545.1 MiB/s, write: 71.6 MiB/s
INFO:  32% (192.3 GiB of 600.0 GiB) in 5m 51s, read: 555.6 MiB/s, write: 77.5 MiB/s
INFO:  33% (198.1 GiB of 600.0 GiB) in 6m 1s, read: 590.4 MiB/s, write: 78.8 MiB/s
INFO:  34% (204.3 GiB of 600.0 GiB) in 6m 14s, read: 494.5 MiB/s, write: 76.6 MiB/s
INFO:  35% (210.3 GiB of 600.0 GiB) in 6m 26s, read: 511.0 MiB/s, write: 45.7 MiB/s
INFO:  36% (216.2 GiB of 600.0 GiB) in 6m 40s, read: 432.0 MiB/s, write: 28.9 MiB/s
INFO:  37% (222.0 GiB of 600.0 GiB) in 6m 53s, read: 458.5 MiB/s, write: 24.3 MiB/s
INFO:  38% (228.7 GiB of 600.0 GiB) in 7m 5s, read: 570.7 MiB/s, write: 36.0 MiB/s
INFO:  39% (234.5 GiB of 600.0 GiB) in 7m 24s, read: 309.9 MiB/s, write: 66.9 MiB/s
INFO:  40% (240.0 GiB of 600.0 GiB) in 7m 31s, read: 813.1 MiB/s, write: 29.7 MiB/s
INFO:  41% (246.0 GiB of 600.0 GiB) in 7m 50s, read: 321.7 MiB/s, write: 43.6 MiB/s
INFO:  42% (252.1 GiB of 600.0 GiB) in 8m 4s, read: 443.4 MiB/s, write: 50.3 MiB/s
INFO:  43% (258.3 GiB of 600.0 GiB) in 8m 18s, read: 454.6 MiB/s, write: 66.3 MiB/s
INFO:  44% (264.0 GiB of 600.0 GiB) in 8m 26s, read: 734.5 MiB/s, write: 44.5 MiB/s
INFO:  45% (270.5 GiB of 600.0 GiB) in 9m 14s, read: 138.2 MiB/s, write: 54.1 MiB/s
INFO:  46% (276.1 GiB of 600.0 GiB) in 9m 43s, read: 199.0 MiB/s, write: 50.1 MiB/s
INFO:  47% (282.4 GiB of 600.0 GiB) in 9m 57s, read: 460.3 MiB/s, write: 73.7 MiB/s
INFO:  48% (288.2 GiB of 600.0 GiB) in 10m 11s, read: 418.9 MiB/s, write: 84.3 MiB/s
INFO:  49% (294.6 GiB of 600.0 GiB) in 10m 18s, read: 941.7 MiB/s, write: 51.4 MiB/s
INFO:  51% (307.4 GiB of 600.0 GiB) in 10m 21s, read: 4.3 GiB/s, write: 0 B/s
INFO:  53% (320.1 GiB of 600.0 GiB) in 10m 24s, read: 4.2 GiB/s, write: 0 B/s
INFO:  55% (332.9 GiB of 600.0 GiB) in 10m 27s, read: 4.3 GiB/s, write: 0 B/s
INFO:  57% (345.6 GiB of 600.0 GiB) in 10m 30s, read: 4.2 GiB/s, write: 0 B/s
INFO:  58% (348.2 GiB of 600.0 GiB) in 10m 33s, read: 884.0 MiB/s, write: 14.7 MiB/s
INFO:  59% (354.5 GiB of 600.0 GiB) in 10m 45s, read: 545.7 MiB/s, write: 91.0 MiB/s
INFO:  60% (360.4 GiB of 600.0 GiB) in 10m 53s, read: 746.0 MiB/s, write: 81.0 MiB/s
INFO:  61% (366.3 GiB of 600.0 GiB) in 11m 2s, read: 679.6 MiB/s, write: 92.9 MiB/s
INFO:  62% (372.2 GiB of 600.0 GiB) in 11m 13s, read: 545.1 MiB/s, write: 69.5 MiB/s
INFO:  63% (378.6 GiB of 600.0 GiB) in 11m 23s, read: 652.0 MiB/s, write: 107.2 MiB/s
INFO:  64% (384.0 GiB of 600.0 GiB) in 11m 36s, read: 428.6 MiB/s, write: 65.8 MiB/s
INFO:  65% (390.4 GiB of 600.0 GiB) in 11m 50s, read: 464.9 MiB/s, write: 62.6 MiB/s
INFO:  66% (396.1 GiB of 600.0 GiB) in 12m 4s, read: 417.7 MiB/s, write: 58.0 MiB/s
INFO:  67% (402.3 GiB of 600.0 GiB) in 12m 15s, read: 581.1 MiB/s, write: 70.5 MiB/s
INFO:  68% (408.1 GiB of 600.0 GiB) in 12m 29s, read: 420.6 MiB/s, write: 62.0 MiB/s
INFO:  69% (414.4 GiB of 600.0 GiB) in 12m 46s, read: 384.2 MiB/s, write: 46.8 MiB/s
INFO:  70% (420.2 GiB of 600.0 GiB) in 13m 3s, read: 348.0 MiB/s, write: 50.1 MiB/s
INFO:  71% (426.6 GiB of 600.0 GiB) in 13m 14s, read: 593.1 MiB/s, write: 48.0 MiB/s
INFO:  72% (433.3 GiB of 600.0 GiB) in 13m 18s, read: 1.7 GiB/s, write: 2.0 MiB/s
INFO:  74% (446.0 GiB of 600.0 GiB) in 13m 21s, read: 4.2 GiB/s, write: 0 B/s
INFO:  76% (457.1 GiB of 600.0 GiB) in 13m 24s, read: 3.7 GiB/s, write: 36.0 MiB/s
INFO:  77% (462.2 GiB of 600.0 GiB) in 13m 34s, read: 530.0 MiB/s, write: 47.2 MiB/s
INFO:  79% (475.0 GiB of 600.0 GiB) in 13m 37s, read: 4.3 GiB/s, write: 0 B/s
INFO:  81% (487.6 GiB of 600.0 GiB) in 13m 40s, read: 4.2 GiB/s, write: 0 B/s
INFO:  83% (500.4 GiB of 600.0 GiB) in 13m 43s, read: 4.3 GiB/s, write: 0 B/s
INFO:  84% (504.1 GiB of 600.0 GiB) in 13m 47s, read: 962.0 MiB/s, write: 32.0 MiB/s
INFO:  85% (510.3 GiB of 600.0 GiB) in 13m 57s, read: 632.4 MiB/s, write: 25.6 MiB/s
INFO:  86% (516.5 GiB of 600.0 GiB) in 14m 4s, read: 899.4 MiB/s, write: 1.1 MiB/s
INFO:  87% (522.8 GiB of 600.0 GiB) in 14m 11s, read: 922.9 MiB/s, write: 0 B/s
INFO:  88% (528.1 GiB of 600.0 GiB) in 14m 29s, read: 304.9 MiB/s, write: 20.4 MiB/s
INFO:  89% (534.1 GiB of 600.0 GiB) in 14m 36s, read: 877.7 MiB/s, write: 12.6 MiB/s
INFO:  90% (540.9 GiB of 600.0 GiB) in 14m 42s, read: 1.1 GiB/s, write: 12.0 MiB/s
INFO:  91% (551.5 GiB of 600.0 GiB) in 14m 45s, read: 3.5 GiB/s, write: 0 B/s
INFO:  93% (562.1 GiB of 600.0 GiB) in 14m 48s, read: 3.5 GiB/s, write: 0 B/s
INFO:  95% (572.3 GiB of 600.0 GiB) in 14m 51s, read: 3.4 GiB/s, write: 0 B/s
INFO:  97% (582.9 GiB of 600.0 GiB) in 14m 54s, read: 3.5 GiB/s, write: 0 B/s
INFO:  98% (593.5 GiB of 600.0 GiB) in 14m 57s, read: 3.6 GiB/s, write: 0 B/s
INFO: 100% (600.0 GiB of 600.0 GiB) in 15m, read: 2.2 GiB/s, write: 0 B/s
INFO: Waiting for server to finish backup validation...
INFO: backup is sparse: 279.40 GiB (46%) total zero data
INFO: backup was done incrementally, reused 559.46 GiB (93%)
INFO: transferred 600.00 GiB in 903 seconds (680.4 MiB/s)
INFO: adding notes to backup
INFO: Finished Backup of VM 102 (00:15:25)
INFO: Backup finished at 2023-10-10 00:21:10

 

[xFede46]

Sorry for the second post. Below there is the vm.conf file updated (the one that i posted above hasn't the start order options activated):

agent: 1
bios: ovmf
boot: order=scsi0
cores: 6
cpu: host
efidisk0: VM_Pool1:vm-102-disk-0,efitype=4m,pre-enrolled-keys=1,size=1M
machine: pc-q35-7.2
memory: 49152
meta: creation-qemu=7.2.0,ctime=1687274110
name: vm_name
net0: virtio=1E:29:19:94:17:06,bridge=vmbr0,firewall=1
numa: 0
onboot: 1
ostype: win11
scsi0: VM_Pool1:vm-102-disk-1,cache=writeback,discard=on,iothread=1,size=100G,ssd=1
scsi1: VM_Pool1:vm-102-disk-3,cache=writeback,discard=on,iothread=1,size=500G,ssd=1
scsi2: Backup:0.0.1.scsi-36e84asd34333asd3asd9316,backup=0,cache=writeback,discard=on,iothread=1,size=1T
scsihw: virtio-scsi-single
smbios1: uuid=ac98e8ce-fcfe-492e-a601-6af7a6c67e2d
sockets: 1
startup: order=6
tpmstate0: VM_Pool1:vm-102-disk-2,size=4M,version=v2.0
vga: virtio
vmgenid: eb852b6c-55a7-4e2e-96d6-0af5107ff783

 

[xFede46]

Sorry for the third post but i keep digging in this problem to find every info that count.
I noticed that the node when is rebooted, the VM starts following the order that i set up and than the VM is stopped (not shutdown, but stopped) and in the start event i have this log:

swtpm_setup: Not overwriting existing state file.
TASK OK

I already tried to delete and recreate the TPM state and the problem is still there.

 

[fiona]

From the log, it seems that the VM was started and then resumed normally:

INFO: starting kvm to execute backup task
swtpm_setup: Not overwriting existing state file.
INFO: attaching TPM drive to QEMU for backup
INFO: started backup task '096edce7-4d2e-4f7e-a8b2-18ec623e45c8'
INFO: resuming VM again after 21 seconds

What is the output of qm status 102 --verbose after the backup? Is there a kvm process running for the VM (you can check with ps aux | grep "kvm -id 102" for example)?

Sorry for the third post but i keep digging in this problem to find every info that count.
I noticed that the node when is rebooted, the VM starts following the order that i set up and than the VM is stopped (not shutdown, but stopped) and in the start event i have this log:

swtpm_setup: Not overwriting existing state file.
TASK OK

I already tried to delete and recreate the TPM state and the problem is still there.

That message is normal. It just says that it uses the state file from last time. You don't usually want to remove the state, it's saved state after all