Merge pull request #257 from dapomeroy/redirect_prints

Redirect prints from Spack to log file

lib/ramble/ramble/application.py

@@ -20,6 +20,7 @@
 import llnl.util.filesystem as fs
 import llnl.util.tty as tty
 import llnl.util.tty.color as color
+import llnl.util.tty.log
 from llnl.util.tty.colify import colified
 
 import spack.util.executable
@@ -106,6 +107,8 @@ def __init__(self, file_path):
         self.license_file = ''
         self.license_inc_name = 'license.inc'
 
+        self.logger = llnl.util.tty.log.log_output(echo=False, debug=tty.debug_level())
+
     def copy(self):
         """Deep copy an application instance"""
         new_copy = type(self)(self._file_path)
@@ -279,6 +282,13 @@ def set_modifiers(self, modifiers):
         if modifiers:
             self.modifiers = modifiers.copy()
 
+    def experiment_log_file(self, logs_dir):
+        """Returns an experiment log file path for the given logs directory"""
+        return os.path.join(
+            logs_dir,
+            self.expander.experiment_namespace) + \
+            '.out'
+
     def get_pipeline_phases(self, pipeline, phase_filters=['*']):
         if pipeline not in self._pipelines:
             tty.die(f'Requested pipeline {pipeline} is not valid.\n',

lib/ramble/ramble/application_types/spack.py

@@ -113,12 +113,14 @@ def _software_install_requested_compilers(self, workspace):
             for pkg_name in workspace.software_environments.get_env_packages(app_context):
                 pkg_spec = workspace.software_environments.get_spec(pkg_name)
                 if 'compiler' in pkg_spec:
-                    tty.debug(f'Trying to install compiler: {pkg_spec["compiler"]}')
+                    tty.msg('Installing compilers')
+                    tty.debug(f'Compilers: {pkg_spec["compiler"]}')
                     comp_spec = workspace.software_environments.get_spec(pkg_spec['compiler'])
                     self.spack_runner.install_compiler(comp_spec['spack_spec'])
 
         except ramble.spack_runner.RunnerError as e:
-            tty.die(e)
+            with self.logger.force_echo():
+                tty.die(e)
 
     def _software_create_env(self, workspace):
         """Create the spack environment for this experiment
@@ -127,6 +129,8 @@ def _software_create_env(self, workspace):
         file for it.
         """
 
+        tty.msg('Creating Spack environment')
+
         # See if we cached this already, and if so return
         env_path = self.expander.env_path
         if not env_path:
@@ -178,23 +182,26 @@ def _software_create_env(self, workspace):
             added_packages = set(self.spack_runner.added_packages())
             for pkg in self.required_packages.keys():
                 if pkg not in added_packages:
-                    tty.die(f'Software spec {pkg} is not defined '
-                            f'in environment {env_context}, but is required '
-                            f'to by the {self.name} application '
-                            'definition')
+                    with self.logger.force_echo():
+                        tty.die(f'Software spec {pkg} is not defined '
+                                f'in environment {env_context}, but is required '
+                                f'to by the {self.name} application '
+                                'definition')
 
             for mod_inst in self._modifier_instances:
                 for pkg in mod_inst.required_packages.keys():
                     if pkg not in added_packages:
-                        tty.die(f'Software spec {pkg} is not defined '
-                                f'in environment {env_context}, but is required '
-                                f'to by the {mod_inst.name} modifier '
-                                'definition')
+                        with self.logger.force_echo():
+                            tty.die(f'Software spec {pkg} is not defined '
+                                    f'in environment {env_context}, but is required '
+                                    f'to by the {mod_inst.name} modifier '
+                                    'definition')
 
             self.spack_runner.deactivate()
 
         except ramble.spack_runner.RunnerError as e:
-            tty.die(e)
+            with self.logger.force_echo():
+                tty.die(e)
 
     def _software_configure(self, workspace):
         """Concretize the spack environment for this experiment
@@ -203,6 +210,8 @@ def _software_configure(self, workspace):
         for  this experiment.
         """
 
+        tty.msg('Concretizing Spack environment')
+
         # See if we cached this already, and if so return
         env_path = self.expander.env_path
 
@@ -224,7 +233,8 @@ def _software_configure(self, workspace):
                 self.spack_runner.concretize()
 
         except ramble.spack_runner.RunnerError as e:
-            tty.die(e)
+            with self.logger.force_echo():
+                tty.die(e)
 
     def _software_install(self, workspace):
         """Install application's software using spack"""
@@ -243,10 +253,13 @@ def _software_install(self, workspace):
             self.spack_runner.set_dry_run(workspace.dry_run)
             self.spack_runner.set_env(env_path)
 
+            tty.msg('Installing software')
+
             self.spack_runner.activate()
             self.spack_runner.install()
         except ramble.spack_runner.RunnerError as e:
-            tty.die(e)
+            with self.logger.force_echo():
+                tty.die(e)
 
     def _define_package_paths(self, workspace):
         """Define variables containing the path to all spack packages
@@ -266,6 +279,9 @@ def _define_package_paths(self, workspace):
         Would define a variable `wrf` that contains the installation path of
         [email protected]
         """
+
+        tty.msg('Defining Spack variables')
+
         try:
             self.spack_runner.set_dry_run(workspace.dry_run)
             self.spack_runner.set_env(self.expander.env_path)
@@ -281,12 +297,15 @@ def _define_package_paths(self, workspace):
                 self.variables[spack_pkg_name] = package_path
 
         except ramble.spack_runner.RunnerError as e:
-            tty.die(e)
+            with self.logger.force_echo():
+                tty.die(e)
 
     def _mirror_software(self, workspace):
         """Mirror software source for this experiment using spack"""
         import re
 
+        tty.msg('Mirroring software')
+
         # See if we cached this already, and if so return
         env_path = self.expander.env_path
         if not env_path:
@@ -305,7 +324,8 @@ def _mirror_software(self, workspace):
 
             self.spack_runner.activate()
 
-            mirror_output = self.spack_runner.mirror_environment(workspace._software_mirror_path)
+            mirror_output = self.spack_runner \
+                                .mirror_environment(workspace._software_mirror_path)
 
             present = 0
             added = 0
@@ -339,7 +359,8 @@ def _mirror_software(self, workspace):
                 workspace._software_mirror_stats.errors.add(i)
 
         except ramble.spack_runner.RunnerError as e:
-            tty.die(e)
+            with self.logger.force_echo():
+                tty.die(e)
 
     def _write_inventory(self, workspace):
         """Add software environment information to hash inventory"""

lib/ramble/ramble/cmd/workspace.py

@@ -430,7 +430,7 @@ def workspace_info(args):
                 header_base = rucolor.nested_4('Variables from')
                 config_vars = ramble.config.config.get('config:variables')
 
-                for exp_name, _ in print_experiment_set.all_experiments():
+                for exp_name, _, _ in print_experiment_set.all_experiments():
                     app_inst = experiment_set.get_experiment(exp_name)
 
                     # Aggregate pipeline phases

lib/ramble/ramble/experiment_set.py

@@ -390,11 +390,15 @@ def build_experiment_chains(self):
 
     def all_experiments(self):
         """Iterator over all experiments in this set"""
+        count = 1
+
         for exp, inst in self.experiments.items():
-            yield exp, inst
+            yield exp, inst, count
+            count += 1
 
         for exp, inst in self.chained_experiments.items():
-            yield exp, inst
+            yield exp, inst, count
+            count += 1
 
     def add_chained_experiment(self, name, instance):
         if name in self.chained_experiments.keys():

lib/ramble/ramble/test/cmd/workspace.py

@@ -7,6 +7,7 @@
 # except according to those terms.
 
 import os
+import glob
 
 import pytest
 
@@ -15,6 +16,7 @@
 import ramble.workspace
 from ramble.software_environments import RambleSoftwareEnvironmentError
 from ramble.main import RambleCommand, RambleCommandError
+from ramble.test.dry_run_helpers import search_files_for_string
 import ramble.config
 
 import spack.util.spack_yaml as syaml
@@ -669,9 +671,11 @@ def test_dryrun_setup():
 
     ws1._re_read()
 
-    output = workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+    workspace('setup', '--dry-run', global_args=['-w', workspace_name])
 
-    assert "Would download file:///tmp/test_file.log" in output
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
+
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
     assert os.path.exists(os.path.join(ws1.root, 'experiments',
                                        'basic', 'test_wl',
                                        'test_experiment',
@@ -740,9 +744,11 @@ def test_matrix_vector_workspace_full():
     for exp in expected_experiments:
         assert exp in output
 
-    output = workspace('setup', '--dry-run', global_args=workspace_flags)
+    workspace('setup', '--dry-run', global_args=workspace_flags)
+
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
 
-    assert "Would download file:///tmp/test_file.log" in output
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
 
     exp_base = os.path.join(ws1.experiment_dir, 'basic', 'test_wl')
     for exp in expected_experiments:
@@ -794,6 +800,7 @@ def test_invalid_vector_workspace():
     output = workspace('setup', '--dry-run',
                        global_args=workspace_flags,
                        fail_on_error=False)
+
     assert "Length mismatch in vector variables in " + \
         "experiment exp_series_{idx}_{n_nodes}_{cells}_{processes_per_node}" in output
 
@@ -1075,12 +1082,13 @@ def test_workspace_archive():
 
     ws1._re_read()
 
-    output = workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+    workspace('setup', '--dry-run', global_args=['-w', workspace_name])
     experiment_dir = os.path.join(ws1.root, 'experiments',
                                   'basic', 'test_wl',
                                   'test_experiment')
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
 
-    assert "Would download file:///tmp/test_file.log" in output
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
     assert os.path.exists(os.path.join(experiment_dir,
                                        'execute_experiment'))
 
@@ -1094,7 +1102,7 @@ def test_workspace_archive():
         f = open(new_file, 'w+')
         f.close()
 
-    output = workspace('archive', global_args=['-w', workspace_name])
+    workspace('archive', global_args=['-w', workspace_name])
 
     assert ws1.latest_archive
     assert os.path.exists(ws1.latest_archive_path)
@@ -1149,12 +1157,13 @@ def test_workspace_tar_archive():
 
     ws1._re_read()
 
-    output = workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+    workspace('setup', '--dry-run', global_args=['-w', workspace_name])
     experiment_dir = os.path.join(ws1.root, 'experiments',
                                   'basic', 'test_wl',
                                   'test_experiment')
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
 
-    assert "Would download file:///tmp/test_file.log" in output
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
     assert os.path.exists(os.path.join(experiment_dir,
                                        'execute_experiment'))
 
@@ -1168,7 +1177,7 @@ def test_workspace_tar_archive():
         f = open(new_file, 'w+')
         f.close()
 
-    output = workspace('archive', '-t', global_args=['-w', workspace_name])
+    workspace('archive', '-t', global_args=['-w', workspace_name])
 
     assert ws1.latest_archive
     assert os.path.exists(ws1.latest_archive_path)
@@ -1225,12 +1234,13 @@ def test_workspace_tar_upload_archive():
 
     ws1._re_read()
 
-    output = workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+    workspace('setup', '--dry-run', global_args=['-w', workspace_name])
     experiment_dir = os.path.join(ws1.root, 'experiments',
                                   'basic', 'test_wl',
                                   'test_experiment')
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
 
-    assert "Would download file:///tmp/test_file.log" in output
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
     assert os.path.exists(os.path.join(experiment_dir,
                                        'execute_experiment'))
 
@@ -1247,8 +1257,8 @@ def test_workspace_tar_upload_archive():
     remote_archive_path = os.path.join(ws1.root, 'archive_backup')
     fs.mkdirp(remote_archive_path)
 
-    output = workspace('archive', '-t', '-u', 'file://' + remote_archive_path,
-                       global_args=['-w', workspace_name])
+    workspace('archive', '-t', '-u', 'file://' + remote_archive_path,
+              global_args=['-w', workspace_name])
 
     assert ws1.latest_archive
     assert os.path.exists(ws1.latest_archive_path)
@@ -1307,12 +1317,13 @@ def test_workspace_tar_upload_archive_config_url():
 
     ws1._re_read()
 
-    output = workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+    workspace('setup', '--dry-run', global_args=['-w', workspace_name])
     experiment_dir = os.path.join(ws1.root, 'experiments',
                                   'basic', 'test_wl',
                                   'test_experiment')
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
 
-    assert "Would download file:///tmp/test_file.log" in output
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
     assert os.path.exists(os.path.join(experiment_dir,
                                        'execute_experiment'))
 
@@ -1332,7 +1343,7 @@ def test_workspace_tar_upload_archive_config_url():
     config('add', 'config:archive_url:%s/' % remote_archive_path,
            global_args=['-w', workspace_name])
 
-    output = workspace('archive', '-t', global_args=['-w', workspace_name])
+    workspace('archive', '-t', global_args=['-w', workspace_name])
 
     assert ws1.latest_archive
     assert os.path.exists(ws1.latest_archive_path)
@@ -1381,9 +1392,11 @@ def test_dryrun_noexpvars_setup():
 
     ws1._re_read()
 
-    output = workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+    workspace('setup', '--dry-run', global_args=['-w', workspace_name])
+
+    out_files = glob.glob(os.path.join(ws1.log_dir, '**', '*.out'), recursive=True)
 
-    assert "Would download file:///tmp/test_file.log" in output
+    assert search_files_for_string(out_files, 'Would download file:///tmp/test_file.log')
     assert os.path.exists(os.path.join(ws1.root, 'experiments',
                                        'basic', 'test_wl',
                                        'test_experiment',

lib/ramble/ramble/test/dry_run_helpers.py

@@ -77,3 +77,11 @@ def dry_run_config(section_name, injections, config_path,
 
     with open(config_path, 'w+') as f:
         syaml.dump(ramble_dict, stream=f)
+
+
+def search_files_for_string(file_list, string):
+    for file in file_list:
+        with open(file) as f:
+            if string in f.read():
+                return True
+    return False