Skip to content

Commit

Permalink
Merge pull request #75 from altheaden/logger-cleanup
Browse files Browse the repository at this point in the history 
Logger cleanup and clarification
  • Loading branch information
@xylar
xylar authored Jun 1, 2023
2 parents 348dca9 + 57212e0 commit 368ae50
Show file tree
Hide file tree
Showing 4 changed files with 52 additions and 38 deletions.
4 changes: 2 additions & 2 deletions docs/tutorials/dev_add_test_group.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -678,13 +678,13 @@ $ cat polaris.o${SLURM_JOBID}
Done.

ocean/yet_another_channel/10km/default
compass calling: polaris.run.serial._run_test()
polaris calling: polaris.run.serial._run_test()
in /gpfs/fs1/home/ac.cbegeman/polaris-repo/main/polaris/run/serial.py

Running steps: initial_state
* step: initial_state

compass calling: polaris.ocean.tests.yet_another_channel.default.Default.validate()
polaris calling: polaris.ocean.tests.yet_another_channel.default.Default.validate()
inherited from: polaris.testcase.TestCase.validate()
in /gpfs/fs1/home/ac.cbegeman/polaris-repo/main/polaris/testcase.py

Expand Down
14 changes: 7 additions & 7 deletions polaris/logging.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,8 @@ def log_method_call(method, logger):
"""
Log the module path and file path of a call to a method, e.g.::
compass calling: compass.landice.tests.dome.decomposition_test.DecompositionTest.run() # noqa: E501
in /turquoise/usr/projects/climate/mhoffman/mpas/compass/compass/landice/tests/dome/decomposition_test/__init__.py # noqa: E501
polaris calling: polaris.landice.tests.dome.decomposition_test.DecompositionTest.run() # noqa: E501
in /turquoise/usr/projects/climate/mhoffman/mpas/polaris/polaris/landice/tests/dome/decomposition_test/__init__.py # noqa: E501
Parameters
----------
Expand Down Expand Up @@ -49,14 +49,14 @@ def log_method_call(method, logger):
actual_location = f'{actual_class.__module__}.{actual_class.__name__}'

# not every class is defined in a file (e.g. python intrinsics) but we
# expect they always are in compass. Still we'll check to make sure.
# expect they always are in polaris. Still we'll check to make sure.
try:
class_file = inspect.getfile(actual_class)
except TypeError:
class_file = None

# log what we found out
logger.info(f'compass calling: {child_location}.{method_name}()')
logger.info(f'polaris calling: {child_location}.{method_name}()')
if child_location != actual_location:
# okay, so we're inheriting this method from somewhere else. Better
# let the user know.
Expand All @@ -69,8 +69,8 @@ def log_function_call(function, logger):
"""
Log the module path and file path of a call to a function, e.g.::
compass calling: compass.parallel.set_cores_per_node()
in /home/xylar/code/compass/compass/compass/parallel.py
polaris calling: polaris.parallel.set_cores_per_node()
in /home/xylar/code/polaris/polaris/polaris/parallel.py
Parameters
----------
Expand All @@ -86,6 +86,6 @@ def log_function_call(function, logger):
filename = inspect.getfile(function)

# log what we found out
logger.info(f'compass calling: '
logger.info(f'polaris calling: '
f'{function.__module__}.{function.__name__}()')
logger.info(f' in {filename}')
70 changes: 42 additions & 28 deletions polaris/run/serial.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,7 +65,7 @@ def run_tests(suite_name, quiet=False, is_test_case=False, steps_to_run=None,
check_parallel_system(config)

# start logging to stdout/stderr
with LoggingContext(suite_name) as logger:
with LoggingContext(suite_name) as stdout_logger:

os.environ['PYTHONUNBUFFERED'] = '1'

Expand All @@ -81,20 +81,20 @@ def run_tests(suite_name, quiet=False, is_test_case=False, steps_to_run=None,
test_times = dict()
success_strs = dict()
for test_name in test_suite['test_cases']:
logger.info(f'{test_name}')
stdout_logger.info(f'{test_name}')

test_case = test_suite['test_cases'][test_name]

if is_test_case:
log_filename = None
test_logger = logger
test_logger = stdout_logger
else:
test_prefix = test_case.path.replace('/', '_')
log_filename = f'{cwd}/case_outputs/{test_prefix}.log'
test_logger = None

success_str, success, test_time = _log_and_run_test(
test_case, logger, test_logger, quiet, log_filename,
test_case, stdout_logger, test_logger, quiet, log_filename,
is_test_case, steps_to_run, steps_to_skip)
success_strs[test_name] = success_str
if not success:
Expand All @@ -105,26 +105,26 @@ def run_tests(suite_name, quiet=False, is_test_case=False, steps_to_run=None,

os.chdir(cwd)

logger.info('Test Runtimes:')
stdout_logger.info('Test Runtimes:')
for test_name, test_time in test_times.items():
secs = round(test_time)
mins = secs // 60
secs -= 60 * mins
logger.info(f'{mins:02d}:{secs:02d} {success_strs[test_name]} '
f'{test_name}')
stdout_logger.info(f'{mins:02d}:{secs:02d} \
{success_strs[test_name]} {test_name}')
secs = round(suite_time)
mins = secs // 60
secs -= 60 * mins
logger.info(f'Total runtime {mins:02d}:{secs:02d}')
stdout_logger.info(f'Total runtime {mins:02d}:{secs:02d}')

if failures == 0:
logger.info('PASS: All passed successfully!')
stdout_logger.info('PASS: All passed successfully!')
else:
if failures == 1:
message = '1 test'
else:
message = f'{failures} tests'
logger.error(f'FAIL: {message} failed, see above.')
stdout_logger.error(f'FAIL: {message} failed, see above.')
sys.exit(1)


Expand Down Expand Up @@ -159,19 +159,19 @@ def run_single_step(step_is_subprocess=False):

# start logging to stdout/stderr
test_name = step.path.replace('/', '_')
with LoggingContext(name=test_name) as logger:
test_case.logger = logger
with LoggingContext(name=test_name) as stdout_logger:
test_case.logger = stdout_logger
test_case.stdout_logger = None
log_function_call(function=_run_test, logger=logger)
logger.info('')
log_function_call(function=_run_test, logger=stdout_logger)
stdout_logger.info('')
_run_test(test_case)

if not step_is_subprocess:
# only perform validation if the step is being run by a user on its
# own
logger.info('')
log_method_call(method=test_case.validate, logger=logger)
logger.info('')
stdout_logger.info('')
log_method_call(method=test_case.validate, logger=stdout_logger)
stdout_logger.info('')
test_case.validate()


Expand Down Expand Up @@ -257,8 +257,9 @@ def _print_to_stdout(test_case, message):
test_case.logger.info(message)


def _log_and_run_test(test_case, logger, test_logger, quiet, log_filename,
is_test_case, steps_to_run, steps_to_skip):
def _log_and_run_test(test_case, stdout_logger, test_logger, quiet,
log_filename, is_test_case, steps_to_run,
steps_to_skip):
# ANSI fail text: https://stackoverflow.com/a/287944/7728169
start_fail = '\033[91m'
start_pass = '\033[92m'
Expand All @@ -278,9 +279,13 @@ def _log_and_run_test(test_case, logger, test_logger, quiet, log_filename,
test_case.stdout_logger = test_logger
else:
# log steps to stdout
test_case.stdout_logger = logger
test_case.stdout_logger = stdout_logger
test_case.logger = test_logger
test_case.log_filename = log_filename

# If we are running a test case on its own, we want a log file per step
# If we are running within a suite, we want a log file per test, with
# output from each of its steps
test_case.new_step_log_file = is_test_case

os.chdir(test_case.work_dir)
Expand Down Expand Up @@ -357,13 +362,13 @@ def _log_and_run_test(test_case, logger, test_logger, quiet, log_filename,
f' baseline comparison: {baseline_status}'

if test_pass:
logger.info(status)
stdout_logger.info(status)
success_str = pass_str
success = True
else:
logger.error(status)
stdout_logger.error(status)
if not is_test_case:
logger.error(f' see: case_outputs/{test_name}.log')
stdout_logger.error(f' see: case_outputs/{test_name}.log')
success_str = fail_str
success = False

Expand All @@ -372,8 +377,8 @@ def _log_and_run_test(test_case, logger, test_logger, quiet, log_filename,
secs = round(test_time)
mins = secs // 60
secs -= 60 * mins
logger.info(f' test runtime: '
f'{start_time_color}{mins:02d}:{secs:02d}{end}')
stdout_logger.info(f' test runtime: '
f'{start_time_color}{mins:02d}:{secs:02d}{end}')

return success_str, success, test_time

Expand All @@ -392,6 +397,8 @@ def _run_test(test_case):
step.config = test_case.config
if test_case.log_filename is not None:
step.log_filename = test_case.log_filename
else:
step.log_filename = None

_print_to_stdout(test_case, f' * step: {step_name}')

Expand Down Expand Up @@ -429,15 +436,18 @@ def _run_step(test_case, step, new_log_file):

_load_dependencies(test_case, step)

test_name = step.path.replace('/', '_')
# each logger needs a unique name
logger_name = step.path.replace('/', '_')
if new_log_file:
log_filename = f'{cwd}/{step.name}.log'
step.log_filename = log_filename
step_logger = None
else:
step_logger = logger
log_filename = None
with LoggingContext(name=test_name, logger=step_logger,

step.log_filename = log_filename

with LoggingContext(name=logger_name, logger=step_logger,
log_filename=log_filename) as step_logger:
step.logger = step_logger
os.chdir(step.work_dir)
Expand All @@ -456,6 +466,10 @@ def _run_step(test_case, step, new_log_file):
step.runtime_setup()

if step.args is not None:
step_logger.info('\nBypassing step\'s run() method and running '
'with command line args\n')
log_function_call(function=run_command, logger=step_logger)
step_logger.info('')
run_command(step.args, step.cpus_per_task, step.ntasks,
step.openmp_threads, step.config, step.logger)
else:
Expand Down
2 changes: 1 addition & 1 deletion polaris/step.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -236,7 +236,7 @@ def __init__(self, test_case, name, subdir=None, cpus_per_task=1,

# these will be set before running the step, dummy placeholders for now
self.logger = logging.getLogger('dummy')
self.log_filename = ""
self.log_filename = None

# output caching
self.cached = cached
Expand Down

0 comments on commit 368ae50

Please sign in to comment.