Help debugging cron issue

[FreeNASBob]

I have a cron job set to run a very simple script that just pipes the output of a command to a file every day at noon. It will run for a month or two and then mysteriously stop running without any changes on the server at all. There is nothing in the log files ... zero. When I manually run the script from the shell it works fine, but if I use the FreeNAS web UI to manually run the job nothing happens. If I reboot it will work fine for another couple of months and then stop again. I don't even know where to start with debugging this.

But from an SSH shell:
user@freenas:~ % crontab -l
crontab: no crontab for user
user@freenas:~ %

 

[FreeNASBob]

This might help explain things:

user@freenas:~ % service cron status
eval: cannot open /var/run/cron.pid: Permission denied
cron is not running.

FreeNAS-11.3-U3.2

 

[FreeNASBob]

WTF?

Code:

user@freenas:~ % service cron start
eval: cannot open /var/run/cron.pid: Permission denied
Starting cron.
limits: setrlimit datasize: Operation not permitted
/etc/rc.d/cron: WARNING: failed to start cron

So ...

Code:

-rw-------  1 root  wheel        4 Jun 19 07:55 cron.pid

Hmmm. Sudo ...

Code:

user@freenas:~ % sudo service cron start
Password:
cron already running?  (pid=2053).

 

[Samuel Tai]

Cron only runs as root. You need to preface your commands with sudo. From your description, something is causing cron to crash after 2 months.

 

[FreeNASBob]

Cron only runs as root. You need to preface your commands with sudo. From your description, something is causing cron to crash after 2 months.

I was trying that as you replied. It appears cron is already running as a user process (not service) belonging to root. Not sure how that happens. Is there maybe some kind of watchdog that's restarting crashed services incorrectly?

 

[jgreco]

It appears cron is already running as a user process (not service) belonging to root.

Aaaaaaahhhhhh, what? This is UNIX. Everything that isn't a kernel process is a user process. And cron is most definitely a user process.

Not sure how that happens. Is there maybe some kind of watchdog that's restarting crashed services incorrectly?

I can imagine that the middleware might have some sort of restart for failed processes, but I haven't looked.

 

[FreeNASBob]

Aaaaaaahhhhhh, what? This is UNIX. Everything that isn't a kernel process is a user process. And cron is most definitely a user process.

I get that, but I don't know a better way to describe a process that's running independent of the service context. I'm assuming something causes cron to crash silently and then it's restarted directly, not through /etc/rc.d/cron.

 

[FreeNASBob]

Killing the cron process and starting the cron service gets things working again, but I still hate to go to consult the files the cron job is supposed to create and find out that for the last three weeks it hasn't been running. I suppose I'll add an email message to the script so I'll know when it stops.

 

[Samuel Tai]

You can look in /var/log/cron and /var/log/middlewared.log to see what might be causing cron to crash or fail to restart.

 

[FreeNASBob]

The cron log only goes back to yesterday, but it looks like it did try to run my cron job:

Code:

Jul  3 11:45:00 freenas /usr/sbin/cron[92233]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Jul  3 11:50:00 freenas /usr/sbin/cron[92296]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Jul  3 11:55:00 freenas /usr/sbin/cron[92359]: (operator) CMD (/usr/libexec/save-entropy > /dev/null 2>&1)
Jul  3 11:55:00 freenas /usr/sbin/cron[92360]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Jul  3 12:00:00 freenas /usr/sbin/cron[92436]: (root) CMD (PATH="/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin:/root/bin" midclt call cronjob.run 1 > /dev/null 2> /dev/null)
Jul  3 12:00:00 freenas /usr/sbin/cron[92438]: (root) CMD (/usr/local/bin/python /usr/local/bin/mfistatus.py > /dev/null 2>&1)
Jul  3 12:00:00 freenas /usr/sbin/cron[92439]: (operator) CMD (/usr/libexec/save-entropy > /dev/null 2>&1)
Jul  3 12:00:00 freenas /usr/sbin/cron[92440]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Jul  3 12:05:00 freenas /usr/sbin/cron[92514]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Jul  3 12:10:00 freenas /usr/sbin/cron[92576]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Jul  3 12:11:00 freenas /usr/sbin/cron[92588]: (operator) CMD (/usr/libexec/save-entropy > /dev/null 2>&1)

middleware.log has no entries for that time:

Code:

[2020/07/03 08:24:52] (DEBUG) UsageService.start():45 - Scheduled next run in 61522 seconds
[2020/07/03 10:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/07/03 10:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/07/03 15:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/07/03 15:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf

Maybe that entry isn't my cron job?

 

[FreeNASBob]

Went back to the last time the job ran successfully on June 22 and checked the middleware logs for some kind of crash or restart between the successful run and the next day when it failed to start. Nothing:

Code:

[2020/06/22 10:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/22 10:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/22 12:39:02] (DEBUG) UsageService.start():45 - Scheduled next run in 94573 seconds
[2020/06/22 15:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/22 15:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/22 20:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/22 20:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 00:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 00:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 03:45:00] (DEBUG) middlewared.plugins.pool.__run():3532 - Pool 'freenas-boot' last scrub datetime.datetime(2020, 6, 19, 3, 45, 7)
[2020/06/23 04:59:00] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update-master.ixsystems.com:443
[2020/06/23 04:59:01] (DEBUG) urllib3.connectionpool._make_request():437 - https://update-master.ixsystems.com:443 "GET /FreeNAS/trains_redir.json HTTP/1.1" 200 235
[2020/06/23 04:59:01] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/trains.txt', 'https://update-master.ixsystems.com/FreeN>
[2020/06/23 04:59:01] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update.ixsystems.com:443
[2020/06/23 04:59:01] (DEBUG) urllib3.connectionpool._make_request():437 - https://update.ixsystems.com:443 "GET /FreeNAS/trains.txt HTTP/1.1" 301 169
[2020/06/23 04:59:01] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update.freenas.org:443
[2020/06/23 04:59:02] (DEBUG) urllib3.connectionpool._make_request():437 - https://update.freenas.org:443 "GET /FreeNAS/trains.txt HTTP/1.1" 200 412
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/trains.txt', 'https://update-master.ixsystems.com/FreeN>
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update-master.ixsystems.com/FreeNAS/FreeNAS-11.3-STABLE/LATEST'])
[2020/06/23 04:59:02] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update-master.ixsystems.com:443
[2020/06/23 04:59:02] (DEBUG) urllib3.connectionpool._make_request():437 - https://update-master.ixsystems.com:443 "GET /FreeNAS/FreeNAS-11.3-STABLE/LATEST HTTP/1.1" 200 1967
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update-master.ixsystems.com/FreeNAS/FreeNAS-11.3-STABLE/LATEST']):  Read 1967 bytes >
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update-master.ixsystems.com/updates/ix_crl.pem'])
[2020/06/23 04:59:02] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update-master.ixsystems.com:443
[2020/06/23 04:59:02] (DEBUG) urllib3.connectionpool._make_request():437 - https://update-master.ixsystems.com:443 "GET /updates/ix_crl.pem HTTP/1.1" 200 1028
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.CheckFreeSpace():77 - CheckFreeSpace(path=/tmp/tmpat9uj36p.pem, pool=None, required=1028)
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update-master.ixsystems.com/updates/ix_crl.pem']):  Read 1028 bytes total
[2020/06/23 04:59:02] (DEBUG) freenasOS.Update.DownloadUpdate():1014 - Going to try checking cached manifest /var/db/system/update/MANIFEST
[2020/06/23 04:59:02] (DEBUG) freenasOS.Update.DownloadUpdate():1038 - Got this exception: [Errno 2] No such file or directory: '/var/db/system/update/MANIFEST'
[2020/06/23 04:59:02] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/Validators/ValidateUpdate-0frmasef.txt', 'https://updat>
[2020/06/23 04:59:02] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update.ixsystems.com:443
[2020/06/23 04:59:03] (DEBUG) urllib3.connectionpool._make_request():437 - https://update.ixsystems.com:443 "GET /FreeNAS/Validators/ValidateUpdate-0frmasef.txt HTTP/1.1" 301 169
[2020/06/23 04:59:03] (DEBUG) urllib3.connectionpool._new_conn():959 - Starting new HTTPS connection (1): update.freenas.org:443
[2020/06/23 04:59:03] (DEBUG) urllib3.connectionpool._make_request():437 - https://update.freenas.org:443 "GET /FreeNAS/Validators/ValidateUpdate-0frmasef.txt HTTP/1.1" 200 185
[2020/06/23 04:59:03] (DEBUG) freenasOS.Configuration.CheckFreeSpace():77 - CheckFreeSpace(path=/var/db/system/update/ValidateUpdate, pool=None, required=185)
[2020/06/23 04:59:03] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/Validators/ValidateUpdate-0frmasef.txt', 'https://updat>
[2020/06/23 04:59:03] (DEBUG) freenasOS.Update.DownloadUpdate():1071 - DownloadUpdate:  No update available
[2020/06/23 05:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 05:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 07:53:30] (DEBUG) urllib3.connectionpool._new_conn():225 - Starting new HTTP connection (1): pkg.cdn.trueos.org:80
[2020/06/23 07:53:30] (DEBUG) urllib3.connectionpool._new_conn():225 - Starting new HTTP connection (1): pkg.cdn.trueos.org:80
[2020/06/23 07:53:30] (DEBUG) urllib3.connectionpool._new_conn():225 - Starting new HTTP connection (1): pkg.freebsd.org:80
[2020/06/23 07:53:30] (DEBUG) urllib3.connectionpool._new_conn():225 - Starting new HTTP connection (1): pkg.freebsd.org:80
[2020/06/23 07:53:31] (DEBUG) urllib3.connectionpool._make_request():437 - http://pkg.cdn.trueos.org:80 "GET /iocage/unstable/All/ HTTP/1.1" 200 None
[2020/06/23 07:53:31] (DEBUG) urllib3.connectionpool._make_request():437 - http://pkg.cdn.trueos.org:80 "GET /iocage/11.3-RELEASE/All/ HTTP/1.1" 200 None
[2020/06/23 07:53:33] (DEBUG) urllib3.connectionpool._new_conn():225 - Starting new HTTP connection (1): pkg.cdn.trueos.org:80
[2020/06/23 07:53:33] (DEBUG) urllib3.connectionpool._new_conn():225 - Starting new HTTP connection (1): pkg.freebsd.org:80
[2020/06/23 07:53:33] (DEBUG) urllib3.connectionpool._make_request():437 - http://pkg.cdn.trueos.org:80 "GET /iocage/11.3-RELEASE/All/ HTTP/1.1" 200 None
[2020/06/23 07:53:38] (DEBUG) urllib3.connectionpool._make_request():437 - http://pkg.freebsd.org:80 "GET /FreeBSD:11:amd64/latest/All/ HTTP/1.1" 200 None
[2020/06/23 07:53:41] (DEBUG) urllib3.connectionpool._make_request():437 - http://pkg.freebsd.org:80 "GET /FreeBSD:11:amd64/latest/All/ HTTP/1.1" 200 None
[2020/06/23 07:53:41] (DEBUG) urllib3.connectionpool._make_request():437 - http://pkg.freebsd.org:80 "GET /FreeBSD:11:amd64/quarterly/All/ HTTP/1.1" 200 None
[2020/06/23 10:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 10:30:00] (DEBUG) EtcService.generate():275 - No new changes for /etc/krb5.conf
[2020/06/23 14:55:27] (DEBUG) UsageService.start():45 - Scheduled next run in 71786 seconds

 

[Samuel Tai]

I wonder if the job not running coincides with the cron log rolling over?

 

[FreeNASBob]

I inserted an email alert into my cron job so I'll know it's failed when I stop getting email notifications. I wish I could GET notifications when the file isn't created, but not sure how to do that independent of cron.