Bug 303341 - rsyslogd logs messages from vixie-cron with incorrect timestamps
Summary: rsyslogd logs messages from vixie-cron with incorrect timestamps
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: rsyslog
Version: rawhide
Hardware: All
OS: Linux
low
low
Target Milestone: ---
Assignee: Peter Vrabec
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2007-09-24 15:31 UTC by Will Woods
Modified: 2007-11-30 22:12 UTC (History)
4 users (show)

Fixed In Version: 1.19.6-2.fc8
Clone Of:
Environment:
Last Closed: 2007-09-25 16:36:01 UTC
Type: ---
Embargoed:

Attachments (Terms of Use)
Proposed patch (1.13 KB, patch)
2007-09-25 08:22 UTC, Tomas Mraz 		no flags Details | Diff
View All

Description Will Woods 2007-09-24 15:31:00 UTC 
(See bug #296741, where this started)

I'm using vixie-cron-4.2-2.fc8 and rsyslog-1.19.2-1.fc8.

I also have vnstat installed, which has a cron job that runs every 5 minutes. I
have confirmed that the job does run every 5 minutes, as expected, but the the
logging messages from this job have the wrong timestamps:

Sep 24 08:01:01 localhost CROND[23396]: (root) CMD (run-parts /etc/cron.hourly)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 08:05:01 localhost CROND[23410]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:01:01 localhost CROND[23552]: (root) CMD (run-parts /etc/cron.hourly)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)
Sep 24 09:05:01 localhost CROND[23566]: (vnstat) CMD (/usr/sbin/vnstat.cron)

Note that the pid is also wrong.
Comment 1 Robert Scheck 2007-09-24 15:45:26 UTC 
Just FYI, -e as parameter to rsyslogd looks better. Either set this as default 
or really fix this problem...
Comment 2 Will Woods 2007-09-24 21:42:20 UTC 
Some extra info: vixie-cron uses the following calls for logging:

if (!syslog_open) {
    openlog("CROND",LOG_PID,LOG_CRON);
    syslog_open = 1;
}
syslog(LOG_INFO,"(%s) %s (%s)", username, event, detail)

So. Every 5 minutes, we're getting the same syslog() call from vixie-cron. And
turning on the "print every message" flag fixes the problem. So it's obviously a
bug in the ReduceRepeat code.

I think using -e is a good workaround until we can be sure this is fixed.
Comment 3 Will Woods 2007-09-24 21:57:51 UTC 
For the record, this is still unfixed in upstream rsyslog-1.19.6.
Comment 4 Tomas Mraz 2007-09-25 08:22:22 UTC 
Created attachment 204961 [details]
Proposed patch

This patch corrects the duplicated message suppression.
Comment 5 Will Woods 2007-09-25 16:36:01 UTC 
Fix confirmed with rsyslog-1.19.6-2.fc8. We should make sure that patch gets
upstream.
Comment 6 Tomas Mraz 2007-09-25 17:04:42 UTC 
Rainer, see the attached patch for the duplicated message suppression.
Comment 7 Rainer Gerhards 2007-09-26 07:44:39 UTC 
I applied the patch I received via mail yesterday, its now in CVS.
Note You need to log in before you can comment on or make changes to this bug.