[IntelMQ-dev] Expected behaviour of bot reloading after log rotation

[Kamil Mankowski]

Hey,

There is a bot's flag ("_sighup_delay") controlling weather a bot 
reloads immediate or waits. Looking at the source code, it looks like an 
expected behaviour, see:

https://github.com/certtools/intelmq/blob/d624988693894e71defdd8b18618f7af98be852c/intelmq/lib/bot.py#L289C27-L297

and:

https://github.com/certtools/intelmq/blob/d624988693894e71defdd8b18618f7af98be852c/intelmq/lib/bot.py#L713-L719

However, I understand your concern: this is okay if the reload happens 
during the one day (logrotate keeps the old log file untouched until 
next run), but it can cause troubles, if there is no message on one day.

Best regards,
Kamil Mankowski
CERT.at GmbH
www.cert.at

On 10/19/23 13:29, Mika Silander wrote:
> Hi all,
> 
>   Apologies for a lengthy message, but I had a set of monitoring scripts that worked like a charm on a physical machine but when moved to a virtual machine with a newer Ubuntu, I see odd  failures in the form of monitoring script processes left hanging on void file handles. I suspect the problem is somehow related to log rotation in connection to bot reloading but I can't figure out how. A few questions at the end.
> 
>   Our setup for reference:
> 
> Ubuntu 22.04 LTS
> python 3.10.12
> intelmq 3.2.2a1
> intelmq-api 3.1.0-rc1
> intelmq-manager 3.2.0
> 
>   We have a simple bot chain: Mail Attachment Collector -> Shadowserver Parser -> N expert bots -> 1 output bot.
> 
> /etc/logrotate.d/intelmq contains:
> 
> /var/log/intelmq/*.log {
>      su intelmq intelmq
>      daily
>      maxsize 10M
>      rotate 60
>      notifempty
>      compress
>      delaycompress
>      create 644 intelmq intelmq
>      sharedscripts
>      postrotate
>          sudo -u intelmq /usr/bin/intelmqctl --quiet reload
>      endscript
> }
> 
>   The cron daemon runs run-parts for targets under /etc/cron.daily/ at 06:25, including /etc/cron.daily/logrotate. Thus, "intelmqctl --quiet reload" gets also executed after all the intelmq log files have been rotated.
> 
>   What I see is that no bot reloads soon after run-parts has finished. The first bot to perform a reload is the Mail Attachment Collector immediately after midnight. The others remain as is until the Mail Attachment Collector reads the day's first report and forwards it to the Shadowserver Parser bot. The parser bot then performs a reload and forwards the events to the first expert in the chain. Once the first event from the parser trickles through the entire bot chain, every bot in turn first performs a reload and then processes the event. In practise, the logrotate triggered bot reload can thus be delayed almost a full day - our first mail reports tend to arrive during the very early morning hours.
> 
>   My question is, is the above reload behaviour as expected? I found it strange that the Mail Attachment Collector reloads at midnight even though it has processed new mail reports after the "intelmqctl reload" call done by logrotate. I would have expected the Mail Attachment Collector to reload itself when the first report arrives for processing after 06:25, i.e. the first report after the call to intelqmctl reload. And, what controls the timing of the Mail Attachment Collector's reload? All its reloads I see in older log files indicate that the reload is consistently run after midnight irrespective of incoming reports and the timing of the intelmqctl reload command.
> 
>   Thanks again and best regards from a puzzled Mika
> 
>   
> 
> 
> 
> 
> _______________________________________________
> IntelMQ-dev mailing list
> https://lists.cert.at/cgi-bin/mailman/listinfo/intelmq-dev
> https://intelmq.readthedocs.io/
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: OpenPGP digital signature
URL: <http://lists.cert.at/pipermail/intelmq-dev/attachments/20231019/35f05462/attachment.sig>