☰

CRON 消息在系统日志中被延迟任意长时间

tag-icon • tag-icon logging cron syslog rsyslog time
CRON 消息在系统日志中被延迟任意长时间

我在一些服务器的系统日志中发现一些与 CRON 相关的消息是在错误的时间写入的，如下所示：

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 (...)

我们发现带有“错误时间”的消息指的是以前的日期时间，而当时的 syslog 内容实际上缺少这些消息行（根据 CRON 计划）。也就是说，这些消息在写入 syslog 时似乎延迟了很长时间。

在上面的例子中，脚本 clean_image_child.py 每分钟执行一次。预期的一行有关其执行的 CRON 消息没有在“8 月 19 日 04:01”这一分钟出现在系统日志中，而是延迟到“8 月 21 日 06:26”之后。仔细检查所有服务器表明，对于我们仍然有“缺少 CRON 消息的系统日志片段”（有些太旧并且已被轮换）的所有此类情况，都可以确认这一观察结果。并且，除了 CRON 之外，我们没有发现任何应用程序/服务存在此类情况（系统日志中的消息延迟）。

我们做了一个实验来调查这个问题。我们给了 CRON 另一个脚本，让它每分钟执行一次，该脚本将一行带有时间戳的消息附加到另一个（它自己的）日志文件中。在这个自我管理的日志文件中，我们每分钟都会收到一条来自脚本的消息，没有一次遗漏。但在系统日志中，某些时候缺少有关运行它的 CRON 消息，这些消息在几小时或几天后出现。因此，只有消息（而不是执行计划）被延迟了。

服务器运行的是 ubuntu 14.04.1 LTS，带有（自编译的）3.18 内核（3.18.0-031800-generic X86_64）。CRON 版本为 3.0pl1-124ubuntu2。rsyslogd 版本为 7.4.4-1ubuntu2。

虽然看起来这种行为不会影响系统中的其他服务，但我仍然很好奇 - 为什么会发生这种情况？是 CRON 或 rsyslogd 中的错误或配置错误，还是内核和这些应用程序之间的版本不匹配？

答案1

实际上，这是 @Stone 评论的重复。只需向所有人明确说明这确实有答案即可。

简而言之，我正在使用的 rsyslog 版本有一个错误，它会将收到的 syslog 消息延迟任意长的时间。错误报告在这里。 升级 rsyslog 解决了这个问题。这不是 CRON 的错。

相关内容