Cron executed with a delay or not at all

[f4242]

Hello,

I have a problem since upgrading my two NAS to FreeNAS 11.3. My crons are executed with a random delay and may even be not executed at all.

Task configuration:

Cron log:

Code:

root@nas:/var/log # grep nfc cron
Jan 27 07:40:00 nas cron: (root) CMD (find /mnt/pool0/PROJETS/ -type d -mindepth 1 -maxdepth 1 ! -name "PROJETS*COPIE" -exec convmv -r -f utf8 -t utf8 --nfc --replace --notest {} \; > /dev/null 2> /dev/null)
Jan 27 09:03:50 nas cron: (root) CMD (find /mnt/pool0/PROJETS/ -type d -mindepth 1 -maxdepth 1 ! -name "PROJETS*COPIE" -exec convmv -r -f utf8 -t utf8 --nfc --replace --notest {} \; > /dev/null 2> /dev/null)
Jan 27 10:25:12 nas cron: (root) CMD (find /mnt/pool0/PROJETS/ -type d -mindepth 1 -maxdepth 1 ! -name "PROJETS*COPIE" -exec convmv -r -f utf8 -t utf8 --nfc --replace --notest {} \; > /dev/null 2> /dev/null)
Jan 27 11:58:29 nas cron: (root) CMD (find /mnt/pool0/PROJETS/ -type d -mindepth 1 -maxdepth 1 ! -name "PROJETS*COPIE" -exec convmv -r -f utf8 -t utf8 --nfc --replace --notest {} \; > /dev/null 2> /dev/null)
Jan 27 13:30:33 nas cron: (root) CMD (find /mnt/pool0/PROJETS/ -type d -mindepth 1 -maxdepth 1 ! -name "PROJETS*COPIE" -exec convmv -r -f utf8 -t utf8 --nfc --replace --notest {} \; > /dev/null 2> /dev/null)

This bug occurs for all my tasks on my two NAS. The run you see at 7:40 is the first after a server reboot. After some hours or days of uptime, the cron is even more unreliable (stop to process task or almost all of them).

 

[Samuel Tai]

See if your time is drifting. See this thread for details: https://www.truenas.com/community/threads/system-is-going-back-in-time-wrong-date.85686/

 

[f4242]

I don't see any time drifting in my syslogs.

 

[Samuel Tai]

No, does your system's time stay locked with clock time? Drift won't appear in the syslogs.

 

[f4242]

I mean, the timestamps I see in the logs are chronological and it doesn't appear the clock goes back in time.

 

[f4242]

On the server that have about 10 days of uptime, I see this in the middlewared.log:

[2021/01/27 17:54:02] (WARNING) middlewared.job.add():202 - There are 26625 jobs waiting or running
[2021/01/27 17:54:02] (WARNING) middlewared.job.add():202 - There are 26626 jobs waiting or running
[2021/01/27 17:54:23] (WARNING) middlewared.job.add():202 - There are 26627 jobs waiting or running

(multiple time per minutes)

middlewared process also eat over 11gb of RAM on this server.

If I go back in the log on the other server I rebooted this morning, I also see this kind of logs, but they are not producing right now.

 

[Samuel Tai]

Wow, you have a stuck cron job somewhere. service cron restart is worth a shot.

 

[f4242]

Restarting the cron service may make it to work again for short term, but the issue will continue (complete reboot doesn't fix it). How could I see what are the stucks cron jobs? I don't see them in ps. I suppose middlewared is queuing them before trying to launch them.

 

[Samuel Tai]

Try disabling all your cron jobs under Tasks->Cron Jobs. Then try service cron stop. See if there's any zombie cron processes via pgrep cron. If so, nuke them. Then restart cron via service cron start. Then monitor your console logs to see if you see that cron waiting jobs error. Try turning on your jobs one by one, to see which might be the bad job.

 

[f4242]

Is there some documentation about how the task jobs are running in FreeNAS 11.3? Is there something new related to task/cron between 11.2-U8 and 11.3-U5?

In /etc/crontab, I just see calls to "midctl call cronjob.run" with a job id. When I watch the cron log, I may see calls to midctl and other times I see my real commands I configured in the task settings. I wonder if what I see is normal? It seem pretty strange.

 

[f4242]

I also have some "rsync task" that stay in "pending" status and don't run even when launched manually with the button. Some others tasks are still working fine...

 

[f4242]

I think I found it. It's a bug that has been fixed but not released to the 11.3 release: https://jira.ixsystems.com/browse/NAS-108345

I manually patched /usr/local/lib/python3.7/site-packages/middlewared/plugins/cron.py then I restarted the middlewared and cron services. Seem good, I'll be able to confirm in some hours...