rsyslog 8.24.0 fails to log message

This problem occurs on a Debian system using rsyslog 8.24.0.  In all other respects rsyslog was and still is operating correctly, so the problem is in the ruleset.

The number of ntpdate entries in the cron log is distracting:

Nov 20 06:01:01  CRON[19514]:  (root) CMD (sh /root/iptables-backup.sh >/dev/null 2>&1)
Nov 20 07:43:01  CRON[7110]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 20 10:43:01  CRON[9972]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 20 13:43:01  CRON[12836]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 20 16:43:01  CRON[15705]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 20 19:43:01  CRON[18578]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 20 22:43:01  CRON[21523]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 21 01:43:01  CRON[24473]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)

Open in new window


The desired effect is to log only the first (01:43) daily occurrence of ntpdate to the cron log.  /etc/rsyslog.conf was modified:

# Log cron into its own file
# Block all but the first daily ntpdate message
if $programname == 'cron' then {
  if $msg contains 'ntpdate' then {
    if not($timereported contains '01:43') then stop
  }
# Anything else gets logged normally
  action(type="omfile" file="/var/log/cron")
  stop
}

Open in new window


Result - now there are no cron log entries.

Side note:  The host is an SBC with hardware clock "issues" that mandate this approach.  Replacing ntpdate with the ntp daemon was tried and didn't work.
LVL 34
Dr. KlahnPrincipal Software EngineerAsked:
Who is Participating?
I wear a lot of hats...

"The solutions and answers provided on Experts Exchange have been extremely helpful to me over the last few years. I wear a lot of hats - Developer, Database Administrator, Help Desk, etc., so I know a lot of things but not a lot about one thing. Experts Exchange gives me answers from people who do know a lot about one thing, in a easy to use platform." -Todd S.

arnoldCommented:
Why are you using ntpdate to sync time on a regular basis where ntpd is a service built for that purpose?
Make sure to configure /etc/ntp.conf with SNTP servers, you can use ntp.org to locate NTP server in your geographic proximate with which your system can synchronize,
Then make sure ntpd service is set to start.
Commonly the ntpd startup script runs ntpdate to sync the clock, and then ntpd maintains the sync as close as possible to while sending requests to the defined NTP servers.

This change will eliminate those entries once disabled in cron.
0
Duncan RoeSoftware DeveloperCommented:
What were the old contents of /etc/rsyslog.conf?
0
Dr. KlahnPrincipal Software EngineerAuthor Commented:
The original contents in that segment were:

# Log cron into its own file
if $programname == 'cron' then {
  action(type="omfile" file="/var/log/cron")
  stop
}

Open in new window

0
Ultimate Tool Kit for Technology Solution Provider

Broken down into practical pointers and step-by-step instructions, the IT Service Excellence Tool Kit delivers expert advice for technology solution providers. Get your free copy now.

arnoldCommented:
Since you are running cron through syslog, and you effectively do not care to see the events of the cron running ntpdate -s 8 times a day, why would like to see it even a couple times?
When installing servers, etc. configuring ntpd is a trivial matter maintaining the time in close proximate throughout the day.
in your setup if there is a significant drift. the time will be jumping every three hours by a minute, minutes, 10s of minutes?

ntpd calculates drift and maintains .....your log does not include the closing/completion of the running of the cron, which could be used to see the time correction.
i.e. if the ntpdate -s takes five seconds to complete on average.
but the time of stop occurs before the start of the run of the JOB.
or on the other side, the stop occurs minutes after the start ran.

run ntpstat
ntpq
peer
and it will tell you ....
when ntpd is running, on a system, a system's clcok can be within 72ms of accuracy with the defined peers in ntp.conf every second.
0
Dr. KlahnPrincipal Software EngineerAuthor Commented:
Arnold, it is not possible to run the ntp daemon on this system; I did state that in the original posting.  It is not a standard PC with a standard clock.
0
arnoldCommented:
timereported or timegenerated....
Possible remedy is to use a counter to see whether this is the first event of the day.
http://www.rsyslog.com/rsyslog-statistic-counter/
in which case it will be recorded, if it is the 8th, reset the counter...
0
Dr. KlahnPrincipal Software EngineerAuthor Commented:
The cause of the problem became evident through inspection of the cron log after a reboot.

Nov 20 19:43:01  CRON[18578]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 20 22:43:01  CRON[21523]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 21 01:43:01  CRON[24473]:  (root) CMD (ntpdate -s 0.us.pool.ntp.org)
Nov 23 17:41:44  cron[1078]:  (CRON) INFO (pidfile fd = 3)
Nov 23 17:41:44  cron[1081]:  (CRON) STARTUP (fork ok)
Nov 23 17:41:44  cron[1081]:  (CRON) INFO (Running @reboot jobs)

Open in new window


Sometimes cron sends its program name in upper case, sometimes it sends it in lower case.  Rewriting the rsyslog rule to account for this solved the issue.  It also revealed PAM messages that were previously not logged due to the level restriction on the default cron logging configuration .. and which are now also excised from the log.

# Log cron into its own file
if (tolower($programname) == 'cron') then {
# But not the PAM messages it issues
if ($msg contains 'pam_unix') then stop
# Only the first ntpdate message each day
  if $msg contains 'ntpdate' then {
    if not($timereported contains '01:43') then stop
  }
  action(type="omfile" file="/var/log/cron")
  stop
}

Open in new window

0

Experts Exchange Solution brought to you by

Your issues matter to us.

Facing a tech roadblock? Get the help and guidance you need from experienced professionals who care. Ask your question anytime, anywhere, with no hassle.

Start your 7-day free trial
Dr. KlahnPrincipal Software EngineerAuthor Commented:
Solved the issue by rewriting the rsyslog rule to account for upper and lower case.  cron logs messages with both.
0
It's more than this solution.Get answers and train to solve all your tech problems - anytime, anywhere.Try it for free Edge Out The Competitionfor your dream job with proven skills and certifications.Get started today Stand Outas the employee with proven skills.Start learning today for free Move Your Career Forwardwith certification training in the latest technologies.Start your trial today
Linux

From novice to tech pro — start learning today.

Question has a verified solution.

Are you are experiencing a similar issue? Get a personalized answer when you ask a related question.

Have a better answer? Share it in a comment.