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 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_setup_without_seaborn(self):
"""Test setup mentions missing seaborn
"""
with mock.patch.dict('sys.modules', {'seaborn': None}):
log_stream = StringIO()
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler(log_stream)
log.reset_instance()
log.initialize()
plot.setup_plotting()
self.assertRegexpMatches(log_stream.getvalue(),
r'Cannot import seaborn')
def test_setup_without_seaborn(self):
"""Test setup mentions missing seaborn
"""
with mock.patch.dict('sys.modules', {'seaborn': None}):
log_stream = StringIO()
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler(log_stream)
log.reset_instance()
log.initialize()
plot.setup_plotting()
self.assertRegexpMatches(log_stream.getvalue(),
r'Cannot import seaborn')
def test_pre_init_logger(self):
"""Test that logging before initializing the logger works
"""
log.fatal("Test")
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Something should be logged here
self.assertNotEqual(len(self.log_stream.getvalue()), 0)
def test_pre_init_logger(self):
"""Test that logging before initializing the logger works
"""
log.fatal("Test")
# Nothing should be logged yet
self.assertEqual(len(self.log_stream.getvalue()), 0)
log.initialize()
# Something should be logged here
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")
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_basic_functionality(self):
"""Test the basic function of the TargetCreator
"""
log_stream = io.StringIO()
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler(log_stream)
log.reset_instance()
log.initialize(console_level=logging.DEBUG)
queue = multiprocessing.Queue()
target_fun = TargetCreator(lambda: None, queue, 'bla')
target_fun()
# Should have logged running
self.assertNotEqual(len(log_stream.getvalue()), 0)
self.assertRegexpMatches(log_stream.getvalue(), r'Running bla')
self.assertTrue(queue.get())
def test_basic_functionality(self):
"""Test the basic function of the TargetCreator
"""
log_stream = io.StringIO()
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler(log_stream)
log.reset_instance()
log.initialize(console_level=logging.DEBUG)
queue = multiprocessing.Queue()
target_fun = TargetCreator(lambda: None, queue, 'bla')
target_fun()
# Should have logged running
self.assertNotEqual(len(log_stream.getvalue()), 0)
self.assertRegexpMatches(log_stream.getvalue(), r'Running bla')
self.assertTrue(queue.get())
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 init_log():
"""Initialize 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)
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_raises_exception(self):
"""Test the TargetCreator with a function that raises an exception
"""
def target():
"""Test function
"""
raise RuntimeError("bla")
log_stream = io.StringIO()
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler(log_stream)
log.reset_instance()
log.initialize(console_level=logging.DEBUG)
queue = multiprocessing.Queue()
target_fun = TargetCreator(target, queue, 'bla')
self.assertRaises(RuntimeError, target_fun)
# Should have logged running
self.assertNotEqual(len(log_stream.getvalue()), 0)
self.assertRegexpMatches(log_stream.getvalue(), r'Running bla')
self.assertRegexpMatches(log_stream.getvalue(),
r'Error in sub-process')
self.assertRegexpMatches(log_stream.getvalue(), r'RuntimeError: bla')
self.assertTrue(queue.get())
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_raises_exception(self):
"""Test the TargetCreator with a function that raises an exception
"""
def target():
"""Test function
"""
raise RuntimeError("bla")
log_stream = io.StringIO()
Logger.CONSOLE_STREAM_HANDLER = logging.StreamHandler(log_stream)
log.reset_instance()
log.initialize(console_level=logging.DEBUG)
queue = multiprocessing.Queue()
target_fun = TargetCreator(target, queue, 'bla')
self.assertRaises(RuntimeError, target_fun)
# Should have logged running
self.assertNotEqual(len(log_stream.getvalue()), 0)
self.assertRegexpMatches(log_stream.getvalue(), r'Running bla')
self.assertRegexpMatches(log_stream.getvalue(),
r'Error in sub-process')
self.assertRegexpMatches(log_stream.getvalue(), r'RuntimeError: bla')
self.assertTrue(queue.get())
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)
