Merge pull request #104 from MarcCote/append_execution_output

Make sure commands output/error are appended to the log.

Author: mgermain

scripts/smart_worker.py

@@ -5,6 +5,7 @@
 import argparse
 import subprocess
 import logging
+import time as t
 
 from smartdispatch import utils
 from smartdispatch.command_manager import CommandManager
@@ -44,11 +45,17 @@ def main():
         stdout_filename = os.path.join(args.logs_dir, uid + ".out")
         stderr_filename = os.path.join(args.logs_dir, uid + ".err")
 
-        with open(stdout_filename, 'w') as stdout_file:
-            with open(stderr_filename, 'w') as stderr_file:
-                stdout_file.write("# " + command + '\n')
-                stderr_file.write("# " + command + '\n')
+        with open(stdout_filename, 'a') as stdout_file:
+            with open(stderr_filename, 'a') as stderr_file:
+                log_datetime = t.strftime("## SMART_DISPATCH - Started on: %Y-%m-%d %H:%M:%S ##\n")
+                if stdout_file.tell() > 0:  # Not the first line in the log file.
+                    log_datetime = t.strftime("\n## SMART_DISPATCH - Resumed on: %Y-%m-%d %H:%M:%S ##\n")
+
+                log_command = "## SMART_DISPATCH - Command: " + command + '\n'
+
+                stdout_file.write(log_datetime + log_command)
                 stdout_file.flush()
+                stderr_file.write(log_datetime + log_command)
                 stderr_file.flush()
 
                 error_code = subprocess.call(command, stdout=stdout_file, stderr=stderr_file, shell=True)

smartdispatch/tests/test_smartdispatch.py

@@ -223,4 +223,4 @@ def test_log_command_line():
     assert_true(t.strftime("## %Y-%m-%d %H:%M:") in lines[6])  # Don't check second.
     assert_equal(lines[7], re.sub(r'(\[)([^\[\]]*\\ [^\[\]]*)(\])', r'"\1\2\3"', command_3))
 
-    shutil.rmtree(temp_dir)
+    shutil.rmtree(temp_dir)

tests/test_smart_dispatch.py

@@ -60,12 +60,12 @@ def test_main_resume(self):
         assert_equal(len(open(running_commands_file).readlines()), 0)
         assert_equal(len(open(pending_commands_file).readlines()), len(commands))
 
-		# Test when batch_uid is a path instead of a jobname.
-		# Setup
+        # Test when batch_uid is a path instead of a jobname.
+        # Setup
         call(self.launch_command, shell=True)
         batch_uid = os.path.join(self.logs_dir, os.listdir(self.logs_dir)[0])
 
-		# Simulate that some commands are in the running state.
+        # Simulate that some commands are in the running state.
         path_job_commands = os.path.join(self.logs_dir, batch_uid, "commands")
         pending_commands_file = pjoin(path_job_commands, "commands.txt")
         running_commands_file = pjoin(path_job_commands, "running_commands.txt")
@@ -85,7 +85,6 @@ def test_main_resume(self):
         assert_equal(len(open(running_commands_file).readlines()), 0)
         assert_equal(len(open(pending_commands_file).readlines()), len(commands))
 
-
     def test_main_resume_only_pending(self):
         # SetUp
         call(self.launch_command, shell=True)

tests/test_smart_worker.py

@@ -31,6 +31,9 @@ def tearDown(self):
     def test_main(self):
         command = ["smart_worker.py", self.command_manager._commands_filename, self.logs_dir]
         assert_equal(call(command), 0)
+        # Simulate a resume, i.e. re-run the command, the output/error should be concatenated.
+        self.command_manager.set_commands_to_run(self.commands)
+        assert_equal(call(command), 0)
 
         # Check output logs
         filenames = os.listdir(self.logs_dir)
@@ -41,13 +44,29 @@ def test_main(self):
                 uid = os.path.splitext(os.path.basename(log_filename))[0]
                 executed_command = self.commands[self.commands_uid.index(uid)]
 
-                # First line is the executed command in comment
-                header = logfile.readline().strip()
-                assert_equal(header, "# " + executed_command)
+                # Since the command was run twice.
+                for i in range(2):
+                    # First line is the datetime of the executed command in comment.
+                    line = logfile.readline().strip()
+
+                    if i == 0:
+                        assert_true("Started" in line)
+                    else:
+                        assert_true("Resumed" in line)
+
+                    assert_true(line.startswith("## SMART_DISPATCH"))
+                    assert_true(time.strftime("%Y-%m-%d %H:%M:") in line)  # Don't check seconds.
+
+                    # Second line is the executed command in comment.
+                    line = logfile.readline().strip()
+                    assert_true(executed_command in line)
 
-                # Next should be the command's output
-                output = logfile.readline().strip()
-                assert_equal(output, executed_command[-1])  # We know those are 'echo' of a digit
+                    # Next should be the command's output
+                    line = logfile.readline().strip()
+                    assert_equal(line, executed_command[-1])  # We know those are 'echo' of a digit
+
+                    # Empty line
+                    assert_equal(logfile.readline().strip(), "")
 
                 # Log should be empty now
                 assert_equal("", logfile.read())
@@ -60,9 +79,25 @@ def test_main(self):
                 uid = os.path.splitext(os.path.basename(log_filename))[0]
                 executed_command = self.commands[self.commands_uid.index(uid)]
 
-                # First line is the executed command in comment
-                header = logfile.readline().strip()
-                assert_equal(header, "# " + executed_command)
+                # Since the command was run twice.
+                for i in range(2):
+                    # First line is the datetime of the executed command in comment.
+                    line = logfile.readline().strip()
+
+                    if i == 0:
+                        assert_true("Started" in line)
+                    else:
+                        assert_true("Resumed" in line)
+
+                    assert_true(line.startswith("## SMART_DISPATCH"))
+                    assert_true(time.strftime("%Y-%m-%d %H:%M:") in line)  # Don't check seconds.
+
+                    # Second line is the executed command in comment.
+                    line = logfile.readline().strip()
+                    assert_true(executed_command in line)
+
+                    # Empty line
+                    assert_equal(logfile.readline().strip(), "")
 
                 # Log should be empty now
                 assert_equal("", logfile.read())