def logging_context():
"""Initialize and close the logger based on the configuration
"""
# Get options related to logging
verbosity = conf['pyexperiment.verbosity']
log_to_file = conf['pyexperiment.log_to_file']
if (((isinstance(log_to_file, str) and log_to_file == 'True')
or (isinstance(log_to_file, bool) and log_to_file))):
log_filename = conf['pyexperiment.log_filename']
else:
log_filename = None
log_file_verbosity = conf['pyexperiment.log_file_verbosity']
rotate_n_logs = int(conf['pyexperiment.rotate_n_logs'])
# Setup the logger for the configuration
log.initialize(console_level=verbosity,
filename=log_filename,
file_level=log_file_verbosity,
no_backups=rotate_n_logs)
# Give control back, but catch exceptions
try:
yield
except Exception as err:
# Reraise exception after the logger is closed
raise err
finally:
log.close()
def logging_context():
"""Initialize and close the logger based on the configuration
"""
# Get options related to logging
verbosity = conf['pyexperiment.verbosity']
log_to_file = conf['pyexperiment.log_to_file']
if (((isinstance(log_to_file, str) and log_to_file == 'True')
or (isinstance(log_to_file, bool) and log_to_file))):
log_filename = conf['pyexperiment.log_filename']
else:
log_filename = None
log_file_verbosity = conf['pyexperiment.log_file_verbosity']
rotate_n_logs = int(conf['pyexperiment.rotate_n_logs'])
# Setup the logger for the configuration
log.initialize(console_level=verbosity,
filename=log_filename,
file_level=log_file_verbosity,
no_backups=rotate_n_logs)
# Give control back, but catch exceptions
try:
yield
except Exception as err:
# Reraise exception after the logger is closed
raise err
finally:
log.close()
def test_print_timings_correct(self):
"""Test timing is about right
"""
buf = io.StringIO()
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
for _ in range(3):
with log.timed("Foo", level=logging.FATAL):
time.sleep(0.01)
with stdout_redirector(buf):
log.print_timings()
# Should print correct stats
self.assertRegexpMatches(buf.getvalue(), r'\'Foo\'')
self.assertRegexpMatches(buf.getvalue(), r'3 times')
self.assertRegexpMatches(buf.getvalue(), r'total = 0.03')
self.assertRegexpMatches(buf.getvalue(), r'median = 0.01')
log.close()
# Correct timings should be logged three times
self.assertRegexpMatches(self.log_stream.getvalue(), r'Foo')
self.assertEqual(len(re.findall(r'Foo',
self.log_stream.getvalue())), 3)
self.assertRegexpMatches(self.log_stream.getvalue(), r'took 0.01')
self.assertEqual(len(re.findall(r'took 0.01',
self.log_stream.getvalue())), 3)
def test_print_timings_correct(self):
"""Test timing is about right
"""
buf = io.StringIO()
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
for _ in range(3):
with log.timed("Foo", level=logging.FATAL):
time.sleep(0.01)
with stdout_redirector(buf):
log.print_timings()
# Should print correct stats
self.assertRegexpMatches(buf.getvalue(), r'\'Foo\'')
self.assertRegexpMatches(buf.getvalue(), r'3 times')
self.assertRegexpMatches(buf.getvalue(), r'total = 0.03')
self.assertRegexpMatches(buf.getvalue(), r'median = 0.01')
log.close()
# Correct timings should be logged three times
self.assertRegexpMatches(self.log_stream.getvalue(), r'Foo')
self.assertEqual(len(re.findall(r'Foo',
self.log_stream.getvalue())), 3)
self.assertRegexpMatches(self.log_stream.getvalue(), r'took 0.01')
self.assertEqual(len(re.findall(r'took 0.01',
self.log_stream.getvalue())), 3)
def test_file_logger_writes_to_file(self):
"""Test logging to file writes something to the log file
"""
with tempfile.NamedTemporaryFile() as temp:
log.initialize(filename=temp.name, no_backups=0)
log.fatal("Test")
log.close()
# Make sure file exists
self.assertTrue(os.path.isfile(temp.name))
lines = temp.readlines()
# There should be exactly one line in the file now
self.assertEqual(len(lines), 1)
def test_info_console_logging(self):
"""Test the most basic console logging at the fatal level
"""
log.initialize(console_level=logging.FATAL)
log.info("Test")
log.close()
# Something should be logged
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize(console_level=logging.DEBUG)
log.info("Test")
log.close()
# Something should be logged
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def test_info_console_logging(self):
"""Test the most basic console logging at the fatal level
"""
log.initialize(console_level=logging.FATAL)
log.info("Test")
log.close()
# Something should be logged
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize(console_level=logging.DEBUG)
log.info("Test")
log.close()
# Something should be logged
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def test_basic_console_logging(self):
"""Test the most basic console logging at the debug level
"""
log.initialize(console_level=logging.DEBUG)
log.debug("Test string: %s, int: %s, float: %f",
'bla',
12,
3.14)
log.close()
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
self.assertRegexpMatches(
self.log_stream.getvalue(),
r'Test string: bla, int: 12, float: 3.14')
def test_timing_logger_logs(self):
"""Test timing code logs a message
"""
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
with log.timed(level=logging.FATAL):
_ = 1 + 1
log.close()
# Something should be logged
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def test_timing_logger_logs(self):
"""Test timing code logs a message
"""
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
with log.timed(level=logging.FATAL):
_ = 1 + 1
log.close()
# Something should be logged
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def test_file_logger_writes_to_file(self):
"""Test logging to file writes something to the log file
"""
with tempfile.NamedTemporaryFile() as temp:
log.initialize(filename=temp.name, no_backups=0)
log.fatal("Test: %f", 3.1415)
log.close()
# Make sure file exists
self.assertTrue(os.path.isfile(temp.name))
lines = temp.readlines()
# There should be exactly one line in the file now
self.assertEqual(len(lines), 1)
# The content should match the logged message
self.assertRegexpMatches(str(lines[0]), r'Test: 3.1415')
def test_file_logger_logs_exception(self):
"""Test logging to file logs exception info
"""
with tempfile.NamedTemporaryFile() as temp:
log.initialize(filename=temp.name, no_backups=0)
try:
raise RuntimeError()
except RuntimeError:
log.exception('Exception...')
log.close()
# Make sure file exists
self.assertTrue(os.path.isfile(temp.name))
lines = temp.readlines()
# There should be exactly more than one line in the file now
self.assertTrue(len(lines) > 1)
# The content should match the logged message
self.assertRegexpMatches(str(lines[0]), r'Exception')
def test_print_timings_complains(self):
"""Test timing code complains if there are no timings
"""
buf = io.StringIO()
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
with stdout_redirector(buf):
log.print_timings()
# Something should be printed
self.assertNotEqual(len(buf.getvalue()), 0)
self.assertRegexpMatches(buf.getvalue(), r'No timings stored')
log.close()
# Nothing should be logged
self.assertEqual(len(self.log_stream.getvalue()), 0)
def test_print_timings_prints(self):
"""Test timing code and printing really prints a message
"""
buf = io.StringIO()
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
with log.timed(level=logging.FATAL):
_ = 1 + 1
with stdout_redirector(buf):
log.print_timings()
# Something should be printed
self.assertNotEqual(len(buf.getvalue()), 0)
log.close()
# Something should be logged
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def test_print_timings_prints(self):
"""Test timing code and printing really prints a message
"""
buf = io.StringIO()
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Still, nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
with log.timed(level=logging.FATAL):
_ = 1 + 1
with stdout_redirector(buf):
log.print_timings()
# Something should be printed
self.assertNotEqual(len(buf.getvalue()), 0)
log.close()
# Something should be logged
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def main(commands=None,
config_spec="",
tests=None,
description=None):
"""Parses command line arguments and configuration, then runs the
appropriate command.
"""
tic = datetime.now()
log.debug("Start: '%s'", " ".join(sys.argv))
log.debug("Time: '%s'", tic)
commands = collect_commands(commands or [])
# Configure the application from the command line and get the
# command to be run
run_command, arguments, interactive = configure(
commands,
config_spec,
"Thanks for using %(prog)s."
if description is None else description)
# Store the commands and tests globally
# I believe global is justified here for simplicity
if tests is not None:
global TESTS # pylint:disable=W0603
TESTS = tests
global COMMANDS # pylint:disable=W0603
COMMANDS = commands
# Initialize the main logger based on the configuration
init_log()
# Handle the state safely
with StateHandler(filename=conf['pyexperiment.state_filename'],
load=conf['pyexperiment.load_state'],
save=conf['pyexperiment.save_state'],
rotate_n_files=conf[
'pyexperiment.rotate_n_state_files']):
# Run the command with the supplied arguments
if run_command is not None:
result = run_command(*arguments)
if result is not None:
print(result)
# Drop to the interactive console if necessary, passing the result
if interactive:
embed_interactive(result=result)
# After everything is done, print timings if necessary
if (((isinstance(conf['pyexperiment.print_timings'], bool)
and conf['pyexperiment.print_timings'])
or conf['pyexperiment.print_timings'] == 'True')):
log.print_timings()
toc = datetime.now()
log.debug("End: '%s'", " ".join(sys.argv))
log.debug("Time: '%s'", toc)
log.debug("Took: %.3fs", (toc - tic).total_seconds())
log.close()
def tearDown(self):
"""Teardown test fixture
"""
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler()
log.close()
log.reset_instance()
def tearDown(self):
"""Teardown test fixture
"""
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler()
log.close()
log.reset_instance()
