HA Shutdown nach dem Backup einer abgeschalteten VM?

[Raudi]

Hallo,

ich beobachte hier bei einer VM fast regelmäßig und bei anderen VM's ab und zu nach dem Backup mit dem aktuellen Proxmox Backup Server die folgende Meldung in den Taks einer abgeschalteten VM:

VM 512 - Shutdown:
task started by HA resource agent
TASK ERROR: VM is locked (backup)



Die Meldung erscheint auch nicht jeden Tag, das Backup ist aber erfolgreich:



Als wenn da HA "denkt", dass die VM beim Backup eingeschaltet ist und die dann abschalten möchte?

Kann ich da in den HA-Logs oder an anderer Stelle noch nach Hinweisen suchen? Was könnte dieses Verhalten verursachen?

Die VM's liegen auf einer NetApp via NFS angebunden im qcow2 Format und beim Backup ist die Methode Snapshot ausgewählt.

PVE ist die Version 9.1.4.

Viele Grüße
Stefan

 

[fstrankowski]

Meistens liegt es an nicht zuzverlässigen Netzwerk-Storages (wie bei dir die NetApp). Hier wird es zu Problemen & Abbrüchen bei den Backups kommen. Bitte probier deine Backups einmal durch, nur weil Sie da aufgelistet sind heißt es ja nicht, dass diese auch funktionieren.

Gib doch mal bitte Logs um die Uhrzeit herum aus, was da so passiert bei den verschiedenen Diensten. Geh mal Journal durch und schau mal +/- 2 Minuten um das Backup herum was da los ist.

 

[Raudi]

Hmm.. Komisch. Ist das normal, dass zum Backup eine VM kurz eingeschaltet wird?

Feb 08 04:19:56 pve02 pvescheduler[1163243]: INFO: Starting Backup of VM 512 (qemu)
Feb 08 04:19:56 pve02 systemd[1]: Started 512.scope.
Feb 08 04:19:57 pve02 kernel: tap512i0: entered promiscuous mode
Feb 08 04:19:57 pve02 kernel: vmbr1: port 6(tap512i0) entered blocking state
Feb 08 04:19:57 pve02 kernel: vmbr1: port 6(tap512i0) entered disabled state
Feb 08 04:19:57 pve02 kernel: tap512i0: entered allmulticast mode
Feb 08 04:19:57 pve02 kernel: vmbr1: port 6(tap512i0) entered blocking state
Feb 08 04:19:57 pve02 kernel: vmbr1: port 6(tap512i0) entered forwarding state
Feb 08 04:19:57 pve02 pvescheduler[1163243]: VM 512 started with PID 1172693.
Feb 08 04:20:05 pve02 pve-ha-lrm[1172763]: VM 512 qmp command failed - VM 512 qmp command 'query-status' failed - got timeout
Feb 08 04:20:05 pve02 pve-ha-lrm[1172763]: VM 512 qmp command 'query-status' failed - got timeout
Feb 08 04:20:05 pve02 pve-ha-lrm[1172763]: stopping service vm:512
Feb 08 04:20:10 pve02 pve-ha-lrm[1172763]: VM 512 qmp command failed - VM 512 qmp command 'query-status' failed - unable to connect to VM 512 qmp socket - timeout after 51 re>
Feb 08 04:20:10 pve02 pve-ha-lrm[1172763]: VM 512 qmp command 'query-status' failed - unable to connect to VM 512 qmp socket - timeout after 51 retries
Feb 08 04:20:10 pve02 pve-ha-lrm[1172829]: shutdown VM 512: UPID:pve02:0011E55D:07880DEB:698800EA:qmshutdown:512:root@pam:
Feb 08 04:20:10 pve02 pve-ha-lrm[1172763]: <root@pam> starting task UPID:pve02:0011E55D:07880DEB:698800EA:qmshutdown:512:root@pam:
Feb 08 04:20:10 pve02 pve-ha-lrm[1172829]: VM is locked (backup)
Feb 08 04:20:10 pve02 pve-ha-lrm[1172763]: <root@pam> end task UPID:pve02:0011E55D:07880DEB:698800EA:qmshutdown:512:root@pam: VM is locked (backup)
Feb 08 04:20:12 pve02 pve-ha-lrm[1172763]: service status vm:512 stopped
Feb 08 04:20:54 pve02 pmxcfs[1654]: [dcdb] notice: data verification successful
Feb 08 04:22:24 pve02 kernel: tap512i0: left allmulticast mode
Feb 08 04:22:24 pve02 kernel: vmbr1: port 6(tap512i0) entered disabled state
Feb 08 04:22:24 pve02 qmeventd[1321]: read: Connection reset by peer
Feb 08 04:22:24 pve02 systemd[1]: 512.scope: Deactivated successfully.
Feb 08 04:22:24 pve02 systemd[1]: 512.scope: Consumed 2min 37.417s CPU time, 118.4M memory peak.
Feb 08 04:22:25 pve02 pvescheduler[1163243]: INFO: Finished Backup of VM 512 (00:02:29)

Und kann es sein, dass HA vom einschalten nichts mitbekommt, erkennt, dass die aktiv ist und die deshalb dann ausschalten möchte?

Denn sonst würde das einschalten ja auch im Task-Log der VM stehen.

Aber das einschalten scheint normal zu sein, hier ein anderer Server:

Feb 08 03:32:24 pve01 pvescheduler[2568221]: INFO: Starting Backup of VM 103 (qemu)
Feb 08 03:32:24 pve01 nfsidmap[2569644]: nss_getpwnam: name 'root@defaultv4iddomain.com' does not map into domain 'raudonis.local'
Feb 08 03:32:24 pve01 nfsidmap[2569645]: nss_name_to_gid: name 'root@defaultv4iddomain.com' does not map into domain 'raudonis.local'
Feb 08 03:32:24 pve01 systemd[1]: Started 103.scope.
Feb 08 03:32:25 pve01 kernel: tap103i0: entered promiscuous mode
Feb 08 03:32:25 pve01 kernel: vmbr1: port 10(tap103i0) entered blocking state
Feb 08 03:32:25 pve01 kernel: vmbr1: port 10(tap103i0) entered disabled state
Feb 08 03:32:25 pve01 kernel: tap103i0: entered allmulticast mode
Feb 08 03:32:25 pve01 kernel: vmbr1: port 10(tap103i0) entered blocking state
Feb 08 03:32:25 pve01 kernel: vmbr1: port 10(tap103i0) entered forwarding state
Feb 08 03:32:25 pve01 pvescheduler[2568221]: VM 103 started with PID 2569665.
Feb 08 03:33:59 pve01 kernel: tap103i0: left allmulticast mode
Feb 08 03:33:59 pve01 kernel: vmbr1: port 10(tap103i0) entered disabled state
Feb 08 03:33:59 pve01 qmeventd[1313]: read: Connection reset by peer
Feb 08 03:33:59 pve01 systemd[1]: 103.scope: Deactivated successfully.
Feb 08 03:33:59 pve01 systemd[1]: 103.scope: Consumed 1min 46.524s CPU time, 118.5M memory peak.
Feb 08 03:34:00 pve01 pvescheduler[2568221]: INFO: Finished Backup of VM 103 (00:01:36)

Aber hier war das Backup schneller, evtl. hat hier das HA nicht mitbekommen, dass die VM kurz an war...

Sieht für mich nach einem Fehler aus, dass HA versucht eine VM, die sich wegen des Backups im "prelaunch" Status befindet, versucht wieder abzuschalten.

Denn so sieht eine abgeschaltete VM während des Backups aus: