Cron running but not working

[stukov]

Hello,

Two of my CentOS machines are affected with a very strange disease. After removing a few faulty lines that caused errors in my logs in one user's crontab, my other scripts ran by cron stopped being ran.

However, it looks much like cron is running...
# service crond status
crond (pid 23242) is running...
# ps auwx | grep crond
root 23242 0.0 0.0 5264 1108 ? Ss Jul15 0:00 crond
root 26436 0.0 0.0 3912 664 pts/1 S+ 10:16 0:00 grep crond
And there is nothing (and I mean nothing) in my logs to help me find the cause of this problem.
Jul 15 16:16:54 webcam01 crond[23242]: (CRON) STARTUP (V5.0)

Any ideas?

Thanks.

[scottro]

Much of the time when a crontab fails to run it's due to a bad $PATH variable. That is, cron has a shorter $PATH than everything else, so I always, if running a script from cron put complete paths in, such as /usr/bin/whatever. (I put this into the script that it's running.)

That's a wild guess though, since this sounds like something that used to work but no longer works. Would you be a bit more specific? For example, are the failed jobs for the same user, a different user? Could it be that the user lacks privilege?

I think I'd try to test it with something really simple, like have it run ls and write it to something to make sure that it at least works. (e.g. ls /var > var.txt)

[stukov]

Thanks for the reply scottro.

I don't think the "path" variable can be the cause here, as the script was working last week. I'd rather suspect an update caused the crash. I have tried removing and installing cron back from Yum. This gave no success.

The problem is not with the jobs of only one users. It's all jobs that are not working. As if cron ran and checked the crontabs but did not ran them at all. Here is my /etc/crontab:
# cat /etc/crontab
SHELL=/bin/bash
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root
HOME=/

# run-parts
01 * * * * root run-parts /etc/cron.hourly
02 4 * * * root run-parts /etc/cron.daily
22 4 * * 0 root run-parts /etc/cron.weekly
42 4 1 * * root run-parts /etc/cron.monthly

I followed your suggestion and tried cron with a simple operation. I added this line to my /etc/crontab:
50 * * * * root /bin/ls / > /tmp/ls.txt
Running the command by hand created the file with the proper output, but cron gave no result again.

Any ideas?

[stukov]

Oops, forgot to mention what happened in my logs:
Jul 15 16:16:54 webcam01 crond[23242]: (CRON) STARTUP (V5.0)
Jul 16 10:39:01 webcam01 crond[23242]: (*system*) RELOAD (/etc/crontab)
Which means that cron isn't that dead... Weird.

[dk_netsvil]

I'd check /var/log/messages and the root account's mail directory just in case. However, if that fails there's a checklist of sorts here (http://aplawrence.com/Unixart/crontab_not_running.html).

[stukov]

Thanks for the reply dk_netsvil.

There is nothing relevant in /var/log/messages; No mail for root.

Thanks for the link, it is well explained and very helpful. However, there is no solution to my problem. crond is running but not executing any tasks!? I rewrote the crontab file to make sure it is not a syntax error of any kind. It looks like this now:
SHELL=/bin/bash
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root
HOME=/

25 * * * * root /bin/ls / > /tmp/ls.txt
crond saw the change and reloaded the crontab:
Jul 16 13:20:01 webcam01 crond[23242]: (*system*) RELOAD (/etc/crontab)and# ls -lut /etc/crontab
-rw-r--r-- 1 root root 352 Jul 16 13:21 /etc/crontab
and my file didn't get created...

[anomie]

Two of my CentOS machines are affected with a very strange disease.

Try:
restorecon -R /usr/sbin/crond /etc/cron*

I've seen cron lose its security context following updates before.

[stukov]

Thanks for the reply anomie. I've executed your command but, still no success.

I've also backed up the old crontab, created a whole new file with a simple crontab definition and tried this. Didn't work.

Are there any ways to make crond more verbose?

[anomie]

I don't know of an option for crond to make him chattier. What sort of logging do you see in /var/log/cron?

[stukov]

This is all I have since it stopped working:
Jul 15 15:59:10 webcam01 crond[23022]: (CRON) STARTUP (V5.0)
Jul 15 16:16:51 webcam01 crond[23223]: (CRON) STARTUP (V5.0)
Jul 15 16:16:54 webcam01 crond[23242]: (CRON) STARTUP (V5.0)
Jul 16 10:39:01 webcam01 crond[23242]: (*system*) RELOAD (/etc/crontab)
Jul 16 13:20:01 webcam01 crond[23242]: (*system*) RELOAD (/etc/crontab)
Jul 16 13:21:01 webcam01 crond[23242]: (*system*) RELOAD (/etc/crontab)
Jul 16 13:34:10 webcam01 crond[27303]: (CRON) STARTUP (V5.0)
Jul 16 13:36:01 webcam01 crond[27303]: (*system*) RELOAD (/etc/crontab)
Jul 16 13:41:01 webcam01 crond[27303]: (*system*) RELOAD (/etc/crontab)
Jul 16 14:26:01 webcam01 crond[27303]: (*system*) RELOAD (/etc/crontab)

[anomie]

Two dumb questions:

Did you restart crond after running restorecon?
Are you checking root's mail? (There's probably nothing, since no jobs appears to be running.)

[stukov]

Thanks for the reply anomie. To answer your questions:

Did you restart crond after running restorecon?
# history | grep -A 1 restorecon
1042 man restorecon
1043 restorecon -R /usr/sbin/crond /etc/cron*
1044 service crond restart
Are you checking root's mail? (There's probably nothing, since no jobs appears to be running.)
# mail
No mail for root

[anomie]

If you haven't checked already, be sure /etc/cron.allow and /etc/cron.deny are not unexpectedly populated. These files are explained in the manpages for crontab(1).

From what you've explained, that does not sound like it's the problem, though. If you have any other recollections of system changes between 'working' and 'broken' that might help establish cause and effect, please share.

[stukov]

I only have a cron.deny file, which is empty.

This problem was firstly reported on another machine which serves as a print server. Then, I had to move a bunch of machines from RHEL 5 to CentOS 5. See thread: http://daemonforums.org/showthread.php?t=1390.

The switch didn't help the print server to revive it's cron. However, I suppose this could be the cause of the webcam's server disease. I switched another bunch of boxes to CentOS this week. All the three of them survived the cron restart, so I am unsure this is the exact cause of the problem.

I tried to reboot both machines (the print server and the webcam server). Intersting thing, the format of my cron logs changed, as if the application used switched from vixie-cron to anacron!?
Jul 17 11:44:10 webcam01 anacron[3215]: Anacron 2.3 started on 2008-07-17
Jul 17 11:44:10 webcam01 anacron[3215]: Will run job `cron.daily' in 65 min.
Jul 17 11:44:10 webcam01 anacron[3215]: Jobs will be executed sequentially
Jul 17 12:49:09 webcam01 anacron[3215]: Job `cron.daily' started
Jul 17 12:49:43 webcam01 anacron[3215]: Job `cron.daily' terminated
Jul 17 12:49:43 webcam01 anacron[3215]: Normal exit (1 jobs run)
Good news: a few tasks ran properly (the daily tasks for example, ran by themselves after), but I am still having the problem with my hourly tasks (some checks for Nagios).

I am going to investigate on the case with this change, any insights are still very appreciated. Thanks.

[anomie]

I only have a cron.deny file, which is empty.

No problem there.

the format of my cron logs changed, as if the application used switched from vixie-cron to anacron!?

anacron is just getting you caught up (i.e. running the cron jobs that were not run by cron).

Good news: a few tasks ran properly (the daily tasks for example, ran by themselves after), but I am still having the problem with my hourly tasks (some checks for Nagios).

So the /etc/cron.daily jobs are running, but the /etc/cron.hourly tasks still are not running? If yes, were the cron.daily jobs run via anacron? (If so, I think you still have the same issue. Again, anacron was just getting you caught up.)

[stukov]

Thanks for the reply anomie. Yes, I still have the same problem. I tough anacron was some kind of remplacement for vixie-cron. Now that I am disillusionned, I have to continue my investigaitons on this case.

Thanks!

[anomie]

I'll admit I am stumped on this one. If I were in your shoes, what I'd do is:

Disable selinux altogether (to try to eliminate it as the cause) temporarily.
Play around with adding the -x option to crond. You can do this in /etc/sysconfig/crond. It appears that may provide you with debug output.


Earlier in the thread I had said I wasn't aware of a crond option to make him chattier, but that was on a CentOS 4 box. (I just checked a CentOS 5 box a moment ago and discovered it.)

[stukov]

Disable selinux altogether (to try to eliminate it as the cause) temporarily.
SELinux was never enabled on this machine. I double checked, and it is in fact disabled.
Play around with adding the -x option to crond. You can do this in /etc/sysconfig/crond. It appears that may provide you with debug output.
Now, it gets even more confusing. I've dimished the delay required for my hourly task to run. It will now run every minute:
* * * * * root run-parts /etc/cron.hourly
I've also added maximum verbosity to my cron's arguments:
# cat /etc/sysconfig/crond
CRONDARGS="-x ext,sch,proc,pars,load,misc,test,bit"
And, it looks very much like my task runs:
[21827] load_database()
[21827] spool dir mtime unch, no load needed.
[21827] tick(54,14,20,6,1)
user [root:0:0:...] cmd="run-parts /etc/cron.monthly"
user [root:0:0:...] cmd="run-parts /etc/cron.weekly"
user [root:0:0:...] cmd="run-parts /etc/cron.daily"
user [root:0:0:...] cmd="run-parts /etc/cron.hourly"
user [root:0:0:...] cmd="python /usr/share/rhn/virtualization/poller.py"
[21827] do_command(run-parts /etc/cron.hourly, (*system*,0,0))
Minute-ly job. Recording time 1216666441
[21827] main process returning to work
[21827] do_command(python /usr/share/rhn/virtualization/poller.py, (*system*,0,0))
[21827] main process returning to work
[21827] Target time=1216652100, sec-to-wait=60
[22024] child_process('run-parts /etc/cron.hourly')
[22024] child continues, closing pipes
[22024] child reading output from grandchild
[22024] got EOF from grandchild
[22024] waiting for grandchild #2 to finish
[22024] grandchild #22026 finished, status=0000
[22024] waiting for grandchild #1 to finish
[22024] no more grandchildren--mail written?
[22025] child_process('python /usr/share/rhn/virtualization/poller.py')
[22024] child process done, exiting
[21827] sigchld...pid #22024 died, stat=0
[21827] sigchld...no dead kids
[22025] child continues, closing pipes
[22025] child reading output from grandchild
[22025] got EOF from grandchild
[22025] waiting for grandchild #2 to finish
[22025] grandchild #22027 finished, status=0000
[22025] waiting for grandchild #1 to finish
[22025] no more grandchildren--mail written?
[22025] child process done, exiting
[21827] sigchld...pid #22025 died, stat=0
[21827] sigchld...no children
However, I have nothing that tells me that the job ran in my /var/log/cron and nothing about cron in /var/log/messages. Syslog not running?
# service syslog status
syslogd (pid 2224) is running...
klogd (pid 2227) is running...
A bit puzzling...

[anomie]

I agree that it looks like crond is issuing a command to run scripts in that directory, e.g.
run-parts /etc/cron.daily

Check to make sure you don't have a permissions issue in cron.daily? Can you run the command I bolded (above) and see what it's doing?
bash -x /usr/bin/run-parts /etc/cron.daily

(Might need to direct the output somewhere for review.)

[stukov]

OK. Looks like everything is fine when ran manually. Here are the results:
# run-parts /etc/cron.daily
#
# bash -x /usr/bin/run-parts /etc/cron.daily
+ set +e
+ '[' 1 -lt 1 ']'
+ '[' '!' -d /etc/cron.daily ']'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/0anacron ']'
+ '[' /etc/cron.daily/0anacron '!=' /etc/cron.daily/0anacron ']'
+ '[' /etc/cron.daily/0anacron '!=' /etc/cron.daily/0anacron ']'
+ '[' /etc/cron.daily/0anacron '!=' /etc/cron.daily/0anacron ']'
+ '[' /etc/cron.daily/0anacron '!=' /etc/cron.daily/0anacron ']'
+ '[' /etc/cron.daily/0anacron '!=' /etc/cron.daily/0anacron ']'
+ '[' -x /etc/cron.daily/0anacron ']'
+ /etc/cron.daily/0anacron
+ awk -v progname=/etc/cron.daily/0anacron 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/0logwatch ']'
+ '[' /etc/cron.daily/0logwatch '!=' /etc/cron.daily/0logwatch ']'
+ '[' /etc/cron.daily/0logwatch '!=' /etc/cron.daily/0logwatch ']'
+ '[' /etc/cron.daily/0logwatch '!=' /etc/cron.daily/0logwatch ']'
+ '[' /etc/cron.daily/0logwatch '!=' /etc/cron.daily/0logwatch ']'
+ '[' /etc/cron.daily/0logwatch '!=' /etc/cron.daily/0logwatch ']'
+ '[' -x /etc/cron.daily/0logwatch ']'
+ /etc/cron.daily/0logwatch
+ awk -v progname=/etc/cron.daily/0logwatch 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/cups ']'
+ '[' /etc/cron.daily/cups '!=' /etc/cron.daily/cups ']'
+ '[' /etc/cron.daily/cups '!=' /etc/cron.daily/cups ']'
+ '[' /etc/cron.daily/cups '!=' /etc/cron.daily/cups ']'
+ '[' /etc/cron.daily/cups '!=' /etc/cron.daily/cups ']'
+ '[' /etc/cron.daily/cups '!=' /etc/cron.daily/cups ']'
+ '[' -x /etc/cron.daily/cups ']'
+ /etc/cron.daily/cups
+ awk -v progname=/etc/cron.daily/cups 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/logrotate ']'
+ '[' /etc/cron.daily/logrotate '!=' /etc/cron.daily/logrotate ']'
+ '[' /etc/cron.daily/logrotate '!=' /etc/cron.daily/logrotate ']'
+ '[' /etc/cron.daily/logrotate '!=' /etc/cron.daily/logrotate ']'
+ '[' /etc/cron.daily/logrotate '!=' /etc/cron.daily/logrotate ']'
+ '[' /etc/cron.daily/logrotate '!=' /etc/cron.daily/logrotate ']'
+ '[' -x /etc/cron.daily/logrotate ']'
+ /etc/cron.daily/logrotate
+ awk -v progname=/etc/cron.daily/logrotate 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/makewhatis.cron ']'
+ '[' /etc/cron.daily/makewhatis.cron '!=' /etc/cron.daily/makewhatis.cron ']'
+ '[' /etc/cron.daily/makewhatis.cron '!=' /etc/cron.daily/makewhatis.cron ']'
+ '[' /etc/cron.daily/makewhatis.cron '!=' /etc/cron.daily/makewhatis.cron ']'
+ '[' /etc/cron.daily/makewhatis.cron '!=' /etc/cron.daily/makewhatis.cron ']'
+ '[' /etc/cron.daily/makewhatis.cron '!=' /etc/cron.daily/makewhatis.cron ']'
+ '[' -x /etc/cron.daily/makewhatis.cron ']'
+ /etc/cron.daily/makewhatis.cron
+ awk -v progname=/etc/cron.daily/makewhatis.cron 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/mlocate.cron ']'
+ '[' /etc/cron.daily/mlocate.cron '!=' /etc/cron.daily/mlocate.cron ']'
+ '[' /etc/cron.daily/mlocate.cron '!=' /etc/cron.daily/mlocate.cron ']'
+ '[' /etc/cron.daily/mlocate.cron '!=' /etc/cron.daily/mlocate.cron ']'
+ '[' /etc/cron.daily/mlocate.cron '!=' /etc/cron.daily/mlocate.cron ']'
+ '[' /etc/cron.daily/mlocate.cron '!=' /etc/cron.daily/mlocate.cron ']'
+ '[' -x /etc/cron.daily/mlocate.cron ']'
+ /etc/cron.daily/mlocate.cron
+ awk -v progname=/etc/cron.daily/mlocate.cron 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/prelink ']'
+ '[' /etc/cron.daily/prelink '!=' /etc/cron.daily/prelink ']'
+ '[' /etc/cron.daily/prelink '!=' /etc/cron.daily/prelink ']'
+ '[' /etc/cron.daily/prelink '!=' /etc/cron.daily/prelink ']'
+ '[' /etc/cron.daily/prelink '!=' /etc/cron.daily/prelink ']'
+ '[' /etc/cron.daily/prelink '!=' /etc/cron.daily/prelink ']'
+ '[' -x /etc/cron.daily/prelink ']'
+ /etc/cron.daily/prelink
+ awk -v progname=/etc/cron.daily/prelink 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/rpm ']'
+ '[' /etc/cron.daily/rpm '!=' /etc/cron.daily/rpm ']'
+ '[' /etc/cron.daily/rpm '!=' /etc/cron.daily/rpm ']'
+ '[' /etc/cron.daily/rpm '!=' /etc/cron.daily/rpm ']'
+ '[' /etc/cron.daily/rpm '!=' /etc/cron.daily/rpm ']'
+ '[' /etc/cron.daily/rpm '!=' /etc/cron.daily/rpm ']'
+ '[' -x /etc/cron.daily/rpm ']'
+ /etc/cron.daily/rpm
+ awk -v progname=/etc/cron.daily/rpm 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ for i in '$1/*[^~,]'
+ '[' -d /etc/cron.daily/tmpwatch ']'
+ '[' /etc/cron.daily/tmpwatch '!=' /etc/cron.daily/tmpwatch ']'
+ '[' /etc/cron.daily/tmpwatch '!=' /etc/cron.daily/tmpwatch ']'
+ '[' /etc/cron.daily/tmpwatch '!=' /etc/cron.daily/tmpwatch ']'
+ '[' /etc/cron.daily/tmpwatch '!=' /etc/cron.daily/tmpwatch ']'
+ '[' /etc/cron.daily/tmpwatch '!=' /etc/cron.daily/tmpwatch ']'
+ '[' -x /etc/cron.daily/tmpwatch ']'
+ /etc/cron.daily/tmpwatch
+ awk -v progname=/etc/cron.daily/tmpwatch 'progname {
print progname ":\n"
progname="";
}
{ print; }'
+ exit 0
I received my daily right after.

[anomie]

You received the output email afterwards?

In my mind we've ruled out:

common gotchas (incomplete PATH, cron.allow/cron.deny, permissions, etc.)
dead crond daemon
selinux
syntactical problem in, e.g., your /etc/cron.daily scripts


Agree? Unless your system clock is going bonkers, I'm out of ideas for the moment. I do find it interesting that the problem started on one RHEL 5 machine, and then eventually crept into other (CentOS) machines as well.

[stukov]

Yep I received it afterwards.

I agree with you anomie. This is very weird. My clocks looks OK, and I am out of ideas too... Sounds like I'm going to have to reinstall those machines! Lucky me they are not assigned a more critical mission.

A big thanks to all who helped me on this one. It's very appreciated.

[BSDfan666]

Perhaps the systems were compromised in some way?

[stukov]

Perhaps the systems were compromised in some way?
This is not impossible. However, I wonder why someone would compromise two internal and useless (I mean, it's only our print server and webcam server...) boxes when they reach our internal LAN...

[BSDfan666]

Perhaps it was an inside job? :)

[scottro]

Maybe it had something to do with that DNS thingie? (There was a note on the CentOS forums from Ned about that, though it seems the whole risk was less than imagined.)
The fact that it crept into others makes me wonder as well, though.

As they're not mission-critical, perhaps reinstallation is one way to start trouble-shooting. Please continue posting on it, as I think we're all curious.

[stukov]

I'm going to try to reproduce the problem on a fresh install of another box. I'll post here back as soon as I know more.

In the meantime, if someone has a good idea to not hesitate to post. I'll try to keep one on the affected box as it is just to test new solutions.

Thanks again to all who posted.