Daily wake-up routine not working after update
-
@altitudehack If you need to see more:
tail -1000f /var/log/fog/fogscheduler.log
-
@tom-elliott I used a capital
-F
to persist when a file is changed and redirected it to another temporary log:tail /var/log/fog/fogscheduler.log -F > /var/log/fog/fogscheduler-tailing.log
caught in the act:
[04-27-21 8:46:23 am] * Starting TaskScheduler Service [04-27-21 8:46:23 am] * Checking for new items every 60 seconds [04-27-21 8:46:23 am] * Starting service loop [04-27-21 8:46:23 am] * 1 task found. [04-27-21 8:46:23 am] * 1 scheduled task(s) to run. [04-27-21 8:46:23 am] * 0 power management task(s) to run. [04-27-21 9:01:23 am] ================================== === ==== ===== ==== === ========= == === == === === ======== ==== == ==== === === ======== ==== == ========= === ==== ==== == ========= === ======== ==== == === === === ======== ==== == ==== === === ========= == === == === === ========== ===== ==== ================================== ===== Free Opensource Ghost ====== ================================== ============ Credits ============= = https://fogproject.org/Credits = ================================== == Released under GPL Version 3 == ================================== [04-27-21 9:01:23 am] Interface not ready, waiting for it to come up: [04-27-21 9:01:33 am] Interface not ready, waiting for it to come up: [04-27-21 9:01:43 am] Interface not ready, waiting for it to come up:
So, no additional info other than identifying the timestamp.
-
Hi @tom-elliott and @altitudehack!
I can confirm on new install. Debian 10 KVM (no https because Scheduled Power Tasking with https didnt work).
Scheduled Power Management Task is working on Master branch, not working on dev-branch (1.5.9.75).
Master:
[04-27-21 12:42:25 pm] * 1 task found. [04-27-21 12:42:25 pm] * Task run time: Tue, 27 Apr 2021 12:42:00 +0000 [04-27-21 12:42:25 pm] * Found a wake on lan task that should run. [04-27-21 12:42:25 pm] | Task sent to fcaa148962ce
And looking for tasks every minute.
Dev-branch:
[04-27-21 1:15:12 pm] * 1 task found. [04-27-21 1:15:12 pm] * 0 scheduled task(s) to run. [04-27-21 1:15:12 pm] * 1 power management task(s) to run.
No more lines in log. Finishes here. No more checking for tasks in log.
Peter
-
@altitudehack and @Petěrko while I still have no idea what’s happening,
Maybe turning on display_errors and ensuring log_errors are turned on can help us out?
https://serverfault.com/questions/153634/php-exit-status-255-what-does-it-mean#:~:text=255 is an error%2C I,the output of the errorMany different resources of course.
systemclt -l status FOGScheudler
tail -100F /var/log/fog/fogscheduler.log >/var/log/fog/fogscheduler_continued.log &
tail -100f /var/log/fog/fogscheduler_continued.log
journalctl -xe
tail -100F /var/log/php-fpm/www-error.log >/var/log/php-fpm/php-fpm-errors-continued.log &
tail -100f /var/log/php-fpm/php-fpm-errors-continued.logUnsure what else we can try.
-
@tom-elliott said in Daily wake-up routine not working after update:
systemctl -l status FOGScheduler
Apr 27 08:46:23 fog.int.visionary.com env[32561]: PHP Parse error: syntax error, unexpected '}', expecting ';' in /var/www/html/fog/lib/fog/timer.class.php on line 128
-
@altitudehack Okay, fixed the error you saw in the latest if you’d be willing to test?
Thanks for the quick turn around.
-
@tom-elliott Yeah I fixed it manually and it looks like it’s working as expected:
[04-27-21 11:25:19 am] * 1 task found. [04-27-21 11:25:19 am] * 1 scheduled task(s) to run. [04-27-21 11:25:19 am] * 0 power management task(s) to run. [04-27-21 11:25:19 am] * Scheduled Task run time: Sat, 01 May 2021 06:00:00 -0500 [04-27-21 11:25:19 am] * [04-27-21 11:26:19 am] * 1 task found. [04-27-21 11:26:19 am] * 1 scheduled task(s) to run. [04-27-21 11:26:19 am] * 0 power management task(s) to run. [04-27-21 11:26:19 am] * Scheduled Task run time: Sat, 01 May 2021 06:00:00 -0500 [04-27-21 11:26:19 am] * [04-27-21 11:27:19 am] * 1 task found. [04-27-21 11:27:19 am] * 1 scheduled task(s) to run. [04-27-21 11:27:19 am] * 0 power management task(s) to run. [04-27-21 11:27:19 am] * Scheduled Task run time: Sat, 01 May 2021 06:00:00 -0500 [04-27-21 11:27:19 am] *
I’ll pull in the fresh code. Sorry I didn’t see that error in the status earlier.
-
I do wish the message:
* Press [Enter] key when database is updated/installed.
would only be displayed if a database update is performed. Kinda feel silly hitting refresh on that page each time I pull in new code
-
@altitudehack You could also run the installer with:
./installfog.sh -y
-
@Tom-Elliott maybe another error to debug in the code:
Apr 27 11:30:54 fog.int.visionary.com systemd[1]: Started FOGScheduler. Apr 27 11:30:55 fog.int.visionary.com env[15253]: PHP Warning: _() expects exactly 1 parameter, 2 given in /var/www/html/fog/lib/fog/timer.class.php on line 134 Apr 27 11:31:55 fog.int.visionary.com env[15253]: PHP Warning: _() expects exactly 1 parameter, 2 given in /var/www/html/fog/lib/fog/timer.class.php on line 134 Apr 27 11:32:55 fog.int.visionary.com env[15253]: PHP Warning: _() expects exactly 1 parameter, 2 given in /var/www/html/fog/lib/fog/timer.class.php on line 134
-
@altitudehack Should be fixed in latest again.
Thank you,
-
@tom-elliott yes, those errors stopped after the latest update. got this little bugger, though:
Apr 27 12:47:45 fog.int.visionary.com systemd[1]: [/usr/lib/systemd/system/FOGScheduler.service:17] Unknown lvalue 'StartLimitIntervalSec' in section 'Unit'
-
@altitudehack https://unix.stackexchange.com/questions/463917/systemds-startlimitintervalsec-and-startlimitburst-never-work
This sounds like a systemd version issue.
What version are you running?
systemctl --version
Should output something like this:
systemd 239 (239-45.el8) +PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy
-
# systemctl --version systemd 219 +PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN
-
@altitudehack what OS are you running?
-
@altitudehack And is this impacting it from running or just a noticed message?
-
@tom-elliott I think it’s just a notice. This is on CentOS 7.9.2.
-
@tom-elliott
I confirm 1.9.5.77 is waking up computers on schedule again.OS: Debian 10
FOG: dev-branch 1.9.5.77, no https.I just noticed way longer Downloading kernel, init and fog-client binaries during update process. Takes approx 10 times longer 10-20 minutes) compare to stable. Sometimes even not finishing and timing out. Maybe problems getting client from fogproject.org?
Anyway, great and quick debugging. Thank you,Tom!
Peter -
@tom-elliott The logs show the service kicked off a WoL this morning, but I was just made aware that it didn’t run and had to run it manually via Groups > Select group > Power Management > Perform Immediately > WoL. Here’s the scheduler log:
[04-28-21 5:59:10 am] * 1 task found. [04-28-21 5:59:10 am] * 1 scheduled task(s) to run. [04-28-21 5:59:10 am] * 0 power management task(s) to run. [04-28-21 5:59:10 am] * Scheduled Task run time: Sat, 01 May 2021 06:00:00 -0500 [04-28-21 5:59:10 am] * This is a cron style task that should run at: 1619866800 [04-28-21 6:00:10 am] * 1 task found. [04-28-21 6:00:10 am] * 1 scheduled task(s) to run. [04-28-21 6:00:10 am] * 0 power management task(s) to run. [04-28-21 6:00:10 am] * Scheduled Task run time: Sat, 01 May 2021 06:00:00 -0500 [04-28-21 6:00:10 am] * This is a cron style task that should run at: 1619866800 [04-28-21 6:01:10 am] * 1 task found. [04-28-21 6:01:10 am] * 1 scheduled task(s) to run. [04-28-21 6:01:10 am] * 0 power management task(s) to run. [04-28-21 6:01:10 am] * Scheduled Task run time: Sat, 01 May 2021 06:00:00 -0500 [04-28-21 6:01:10 am] * This is a cron style task that should run at: 1619866800
Curiously, the Service Master log has no entries since the last restart:
/var/log/fog/servicemaster.log [04-27-21 11:39:09 am] FOGImageSize forked child process (18037). [04-27-21 11:39:09 am] Service_Signal_handler (15271) received signal 15. [04-27-21 11:39:09 am] Service_Signal_handler (15271) killing child (15518). [04-27-21 11:39:09 am] Service_Signal_handler (15271) exiting. [04-27-21 11:39:09 am] FOGImageSize child process (18037) is running. [04-27-21 11:39:09 am] FOGSnapinHash Start [04-27-21 11:39:09 am] FOGSnapinHash forked child process (18126). [04-27-21 11:39:09 am] FOGSnapinHash child process (18126) is running. [04-27-21 12:23:48 pm] Service_Signal_handler (17870) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (17870) killing child (17966). [04-27-21 12:23:48 pm] Service_Signal_handler (17870) exiting. [04-27-21 12:23:48 pm] Service_Signal_handler (17840) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (17840) killing child (17861). [04-27-21 12:23:48 pm] Service_Signal_handler (17840) exiting. [04-27-21 12:23:48 pm] Service_Signal_handler (17853) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (17853) killing child (17883). [04-27-21 12:23:48 pm] Service_Signal_handler (17853) exiting. [04-27-21 12:23:48 pm] Service_Signal_handler (17817) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (17817) killing child (17826). [04-27-21 12:23:48 pm] Service_Signal_handler (17817) exiting. [04-27-21 12:23:48 pm] Service_Signal_handler (17825) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (17825) killing child (17839). [04-27-21 12:23:48 pm] Service_Signal_handler (17825) exiting. [04-27-21 12:23:48 pm] Service_Signal_handler (18058) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (18058) killing child (18126). [04-27-21 12:23:48 pm] Service_Signal_handler (18058) exiting. [04-27-21 12:23:48 pm] Service_Signal_handler (17973) received signal 15. [04-27-21 12:23:48 pm] Service_Signal_handler (17973) killing child (18037). [04-27-21 12:23:48 pm] Service_Signal_handler (17973) exiting. [04-27-21 12:24:09 pm] FOGMulticastManager Start [04-27-21 12:24:09 pm] FOGMulticastManager forked child process (32107). [04-27-21 12:24:09 pm] FOGMulticastManager child process (32107) is running. [04-27-21 12:24:09 pm] FOGImageReplicator Start [04-27-21 12:24:09 pm] FOGImageReplicator forked child process (32112). [04-27-21 12:24:09 pm] FOGImageReplicator child process (32112) is running. [04-27-21 12:24:09 pm] FOGTaskScheduler Start [04-27-21 12:24:09 pm] FOGTaskScheduler forked child process (32127). [04-27-21 12:24:09 pm] FOGTaskScheduler child process (32127) is running. [04-27-21 12:24:09 pm] FOGSnapinReplicator Start [04-27-21 12:24:09 pm] FOGSnapinReplicator forked child process (32133). [04-27-21 12:24:09 pm] FOGSnapinReplicator child process (32133) is running. [04-27-21 12:24:09 pm] FOGPingHosts Start [04-27-21 12:24:09 pm] FOGPingHosts forked child process (32315). [04-27-21 12:24:09 pm] FOGPingHosts child process (32315) is running. [04-27-21 12:24:09 pm] FOGSnapinHash Start [04-27-21 12:24:09 pm] FOGSnapinHash forked child process (32379). [04-27-21 12:24:09 pm] FOGSnapinHash child process (32379) is running. [04-27-21 12:24:09 pm] FOGImageSize Start [04-27-21 12:24:09 pm] FOGImageSize forked child process (32424). [04-27-21 12:24:09 pm] FOGImageSize child process (32424) is running.
Is that expected? Would any other logs be useful?
Thank you for your work towards resolving this! -
@altitudehack I’m going to guess your apache access logs would be handy.
Do you use HTTPS as part of your web gui?
I did make a small change to try to send WOL packets first across https, then across http, (so it will be sending packets twice for each machine needed) but as http->https forces a redirect, the mac address to wake up is lost in the redirect.
By trying HTTPS before HTTP we should be able to maintain the variable input sending properly.
This is just a guess.
Of course, if you’d like, you can also delete the scheduled task and retry using the PowerManagement Scheduled WOL as @Petěrko shows that it is working now. I’m sorry as I feel like I’m making you jump through hoops and that is definitely not my intent.
As for the service logs, this is good. It was restarting the service constantly because of the errors it was seeing from PHP (the missing
;
and the_() expects one parameter but 2 given
)