Bot debugging

intelmq/bin/intelmqctl.py

@@ -15,6 +15,7 @@
                      STARTUP_CONF_FILE, SYSTEM_CONF_FILE, VAR_RUN_PATH,
                      BOTS_FILE)
 from intelmq.lib import utils
+from intelmq.lib.bot_debugger import BotDebugger
 from intelmq.lib.pipeline import PipelineFactory
 
 
@@ -117,33 +118,32 @@ def __init__(self, runtime_configuration, logger, controller):
                 self.logger.error('Directory %s does not exist and cannot be '
                                   'created: %s.', self.PIDDIR, exc)
 
-    def bot_run(self, bot_id):
+    def bot_run(self, bot_id, run_subcommand=None, message_action_kind=None, dryrun=None, msg=None):
         pid = self.__read_pidfile(bot_id)
-        if pid:
-            if self.__status_process(pid):
-                log_bot_error('running', bot_id)
-                return 'running'
-            else:
-                self.__remove_pidfile(bot_id)
+        if pid and self.__status_process(pid):
+            paused = True
+            self.bot_stop(bot_id)
+        else:
+            paused = False
+
         log_bot_message('starting', bot_id)
         filename = self.PIDFILE.format(bot_id)
         with open(filename, 'w') as fp:
             fp.write(str(os.getpid()))
 
-        bot_module = self.__runtime_configuration[bot_id]['module']
-        module = importlib.import_module(bot_module)
-        bot = getattr(module, 'BOT')
         try:
-            instance = bot(bot_id)
-            instance.start()
-        except (Exception, KeyboardInterrupt) as exc:
-            print('Bot failed: %s' % exc)
-            retval = 1
+            BotDebugger(self.__runtime_configuration[bot_id]['module'], bot_id, run_subcommand, message_action_kind, dryrun, msg)
+            retval = 0
+        except KeyboardInterrupt:
+            print('Keyboard interrupt.')
+            retval = 0
         except SystemExit as exc:
             print('Bot exited with code %s.' % exc)
             retval = exc
 
         self.__remove_pidfile(bot_id)
+        if paused:
+            self.bot_start(bot_id)
         return retval
 
     def bot_start(self, bot_id, getstatus=True):
@@ -305,10 +305,12 @@ def __init__(self, interactive: bool=False, return_type: str="python", quiet: bo
 
         Outputs are logged to /opt/intelmq/var/log/intelmqctl"""
         EPILOG = '''
-        intelmqctl [start|stop|restart|status|reload|run] bot-id
+        intelmqctl [start|stop|restart|status|reload] bot-id
         intelmqctl [start|stop|restart|status|reload]
         intelmqctl list [bots|queues]
         intelmqctl log bot-id [number-of-lines [log-level]]
+        intelmqctl run bot-id message [get|pop|send --msg]
+        intelmqctl run bot-id process [--msg|--dryrun]
         intelmqctl clear queue-id
         intelmqctl check
 
@@ -321,8 +323,12 @@ def __init__(self, interactive: bool=False, return_type: str="python", quiet: bo
 Get status of a bot:
     intelmqctl status bot-id
 
-Run a bot directly (blocking) for debugging purpose:
+Run a bot directly for debugging purpose and temporarily leverage the logging level to DEBUG:
     intelmqctl run bot-id
+See the message that waits in the input queue.
+    intelmqctl run bot-id message get
+See additional help for further explanation.
+    intelmqctl run bot-id --help
 
 Starting the botnet (all bots):
     intelmqctl start
@@ -434,6 +440,19 @@ def __init__(self, interactive: bool=False, return_type: str="python", quiet: bo
             parser_run = subparsers.add_parser('run', help='Run a bot interactively')
             parser_run.add_argument('bot_id',
                                     choices=self.runtime_configuration.keys())
+            parser_run_subparsers = parser_run.add_subparsers(title='run-subcommands')
+            parser_run_message = parser_run_subparsers.add_parser('message', help='Debug bot\'s pipelines. Get the message in the input pipeline, pop it (cut it) and display it, or send the message directly to bot\'s output pipeline.')
+            parser_run_message.add_argument('message_action_kind', choices=["get", "pop", "send"])
+            parser_run_message.add_argument('msg', nargs='?', help='If send was chosen, put here the message in JSON.')
+            parser_run_message.set_defaults(run_subcommand="message")
+            parser_run_process = parser_run_subparsers.add_parser('process', help='Single run of bot\'s process() method.')
+            parser_run_process.add_argument('--dryrun', '-d', action='store_true',
+                                            help='Never really pop the message from the input pipeline '
+                                                 'nor send to output pipeline.')
+            parser_run_process.add_argument('--msg', '-m',
+                                            help='Trick the bot to process this JSON '
+                                                 'instead of the Message in its pipeline.')
+            parser_run_process.set_defaults(run_subcommand="process")
             parser_run.set_defaults(func=self.bot_run)
 
             parser_check = subparsers.add_parser('check',
@@ -518,8 +537,8 @@ def run(self):
         elif results == 'error':
             return 1
 
-    def bot_run(self, bot_id):
-        return self.bot_process_manager.bot_run(bot_id)
+    def bot_run(self, bot_id, run_subcommand=None, message_action_kind=None, dryrun=None, msg=None):
+        return self.bot_process_manager.bot_run(bot_id, run_subcommand, message_action_kind, dryrun, msg)
 
     def bot_start(self, bot_id, getstatus=True):
         if bot_id is None:
@@ -865,6 +884,5 @@ def main():  # pragma: no cover
     x = IntelMQController(interactive=True)
     return x.run()
 
-
 if __name__ == "__main__":  # pragma: no cover
     exit(main())

intelmq/lib/bot_debugger.py

@@ -0,0 +1,84 @@
+# -*- coding: utf-8 -*-
+"""
+Utilities for debugging intelmq bots.
+
+BotDebugger is called via intelmqctl. It starts a live running bot instance,
+leverages logging to DEBUG level and permits even a non-skilled programmer
+who may find themselves puzzled with Python nuances and server deployment twists
+to see what's happening in the bot and where's the error.
+
+Depending on the subcommand received, the class either
+ * starts the bot as is (default)
+ * processes single message, either injected or from default pipeline (process subcommand)
+ * reads the message from input pipeline or send a message to output pipeline (message subcommand)
+"""
+import logging
+import json
+from pprint import pprint
+
+from importlib import import_module
+from intelmq.lib.utils import StreamHandler, error_message_from_exc
+from intelmq.lib.message import Event, MessageFactory
+
+
+class BotDebugger:
+        def leverageLogger(self, level=logging.DEBUG):
+            self.instance.logger.setLevel(level)
+            for h in self.instance.logger.handlers:
+                if isinstance(h, StreamHandler):
+                    h.setLevel(level)
+
+        def __init__(self, module_path, bot_id, run_subcommand=None, message_kind=None, dryrun=None, msg=None):
+            module = import_module(module_path)
+            bot = getattr(module, 'BOT')
+            self.instance = bot(bot_id)
+            self.leverageLogger()
+
+            if not run_subcommand:
+                self.instance.start()
+            else:
+                self.instance._Bot__connect_pipelines()
+                if run_subcommand == "process":
+                    self._process(dryrun, msg)
+                elif run_subcommand == "message":
+                    self.leverageLogger(level=logging.INFO)
+                    self._message(message_kind, msg)
+                else:
+                    print("Subcommand {} not known.".format(run_subcommand))
+
+        def _process(self, dryrun, msg):
+            if msg:
+                self.instance._Bot__source_pipeline.receive = lambda: msg
+                self.instance.logger.info("Message from cli will be used when processing.")
+
+            if dryrun:
+                self.instance.send_message = lambda msg: self.instance.logger.info("DRYRUN: Message would be sent now!")
+                self.instance.acknowledge_message = lambda: self.instance.logger.info("DRYRUN: Message would be acknowledged now!")
+                print("Dryrun only, no message will be really sent through.")
+
+            self.instance.logger.info("Processing...")
+            self.instance.process()
+
+        class PoorBot:
+            pass
+
+        def _message(self, message_action_kind, msg):
+            if message_action_kind == "get":
+                self.instance.logger.info("Trying to get the message...")
+                pprint(self.instance.receive_message())
+            elif message_action_kind == "pop":
+                self.instance.logger.info("Trying to pop the message...")
+                pprint(self.instance.receive_message())
+                self.instance.acknowledge_message()
+            elif message_action_kind == "send":
+                if msg:
+                    try:
+                        msg = MessageFactory.unserialize(msg)
+                    except (Exception, KeyError, TypeError, json.JSONDecodeError) as exc:
+                        print("Message can not be parsed from JSON: " + error_message_from_exc(exc))
+                        return
+                    self.instance.send_message(msg)
+                    self.instance.logger.info("Message sent to output pipelines.")
+                else:
+                    self.instance.logger.info("Message missing!")
+