[IntelMQ-dev] Unexpected log entry ordering in bots' logs

[Mika Silander]

Hi all,

 I've been implementing a set of monitoring scripts for our intelmq instance. The scripts analyse the log files the bots output. One basic assumption of these scripts is that log entries are ordered according to time: the log entry on line N in the log file is older than the one on line N+1 and so forth. One of our scripts alerts if this assumption does not hold. This morning it reported the following unexpected ordering in the log of mail attachment bot (logrotated once, the file was /var/log/intelmq/mail-attachment-collector.log.1) :

...

2022-10-30 03:58:49,387 - mail-attachment-collector - INFO - Idling for 60.0s (1m) now.
2022-10-30 03:59:49,537 - mail-attachment-collector - INFO - Idling for 60.0s (1m) now.
2022-10-30 03:00:49,681 - mail-attachment-collector - INFO - Idling for 60.0s (1m) now.
2022-10-30 03:01:49,829 - mail-attachment-collector - INFO - Idling for 60.0s (1m) now.
...

 Any ideas as to why this happens? I already suspected logrotate and the bot net reload functionality, but logrotate is run for the bot net at 06:25 so this seems to be unrelated. I also guess this does not have to do with the mail bot's implementation but one could rather see this happen with other bots as well. A file handle flushing issue?

Br, Mika