Merge pull request #35 from Alignak-monitoring-contrib/log-datetime

Set default log date format as YYYY-MM-DD HH:MM:SS

alignak_module_logs/etc/arbiter/modules/mod-logs-logger.json

@@ -4,6 +4,7 @@
     "formatters": {
         "local": {
             "format": "[%(asctime)s] %(levelname)s: [%(name)s] %(message)s"
+            ,"datefmt": "%Y-%m-%d %H:%M:%S"
         }
     },
 

alignak_module_logs/logs.py

@@ -206,6 +206,7 @@ def getBackendAvailability(self):
         if not self.backend_generate:
             generate = 'disabled'
 
+        self.backend_available = False
         try:
             if not self.backend.authenticated:
                 logger.info("Signing-in to the backend...")
@@ -219,7 +220,6 @@ def getBackendAvailability(self):
             logger.warning("Alignak backend is currently not available.")
             logger.warning("Exception: %s", exp)
             logger.warning("Response: %s", exp.response)
-            self.backend_available = False
 
     def do_loop_turn(self):  # pragma: no cover
         """This function is present because of an abstract function in the BaseModule class"""

test/mod-logs-logger-datetime.json

@@ -0,0 +1,61 @@
+{
+    "version": 1,
+    "disable_existing_loggers": false,
+    "formatters": {
+        "local": {
+            "format": "[%(asctime)s] %(levelname)s: [%(name)s] %(message)s"
+            ,"datefmt": "%Y-%m-%d %H:%M:%S"
+        }
+    },
+
+    "handlers": {
+        "console": {
+            "class": "logging.StreamHandler",
+            "level": "DEBUG",
+            "formatter": "local",
+            "stream": "ext://sys.stdout"
+        },
+        "rotating_file_handler": {
+            "class": "logging.handlers.RotatingFileHandler",
+            "level": "INFO",
+            "formatter": "local",
+            "filename": "./logs3/rotating-monitoring.log",
+            "maxBytes": 10485760,
+            "backupCount": 20,
+            "encoding": "utf8"
+        },
+        "timed_rotating_file_handler": {
+            "class": "logging.handlers.TimedRotatingFileHandler",
+            "level": "INFO",
+            "formatter": "local",
+            "filename": "./logs3/timed-rotating-monitoring.log",
+            "when": "midnight",
+            "interval": 1,
+            "backupCount": 20,
+            "encoding": "utf8"
+        },
+        "monitoring_logs": {
+            "class": "logging.handlers.TimedRotatingFileHandler",
+            "level": "INFO",
+            "formatter": "local",
+            "filename": "./logs3/monitoring-logs.log",
+            "when": "midnight",
+            "interval": 1,
+            "backupCount": 30,
+            "encoding": "utf8"
+        }
+    },
+
+    "loggers": {
+        "monitoring-logs": {
+            "level": "INFO",
+            "handlers": ["monitoring_logs"],
+            "propagate": "no"
+        }
+    },
+
+    "root": {
+        "level": "INFO",
+        "handlers": ["console", "rotating_file_handler", "timed_rotating_file_handler"]
+    }
+}

test/test_module.py

@@ -453,7 +453,7 @@ def test_module_start_parameters_2(self):
             re.escape(" - rotation every 1 midnight, keeping 365 files"), 6)
 
         # -----
-        # Provide parameters - logger configuration file (exists)
+        # Provide parameters - logger configuration file with a syntax error
         # -----
         # Clear logs
         self.clear_logs()
@@ -788,3 +788,145 @@ def test_module_zzz_logger_json_configuration(self):
         # And we clear all now
         self.modulemanager.stop_all()
         # Stopping module logs
+
+    def test_module_zzz_logger_json_configuration_date_format(self):
+        """Test the module with a logger configured with a json file - set date formatting
+        :return:
+        """
+        self.print_header()
+        # Obliged to call to get a self.logger...
+        self.setup_with_file('cfg/cfg_default.cfg')
+        self.assertTrue(self.conf_is_correct)
+
+        if not os.path.exists('./logs3'):
+            os.mkdir('./logs3')
+
+        if os.path.exists('./logs3/monitoring-logs.log'):
+            os.remove('./logs3/monitoring-logs.log')
+
+        # Create an Alignak module
+        mod = Module({
+            'module_alias': 'logs',
+            'module_types': 'logs',
+            'python_name': 'alignak_module_logs',
+            'logger_configuration': './mod-logs-logger-datetime.json',
+        })
+
+        # Create the modules manager for a daemon type
+        self.modulemanager = ModulesManager('receiver', None)
+
+        # Load an initialize the modules:
+        #  - load python module
+        #  - get module properties and instances
+        self.modulemanager.load_and_init([mod])
+
+        # Clear logs
+        self.clear_logs()
+
+        my_module = self.modulemanager.instances[0]
+
+        # Start external modules
+        self.modulemanager.start_external_instances()
+
+        # Starting external module logs
+        self.assert_log_match("Trying to initialize module: logs", 0)
+        self.assert_log_match("Starting external module logs", 1)
+        self.assert_log_match("Starting external process for module logs", 2)
+        self.assert_log_match("logs is now started", 3)
+
+        time.sleep(1)
+
+        # Check alive
+        self.assertIsNotNone(my_module.process)
+        self.assertTrue(my_module.process.is_alive())
+
+        time.sleep(1)
+
+        instance = alignak_module_logs.get_instance(mod)
+        self.assertIsInstance(instance, BaseModule)
+
+        # No more logs because the logger got re-configured... but some files exist
+        self.assertTrue(os.path.exists('./logs3/monitoring-logs.log'))
+        # self.assertTrue(os.path.exists('/tmp/rotating-monitoring.log'))
+        # self.assertTrue(os.path.exists('/tmp/timed-rotating-monitoring.log'))
+        time.sleep(5)
+        # On Travis build this assertion fails !
+        # self.assertTrue(os.path.exists('/tmp/monitoring-logs.log'))
+
+        b = Brok({'type': 'monitoring_log', 'data': {'level': 'info', 'message': 'test message'}})
+        b.prepare()
+        instance.manage_brok(b)
+
+        b = Brok({'type': 'monitoring_log', 'data': {'level': 'info',
+                                                     'message': 'test message\r\nlong output'}})
+        b.prepare()
+        instance.manage_brok(b)
+
+        # Get the monitoring logs log file that should contain only two lines
+        with open('./logs3/monitoring-logs.log', 'r') as f:
+            data = f.readlines()
+            print(data)
+            # Only two lines, even if a message has a \r
+            self.assertEqual(2, len(data))
+
+        # Stop the module
+        self.modulemanager.clear_instances()
+
+        self.show_logs()
+        self.assert_log_match("Trying to initialize module: logs", 0)
+        self.assert_log_match("Starting external module logs", 1)
+        self.assert_log_match("Starting external process for module logs", 2)
+        self.assert_log_match("logs is now started", 3)
+        self.assert_log_match("Give an instance of alignak_module_logs for alias: logs", 4)
+        self.assert_log_match("logger configuration defined in ./mod-logs-logger-datetime.json", 5)
+        self.assert_log_match("Alignak Backend is not configured. "
+                              "Some module features will not be available.", 6)
+        self.assert_log_match("Request external process to stop for logs", 7)
+        self.assert_log_match("I'm stopping module 'logs'", 8)
+        self.assert_log_match("External process stopped.", 9)
+
+        # Load an initialize the modules:
+        #  - load python module
+        #  - get module properties and instances
+        self.modulemanager.load_and_init([mod])
+
+        my_module = self.modulemanager.instances[0]
+
+        # Start external modules
+        self.modulemanager.start_external_instances()
+
+        self.show_logs()
+
+        b = Brok({'type': 'monitoring_log', 'data': {'level': 'info', 'message': 'test message'}})
+        b.prepare()
+        instance.manage_brok(b)
+
+        b = Brok({'type': 'monitoring_log', 'data': {'level': 'info',
+                                                     'message': 'test message\r\nlong output'}})
+        b.prepare()
+        instance.manage_brok(b)
+
+        b = Brok({'type': 'monitoring_log', 'data': {'level': 'info', 'message': 'test message'}})
+        b.prepare()
+        instance.manage_brok(b)
+
+        b = Brok({'type': 'monitoring_log', 'data': {'level': 'info',
+                                                     'message': 'test message\r\nlong output'}})
+        b.prepare()
+        instance.manage_brok(b)
+
+        # Get the monitoring logs log file that should contain only two lines
+        # 6 lines:
+        #  - 2 existing before module stop and restart,
+        #  - 4 broks received after restart
+        with open('./logs3/monitoring-logs.log', 'r') as f:
+            data = f.readlines()
+            print(data)
+            self.assertEqual(6, len(data))
+
+        # Stop the module
+        self.modulemanager.clear_instances()
+
+        # And we clear all now
+        self.modulemanager.stop_all()
+        # Stopping module logs

test/test_module_backend.py

@@ -334,11 +334,32 @@ def test_module_zzz_get_logs(self):
         b.prepare()
         instance.manage_brok(b)
 
+        b = Brok({'type': 'monitoring_log', 'data': {
+            'level': 'info',
+            'message': "HOST COMMENT: test;alignak;Host comment"
+        }})
+        b.prepare()
+        instance.manage_brok(b)
+
+        b = Brok({'type': 'monitoring_log', 'data': {
+            'level': 'info',
+            'message': "HOST COMMENT: test;alignak;Host comment 2"
+        }})
+        b.prepare()
+        instance.manage_brok(b)
+
+        b = Brok({'type': 'monitoring_log', 'data': {
+            'level': 'info',
+            'message': "HOST COMMENT: test;alignak;Host comment 3"
+        }})
+        b.prepare()
+        instance.manage_brok(b)
+
         # Get log file that should contain one line
         with open('./logs2/monitoring-logs.log', 'r') as f:
             data = f.readlines()
         print("Read data: %s" % data)
-        self.assertEqual(13, len(data))
+        self.assertEqual(16, len(data))
         logs = []
         for line in data:
             line = line.replace('ERROR: ', '')
@@ -397,7 +418,7 @@ def test_module_zzz_get_logs(self):
         r = backend.get('history')
         for item in r['_items']:
             print("- %s" % item)
-        self.assertEqual(len(r['_items']), 6)
+        self.assertEqual(len(r['_items']), 9)
 
         assert r['_items'][0]['host_name'] == 'n/a'
         assert r['_items'][0]['service_name'] == 'n/a'
@@ -435,5 +456,23 @@ def test_module_zzz_get_logs(self):
         assert r['_items'][5]['type'] == 'webui.comment'
         assert r['_items'][5]['message'] == 'Service comment'
 
+        assert r['_items'][6]['host_name'] == 'test'
+        assert r['_items'][6]['service_name'] == 'n/a'
+        assert r['_items'][6]['user_name'] == 'alignak'
+        assert r['_items'][6]['type'] == 'webui.comment'
+        assert r['_items'][6]['message'] == 'Host comment'
+
+        assert r['_items'][7]['host_name'] == 'test'
+        assert r['_items'][7]['service_name'] == 'n/a'
+        assert r['_items'][7]['user_name'] == 'alignak'
+        assert r['_items'][7]['type'] == 'webui.comment'
+        assert r['_items'][7]['message'] == 'Host comment 2'
+
+        assert r['_items'][8]['host_name'] == 'test'
+        assert r['_items'][8]['service_name'] == 'n/a'
+        assert r['_items'][8]['user_name'] == 'alignak'
+        assert r['_items'][8]['type'] == 'webui.comment'
+        assert r['_items'][8]['message'] == 'Host comment 3'
+
         # Note that RETENTION, CURRENT STATE, and CHECKS monitoring log
         # are not stored as events in the Alignak backend!