CRON messages being delayed for arbitrary long time in syslog

I found in a few servers's syslog that some of the CRON related messages are written in a wrong time, like the following:

Aug 21 06:26:01 hty-controller CRON[30159]: (root) CMD (   python /.../clean_image_child.py)
Aug 21 06:26:01 hty-controller CRON[30156]: (CRON) info (...)
Aug 21 06:26:03 hty-controller CRON[29302]: (CRON) info (...)
Aug 19 04:01:01 hty-controller CRON[30176]: (root) CMD (   python /.../clean_image_child.py)
Aug 21 06:27:01 hty-controller CRON[30178]: (root) CMD (   python /var/lib/.../recycle_bin.py)
Aug 21 06:27:01 hty-controller CRON[30179]: (root) CMD (   python /.../clean_image_child.py)
Aug 21 06:27:01 hty-controller CRON[30177]: (CRON) info (...)

It is found that the messages with "wrong time" are referring to a previous date time, and the syslog content at the time being referred to is actually missing exactly these lines of messages (according to CRON schedule). That is the messages seems to be delayed for a long time when written to syslog.

In the above example, the script clean_image_child.py is being executed every minute. The expected one line of CRON message about its execution did not show up in syslog on the minute of "Aug 19 04:01", but was delayed to (after) "Aug 21 06:26". A careful check on all the servers shows that the observation can be confirmed for all such cases where we still have the "syslog snippet with missing CRON messages" (some are too old and have been rotated). And we found no such cases (of message delays in syslog) for any applications/services other than CRON.

We made an experiment to investigate this. We gave another script to CRON for executing every minute, which appends one line of message with a timestamp to another (its own) log file. In this self managed log file we have one message every minute from the script, without a single miss. But in syslog there were missing CRON messages about running it at some points, which appeared a few hours or days later. So it is only the message (not the schedule of execution) that is being delayed.

The servers are running ubuntu 14.04.1 LTS with a (self compiled) 3.18 kernel (3.18.0-031800-generic X86_64). The CRON version is 3.0pl1-124ubuntu2. And rsyslogd version is 7.4.4-1ubuntu2.

Although it looks like this behavior will not affect other services in the system, I'm still curious - why would this happen? Is it a bug or miss config in CRON, or in rsyslogd, or a version miss match between the kernel and those applications?

Solution 1:

Actually this is a duplicate of @Stone 's comment. Just make it clear to everyone this do have an answer.

In short, there is a bug in the version of rsyslog I'm using, which will delay syslog message it received for arbitrary length of time. Bug report is here. And upgrading rsyslog solved the problem. It is not CRON's fault.