[svn-commits] mjordan: testsuite/asterisk/trunk r5029 - in /asterisk/trunk: ./ lib/python/a...
SVN commits to the Digium repositories
svn-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 svn-commits
mailing list