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
Hi Mika,
If you sever has the local time configured and switches from Daylight Saving Time to normal/winter time, such a glitch is expected behavior and is independent from IntelMQ.
best regards Sebastian
On 10/31/22 8:58 AM, Mika Silander wrote:
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 _______________________________________________ IntelMQ-dev mailing list https://lists.cert.at/cgi-bin/mailman/listinfo/intelmq-dev https://intelmq.readthedocs.io/
Dang! Forgot completely the change to winter time ... matches perfectly with the moment of change on Sunday morning. Thanks for pointing that out Sebastian! Well, at least it's comforting to know that my monitoring scripts spotted that "anomaly" as expected.
Br, Mika
----- Original Message ----- From: "Sebix" sebix@sebix.at To: "Mika Silander" mika.silander@csc.fi, "intelmq-dev" intelmq-dev@lists.cert.at Sent: Monday, 31 October, 2022 10:08:01 Subject: Re: [IntelMQ-dev] Unexpected log entry ordering in bots' logs
Hi Mika,
If you sever has the local time configured and switches from Daylight Saving Time to normal/winter time, such a glitch is expected behavior and is independent from IntelMQ.
best regards Sebastian
On 10/31/22 8:58 AM, Mika Silander wrote:
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 _______________________________________________ IntelMQ-dev mailing list https://lists.cert.at/cgi-bin/mailman/listinfo/intelmq-dev https://intelmq.readthedocs.io/
On 2022-10-31 08:58, Mika Silander wrote:
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?
Because the time stamps are in the local time zone, and that's when the switch from summer to winter time occurred in the eastern European time zone.