Merge lp:~sseman/juju-chaos-monkey/logging into lp:juju-chaos-monkey

[Seman]

Added logging and timestamp.

[lp:~sseman/juju-chaos-monkey/logging]

4. By Seman on 2015-04-30

Updated error logging function.

[John George (jog)]

You would not need to provide and maintain the helper log() and log_error() functions if only the root logger was used. Then to write to the log each file would just need to import the logger module and call logger.info(), logger.warning, logger.error(), logger,critical(), logger.debug or logger.exception().

review: Needs Fixing

[lp:~sseman/juju-chaos-monkey/logging]

5. By Seman on 2015-04-30

Removed log() and log_error()

[Seman (sseman)]

Thank you John for the review. I removed log() and log_error(). Also, see inline comments.

[John George (jog)]

Thank you.

review: Approve

=== modified file 'chaos/kill.py'
--- chaos/kill.py	2015-04-29 19:57:39 +0000
+++ chaos/kill.py	2015-04-30 22:20:24 +0000
@@ -1,9 +1,10 @@
+import logging
+
 from chaos_monkey_base import (
     Chaos,
     ChaosMonkeyBase,
 )
 from utility import (
-    log,
     NotFound,
     run_shell_command,
 )
@@ -29,20 +30,20 @@
         return pids.split(' ')
 
     def kill_jujud(self, quiet_mode=True):
-        log("Kill.kill_jujud")
+        logging.info("Kill.kill_jujud")
         pids = self.get_pids('jujud')
         if not pids:
-            log("Jujud process ID not found")
+            logging.error("Jujud process ID not found")
             if not quiet_mode:
                 raise NotFound('Process id not found')
             return
         run_shell_command('kill -s SIGKILL ' + pids[0])
 
     def kill_mongodb(self, quiet_mode=True):
-        log("Kill.kill_mongod")
+        logging.info("Kill.kill_mongod")
         pids = self.get_pids('mongod')
         if not pids:
-            log("MongoDB process ID not found")
+            logging.error("MongoDB process ID not found")
             if not quiet_mode:
                 raise NotFound('Process id not found')
             return

=== modified file 'chaos/net.py'
--- chaos/net.py	2015-04-29 19:57:39 +0000
+++ chaos/net.py	2015-04-30 22:20:24 +0000
@@ -1,9 +1,10 @@
+import logging
+
 from chaos_monkey_base import (
     Chaos,
     ChaosMonkeyBase,
 )
 from utility import (
-    log,
     run_shell_command,
 )
 
@@ -22,62 +23,62 @@
         return cls()
 
     def reset(self):
-        log("Net.reset ")
+        logging.info("Net.reset ")
         cmd = 'ufw reset'
         run_shell_command(cmd)
 
     def default_deny(self):
-        log("Net.default_deny")
+        logging.info("Net.default_deny")
         cmd = "ufw default deny"
         run_shell_command(cmd)
 
     def default_allow(self):
-        log("Net.default_allow")
+        logging.info("Net.default_allow")
         cmd = "ufw default allow"
         run_shell_command(cmd)
 
     def allow_ssh(self):
-        log("Net.allow_ssh")
+        logging.info("Net.allow_ssh")
         cmd = 'ufw allow ssh'
         run_shell_command(cmd)
 
     def deny_ssh(self):
-        log("Net.deny_ssh")
+        logging.info("Net.deny_ssh")
         cmd = 'ufw deny ssh'
         run_shell_command(cmd)
 
     def deny_all_incoming_and_outgoing_except_ssh(self):
-        log("Net.deny_all_incoming_and_outgoing_except_ssh")
+        logging.info("Net.deny_all_incoming_and_outgoing_except_ssh")
         self.deny_all_incoming_except_ssh()
         self.deny_all_outgoing_except_ssh()
 
     def allow_all_incoming_and_outgoing(self):
-        log("Net.allow_all_incoming_and_outgoing")
+        logging.info("Net.allow_all_incoming_and_outgoing")
         self.allow_all_incoming()
         self.allow_all_outgoing()
 
     def deny_all_incoming_except_ssh(self):
-        log("Net.deny_all_incoming_except_ssh")
+        logging.info("Net.deny_all_incoming_except_ssh")
         self.allow_ssh()
         self.default_deny()
 
     def allow_all_incoming(self):
-        log("Net.allow_all_incoming")
+        logging.info("Net.allow_all_incoming")
         self.default_allow()
 
     def deny_all_outgoing_except_ssh(self):
-        log("Net.deny_all_outgoing_except_ssh")
+        logging.info("Net.deny_all_outgoing_except_ssh")
         self.allow_ssh()
         cmd = 'ufw deny out to any'
         run_shell_command(cmd)
 
     def allow_all_outgoing(self):
-        log("Net.allow_all_outgoing")
+        logging.info("Net.allow_all_outgoing")
         cmd = 'ufw delete deny out to any'
         run_shell_command(cmd)
 
     def deny_port(self, port=8080):
-        log("Net.deny_port port=%s" % port)
+        logging.info("Net.deny_port port=%s" % port)
         cmd = 'ufw deny ' + str(port)
         run_shell_command(cmd)
 

=== modified file 'runner.py'
--- runner.py	2015-04-29 19:57:39 +0000
+++ runner.py	2015-04-30 22:20:24 +0000
@@ -1,8 +1,12 @@
 from argparse import ArgumentParser
+import logging
 from time import time
 
 from chaos_monkey import ChaosMonkey
-from utility import BadRequest
+from utility import (
+    BadRequest,
+    setup_logging,
+)
 
 
 def random(run_timeout, enablement_timeout):
@@ -35,6 +39,12 @@
     parser.add_argument(
         '-tt', '--total-timeout', default=60, type=int,
         help="Total timeout in seconds")
+    parser.add_argument('-lp', '--log-path', help='Where to write logs.',
+                        default='log/results.log')
+    parser.add_argument('-lc', '--log-count', default=2, type=int,
+                        help='The number of backups to keep.')
     args = parser.parse_args()
+    setup_logging(log_path=args.log_path, log_count=args.log_count)
+    logging.info('Chaos monkey started')
     random(run_timeout=args.total_timeout,
            enablement_timeout=args.enablement_timeout)

=== modified file 'tests/test_utility.py'
--- tests/test_utility.py	2015-04-29 19:57:39 +0000
+++ tests/test_utility.py	2015-04-30 22:20:24 +0000
@@ -1,9 +1,15 @@
+import logging
+from logging.handlers import RotatingFileHandler
 from subprocess import CalledProcessError
+from tempfile import NamedTemporaryFile
 from unittest import TestCase
 
 from mock import patch
 
-from utility import run_shell_command
+from utility import (
+    run_shell_command,
+    setup_logging,
+)
 
 
 class TestUtility(TestCase):
@@ -20,3 +26,63 @@
     def test_run_shell_command_output(self):
         output = run_shell_command('echo "hello"')
         self.assertEqual(output, '"hello"\n')
+
+    def test_setup_logging(self):
+        with NamedTemporaryFile() as temp_file:
+            setup_logging(temp_file.name, log_count=1)
+        logger = logging.getLogger()
+        self.assertEqual(logger.level, logging.DEBUG)
+        self.assertEqual(logger.name, 'root')
+        handlers = logger.handlers
+        self.assertIn(
+            type(handlers[0]), [RotatingFileHandler, logging.StreamHandler])
+        self.assertIn(
+            type(handlers[1]), [RotatingFileHandler, logging.StreamHandler])
+
+    def test_setup_logging_formatter(self):
+        log_count = 1
+        with NamedTemporaryFile() as temp_file:
+            with patch('logging.Formatter') as l_mock:
+                setup_logging(temp_file.name, log_count=log_count)
+        logger = logging.getLogger()
+        self.assertEqual(logger.name, 'root')
+        l_mock.assert_called_once_with(
+            '%(asctime)s %(levelname)s %(message)s', '%Y-%m-%d %H:%M:%S')
+
+    def test_setup_logging_rotating_file_handler(self):
+        log_count = 1
+        with NamedTemporaryFile() as temp_file:
+            with patch('utility.RotatingFileHandler') as mock:
+                setup_logging(temp_file.name, log_count=log_count)
+        mock.assert_called_once_with(
+            temp_file.name, maxBytes=1024 * 1024 * 512, backupCount=log_count)
+
+    def test_log(self):
+        with NamedTemporaryFile() as temp_file:
+            setup_logging(temp_file.name, log_count=1)
+            logging.info('testing123')
+            with open(temp_file.name, 'r') as file_reader:
+                content = file_reader.read()
+                # log format: 2015-04-29 14:03:02 INFO testing123
+                match = content.split(' ', 2)[2]
+                self.assertEqual(match, 'INFO testing123\n')
+
+    def test_log_debug(self):
+        with NamedTemporaryFile() as temp_file:
+            setup_logging(temp_file.name, log_count=1)
+            logging.debug("testing123")
+            with open(temp_file.name, 'r') as file_reader:
+                content = file_reader.read()
+                # log format: 2015-04-29 14:03:02 INFO testing123
+                match = content.split(' ', 2)[2]
+                self.assertEqual(match, 'DEBUG testing123\n')
+
+    def test_log_error(self):
+        with NamedTemporaryFile() as temp_file:
+            setup_logging(temp_file.name, log_count=1)
+            logging.error("testing123")
+            with open(temp_file.name, 'r') as file_reader:
+                content = file_reader.read()
+                # log format: 2015-04-29 14:03:02 INFO testing123
+                match = content.split(' ', 2)[2]
+                self.assertEqual(match, 'ERROR testing123\n')

=== modified file 'utility.py'
--- utility.py	2015-04-29 19:57:39 +0000
+++ utility.py	2015-04-30 22:20:24 +0000
@@ -1,5 +1,8 @@
 from __future__ import print_function
 
+import logging
+from logging.handlers import RotatingFileHandler
+
 from subprocess import (
     CalledProcessError,
     check_output,
@@ -12,14 +15,25 @@
     try:
         output = check_output(shell_cmd)
     except CalledProcessError:
-        log("Command generated error: %s " % cmd)
+        logging.error("Command generated error: %s " % cmd)
         if not quiet_mode:
             raise
     return output
 
 
-def log(log_str):
-    print(log_str)
+def setup_logging(log_path, log_count):
+    """Install log handlers to output to file and stream."""
+    formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s',
+                                  '%Y-%m-%d %H:%M:%S')
+    root_logger = logging.getLogger()
+    rf_handler = RotatingFileHandler(
+        log_path, maxBytes=1024 * 1024 * 512, backupCount=log_count)
+    rf_handler.setFormatter(formatter)
+    root_logger.addHandler(rf_handler)
+    s_handler = logging.StreamHandler()
+    s_handler.setFormatter(formatter)
+    root_logger.addHandler(s_handler)
+    root_logger.setLevel(logging.DEBUG)
 
 
 class NotFound(Exception):