Bug 303341

Summary: rsyslogd logs messages from vixie-cron with incorrect timestamps
Product: [Fedora] Fedora Reporter: Will Woods <wwoods>
Component: rsyslogAssignee: Peter Vrabec <pvrabec>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: low    
Version: rawhideCC: redhat-bugzilla, rgerhards, theinric, tmraz
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: 1.19.6-2.fc8 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2007-09-25 16:36:01 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Proposed patch none

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.