SOLVED Daily wake-up routine not working after update


  • @altitudehack Should be fixed in latest again.

    Thank you,


  • @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 You could also run the installer with:

    ./installfog.sh -y


  • 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 🙂


  • @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.


  • @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 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 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 error

    Many 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.log

    Unsure what else we can try.


  • 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


  • @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.


  • @altitudehack If you need to see more:

    tail -1000f /var/log/fog/fogscheduler.log


  • Interesting?

    /var/log/fog/servicemaster.log
    ...
    [04-27-21 6:54:30 am] Service_Signal_handler (1657) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1657) killing child (1669).
    [04-27-21 6:54:30 am] Service_Signal_handler (1657) exiting.
    [04-27-21 6:54:30 am] Service_Signal_handler (1653) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1653) killing child (1673).
    [04-27-21 6:54:30 am] Service_Signal_handler (1653) exiting.
    [04-27-21 6:54:30 am] Service_Signal_handler (1652) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1652) killing child (1672).
    [04-27-21 6:54:30 am] Service_Signal_handler (1652) exiting.
    [04-27-21 6:54:30 am] Service_Signal_handler (1654) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1654) killing child (5610).
    [04-27-21 6:54:30 am] Service_Signal_handler (1654) exiting.
    [04-27-21 6:54:30 am] Service_Signal_handler (1655) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1655) killing child (1671).
    [04-27-21 6:54:30 am] Service_Signal_handler (1655) exiting.
    [04-27-21 6:54:30 am] Service_Signal_handler (1658) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1658) killing child (1674).
    [04-27-21 6:54:30 am] Service_Signal_handler (1658) exiting.
    [04-27-21 6:54:30 am] Service_Signal_handler (1656) received signal 15.
    [04-27-21 6:54:30 am] Service_Signal_handler (1656) killing child (1670).
    [04-27-21 6:54:30 am] Service_Signal_handler (1656) exiting.
    [04-27-21 6:54:59 am] FOGSnapinReplicator Start
    [04-27-21 6:54:59 am] FOGSnapinReplicator forked child process (1666).
    [04-27-21 6:54:59 am] FOGSnapinHash Start
    [04-27-21 6:54:59 am] FOGSnapinReplicator child process (1666) is running.
    [04-27-21 6:54:59 am] FOGSnapinHash child process (1667) is running.
    [04-27-21 6:54:59 am] FOGSnapinHash forked child process (1667).
    [04-27-21 6:54:59 am] FOGTaskScheduler Start
    [04-27-21 6:54:59 am] FOGPingHosts Start
    [04-27-21 6:54:59 am] FOGTaskScheduler forked child process (1668).
    [04-27-21 6:54:59 am] FOGMulticastManager Start
    [04-27-21 6:54:59 am] FOGPingHosts forked child process (1669).
    [04-27-21 6:54:59 am] FOGMulticastManager forked child process (1670).
    [04-27-21 6:54:59 am] FOGImageReplicator Start
    [04-27-21 6:54:59 am] FOGMulticastManager child process (1670) is running.
    [04-27-21 6:54:59 am] FOGPingHosts child process (1669) is running.
    [04-27-21 6:54:59 am] FOGImageReplicator forked child process (1671).
    [04-27-21 6:54:59 am] FOGImageSize Start
    [04-27-21 6:54:59 am] FOGImageReplicator child process (1671) is running.
    [04-27-21 6:54:59 am] FOGImageSize forked child process (1672).
    [04-27-21 6:54:59 am] FOGImageSize child process (1672) is running.
    [04-27-21 6:54:59 am] FOGTaskScheduler child process (1668) is running.
    [04-27-21 7:04:59 am] FOGTaskScheduler child process (1668) exited with code 255.
    [04-27-21 7:09:59 am] FOGTaskScheduler forked child process (6149).
    [04-27-21 7:09:59 am] FOGTaskScheduler child process (6149) is running.
    

    What caught my attention was the FOGTaskScheduler child process (1668) exited with code 255


  • Well crap. It happened again. I was looking away so missed it:

    [04-27-21 7:09:59 am] Interface not ready, waiting for it to come up:
    [04-27-21 7:10:09 am] Interface not ready, waiting for it to come up:
    [04-27-21 7:10:19 am] Interface not ready, waiting for it to come up:
    

    I think the logs are cleaned up a little too quickly for me to catch what’s going on. Any way to use logrotate on them rather than wiping them out upon service restarts?


  • @tom-elliott This setting? Haven’t modified it since initial installation:
    Screenshot from 2021-04-27 08-24-12.png


  • @altitudehack Well, there goes that theory.

    Unsure where to look.

    Can you check on FOG Configuration -> FOG Settings -> FOG_WEB_HOST (Maybe Web Host on the interface for you?) to see that the web host is defined?


  • @tom-elliott

    # df -hPT
    Filesystem              Type      Size  Used Avail Use% Mounted on
    devtmpfs                devtmpfs  1.9G     0  1.9G   0% /dev
    tmpfs                   tmpfs     1.9G     0  1.9G   0% /dev/shm
    tmpfs                   tmpfs     1.9G  9.0M  1.9G   1% /run
    tmpfs                   tmpfs     1.9G     0  1.9G   0% /sys/fs/cgroup
    /dev/mapper/cl_fog-root xfs        16G  6.3G  9.8G  40% /
    /dev/sda1               xfs      1014M  312M  703M  31% /boot
    /dev/mapper/cl_fog-var  xfs       5.0G  3.4G  1.7G  67% /var
    /dev/mapper/cl_fog-home xfs        10G  930M  9.1G  10% /home
    /dev/mapper/fog_images  xfs       1.0T   37G  988G   4% /images
    tmpfs                   tmpfs     379M     0  379M   0% /run/user/27129
    tmpfs                   tmpfs     379M     0  379M   0% /run/user/0
    

  • @altitudehack What’s really strange to me is you should see at least the FOG_WEB_HOST setting.

    Can you check disk space and usage for your whole system?

    df -h

    The fact that FOG_WEB_HOST is coming back with nothing seems to me that the Database is dying or there, somehow, isn’t a defined point for this.


  • @Tom-Elliott I noticed another update was available yesterday so ran it, rebooted and went to bed. Unfortunately woke up to more Interface not ready messages…

     1444  2021-04-26 17:11:15 cd fogproject-dev-branch/
     1445  2021-04-26 17:11:18 git pull
     1447  2021-04-26 17:11:47 cd bin
     1449  2021-04-26 17:12:01 ./installfog.sh 
     1450  2021-04-26 17:17:26 reboot
    ...
    [04-26-21 5:32:51 pm] Interface not ready, waiting for it to come up: 
    [04-26-21 5:33:01 pm] Interface not ready, waiting for it to come up: 
    [04-26-21 5:33:11 pm] Interface not ready, waiting for it to come up: 
    ...
    [04-26-21 5:33:21 pm] Interface not ready, waiting for it to come up: 
    [04-26-21 5:33:31 pm] Interface not ready, waiting for it to come up: 
    [04-26-21 5:33:41 pm] Interface not ready, waiting for it to come up: 
    

    One thing that stands out to me is that the FOG server was rebooted at 5:17 last night, but the first message in the logs was timestamped 5:32. What was happening for those 15 minutes?

    I rebooted again this morning and the interface came up immediately. I’ll keep an eye on the logs to see if it goes sideways in a few minutes:

     1464  2021-04-27 06:54:30 reboot
    ...
    tail /var/log/fog/fogscheduler.log
    [04-27-21 6:54:59 am] Interface Ready with IP Address: [localIP]
    [04-27-21 6:54:59 am] Interface Ready with IP Address: 127.0.0.1
    [04-27-21 6:54:59 am] Interface Ready with IP Address: 127.0.1.1
    [04-27-21 6:54:59 am] Interface Ready with IP Address: fog.my.domain.com
    [04-27-21 6:54:59 am]  * Starting TaskScheduler Service
    [04-27-21 6:54:59 am]  * Checking for new items every 60 seconds
    [04-27-21 6:54:59 am]  * Starting service loop
    [04-27-21 6:54:59 am]  * 1 task found.
    [04-27-21 6:54:59 am]  * 1 scheduled task(s) to run.
    [04-27-21 6:54:59 am]  * 0 power management task(s) to run.
    

  • @tom-elliott Good morning, Tom! When I checked logs this morning it was full of ‘waiting for the interface to come up’ messages. I checked the order of my commands on Friday and can confirm that I did bounce the scheduler service after truncating the table:

     1430  2021-04-23 15:25:07 mysql -uroot -p
     1431  2021-04-23 15:25:27 systemctl restart FOGScheduler
    

    I’m not sure what I missed. I restarted the service this morning and the interface came up. It looks like the previous logs were lost when I restarted the service.
    Thank you for checking in!


  • Just wanted to follow up. Hopefully all is working as expected now?

200
Online

9.8k
Users

16.1k
Topics

148.5k
Posts