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 main(default=None,
commands=None,
config_spec="",
tests=None,
description=None):
"""Parses command line arguments and configuration, then runs the
appropriate command.
"""
start_time = datetime.now()
log.debug("Start: '%s'", " ".join(sys.argv))
log.debug("Time: '%s'", start_time)
commands = collect_commands(default, commands or [])
# Configure the application from the command line and get the
# command to be run
run_command, arguments, interactive = configure(
default, 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
# and handle the state safely
with logging_context(), \
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()
end_time = datetime.now()
log.debug("End: '%s'", " ".join(sys.argv))
log.debug("Time: '%s'", end_time)
log.debug("Took: %.3fs", (end_time - start_time).total_seconds())
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(default=None,
commands=None,
config_spec="",
tests=None,
description=None):
"""Parses command line arguments and configuration, then runs the
appropriate command.
"""
start_time = datetime.now()
log.debug("Start: '%s'", " ".join(sys.argv))
log.debug("Time: '%s'", start_time)
commands = collect_commands(default, commands or [])
# Configure the application from the command line and get the
# command to be run
run_command, arguments, interactive = configure(
default,
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
# and handle the state safely
with logging_context(), \
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()
end_time = datetime.now()
log.debug("End: '%s'", " ".join(sys.argv))
log.debug("Time: '%s'", end_time)
log.debug("Took: %.3fs", (end_time - start_time).total_seconds())