verify fails with "TASK ERROR: Server shutdown requested - aborting task"

[IZT]

Hi all, in the last 60 days 10 verify tasks failed, with "TASK ERROR: Server shutdown requested - aborting task". I compared timestamps and found that in 9/10 cases this was due to systemd reloading proxmox-backup-proxy.service, but in one case it seems a backup job finished and the server exited:

Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Upload statistics for 'drive-sata1.img.fidx'
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: UUID: 28acc0dc83fe4014839e5475fcdfea28
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Checksum: 1d6e1f6b240aeedbbc84caa59d1f6d26a24fea8134bc554abfc34ada71eee590
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Size: 1099511627776
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Chunk count: 262144
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Upload size: 64336429056 (5%)
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Duplicates: 246805+13 (94%)
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Compression: 30%
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: successfully closed fixed index 2
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Upload statistics for 'drive-sata0.img.fidx'
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: UUID: 7a3d17369828493d9af88ead990fc593
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Checksum: 6cef00e567830a8e76e1345068e64bd506731d1d87bc96729a54635630e38073
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Size: 4280287232
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Chunk count: 1021
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Upload size: 25165824 (0%)
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Duplicates: 1015+1 (99%)
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: Compression: 4%
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: successfully closed fixed index 1
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: add blob "/backup/proxmox-backup-server/vm/114/2024-07-06T04:46:36Z/index.json.blob" (382 bytes, comp: 382)
Jul 06 08:29:06 izt-server2 proxmox-backup-proxy[3095314]: syncing filesystem
Jul 06 08:29:09 izt-server2 proxmox-backup-proxy[3095314]: successfully finished backup
Jul 06 08:29:09 izt-server2 proxmox-backup-proxy[3095314]: backup finished successfully
Jul 06 08:29:09 izt-server2 proxmox-backup-proxy[3095314]: TASK OK
Jul 06 08:29:09 izt-server2 proxmox-backup-proxy[3095314]: done - exit server

Is there anything we can do to prevent this from happening (so often)?

Thanks for hints, Gregor

 

[ggoller]

Hi!
well it could be that the process panics or crashes for some reason... Could you post the syslog of when the crash happens?

 

[IZT]

Thanks for your question which helped me digging deeper in the log files. I now realize, that 9/10 cases were related to systemd reloading proxmox-backup.service due to an unattended upgrade of package proxmox-backup-server. Don't know if that could be handled less drastic (probably difficult to wait for running tasks, since some take days...).



So this is the latest log of such failed backup, the only one not happening, while systemd is reloading proxmox-backup.service

2024-07-06T08:29:09+02:00: Automatically verifying newly added snapshot
2024-07-06T08:29:09+02:00: verify pbs2:vm/114/2024-07-06T04:46:36Z
2024-07-06T08:29:09+02:00:   check qemu-server.conf.blob
2024-07-06T08:29:09+02:00: TASK ERROR: Server shutdown requested - aborting task

And this is the corresponding time interval from syslog:

2024-07-06T08:25:02.545815+02:00 izt-server2 systemd[1]: session-45766.scope: Deactivated successfully.
2024-07-06T08:29:06.028200+02:00 izt-server2 proxmox-backup-proxy[3095314]: Upload statistics for 'drive-sata1.img.fidx'
2024-07-06T08:29:06.028661+02:00 izt-server2 proxmox-backup-proxy[3095314]: UUID: 28acc0dc83fe4014839e5475fcdfea28
2024-07-06T08:29:06.028694+02:00 izt-server2 proxmox-backup-proxy[3095314]: Checksum: 1d6e1f6b240aeedbbc84caa59d1f6d26a24fea8134bc554abfc34ada71eee590
2024-07-06T08:29:06.028720+02:00 izt-server2 proxmox-backup-proxy[3095314]: Size: 1099511627776
2024-07-06T08:29:06.028748+02:00 izt-server2 proxmox-backup-proxy[3095314]: Chunk count: 262144
2024-07-06T08:29:06.028769+02:00 izt-server2 proxmox-backup-proxy[3095314]: Upload size: 64336429056 (5%)
2024-07-06T08:29:06.028806+02:00 izt-server2 proxmox-backup-proxy[3095314]: Duplicates: 246805+13 (94%)
2024-07-06T08:29:06.028834+02:00 izt-server2 proxmox-backup-proxy[3095314]: Compression: 30%
2024-07-06T08:29:06.028879+02:00 izt-server2 proxmox-backup-proxy[3095314]: successfully closed fixed index 2
2024-07-06T08:29:06.029962+02:00 izt-server2 proxmox-backup-proxy[3095314]: Upload statistics for 'drive-sata0.img.fidx'
2024-07-06T08:29:06.030050+02:00 izt-server2 proxmox-backup-proxy[3095314]: UUID: 7a3d17369828493d9af88ead990fc593
2024-07-06T08:29:06.030096+02:00 izt-server2 proxmox-backup-proxy[3095314]: Checksum: 6cef00e567830a8e76e1345068e64bd506731d1d87bc96729a54635630e38073
2024-07-06T08:29:06.030133+02:00 izt-server2 proxmox-backup-proxy[3095314]: Size: 4280287232
2024-07-06T08:29:06.030158+02:00 izt-server2 proxmox-backup-proxy[3095314]: Chunk count: 1021
2024-07-06T08:29:06.030190+02:00 izt-server2 proxmox-backup-proxy[3095314]: Upload size: 25165824 (0%)
2024-07-06T08:29:06.030214+02:00 izt-server2 proxmox-backup-proxy[3095314]: Duplicates: 1015+1 (99%)
2024-07-06T08:29:06.030237+02:00 izt-server2 proxmox-backup-proxy[3095314]: Compression: 4%
2024-07-06T08:29:06.030266+02:00 izt-server2 proxmox-backup-proxy[3095314]: successfully closed fixed index 1
2024-07-06T08:29:06.030879+02:00 izt-server2 proxmox-backup-proxy[3095314]: add blob "/backup/proxmox-backup-server/vm/114/2024-07-06T04:46:36Z/index.json.blob" (382 bytes, comp: 382)
2024-07-06T08:29:06.031732+02:00 izt-server2 proxmox-backup-proxy[3095314]: syncing filesystem
2024-07-06T08:29:09.001894+02:00 izt-server2 proxmox-backup-proxy[3095314]: successfully finished backup
2024-07-06T08:29:09.002308+02:00 izt-server2 proxmox-backup-proxy[3095314]: backup finished successfully
2024-07-06T08:29:09.006932+02:00 izt-server2 proxmox-backup-proxy[3095314]: TASK OK
2024-07-06T08:29:09.025290+02:00 izt-server2 proxmox-backup-proxy[3095314]: done - exit server
2024-07-06T08:29:10.020571+02:00 izt-server2 kernel: [4630713.983929] tap114i0: left allmulticast mode
2024-07-06T08:29:10.020589+02:00 izt-server2 kernel: [4630713.984365] vmbr0: port 3(tap114i0) entered disabled state
2024-07-06T08:29:10.073422+02:00 izt-server2 qmeventd[1498]: read: Connection reset by peer
2024-07-06T08:29:10.235244+02:00 izt-server2 systemd[1]: 114.scope: Deactivated successfully.
2024-07-06T08:29:10.235394+02:00 izt-server2 systemd[1]: 114.scope: Consumed 1h 1min 19.598s CPU time.
2024-07-06T08:29:10.996816+02:00 izt-server2 qmeventd[1186381]: Starting cleanup for 114
2024-07-06T08:29:10.996914+02:00 izt-server2 qmeventd[1186381]: trying to acquire lock...
2024-07-06T08:29:11.075805+02:00 izt-server2 qmeventd[1186381]:  OK
2024-07-06T08:29:11.077188+02:00 izt-server2 qmeventd[1186381]: Finished cleanup for 114

I don't see, why the server exits, but this seems to be the reason, why the verify fails.


For the record, the rest is an example case where the verify failed, because of an unattended upgrade of package proxmox-backup-server:

And this would be the second to latest failure, this and the other ones happened while systemd is reloading the daemon:

2024-07-06T06:46:34+02:00: Automatically verifying newly added snapshot
2024-07-06T06:46:34+02:00: verify pbs2:vm/113/2024-07-06T03:00:03Z
2024-07-06T06:46:34+02:00:   check qemu-server.conf.blob
2024-07-06T06:46:34+02:00:   check drive-scsi0.img.fidx
2024-07-06T06:52:22+02:00: TASK ERROR: Server shutdown requested - aborting task

And this the corresponding syslog:

2024-07-06T06:52:10.513384+02:00 izt-server2 systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities...
2024-07-06T06:52:20.359297+02:00 izt-server2 systemd[1]: Reloading.
2024-07-06T06:52:21.059369+02:00 izt-server2 systemd[1]: proxmox-backup-daily-update.timer: Deactivated successfully.
2024-07-06T06:52:21.059584+02:00 izt-server2 systemd[1]: Stopped proxmox-backup-daily-update.timer - Daily Proxmox Backup Server update and maintenance activities.
2024-07-06T06:52:21.059704+02:00 izt-server2 systemd[1]: Stopping proxmox-backup-daily-update.timer - Daily Proxmox Backup Server update and maintenance activities...
2024-07-06T06:52:21.059805+02:00 izt-server2 systemd[1]: Started proxmox-backup-daily-update.timer - Daily Proxmox Backup Server update and maintenance activities.
2024-07-06T06:52:21.714379+02:00 izt-server2 systemd[1]: Reloading.
2024-07-06T06:52:22.349090+02:00 izt-server2 systemd[1]: Reloading proxmox-backup.service - Proxmox Backup API Server...
2024-07-06T06:52:22.353301+02:00 izt-server2 systemd[1]: Reloaded proxmox-backup.service - Proxmox Backup API Server.
2024-07-06T06:52:22.354955+02:00 izt-server2 systemd[1]: Reloading proxmox-backup-proxy.service - Proxmox Backup API Proxy Server...
2024-07-06T06:52:22.356893+02:00 izt-server2 systemd[1]: Reloaded proxmox-backup-proxy.service - Proxmox Backup API Proxy Server.
2024-07-06T06:52:22.358932+02:00 izt-server2 proxmox-backup-proxy[3095314]: got reload request (SIGHUP)
2024-07-06T06:52:22.359049+02:00 izt-server2 proxmox-backup-proxy[3095314]: request_shutdown
2024-07-06T06:52:22.362334+02:00 izt-server2 proxmox-backup-proxy[3095314]: daemon reload...
2024-07-06T06:52:22.363271+02:00 izt-server2 proxmox-backup-api[3095312]: got reload request (SIGHUP)
2024-07-06T06:52:22.363351+02:00 izt-server2 proxmox-backup-api[3095312]: request_shutdown
2024-07-06T06:52:22.367137+02:00 izt-server2 proxmox-backup-api[3095312]: daemon reload...
2024-07-06T06:52:22.388813+02:00 izt-server2 proxmox-backup-api[3095312]: daemon shut down.
2024-07-06T06:52:22.388909+02:00 izt-server2 proxmox-backup-api[3095312]: server shutting down, waiting for active workers to complete
2024-07-06T06:52:22.388988+02:00 izt-server2 proxmox-backup-api[3095312]: done - exit server
2024-07-06T06:52:22.405842+02:00 izt-server2 proxmox-backup-api[1107915]: service is ready
2024-07-06T06:52:22.415769+02:00 izt-server2 systemd[1]: proxmox-backup-proxy.service: Supervising process 1107959 which is not our child. We'll most likely not notice when it exits.
2024-07-06T06:52:22.416218+02:00 izt-server2 proxmox-backup-proxy[3095314]: daemon shut down.
2024-07-06T06:52:22.416407+02:00 izt-server2 proxmox-backup-proxy[3095314]: server shutting down, waiting for active workers to complete
2024-07-06T06:52:22.441461+02:00 izt-server2 proxmox-backup-proxy[1107959]: service is ready
2024-07-06T06:52:22.447960+02:00 izt-server2 proxmox-backup-proxy[1107959]: applied rrd journal (2774 entries in 0.012 seconds)
2024-07-06T06:52:22.448058+02:00 izt-server2 proxmox-backup-proxy[1107959]: write rrd data back to disk
2024-07-06T06:52:22.454517+02:00 izt-server2 proxmox-backup-proxy[1107959]: starting rrd data sync
2024-07-06T06:52:22.459969+02:00 izt-server2 proxmox-backup-proxy[1107959]: rrd journal successfully committed (25 files in 0.012 seconds)
2024-07-06T06:52:33.900079+02:00 izt-server2 postfix/pickup[960686]: DB8F73C0067: uid=0 from=<root>

And this is from the corresponding unattended-backup.log:

2024-07-06 06:52:11,184 INFO Skript für automatische Systemaktualisierung wird gestartet
2024-07-06 06:52:11,185 INFO Erlaubte Ursprünge sind: origin=Debian,codename=bookworm,label=Debian, origin=Debian,codename=bookworm,label=Debian-Security, origin=Debian,codename=bookworm-secu
rity,label=Debian-Security, origin=Debian,codename=bookworm,label=Debian, origin=Debian,codename=bookworm,label=Debian-Security, origin=Debian,codename=bookworm-security,label=Debian-Security
, origin=Proxmox,codename=bookworm,label=Proxmox Debian Repository, origin=Proxmox,codename=bookworm,label=Proxmox Backup System Debian Repository
2024-07-06 06:52:11,185 INFO Anfangsnegativliste: 
2024-07-06 06:52:11,185 INFO Initial whitelist (not strict): 
2024-07-06 06:52:15,642 INFO Pakete, welche aktualisiert werden: krb5-locales libgssapi-krb5-2 libk5crypto3 libkrb5-3 libkrb5support0 proxmox-backup-client proxmox-backup-docs proxmox-backup-
file-restore proxmox-backup-server pve-qemu-kvm
2024-07-06 06:52:15,643 INFO dpkg-Protokoll wird nach /var/log/unattended-upgrades/unattended-upgrades-dpkg.log geschrieben
2024-07-06 06:52:33,234 INFO Alle Systemaktualisierungen installiert

Regards, Gregor

 

[ggoller]

You could just disable the `apt-daily-upgrade.service` service and upgrade manually from time to time.

 

[IZT]

Thanks, but I rather accept that some backups fail. Now at least I know why in most of the last cases.