Missing defaults.conf params not getting logged by bot processes

[chorsley]

I encountered an issue where intelmqctl start would immediately have all bots exits with no errors in their respective logs or intelmqctl.log. After a fair bit of strace, pdb and trial and error, made the following temporary change to bin/intelmqctl.py so each bot process started once again logged to stdout and stderr:

    def bot_start(self, bot_id, getstatus=True):
        ...
        with open('/dev/null', 'w') as devnull:
            try:
                # temp debugging: comment out output suppression
                proc = psutil.Popen(cmdargs) #, stdout=devnull, stderr=devnull)

That immediately revealed in console:

$ intelmqctl start
....
DEBUG - Defaults configuration: parameter 'https_proxy' loaded with value None.
CRITICAL - Traceback (most recent call last):
  File "/opt/intelmq/venv/lib/python3.5/site-packages/intelmq/lib/bot.py", line 56, in __init__
    self.__load_defaults_configuration()
  File "/opt/intelmq/venv/lib/python3.5/site-packages/intelmq/lib/bot.py", line 420, in __load_defaults_configuration
    self.parameters.log_processed_messages_seconds = datetime.timedelta(seconds=self.parameters.log_processed_messages_second
s)
AttributeError: 'Parameters' object has no attribute 'log_processed_messages_seconds'

... revealing that my slightly old default.conf was no longer compatible with the current version and I was missing mandatory values. Adding those params resolved the issue, with bots running again. This traceback didn't end up getting logged into each individual bot's log as I would have liked.

I don't have a suggestion on solving this presently, but thought I'd at least log while it's fresh in my mind - suggestions welcome.

[aaronkaplan]

I think what's needed is a check if all mandatory config values exist.
"self-check" upon startup.

It's a pretty nasty error to find and debug, thanks for finding this!
We should definitely improve this one - especially for UX

[chorsley]

Yes, it would be worth investigating both validation of the config files, as well as reviewing when logging becomes active for spawned bot processes, to put any startup errors like this in the relevant log files.

[ghost]

The necessity to have those parameters is documented in both the NEWs-file and the CHANGELOG. Also, using the intelmqctl run would have been far faster - it even can start a debugger, but that wouldn't have been necessary at all. Needless to say that this is documented too.

As the intelmqctl tool is calling the bots as processes, detecting errors there is not trivial. Pull requests are welcome. You are not the first one to request this but apparently it wasn't important enough for anyone to implement it.

We can also call intelmqctl check implicitly before every call, but that adds extra overhead and costs time. Checking for defaults.conf completeness in intelmqctl check would be a good idea. Again: Pull requests welcome.

[chorsley]

The tip for intelmqctl run [bot] is great thanks, and would have solved my problem - the more you know! :) It hadn't occurred to me to look further than intelmqctl start [bot], which as a newbie looks very similar, but are very different as I now know and didn't produce the logging output I needed.

As another suggestion - perhaps a rename or alias for intelmqctl run like intelmqctl debug-run to make it clearer how it differs from start?

I'd say the bot logging issue is the more underlying one here, rather than config validation (though that's good too). Anything missing from the config would get flagged by the bot log, as long as the log is there to be observed. It's great that changes are communicated in the NEWS and CHANGELOG files, but there's a chance not every point in them will be noticed before an upgrade (guilty!).

[ghost]

It's great that changes are communicated in the NEWS and CHANGELOG files, but there's a chance not every point in them will be noticed before an upgrade (guilty!).

And it's documented in the UPGRADING doc file that you should do so...

[chorsley]

For sure, it's indeed documented. Over and above that, it's great from a usability point of view for new users that the software gently points out issues interactively as much as is possible. I'll be happy to make pull requests as I go where there are quick wins to make on that front.

[ghost]

Please have a look at #1042 if it does fix your issues or if you have any (additional) suggestions. Reviews are welcome too.

[chorsley]

Thanks @wagner-certat! With #1042 I can confirm intelmqctl check works well for missing parameters. It also now emits errors for the start of a single bot, e.g.

(venv) intelmq@intelmqdev:/opt/intelmq$ intelmqctl start cymru-whois-expert
intelmqctl: Starting cymru-whois-expert...
intelmqctl: cymru-whois-expert is stopped.
CRITICAL - Traceback (most recent call last):
  File "/opt/intelmq/venv/src/intelmq/intelmq/lib/bot.py", line 57, in __init__
    self.__load_defaults_configuration()
  File "/opt/intelmq/venv/src/intelmq/intelmq/lib/bot.py", line 423, in __load_defaults_configuration
    self.parameters.log_processed_messages_seconds = datetime.timedelta(seconds=self.parameters.log_processed_messages_seconds)
AttributeError: 'Parameters' object has no attribute 'log_processed_messages_seconds'

Is there any way we can extend this to intelmqctl start for all bots also? This would be the more common use case to my mind. It remains quiet about errors, e.g.:

(venv) intelmq@intelmqdev:/opt/intelmq$ intelmqctl start
intelmqctl: Starting cymru-whois-expert...
...
intelmqctl: url2fqdn-expert is running.
intelmqctl: Botnet is running.

(venv) intelmq@intelmqdev:/opt/intelmq$ intelmqctl status
intelmqctl: cymru-whois-expert is stopped.
intelmqctl: deduplicator-expert is stopped.
intelmqctl: file-output is stopped.
...

[ghost]

Is there any way we can extend this to intelmqctl start for all bots also?

How shout the output look like then? Imagine 20/20 bots fail to start, each bot has 7 lines of logs. In total this gives 8*20+20=180 lines of output. Alternatively we can just print a hint to start the bots separately or use run-subcommand.

[chorsley]

Speaking for myself, I'd be fine with ~180 lines of output if I could quickly diagnose there was a problem with my settings for all bots. I'd say it's better to be explicit and verbose about the problem if the bots have failed to start.