[SOLVED] Repeatedly getting "Garbage collection failed: Server shutdown requested - aborting task" every time

H

hohl

Member
Jun 18, 2020
33
2
13
31
Hello Proxmox community,

I've given the new Proxmox Backup Server a try, but I'm stuck with some issue I couldn't figure my own way around: whenever a garbage collection attempt is made (automated by schedule, or manually triggered) the tasks immediately errs out with the message: "Garbage collection failed: Server shutdown requested - aborting task". This happens for all Datastores and the setup is still quite fresh, so I wouldn't expect any breaking customisation that causes this behaviour. I also tried to just gently reboot the server - hoping that any potential lock file might be deleted this way - but that didn't change anything. I'm on the latest release (ver. 1.0-8) if that matters.

Any ideas what I can try to fix this?

Thanks in advance,
Michael
 
can you try to manually restart the relevant daemons:

systemctl restart proxmox-backup proxmox-backup-proxy

note that this will abort all running tasks
 
Sure, I'm just evaluating PBS for now, so it's no big deal to kill any processes. ;)

Strange, that seems to have fixed it. As mentioned, I already gracefully rebooted the device (by simply running `reboot`), but restarting `proxmox-backup` and `proxmox-backup-proxy` now seems to have made the error message go away.
 
hohl said:
I already gracefully rebooted the device (by simply running `reboot`), but restarting `proxmox-backup` and `proxmox-backup-proxy` now seems to have made the error message go away.
Click to expand...
mhmm... thats indeed weird. do you maybe have logs (syslog/journal) from before the reboot until the service restart?
 
No, but it just happened again: got a mail for a failed garbage collection task at 0:00 UTC tonight. Syslog around this time says something about a restart of some service at that time. Maybe it's just some inconvenient timely overlap of some scheduled auto-restart/reload task?

Code: 
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: Upload size: 63 (100%)
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: Compression: 119%
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: successfully closed dynamic index 1
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: add blob "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-09T23:03:09Z/index.json.blob" (321 bytes, comp: 321)
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: successfully finished backup
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: backup finished successfully
Mar  9 23:03:10 pbs proxmox-backup-proxy[4055]: TASK OK
Mar  9 23:17:01 pbs CRON[14423]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/pve-compute-1/vm/109/2021-03-08T02:31:21Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-07T00:03:09Z"
Mar 10 00:00:00 pbs systemd[1]: Starting Rotate log files...
Mar 10 00:00:00 pbs systemd[1]: Starting Daily man-db regeneration...
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-07T01:03:09Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-07T02:03:10Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-07T03:03:10Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-07T04:03:10Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/PROJECTNAME/2021-03-07T05:03:10Z"
[[ TRUNCATED REPETETIVE STUFF TO MAKE THIS POST FIT INTO THE FORUM ]]
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T00:49:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T00:51:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T00:53:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T00:55:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T00:57:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T06:00:01Z"
Mar 10 00:00:00 pbs rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="507" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Mar 10 00:00:00 pbs systemd[1]: logrotate.service: Succeeded.
Mar 10 00:00:00 pbs systemd[1]: Started Rotate log files.
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T06:02:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T06:04:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T06:06:01Z"
[[ TRUNCATED REPETETIVE STUFF ]]
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T18:50:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T18:52:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T18:54:01Z"
Mar 10 00:00:00 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-09T18:56:01Z"
Mar 10 00:00:01 pbs CRON[14951]: (root) CMD (/etc/letsencrypt/renew.sh )
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: starting new backup on datastore 'PROJECTNAME': "host/uploads/2021-03-10T00:00:01Z"
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: download 'index.json.blob' from previous backup.
Mar 10 00:00:01 pbs systemd[1]: Reloading Proxmox Backup API Proxy Server.
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: register chunks in 'uploads.pxar.didx' from previous backup.
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: download 'uploads.pxar.didx' from previous backup.
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: got reload request (SIGHUP)
Mar 10 00:00:01 pbs systemd[1]: Reloaded Proxmox Backup API Proxy Server.
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: SET SHUTDOWN MODE
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: created new dynamic index 1 ("host/uploads/2021-03-10T00:00:01Z/catalog.pcat1.didx")
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: SET SHUTDOWN MODE
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: daemon reload...
Mar 10 00:00:01 pbs proxmox-backup-proxy[4055]: created new dynamic index 2 ("host/uploads/2021-03-10T00:00:01Z/uploads.pxar.didx")
Mar 10 00:00:01 pbs postfix/pickup[14903]: E0289181922: uid=34 from=<root>
Mar 10 00:00:01 pbs postfix/cleanup[14964]: E0289181922: message-id=<20210310000001.E0289181922@pbs.vie.COMPANYNAME.net>
Mar 10 00:00:02 pbs postfix/qmgr[757]: E0289181922: from=<root@pbs.vie.COMPANYNAME.net>, size=1270, nrcpt=1 (queue active)
Mar 10 00:00:02 pbs postfix/pickup[14903]: 0B15E181AF4: uid=34 from=<root>
Mar 10 00:00:02 pbs postfix/cleanup[14964]: 0B15E181AF4: message-id=<20210310000002.0B15E181AF4@pbs.vie.COMPANYNAME.net>
Mar 10 00:00:02 pbs postfix/qmgr[757]: 0B15E181AF4: from=<root@pbs.vie.COMPANYNAME.net>, size=1273, nrcpt=1 (queue active)
Mar 10 00:00:02 pbs proxmox-backup-proxy[4055]: rotated access log, telling daemons to re-open log file
Mar 10 00:00:02 pbs proxmox-backup-proxy[4055]: re-opening log file
Mar 10 00:00:02 pbs proxmox-backup-api[4040]: re-opening log file
Mar 10 00:00:02 pbs postfix/smtp[14966]: connect to mail.COMPANYNAME.net[XXX.YYY.97.103]:25: Network is unreachable
Mar 10 00:00:02 pbs systemd[1]: man-db.service: Succeeded.
Mar 10 00:00:02 pbs systemd[1]: Started Daily man-db regeneration.
Mar 10 00:00:02 pbs systemd[1]: proxmox-backup-proxy.service: Supervising process 14971 which is not our child. We'll most likely not notice when it exits.
Mar 10 00:00:02 pbs postfix/smtp[14967]: 0B15E181AF4: to=<MYNAME@COMPANYNAME.net>, relay=mail.COMPANYNAME.net[2a0d:f300:0:1239::1]:25, delay=1.1, delays=0.35/0.03/0.16/0.59, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 4A55D41216)
Mar 10 00:00:02 pbs postfix/qmgr[757]: 0B15E181AF4: removed
Mar 10 00:00:02 pbs postfix/smtp[14966]: E0289181922: to=<MYNAME@COMPANYNAME.net>, relay=mail.COMPANYNAME.net[2a0d:f300:0:1239::1]:25, delay=1.2, delays=0.35/0.02/0.18/0.61, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 4E0E54166B)
Mar 10 00:00:02 pbs postfix/qmgr[757]: E0289181922: removed
Mar 10 00:00:02 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/112/2021-03-08T02:22:15Z"
Mar 10 00:00:03 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/108/2021-03-08T02:15:11Z"
Mar 10 00:00:03 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/102/2021-03-08T02:15:09Z"
Mar 10 00:00:03 pbs proxmox-backup-proxy[4055]: daemon shut down...
Mar 10 00:00:03 pbs proxmox-backup-proxy[4055]: server shutting down, waiting for active workers to complete
Mar 10 00:00:03 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/105/2021-03-08T02:15:12Z"
Mar 10 00:00:04 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/111/2021-03-08T02:22:11Z"
Mar 10 00:00:04 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/107/2021-03-08T02:15:18Z"
Mar 10 00:00:04 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/113/2021-03-08T02:22:18Z"
Mar 10 00:00:05 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/101/2021-03-08T02:15:03Z"
Mar 10 00:00:05 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/1107/2021-03-08T02:21:24Z"
Mar 10 00:00:05 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/106/2021-03-08T02:15:15Z"
Mar 10 00:00:06 pbs proxmox-backup-proxy[4055]: removing backup snapshot "/mnt/datastore/storage/OTHERPROJECT/vm/100/2021-03-08T02:15:03Z"
Mar 10 00:00:06 pbs postfix/pickup[14903]: 3276A181B36: uid=34 from=<root>
Mar 10 00:00:06 pbs postfix/cleanup[14964]: 3276A181B36: message-id=<20210310000006.3276A181B36@pbs.vie.COMPANYNAME.net>
Mar 10 00:00:06 pbs postfix/qmgr[757]: 3276A181B36: from=<root@pbs.vie.COMPANYNAME.net>, size=1249, nrcpt=1 (queue active)
Mar 10 00:00:06 pbs postfix/smtp[14967]: connect to mail.COMPANYNAME.net[XXX.YYY.97.103]:25: Network is unreachable
Mar 10 00:00:06 pbs postfix/smtp[14967]: 3276A181B36: to=<MYNAME@COMPANYNAME.net>, relay=mail.COMPANYNAME.net[2a0d:f300:0:1239::1]:25, delay=0.58, delays=0/0/0.08/0.49, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 4A90F41216)
Mar 10 00:00:06 pbs postfix/qmgr[757]: 3276A181B36: removed
Mar 10 00:01:01 pbs proxmox-backup-proxy[14971]: GET /api2/json/backup?backup-id=uploads&backup-time=1615334461&backup-type=host&benchmark=false&debug=false&store=PROJECTNAME: 400 Bad Request: [client [2a0d:f300:0:124e::1]:56164] unable to acquire lock on backup group directory "/mnt/datastore/storage/PROJECTNAME/host/uploads" - another backup is already running
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Upload statistics for 'uploads.pxar.didx'
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: UUID: c8e16d15a92c4498956a86c77d308795
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Checksum: 93a74e3fd8af8ff6a04472159bdbd3976b6b6e89837a0fc5d7965dfc0d23354a
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Size: 4635191529
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Chunk count: 870
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Upload size: 23582162 (0%)
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Duplicates: 866+0 (99%)
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Compression: 85%
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: successfully closed dynamic index 2
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Upload statistics for 'catalog.pcat1.didx'
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: UUID: 82797710d5bc4cddbab1b4b980f1814a
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Checksum: e3328cfc3deda66ddbc9abdeed58de35d01807333477f859e6ee673e4151f476
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Size: 2832489
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Chunk count: 9
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Upload size: 2832489 (100%)
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Duplicates: 0+8 (88%)
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: Compression: 17%
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: successfully closed dynamic index 1
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: add blob "/mnt/datastore/storage/PROJECTNAME/host/uploads/2021-03-10T00:00:01Z/index.json.blob" (317 bytes, comp: 317)
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: successfully finished backup
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: backup finished successfully
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: TASK OK
Mar 10 00:01:22 pbs proxmox-backup-proxy[4055]: done - exit server
Mar 10 00:02:01 pbs proxmox-backup-proxy[14971]: starting new backup on datastore 'PROJECTNAME': "host/uploads/2021-03-10T00:02:01Z"
Mar 10 00:02:01 pbs proxmox-backup-proxy[14971]: download 'index.json.blob' from previous backup.
Mar 10 00:02:01 pbs proxmox-backup-proxy[14971]: register chunks in 'uploads.pxar.didx' from previous backup.
Mar 10 00:02:01 pbs proxmox-backup-proxy[14971]: download 'uploads.pxar.didx' from previous backup.
Mar 10 00:02:01 pbs proxmox-backup-proxy[14971]: created new dynamic index 1 ("host/uploads/2021-03-10T00:02:01Z/catalog.pcat1.didx")
Mar 10 00:02:01 pbs proxmox-backup-proxy[14971]: created new dynamic index 2 ("host/uploads/2021-03-10T00:02:01Z/uploads.pxar.didx")
Mar 10 00:03:01 pbs proxmox-backup-proxy[14971]: GET /api2/json/backup?backup-id=uploads&backup-time=1615334581&backup-type=host&benchmark=false&debug=false&store=PROJECTNAME: 400 Bad Request: [client [2a0d:f300:0:124e::1]:56168] unable to acquire lock on backup group directory "/mnt/datastore/storage/PROJECTNAME/host/uploads" - another backup is already running
Mar 10 00:03:10 pbs proxmox-backup-proxy[14971]: starting new backup on datastore 'PROJECTNAME': "host/PROJECTNAME/2021-03-10T00:03:10Z"
Mar 10 00:03:10 pbs proxmox-backup-proxy[14971]: download 'index.json.blob' from previous backup.
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: register chunks in 'postgres.pxar.didx' from previous backup.
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: download 'postgres.pxar.didx' from previous backup.
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: created new dynamic index 1 ("host/PROJECTNAME/2021-03-10T00:03:10Z/catalog.pcat1.didx")
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: created new dynamic index 2 ("host/PROJECTNAME/2021-03-10T00:03:10Z/postgres.pxar.didx")
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Upload statistics for 'postgres.pxar.didx'
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: UUID: 4597e19be11547c48b92b202bf97ce34
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Checksum: 9bb935ca18997c478be341738ef59bcfbbea2678b83bbcb6d9621128a0212ffe
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Size: 10946217
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Chunk count: 3
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Upload size: 10946217 (100%)
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Compression: 100%
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: successfully closed dynamic index 2
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Upload statistics for 'catalog.pcat1.didx'
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: UUID: 14cb1008c2654ef79f1d3f932d334ddd
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Checksum: e5ee6155c67b970f79c832f378990e0b8f832b3733937f1493c5ddbca3168782
Mar 10 00:03:11 pbs proxmox-backup-proxy[14971]: Size: 63
 
Last edited:
hohl said:
Mar 10 00:00:01 pbs CRON[14951]: (root) CMD (/etc/letsencrypt/renew.sh )
[...]
Mar 10 00:00:01 pbs systemd[1]: Reloading Proxmox Backup API Proxy Server.
Click to expand...

probably the letsencrypt script that reloads the proxy? garbage collects are the only type of tasks that get aborted on a proxy reload
 
  • Like
Reactions: hohl
dcsapak said:
probably the letsencrypt script that reloads the proxy? garbage collects are the only type of tasks that get aborted on a proxy reload
Click to expand...
Oh... yeah, that could be it. Very likely actually as it has to restart `proxmox-backup-proxy` to apply the SSL certificates. (Or, maybe I just need to adopt the renewal script to only reload if the certificate actually got renewed.) I just moved LetsEncrypt to 0:50Z, lets see if that fixes the issue. Sorry, for wasting your time in that case.
 
Last edited:
actually a reload will also cancel the garbage collection... i'll try to find out if that's necessary or if we could change the garbage collect to continue to run
 
also, if you want you can open a bug request here: https://bugzilla.proxmox.com
we probably want to continue the garbage collection on the newly started process even if we abort it on the old one on a reload
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom