[SOLVED] pvescheduler only runs on restart

[robetus]

Backup Server 2.4-1
Virtual Environment 7.4-3

My scheduled backups will not run unless I run the following on my proxmox server:

systemctl stop pvescheduler
systemctl start pvescheduler

After I do this the scheduled backup triggers and runs but it will not run daily as it is set to do. I know the servers are seeing the schedule because as soon as restart pvescheduler the backup runs. I do have "Repeat Missed" checked. The retention is set to to Keep Last 2 and nothing else.

What can I check to get this backup to run every day? There is a malfunction here that I need to fix.

 

[dcsapak]

when it's in that state that it should have run, but didn't can you post the content of the file

/var/lib/pve-manager/jobs/vzdump-<ID>.json ?

also the journal from a time where it should have run would be interesting

 

[robetus]

This is the json file:

{"upid":"UPID:proxmox:001EC557:0ABAE3BB:64574277:vzdump::root@pam:","state":"started","config":{"enabled":1,"schedule":"21:00"}}

I'm not sure what you mean by the journal, can you be more specific on how I can give you the output of journal?

 

[dcsapak]

you can get the output of the journal/syslog with the 'journalctl' command
(see 'man journalctl' for details)

you can e.g. limit the timeframe with the '--since' and '--until' parameters

This is the json file:

{"upid":"UPID:proxmox:001EC557:0ABAE3BB:64574277:vzdump::root@pam:","state":"started","config":{"enabled":1,"schedule":"21:00"}}

was the mentioned task running at that time (at which time did you execute that command ?)

the upid shows that the task was started at 'Sun 07 May 2023 08:17:27 AM CEST'

 

[robetus]

That's correct and it did not run on May 8, it refuses to run every day at 9pm which it is scheduled to do. 08:17:27 AM CEST is the time that I manually clicked the run button inside proxmox, the backup will not run otherwise.

Here is the journal output:

root@proxmox:~# journalctl --unit=pvescheduler.service
-- Journal begins at Fri 2022-12-09 00:58:46 AKST, ends at Mon 2023-05-08 23:33:23 AKDT. --
Dec 09 00:59:26 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
Dec 09 00:59:26 proxmox.example.com pvescheduler[63670]: starting server
Dec 09 00:59:26 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
-- Boot 590d4b2269464b0ca50761672c6 --
Dec 12 15:38:22 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
Dec 12 15:38:23 proxmox.example.com pvescheduler[116007]: starting server
Dec 12 15:38:23 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
Dec 15 10:41:04 proxmox.example.com systemd[1]: Stopping Proxmox VE scheduler...
Dec 15 10:41:05 proxmox.example.com pvescheduler[116007]: received signal TERM
Dec 15 10:41:05 proxmox.example.com pvescheduler[116007]: got shutdown request, signal running jobs to stop
Dec 15 10:41:05 proxmox.example.com pvescheduler[116007]: server stopped
Dec 15 10:41:06 proxmox.example.com systemd[1]: pvescheduler.service: Succeeded.
Dec 15 10:41:06 proxmox.example.com systemd[1]: Stopped Proxmox VE scheduler.
Dec 15 10:41:06 proxmox.example.com systemd[1]: pvescheduler.service: Consumed 53.578s CPU time.
-- Boot 8d19ccbefa604e9c9a20832d5c45 --
Dec 15 11:00:07 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
Dec 15 11:00:08 proxmox.example.com pvescheduler[98698]: starting server
Dec 15 11:00:08 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
-- Boot f8f3aceba5c24dd09a824abf5b64 --
Dec 24 00:20:59 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
Dec 24 00:21:00 proxmox.example.com pvescheduler[138478]: starting server
Dec 24 00:21:00 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
Dec 24 00:52:20 proxmox.example.com systemd[1]: Stopping Proxmox VE scheduler...
Dec 24 00:52:21 proxmox.example.com pvescheduler[138478]: received signal TERM
Dec 24 00:52:21 proxmox.example.com pvescheduler[138478]: got shutdown request, signal running jobs to stop
Dec 24 00:52:21 proxmox.example.com pvescheduler[138478]: server stopped
Dec 24 00:52:22 proxmox.example.com systemd[1]: pvescheduler.service: Succeeded.
Dec 24 00:52:22 proxmox.example.com systemd[1]: Stopped Proxmox VE scheduler.
Dec 24 00:52:22 proxmox.example.com systemd[1]: pvescheduler.service: Consumed 1.925s CPU time.
-- Boot 57ecc06d9be1412a911ce1872da --
Dec 24 01:46:19 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
Dec 24 01:46:20 proxmox.example.com pvescheduler[97393]: starting server
Dec 24 01:46:20 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
Jan 24 17:04:44 proxmox.example.com systemd[1]: Stopping Proxmox VE scheduler...
Jan 24 17:04:45 proxmox.example.com pvescheduler[97393]: received signal TERM
Jan 24 17:04:45 proxmox.example.com pvescheduler[97393]: got shutdown request, signal running jobs to stop
Jan 24 17:04:45 proxmox.example.com pvescheduler[97393]: server stopped
Jan 24 17:04:46 proxmox.example.com systemd[1]: pvescheduler.service: Succeeded.
Jan 24 17:04:46 proxmox.example.com systemd[1]: Stopped Proxmox VE scheduler.
Jan 24 17:04:46 proxmox.example.com systemd[1]: pvescheduler.service: Consumed 9min 40.285s CPU time.
-- Boot 4d6928397340dfadsfb43a3e1a --
Jan 24 17:22:43 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
Jan 24 17:22:44 proxmox.example.com pvescheduler[178717]: starting server
Jan 24 17:22:44 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
Feb 02 21:00:01 proxmox.example.com pvescheduler[3839430]: <root@pam> starting task UPID
Feb 02 21:00:01 proxmox.example.com pvescheduler[3839431]: INFO: starting new backup job: vzdump --storage proxmoxbak.example.c>
Feb 02 21:00:01 proxmox.example.com pvescheduler[3839431]: INFO: Starting Backup of VM 101 (lxc)
Feb 02 21:00:07 proxmox.example.com pvescheduler[3839431]: INFO: Finished Backup of VM 101 (00:00:06)
Feb 02 21:00:07 proxmox.example.com pvescheduler[3839431]: INFO: Starting Backup of VM 102 (qemu)

 

[dcsapak]

Here is the journal output:

seems it's cut off sometime in february, would be better to limit it to the last few days (like i mentioned with the since/until parameters)

That's correct and it did not run on May 8, it refuses to run every day at 9pm which it is scheduled to do. 08:17:27 AM CEST is the time that I manually clicked the run button inside proxmox, the backup will not run otherwise.

ok but it seems that from the schedulers perspective the task is still running (or there is some other problem that is hopefully logged in the journal)
the first thing we do is trying to check if the task already stopped and then updating the statefile
so either the process is still running (check with e.g. ps ax), it's detecting the task as running wrongly or updating/parsing the task state fails for some reason

 

[robetus]

root@proxmox:~# journalctl --unit=pvescheduler.service --since 2023-05-05
-- Journal begins at Fri 2022-12-09 00:58:46 AKST, ends at Tue 2023-05-09 01:17:01 AKDT. --
May 06 22:16:47 proxmox.example.com systemd[1]: Stopping Proxmox VE scheduler...
May 06 22:16:48 proxmox.example.com pvescheduler[1356427]: received signal TERM
May 06 22:16:48 proxmox.example.com pvescheduler[1356427]: got shutdown request, signal running jobs to stop
May 06 22:16:51 proxmox.example.com pvescheduler[1356427]: server stopped
May 06 22:16:52 proxmox.example.com systemd[1]: pvescheduler.service: Succeeded.
May 06 22:16:52 proxmox.example.com systemd[1]: Stopped Proxmox VE scheduler.
May 06 22:16:52 proxmox.example.com systemd[1]: pvescheduler.service: Consumed 6min 52.606s CPU time.
May 06 22:17:26 proxmox.example.com systemd[1]: Starting Proxmox VE scheduler...
May 06 22:17:27 proxmox.example.com pvescheduler[2016387]: starting server
May 06 22:17:27 proxmox.example.com systemd[1]: Started Proxmox VE scheduler.
May 06 22:17:27 proxmox.example.com pvescheduler[2016389]: <root@pam> starting task UPID:proxmox:001EC486:0ABAE2DB:64574277:vzdump::root@pam:
May 06 22:17:27 proxmox.example.com pvescheduler[2016390]: INFO: starting new backup job: vzdump 102 104 105 108 109 112 113 114 115 116 118 119 120 --quiet 1 --mailnotification failure --storage >
May 06 22:17:27 proxmox.example.com pvescheduler[2016390]: INFO: Starting Backup of VM 102 (qemu)

This is all I get from the logs even if I put the date back a few more days. The --until set to today outputs the same. I think this is the last time it ran by itself without me manually running it.

I found this thread, looks to be the same issue: https://forum.proxmox.com/threads/backups-not-running-after-upgrade-to-7-4.124784/

I just upgraded proxmox maybe something will change.

The backup started right away when I ran: systemctl restart pvescheduler

 

[robetus]

The update to 7.4-3 has fixed this issue.