Crontab jobs disappeared.

[Ripshod]

My cru script only added logging. It would not fix anything itself.

Strange.

 

[Viktor Jaep]

Strange.

When you say the jobs "clashed", what did you mean with that? Did they both try to get concurrently loaded, and hung? Is this where a change in the lock mechanism would help?

 

[Ripshod]

When you say the jobs "clashed", what did you mean with that? Did they both try to get concurrently loaded, and hung? Is this where a change in the lock mechanism would help?

Yes, both try loading at the same time. I presume cron can't multi-task. Moving the two cronjobs apart by a couple of minutes definitely seems to have stabilised things. I can't believe I only noticed this a week ago, after posting my list ages ago

 

[Viktor Jaep]

Yes, both try loading at the same time. I presume cron can't multi-task. Moving the two cronjobs apart by a couple of minutes definitely seems to have stabilised things. I can't believe I only noticed this a week ago, after posting my list ages ago

It's hard to believe that jobs executing at the same time wasn't anticipated for already. But if that's the temporary fix until it can be formally addressed by whoever has that capability, then we'll need to make note. Perhaps before scripts perform any cru actions, they need to see if any jobs with that same time already exist, and warn the user, or choose a new time?

 

[glens]

Just automatically add a minute...

Seems cron would simply cue them. Can't believe this would be an issue.

 

[ColinTaylor]

Yes, both try loading at the same time. I presume cron can't multi-task. Moving the two cronjobs apart by a couple of minutes definitely seems to have stabilised things. I can't believe I only noticed this a week ago, after posting my list ages ago

crond doesn't multitask anything, it's scheduler. Every minute it sequentially reads the crontab and then spawns separate processes for any jobs that need to run. Multiple processes running at the same time is a normal function of Linux. If there are problems with two jobs running at the same time then that's an issue with the jobs themselves (or something it calls, e.g. nvram).

Bear in mind that cru is not the same as crond. I seem to recall that one of the problems appeared to be multiple copies of cru running at roughly the same time, hence the speculation there's a locking problem with cru.

 

[Ripshod]

All I know is if BACKUPMON and spdMerlin clash there's a serious problem maybe 1 in 4 occasions.

 

[Ripshod]

I've also discovered that when Diversion restarts Dnsmasq the modified cru stops logging:

Feb 16 14:00:22 ripshod cru[5782]: Action: a, JobID: Diversion_RotateLogs, Args: a Diversion_RotateLogs 20 5 * * * /bin/sh /opt/share/diversion/file/rotate-logs.div
Feb 16 14:00:22 ripshod cru[5782]: Calling PID: 5258, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Feb 16 14:00:22 ripshod cru[5782]: Jobs before: 7, after: 8
Feb 16 14:00:22 ripshod cru[5810]: Action: a, JobID: Diversion_CountAds, Args: a Diversion_CountAds 20 17 * * * diversion count_ads count
Feb 16 14:00:22 ripshod cru[5810]: Calling PID: 5258, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Feb 16 14:00:22 ripshod cru[5810]: Jobs before: 8, after: 9
Feb 16 14:00:22 ripshod cru[5839]: Action: a, JobID: Diversion_WeeklyStats, Args: a Diversion_WeeklyStats 30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div
Feb 16 14:00:22 ripshod cru[5839]: Calling PID: 5258, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Feb 16 14:00:22 ripshod cru[5839]: Jobs before: 9, after: 10
Feb 16 14:00:22 ripshod Diversion: restarted Dnsmasq to apply settings
Feb 16 14:00:22 ripshod stubby[5902]: Read config from file /etc/stubby/stubby.yml
Feb 16 14:00:22 ripshod stubby[5902]: Stubby version: Stubby 0.4.2
Feb 16 14:00:22 ripshod uiDivStats: dnsmasq has restarted, restarting taildns

You can see the count gets to 10, but there's nothing logged after this. I'm currently sitting on 19 jobs.

This whole thing is just so confuddling. I'm not going to stress about this, this is probably self inflicted with all the scripts I have loaded right now. I have my fix - I'm happy.

 

[XIII]

Did you make any progress on this?

I just discovered that I lost a cron job a week ago... (on 18-Feb-2024)

Besides the lost job (a manual one that I added myself) I see these changes:

This block moved up in the output of `crontab -l` (but did not change; only move):

25 18 * * * sh /jffs/scripts/firewall banmalware #Skynet_banmalware#
20 1 * * Mon sh /jffs/scripts/firewall update #Skynet_autoupdate#
0 * * * * sh /jffs/scripts/firewall save #Skynet_save#

This line changed from:

34 */12 * * * sh /jffs/scripts/firewall debug genstats #Skynet_genstats#

into:

55 */12 * * * sh /jffs/scripts/firewall debug genstats #Skynet_genstats#

My entry that got deleted was the last line in the list.

Does the above point to Skynet as the culprit, or is this just coincidence?

 

[DJones]

I have nothing to add to this conversation, except it’s an interesting topic, and amusing to watch the all the “furniture” dev’s get involved in solving this.

 

[alan6854321]

I started this thread when I saw ALL my cronjobs disappear.
I've been watching them, but it hasn't happened since.

I haven't installed the logging script to watch the "cru" command, but a few people have done and there hasn't been any feedback from them yet so I assume it hasn't been seen by them either.

 

[Viktor Jaep]

I started this thread when I saw ALL my cronjobs disappear.
I've been watching them, but it hasn't happened since.

I haven't installed the logging script to watch the "cru" command, but a few people have done and there hasn't been any feedback from them yet so I assume it hasn't been seen by them either.

This has been a real tough one to pin down... I wish someone would find a smoking gun...

My entry that got deleted was the last line in the list.

Can you post exactly what that entry looked like?

Does the above point to Skynet as the culprit, or is this just coincidence?

I was looking through the skynet code, and I'm just not seeing how your entry would get deleted. The beginning number changes because it randomly picks a number between 28 and 58 (or so). But why it decided to delete that entry and add a new one is mysterious to me.

Typically, entries within files like "services-start" are deleted based on a match of wording... so it could be that if your command had some wording in it that matched what one of these scripts is looking for in order to delete the line, then that could be a possibility. That's why I was curious to see exactly what your entry looks like.

 

[ColinTaylor]

I was looking through the skynet code, and I'm just not seeing how your entry would get deleted. The beginning number changes because it randomly picks a number between 28 and 58 (or so). But why it decided to delete that entry and add a new one is mysterious to me.

As far as I can see that specific crontab entry is updated every time the webUI page is installed. Which is every time Skynet is started or restarted.

 

[Ripshod]

I've had four cron jobs miss since I started tracing. None of them were deliberately removed by "cru d", and 3 of them were skynet.
Since I moved the BACKUPMON job a few minutes later I've had no issues. There's nothing written down as I found my answer.

 

[XIII]

Can you post exactly what that entry looked like?

Yes:

1-59/10 * * * * /jffs/scripts/op-cron hc-nextdns #hcNextDNS#

 

[XIII]

Sorry, false alarm.

I rebooted my router last Sunday and I keep forgetting that, unlike cron on my Raspberry Pi's, the router's cron jobs are not persistent over boots, unless you run "cru a" from some script at boot, which I (already) did for all older entries, but not for this single recent addition... Fixed!

 

[Weblee2407]

I ended up writing a script that re-added my cru entries - that is, those not created by one of the add-on packages. My problem(s) seem to be when the cable modem had a reset and after a router reboot. I put a call to the re-post script in wan-event. I have seen the listing sequence change - mine start out on the bottom but work their way up. I was waiting on some info from the cru monitoring script too.

 

[Ripshod]

I've had four cron jobs miss since I started tracing. None of them were deliberately removed by "cru d", and 3 of them were skynet.
Since I moved the BACKUPMON job a few minutes later I've had no issues. There's nothing written down as I found my answer.

Or so I thought. It happened again last night. Right now I only have 4 outof 19 crons still running. And I caught it in the logs.

Cronj log:

Mar  6 21:37:56 ripshod cru[11191]: Action: d, JobID: Diversion_LocalBackup, Args: d Diversion_LocalBackup
Mar  6 21:37:56 ripshod cru[11191]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:56 ripshod cru[11191]: Jobs before: 19, after: 19
Mar  6 21:37:56 ripshod cru[11265]: Action: a, JobID: Diversion_UpdateBL, Args: a Diversion_UpdateBL 00 2 * * Sat /bin/sh /opt/share/diversion/file/update-bl.div reset
Mar  6 21:37:56 ripshod cru[11265]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:56 ripshod cru[11265]: Jobs before: 19, after: 19
Mar  6 21:37:56 ripshod cru[11349]: Action: d, JobID: Diversion_UpdateBLTwo, Args: d Diversion_UpdateBLTwo
Mar  6 21:37:56 ripshod cru[11349]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:56 ripshod cru[11349]: Jobs before: 19, after: 19
Mar  6 21:37:56 ripshod cru[11420]: Action: a, JobID: Diversion_RotateLogs, Args: a Diversion_RotateLogs 20 5 * * * /bin/sh /opt/share/diversion/file/rotate-logs.div
Mar  6 21:37:56 ripshod cru[11420]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:56 ripshod cru[11420]: Jobs before: 19, after: 19
Mar  6 21:37:56 ripshod cru[11470]: Action: d, JobID: Skynet_genstats, Args: d Skynet_genstats
Mar  6 21:37:56 ripshod cru[11470]: Calling PID: 2175, CMD: sh/jffs/scripts/firewallstartskynetloc=/tmp/mnt/asus/skynet
Mar  6 21:37:56 ripshod cru[11492]: Action: a, JobID: Diversion_CountAds, Args: a Diversion_CountAds 20 17 * * * diversion count_ads count
Mar  6 21:37:56 ripshod cru[11492]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:56 ripshod cru[11470]: Jobs before: 19, after: 19
Mar  6 21:37:56 ripshod cru[11492]: Jobs before: 19, after: 19
Mar  6 21:37:56 ripshod cru[11568]: Action: a, JobID: Skynet_genstats, Args: a Skynet_genstats 31 */12 * * * sh /jffs/scripts/firewall debug genstats
Mar  6 21:37:56 ripshod cru[11568]: Calling PID: 2175, CMD: sh/jffs/scripts/firewallstartskynetloc=/tmp/mnt/asus/skynet
Mar  6 21:37:56 ripshod cru[11574]: Action: a, JobID: Diversion_WeeklyStats, Args: a Diversion_WeeklyStats 30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div
Mar  6 21:37:56 ripshod cru[11574]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:56 ripshod cru[11568]: Jobs before: 19, after: 1
Mar  6 21:37:56 ripshod cru[11574]: Jobs before: 19, after: 1
Mar  6 21:37:59 ripshod cru[14991]: Action: d, JobID: Diversion_LocalBackup, Args: d Diversion_LocalBackup
Mar  6 21:37:59 ripshod cru[14991]: Calling PID: 14977, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:59 ripshod cru[14991]: Jobs before: 1, after: 1
Mar  6 21:37:59 ripshod cru[15019]: Action: a, JobID: Diversion_UpdateBL, Args: a Diversion_UpdateBL 00 2 * * Sat /bin/sh /opt/share/diversion/file/update-bl.div reset
Mar  6 21:37:59 ripshod cru[15019]: Calling PID: 14977, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:59 ripshod cru[15019]: Jobs before: 1, after: 2
Mar  6 21:37:59 ripshod cru[15060]: Action: d, JobID: Diversion_UpdateBLTwo, Args: d Diversion_UpdateBLTwo
Mar  6 21:37:59 ripshod cru[15060]: Calling PID: 14977, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:59 ripshod cru[15060]: Jobs before: 2, after: 2
Mar  6 21:37:59 ripshod cru[15095]: Action: a, JobID: Diversion_RotateLogs, Args: a Diversion_RotateLogs 20 5 * * * /bin/sh /opt/share/diversion/file/rotate-logs.div
Mar  6 21:37:59 ripshod cru[15095]: Calling PID: 14977, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:59 ripshod cru[15095]: Jobs before: 2, after: 3
Mar  6 21:37:59 ripshod cru[15139]: Action: a, JobID: Diversion_CountAds, Args: a Diversion_CountAds 20 17 * * * diversion count_ads count
Mar  6 21:37:59 ripshod cru[15139]: Calling PID: 14977, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:59 ripshod cru[15139]: Jobs before: 3, after: 4
Mar  6 21:37:59 ripshod cru[15168]: Action: a, JobID: Diversion_WeeklyStats, Args: a Diversion_WeeklyStats 30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div
Mar  6 21:37:59 ripshod cru[15168]: Calling PID: 14977, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:37:59 ripshod cru[15168]: Jobs before: 4, after: 4
Mar  6 21:38:01 ripshod cru[16052]: Action: d, JobID: Diversion_LocalBackup, Args: d Diversion_LocalBackup
Mar  6 21:38:01 ripshod cru[16052]: Calling PID: 16010, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:01 ripshod cru[16052]: Jobs before: 4, after: 4
Mar  6 21:38:01 ripshod cru[16116]: Action: a, JobID: Diversion_UpdateBL, Args: a Diversion_UpdateBL 00 2 * * Sat /bin/sh /opt/share/diversion/file/update-bl.div reset
Mar  6 21:38:01 ripshod cru[16116]: Calling PID: 16010, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:01 ripshod cru[16116]: Jobs before: 4, after: 4
Mar  6 21:38:01 ripshod cru[16189]: Action: d, JobID: Diversion_UpdateBLTwo, Args: d Diversion_UpdateBLTwo
Mar  6 21:38:01 ripshod cru[16189]: Calling PID: 16010, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:01 ripshod cru[16189]: Jobs before: 4, after: 4
Mar  6 21:38:01 ripshod cru[16250]: Action: a, JobID: Diversion_RotateLogs, Args: a Diversion_RotateLogs 20 5 * * * /bin/sh /opt/share/diversion/file/rotate-logs.div
Mar  6 21:38:01 ripshod cru[16250]: Calling PID: 16010, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:01 ripshod cru[16250]: Jobs before: 4, after: 4
Mar  6 21:38:01 ripshod cru[16314]: Action: a, JobID: Diversion_CountAds, Args: a Diversion_CountAds 20 17 * * * diversion count_ads count
Mar  6 21:38:01 ripshod cru[16314]: Calling PID: 16010, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:01 ripshod cru[16314]: Jobs before: 4, after: 4
Mar  6 21:38:01 ripshod cru[16381]: Action: a, JobID: Diversion_WeeklyStats, Args: a Diversion_WeeklyStats 30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div
Mar  6 21:38:01 ripshod cru[16381]: Calling PID: 16010, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:01 ripshod cru[16381]: Jobs before: 4, after: 4
Mar  6 21:38:03 ripshod cru[18385]: Action: d, JobID: Diversion_LocalBackup, Args: d Diversion_LocalBackup
Mar  6 21:38:03 ripshod cru[18385]: Calling PID: 18371, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:03 ripshod cru[18385]: Jobs before: 4, after: 4
Mar  6 21:38:03 ripshod cru[18430]: Action: a, JobID: Diversion_UpdateBL, Args: a Diversion_UpdateBL 00 2 * * Sat /bin/sh /opt/share/diversion/file/update-bl.div reset
Mar  6 21:38:03 ripshod cru[18430]: Calling PID: 18371, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:03 ripshod cru[18430]: Jobs before: 4, after: 4
Mar  6 21:38:03 ripshod cru[18484]: Action: d, JobID: Diversion_UpdateBLTwo, Args: d Diversion_UpdateBLTwo
Mar  6 21:38:03 ripshod cru[18484]: Calling PID: 18371, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:03 ripshod cru[18484]: Jobs before: 4, after: 4
Mar  6 21:38:03 ripshod cru[18533]: Action: a, JobID: Diversion_RotateLogs, Args: a Diversion_RotateLogs 20 5 * * * /bin/sh /opt/share/diversion/file/rotate-logs.div
Mar  6 21:38:03 ripshod cru[18533]: Calling PID: 18371, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:04 ripshod cru[18533]: Jobs before: 4, after: 4
Mar  6 21:38:04 ripshod cru[18584]: Action: a, JobID: Diversion_CountAds, Args: a Diversion_CountAds 20 17 * * * diversion count_ads count
Mar  6 21:38:04 ripshod cru[18584]: Calling PID: 18371, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf
Mar  6 21:38:04 ripshod cru[18584]: Jobs before: 4, after: 4
Mar  6 21:38:04 ripshod cru[18639]: Action: a, JobID: Diversion_WeeklyStats, Args: a Diversion_WeeklyStats 30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div
Mar  6 21:38:04 ripshod cru[18639]: Calling PID: 18371, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf

cru l:

*/10 * * * * /jffs/scripts/YazFi check #YazFi#
00 2 * * Sat /bin/sh /opt/share/diversion/file/update-bl.div reset #Diversion_UpdateBL#
20 5 * * * /bin/sh /opt/share/diversion/file/rotate-logs.div #Diversion_RotateLogs#
20 17 * * * diversion count_ads count #Diversion_CountAds#
30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div #Diversion_WeeklyStats#

I'll let peeps think about this. Off to the day job so I'll catch up later.

 

[Ripshod]

From System messages:

Mar  6 21:37:55 ripshod Diversion: restarted Dnsmasq to apply settings
Mar  6 21:37:55 ripshod stubby[10907]: Read config from file /etc/stubby/stubby.yml
Mar  6 21:37:55 ripshod stubby[10907]: Stubby version: Stubby 0.4.2
Mar  6 21:37:55 ripshod uiDivStats: dnsmasq has restarted, restarting taildns
Mar  6 21:37:55 ripshod custom_script: Running /jffs/scripts/service-event (args: restart dnsmasq)
Mar  6 21:37:56 ripshod custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Mar  6 21:37:56 ripshod custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Mar  6 21:37:56 ripshod Diversion: restarted Dnsmasq to apply settings
Mar  6 21:37:56 ripshod stubby[11754]: Read config from file /etc/stubby/stubby.yml
Mar  6 21:37:56 ripshod stubby[11754]: Stubby version: Stubby 0.4.2
Mar  6 21:37:56 ripshod uiDivStats: dnsmasq has restarted, restarting taildns
Mar  6 21:37:56 ripshod YazFi_[12353]: Firewall restarted - sleeping 10s before running YazFi
Mar  6 21:37:58 ripshod Gilly: dnsmasq tainted detected, restarting dnsmasq

 

[dave14305]

Mar 6 21:37:56 ripshod cru[11568]: Action: a, JobID: Skynet_genstats, Args: a Skynet_genstats 31 */12 * * * sh /jffs/scripts/firewall debug genstats 
Mar 6 21:37:56 ripshod cru[11568]: Calling PID: 2175, CMD: sh/jffs/scripts/firewallstartskynetloc=/tmp/mnt/asus/skynet
Mar 6 21:37:56 ripshod cru[11574]: Action: a, JobID: Diversion_WeeklyStats, Args: a Diversion_WeeklyStats 30 1 * * Sat /bin/sh /opt/share/diversion/file/stats.div 
Mar 6 21:37:56 ripshod cru[11574]: Calling PID: 11144, CMD: /bin/sh/jffs/scripts/dnsmasq.postconf/etc/dnsmasq.conf 
Mar 6 21:37:56 ripshod cru[11568]: Jobs before: 19, after: 1 
Mar 6 21:37:56 ripshod cru[11574]: Jobs before: 19, after: 1

This looks like a concurrency problem since both invocations saw 19 jobs before but only 1 after. Adding a locking feature wouldn’t hurt.