ENH: Log count of processed messages configurable

fixes #743

CHANGELOG.md

@@ -4,6 +4,12 @@ CHANGELOG
 in development
 --------------
 
+### General changes
+- It's now configurable how often the bots are logging how much events they have sent, based on both the amount and time. (fixes #743)
+
+### Configuration
+- Added `log_processed_messages_count` (500) and `log_processed_messages_seconds` (900) to defaults.conf.
+
 ### Documentation
 - Dropped install scripts, see INSTALL.md for more detailed instructions and explanations
 

NEWS.md

@@ -13,6 +13,12 @@ See the changelog for a full list of changes.
 in development
 --------------
 
+### Configuration
+Two new fields have been added to `defaults.conf` which are expected by the bots:
+- `"log_processed_messages_count": 500` and
+- `'log_processed_messages_seconds": 900`
+Configure them in your setup and optionally adapt the values to your needs.
+
 ### Postgres databases
 Use the following statement carefully to upgrade your database.
 ```SQL

intelmq/etc/defaults.conf

@@ -16,6 +16,8 @@
     "http_verify_cert": true,
     "https_proxy": null,
     "load_balance": false,
+    "log_processed_messages_count": 500,
+    "log_processed_messages_seconds": 900,
     "logging_handler": "file",
     "logging_level": "INFO",
     "logging_path": "/opt/intelmq/var/log/",

intelmq/lib/bot.py

@@ -30,6 +30,7 @@ class Bot(object):
     """ Not to be reset when initialized again on reload. """
     __current_message = None
     __message_counter = 0
+    __message_counter_start = None
     # Bot is capable of SIGHUP delaying
     sighup_delay = True
 
@@ -335,8 +336,13 @@ def send_message(self, *messages):
 
             self.logger.debug("Sending message.")
             self.__message_counter += 1
-            if self.__message_counter % 500 == 0:
-                self.logger.info("Processed %s messages.", self.__message_counter)
+            if not self.__message_counter_start:
+                self.__message_counter_start = datetime.datetime.now()
+            if self.__message_counter % self.parameters.log_processed_messages_count == 0 or \
+               datetime.datetime.now() - self.__message_counter_start > self.parameters.log_processed_messages_seconds:
+                self.logger.info("Processed %d messages since last logging.", self.__message_counter)
+                self.__message_counter = 0
+                self.__message_counter_start = datetime.datetime.now()
 
             raw_message = libmessage.MessageFactory.serialize(message)
             self.__destination_pipeline.send(raw_message)
@@ -414,6 +420,8 @@ def __load_defaults_configuration(self):
             setattr(self.parameters, option, value)
             self.__log_configuration_parameter("defaults", option, value)
 
+        self.parameters.log_processed_messages_seconds = datetime.timedelta(seconds=self.parameters.log_processed_messages_seconds)
+
     def __load_system_configuration(self):
         if os.path.exists(SYSTEM_CONF_FILE):
             self.__log_buffer.append(('warning', "system.conf is deprecated "

intelmq/tests/lib/test_bot.py

@@ -12,10 +12,7 @@
 import intelmq.lib.pipeline as pipeline
 import intelmq.lib.utils as utils
 import intelmq.lib.test as test
-
-
-with mock.patch('intelmq.lib.utils.load_configuration', new=test.mocked_config()):
-    from intelmq.tests.lib import test_parser_bot
+from intelmq.tests.lib import test_parser_bot
 
 
 class TestBot(unittest.TestCase):

intelmq/tests/lib/test_parser_bot.py

@@ -1,5 +1,6 @@
 # -*- coding: utf-8 -*-
 import base64
+import datetime
 import unittest
 import unittest.mock as mock
 
@@ -48,7 +49,6 @@
 192.0.2.3,bllaa
 #ending line
 """
-RAW_SPLIT = RAW.strip().splitlines()
 
 EXAMPLE_REPO_1 = {"feed.url": "http://www.example.com/",
                   "time.observation": "2015-08-11T13:03:40+00:00",
@@ -63,6 +63,9 @@
                  'raw': 'c291cmNlLmlwLGZvb2Jhcg0KMTkyLjAuMi4zLGJsbGFhDQo='
                  }
 
+EXAMPLE_SHORT = EXAMPLE_REPORT.copy()
+EXAMPLE_SHORT['raw'] = utils.base64_encode('\n'.join(RAW_SPLIT[:2] + [RAW_SPLIT[1]]))
+
 
 class DummyParserBot(bot.ParserBot):
     """
@@ -141,6 +144,21 @@ def test_missing_raw(self):
                                            'bug or misconfiguration in previous bots.',
                                    levelname='WARNING')
 
+    def test_processed_mesages_count(self):
+        self.sysconfig = {'log_processed_messages_count': 1}
+        self.input_message = EXAMPLE_SHORT
+        self.run_bot()
+        self.assertAnyLoglineEqual(message='Processed 1 messages since last logging.',
+                                   levelname='INFO')
+
+    def test_processed_mesages_seconds(self):
+        self.sysconfig = {'log_processed_messages_count': 10,
+                          'log_processed_messages_seconds': datetime.timedelta(seconds=0)}
+        self.input_message = EXAMPLE_SHORT
+        self.run_bot()
+        self.assertAnyLoglineEqual(message='Processed 1 messages since last logging.',
+                                   levelname='INFO')
+
 
 class TestDummyCSVParserBot(test.BotTestCase, unittest.TestCase):
     @classmethod