[asterisk-commits] mjordan: testsuite/asterisk/trunk r5029 - in /asterisk/trunk: ./ lib/python/a...

SVN commits to the Asterisk project asterisk-commits at lists.digium.com
Tue May 13 07:46:42 CDT 2014


Author: mjordan
Date: Tue May 13 07:46:28 2014
New Revision: 5029

URL: http://svnview.digium.com/svn/testsuite?view=rev&rev=5029
Log:
testsuite: Improve Logging

This patch changes up the logging in the Asterisk Test Suite. It reduces the
amount of logging done in the logs/ directory by default (although this can
always be bumped up via logger.conf), and it redirects the vast majority of
the test suite logs to the actual sandboxed test run directories themselves.

When we first added Python logging, there were far fewer tests. Having all
tests dump into the same log files actually felt like a benefit, since
during test development (or when developing many tests) it made it easier to
debug test failures. Over time, however, this approach has run into a number
of problems:
(1) Many of the tests are much 'chattier' than they used to be. Having twisted,
    starpy, websockets, requests, and other libraries dump information has
    greatly increased the number of log messages.
(2) There are a lot more tests than there were when this was added.
(3) Tailing a log file is not always the best way to debug. Sometimes you have
    to search through an entire log file for one run. Finding the error
    becomes problematic when your editor of choice chokes on the size of the
    file. This is particularly true for the continuous integration agents,
    which have to include incredibly large log files when a test fails.

Hence, this patch.

Logging now works in the following way:
(1) The test_case.TestCase class now always sets up the logging. The logging
    set up done by test_runner was removed (as it only logged out a few
    messages before an instance of TestCase was created anyway).
(2) A global logger can still be configured in logger.conf. It now only sets up
    a logger of INFO messages and higher. This allows a test executor to watch
    which tests are being run, without getting spammed. During test
    development, the log message level can be increased to DEBUG.
(3) TestCase now places the Asterisk directories created by the test execution
    in a further subfolder, run_N (where N increases with each execution of
    that test). Where before you might have:

      tests/my_test/ast1
      tests/my_test/ast2
      tests/my_test/ast3
      tests/my_test/ast4

    You will now have:

      tests/my_test/run_1/ast1
      tests/my_test/run_1/ast2
      tests/my_test/run_2/ast1
      tests/my_test/run_2/ast2

    This lets you determine which Asterisk instances belong together, and also
    makes it possible for only the erroring test run to be archived when a test
    fails (as opposed to every Asterisk directory)
(4) TestCase now creates a DEBUG and INFO log file(s) in the run directory.
    These contain the full Asterisk logs for the test run.

Review: https://reviewboard.asterisk.org/r/3489/


Modified:
    asterisk/trunk/lib/python/asterisk/asterisk.py
    asterisk/trunk/lib/python/asterisk/test_case.py
    asterisk/trunk/lib/python/asterisk/test_runner.py
    asterisk/trunk/logger.conf
    asterisk/trunk/runtests.py

Modified: asterisk/trunk/lib/python/asterisk/asterisk.py
URL: http://svnview.digium.com/svn/testsuite/asterisk/trunk/lib/python/asterisk/asterisk.py?view=diff&rev=5029&r1=5028&r2=5029
==============================================================================
--- asterisk/trunk/lib/python/asterisk/asterisk.py (original)
+++ asterisk/trunk/lib/python/asterisk/asterisk.py Tue May 13 07:46:28 2014
@@ -212,14 +212,15 @@
         self._stop_cancel_tokens = []
         self.directories = {}
         self.ast_version = AsteriskVersion()
-        self.base = Asterisk.test_suite_root
         self.process_protocol = None
         self.process = None
         self.astetcdir = ""
         self.original_astmoddir = ""
 
         if base is not None:
-            self.base = "%s/%s" % (self.base, base)
+            self.base = base
+        else:
+            self.base = Asterisk.test_suite_root
         if self.localtest_root:
             self.ast_binary = self.localtest_root + "/usr/sbin/asterisk"
         else:

Modified: asterisk/trunk/lib/python/asterisk/test_case.py
URL: http://svnview.digium.com/svn/testsuite/asterisk/trunk/lib/python/asterisk/test_case.py?view=diff&rev=5029&r1=5028&r2=5029
==============================================================================
--- asterisk/trunk/lib/python/asterisk/test_case.py (original)
+++ asterisk/trunk/lib/python/asterisk/test_case.py Tue May 13 07:46:28 2014
@@ -1,6 +1,6 @@
 #!/usr/bin/env python
 """
-Copyright (C) 2010-2012, Digium, Inc.
+Copyright (C) 2010-2014, Digium, Inc.
 Paul Belanger <pabelanger at digium.com>
 
 This program is free software, distributed under the terms of
@@ -31,12 +31,14 @@
 except:
     PCAP_AVAILABLE = False
 
-LOGGER = logging.getLogger(__name__)
-
-def setup_logging():
+LOGGER = None
+
+def setup_logging(log_dir):
     """Initialize the logger"""
 
-    config_file = os.path.join(os.getcwd(), TestCase.default_log_file_name)
+    global LOGGER
+
+    config_file = os.path.join(os.getcwd(), "logger.conf")
     if os.path.exists(config_file):
         try:
             logging.config.fileConfig(config_file, None, False)
@@ -49,7 +51,26 @@
         msg = ("WARNING: no logging.conf file found; using default "
                "configuration")
         print msg
-        logging.basicConfig(level=TestCase.default_log_level)
+        logging.basicConfig(level=logging.DEBUG)
+
+    root_logger = logging.getLogger()
+    root_logger.setLevel(level=logging.DEBUG)
+
+    LOGGER = logging.getLogger(__name__)
+
+    fmt = '[%(asctime)s] %(levelname)s[%(process)d]: %(name)s:%(lineno)d %(funcName)s: %(message)s'
+    datefmt = '%b %d %H:%M:%S'
+    form = logging.Formatter(fmt=fmt, datefmt=datefmt)
+
+    fh = logging.FileHandler(os.path.join(log_dir, 'full.txt'))
+    fh.setLevel(logging.DEBUG)
+    fh.setFormatter(form)
+    root_logger.addHandler(fh)
+
+    mh = logging.FileHandler(os.path.join(log_dir, 'messages.txt'))
+    mh.setLevel(logging.INFO)
+    mh.setFormatter(form)
+    root_logger.addHandler(mh)
 
 
 class TestCase(object):
@@ -58,11 +79,7 @@
     twisted reactor, and various other utilities.
     """
 
-    default_log_file_name = "logger.conf"
-
-    default_log_level = "WARN"
-
-    def __init__(self, test_path = '', test_config=None):
+    def __init__(self, test_path='', test_config=None):
         """Create a new instance of a TestCase. Must be called by inheriting
         classes.
 
@@ -109,9 +126,7 @@
         self.pcapfilename = None
         self.create_pcap = False
         self._stopping = False
-        self.testlogdir = os.path.join(Asterisk.test_suite_root,
-                                       self.base,
-                                       str(os.getpid()))
+        self.testlogdir = self._set_test_log_directory()
         self.ast_version = AsteriskVersion()
         self._start_callbacks = []
         self._stop_callbacks = []
@@ -130,7 +145,9 @@
         os.makedirs(self.testlogdir)
 
         # Set up logging
-        setup_logging()
+        setup_logging(self.testlogdir)
+
+        LOGGER.info("Executing " + self.test_name)
 
         if PCAP_AVAILABLE and self.create_pcap:
             self.pcapfilename = os.path.join(self.testlogdir, "dumpfile.pcap")
@@ -138,13 +155,24 @@
 
         self._setup_conditions()
 
-        LOGGER.info("Executing " + self.test_name)
-
         # Enable twisted logging
         observer = log.PythonLoggingObserver()
         observer.start()
 
         reactor.callWhenRunning(self._run)
+
+    def _set_test_log_directory(self):
+        """Determine which logging directory we should use for this test run
+
+        Returns:
+        The full path that should be used as the directory for all log data
+        """
+        i = 1
+        base_path = os.path.join(Asterisk.test_suite_root, self.base)
+        while os.path.isdir(os.path.join(base_path, "run_%d" % i)):
+            i += 1
+        full_path = os.path.join(base_path, "run_%d" % i)
+        return full_path
 
     def _setup_conditions(self):
         """Register pre and post-test conditions.
@@ -208,7 +236,7 @@
             num = i + 1
             LOGGER.info("Creating Asterisk instance %d" % num)
             host = "127.0.0.%d" % num
-            self.ast.append(Asterisk(base=self.base, host=host,
+            self.ast.append(Asterisk(base=self.testlogdir, host=host,
                                      ast_conf_options=self.ast_conf_options))
             self.condition_controller.register_asterisk_instance(self.ast[i])
             # If a base configuration for this Asterisk instance has been

Modified: asterisk/trunk/lib/python/asterisk/test_runner.py
URL: http://svnview.digium.com/svn/testsuite/asterisk/trunk/lib/python/asterisk/test_runner.py?view=diff&rev=5029&r1=5028&r2=5029
==============================================================================
--- asterisk/trunk/lib/python/asterisk/test_runner.py (original)
+++ asterisk/trunk/lib/python/asterisk/test_runner.py Tue May 13 07:46:28 2014
@@ -4,7 +4,7 @@
 This module provides an entry point, loading, and teardown of test
 runs for the Test Suite
 
-Copyright (C) 2012, Digium, Inc.
+Copyright (C) 2014, Digium, Inc.
 Matt Jordan <mjordan at digium.com>
 
 This program is free software, distributed under the terms of
@@ -279,20 +279,6 @@
     if argv is None:
         args = sys.argv
 
-    # Set up logging - we're probably the first ones run!
-    log_config_file = os.path.join(os.getcwd(), "%s" % 'logger.conf')
-    if os.path.exists(log_config_file):
-        try:
-            logging.config.fileConfig(log_config_file, None, False)
-        except:
-            print "WARNING: failed to preserve existing loggers - some " \
-            "logging statements may be missing"
-            logging.config.fileConfig(log_config_file)
-    else:
-        print "WARNING: no logging.conf file found at %s; using default " \
-        " configuration" % (log_config_file)
-        logging.basicConfig()
-
     if (len(args) < 2):
         LOGGER.error("test_runner requires the full path to the test " \
                      "directory to execute")

Modified: asterisk/trunk/logger.conf
URL: http://svnview.digium.com/svn/testsuite/asterisk/trunk/logger.conf?view=diff&rev=5029&r1=5028&r2=5029
==============================================================================
--- asterisk/trunk/logger.conf (original)
+++ asterisk/trunk/logger.conf Tue May 13 07:46:28 2014
@@ -3,10 +3,10 @@
 #
 
 [loggers]
-keys=root,AMI,asterisk,test_case
+keys=root
 
 [handlers]
-keys=stdout,normalFile,verboseFile
+keys=stdout,normalFile
 
 [formatters]
 keys=default
@@ -15,37 +15,7 @@
 # they can be configured below this section.
 [logger_root]
 level=NOTSET
-handlers=stdout,normalFile,verboseFile
-
-[logger_AMI]
-level=INFO
-propagate=0
-handlers=stdout,normalFile,verboseFile
-qualname=AMI
-
-[logger_ari]
-level=INFO
-propagate=0
-handlers=stdout,normalFile,verboseFile
-qualname=ari
-
-[logger_asterisk]
-level=NOTSET
-propagate=0
-handlers=stdout,normalFile,verboseFile
-qualname=asterisk
-
-[logger_test_case]
-level=NOTSET
-propagate=0
-handlers=stdout,normalFile,verboseFile
-qualname=asterisk.test_case
-
-[logger_test_runner]
-level=NOTSET
-propagate=0
-handlers=stdout,normalFile,verboseFile
-qualname=test_runner
+handlers=stdout,normalFile
 
 [handler_stdout]
 class=StreamHandler
@@ -58,11 +28,6 @@
 level=INFO
 formatter=default
 args=('./logs/messages.txt', 'a', 67108864, 5)
-[handler_verboseFile]
-class=handlers.RotatingFileHandler
-level=DEBUG
-formatter=default
-args=('./logs/full.txt', 'a', 67108864, 10)
 
 # Formatter definitions for handlers defined in this configuration file
 [formatter_default]

Modified: asterisk/trunk/runtests.py
URL: http://svnview.digium.com/svn/testsuite/asterisk/trunk/runtests.py?view=diff&rev=5029&r1=5028&r2=5029
==============================================================================
--- asterisk/trunk/runtests.py (original)
+++ asterisk/trunk/runtests.py Tue May 13 07:46:28 2014
@@ -74,21 +74,21 @@
             self.__parse_run_output(self.stdout)
 
             self.passed = (p.returncode == 0 and self.test_config.expect_pass) or (p.returncode and not self.test_config.expect_pass)
-            core_dumps = self.__check_for_core()
+            core_dumps = self._check_for_core()
             if (len(core_dumps)):
                 print "Core dumps detected; failing test"
                 self.passed = False
-                self.__archive_core_dumps(core_dumps)
+                self._archive_core_dumps(core_dumps)
+
             if not self.passed:
-                self.__archive_ast_logs()
-                self.__archive_pcap_dump()
+                self._archive_logs()
             print 'Test %s %s\n' % (cmd, 'passed' if self.passed else 'failed')
 
         else:
             print "FAILED TO EXECUTE %s, it must exist and be executable" % cmd
         self.time = time.time() - start_time
 
-    def __check_for_core(self):
+    def _check_for_core(self):
         contents = os.listdir('.')
         core_files = []
         for item in contents:
@@ -96,7 +96,7 @@
                 core_files.append(item)
         return core_files
 
-    def __archive_core_dumps(self, core_dumps):
+    def _archive_core_dumps(self, core_dumps):
         for core in core_dumps:
             if not os.path.exists(core):
                 print "Unable to find core dump file %s, skipping" % core
@@ -112,7 +112,7 @@
                 res = subprocess.call(gdb_cmd, stdout=dest_file, stderr=subprocess.STDOUT)
                 if res != 0:
                     print "error analyzing core dump; gdb exited with %d" % res
-                """ Copy the backtrace over to the logs """
+                # Copy the backtrace over to the logs
             except OSError, ose:
                 print "OSError ([%d]: %s) occurred while executing %r" % (ose.errno, ose.strerror, gdb_cmd)
                 return
@@ -126,36 +126,51 @@
                 except OSError, e:
                     print "Error removing core file: %s: Beware of the stale core file in CWD!" % (e,)
 
-    def __archive_ast_logs(self):
-        ast_directories = "%s/%s" % (Asterisk.test_suite_root, self.test_name.lstrip("tests/"))
+    def _archive_logs(self):
+        test_run_dir = os.path.join(Asterisk.test_suite_root,
+                       self.test_name.lstrip('tests/'))
+
         i = 1
-        while True:
-            if os.path.isdir("%s/ast%d" % (ast_directories, i)):
-                ast_dir = "%s/ast%d/var/log/asterisk" % (ast_directories, i)
-                dest_dir = "./logs/%s/ast%d/var/log/asterisk" % (self.test_name.lstrip("tests/"), i)
-                """ Only archive the logs if we havent archived it for this test run yet """
-                if not os.path.exists(dest_dir):
-                    try:
-                        hardlink_or_copy(ast_dir + "/messages.txt",
-                            dest_dir + "/messages.txt")
-                        hardlink_or_copy(ast_dir + "/full.txt",
-                            dest_dir + "/full.txt")
-                        if os.path.exists(ast_dir + "/mmlog"):
-                            hardlink_or_copy(ast_dir + "/mmlog",
-                                dest_dir + "/mmlog")
-                    except Exception, e:
-                        print "Exception occurred while archiving logs from %s to %s: %s" % (
-                            ast_dir, dest_dir, e
-                        )
-            else:
-                break
+        # Find the last run
+        while os.path.isdir(os.path.join(test_run_dir, 'run_%d' % i)):
             i += 1
-
-    def __archive_pcap_dump(self):
+        run_num = i - 1
+        run_dir = os.path.join(test_run_dir, 'run_%d' % run_num)
+        archive_dir = os.path.join('./logs',
+                                   self.test_name.lstrip('tests/'),
+                                   'run_%d' % run_num)
+        self._archive_ast_logs(run_num, run_dir, archive_dir)
+        self._archive_pcap_dump(run_dir, archive_dir)
+        hardlink_or_copy(os.path.join(run_dir, 'messages.txt'),
+                         os.path.join(archive_dir, 'messages.txt'))
+        hardlink_or_copy(os.path.join(run_dir, 'full.txt'),
+                         os.path.join(archive_dir, 'full.txt'))
+
+    def _archive_ast_logs(self, run_num, run_dir, archive_dir):
+        """Archive the Asterisk logs"""
+        i = 1
+        while os.path.isdir(os.path.join(run_dir, 'ast%d/var/log/asterisk' % i)):
+            ast_dir = "%s/ast%d/var/log/asterisk" % (run_dir, i)
+            dest_dir = os.path.join(archive_dir,
+                                    'ast%d/var/log/asterisk' % i)
+            try:
+                hardlink_or_copy(ast_dir + "/messages.txt",
+                    dest_dir + "/messages.txt")
+                hardlink_or_copy(ast_dir + "/full.txt",
+                    dest_dir + "/full.txt")
+                if os.path.exists(ast_dir + "/mmlog"):
+                    hardlink_or_copy(ast_dir + "/mmlog",
+                        dest_dir + "/mmlog")
+            except Exception, e:
+                print "Exception occurred while archiving logs from %s to %s: %s" % (
+                    ast_dir, dest_dir, e
+                )
+            i += 1
+
+    def _archive_pcap_dump(self, run_dir, archive_dir):
         filename = "dumpfile.pcap"
-        test_base = self.test_name.lstrip("tests/")
-        src = os.path.join(Asterisk.test_suite_root, test_base, str(self.pid), filename)
-        dst = os.path.join("logs", test_base, filename)
+        src = os.path.join(run_dir, filename)
+        dst = os.path.join(archive_dir, filename)
         if os.path.exists(src):
             try:
                 hardlink_or_copy(src, dst)




More information about the asterisk-commits mailing list