def __init__(self, nb_workers):
self._lt = LogsFollower()
self._logger = WorkflowRunner.get_logger()
self._pool = None
if nb_workers == -1:
self._nb_workers = int((cpu_count() + 1) / 2)
else:
self._nb_workers = nb_workers
self._free_workers = None
self._completed_processes = []
def test_thread_protection(self):
"""When a section of code using the LogsFollower is complete, the thread should stop"""
lf = LogsFollower()
lf.follow_process("stdout", "stderr", "process_id")
with lf.trace_in_background():
assert lf._thread.is_alive(), "Backgroung thread isn't running..."
with open("stdout", "w") as fout, \
open("stderr", "w") as ferr:
fout.write("file stdout")
ferr.write("file stderr")
assert not lf._thread.is_alive(), "Backgroung hasn't stopped !"
def test_log_format_stdout_stderr(self):
"""logs should display log level and message"""
with CaptureOutputs() as co:
lf = LogsFollower()
lf.follow_process("stdout", "stderr", "process_id")
with open("stdout", "w") as fout, \
open("stderr", "w") as ferr:
fout.write("file stdout")
ferr.write("file stderr")
while lf.trace_logs():
pass
assert co.output.find(
"[process_id::stdout] file stdout") >= 0, co.output
assert co.output.find(
"[process_id::stderr] file stderr") >= 0, co.output
def test_log_should_(self):
""" The last char of the file must be logged even if the
file does not finish with CR """
with CaptureOutputs() as co:
logger = LogsFollower.get_logger()
lt = LogTracer(logger, logging.INFO, "test.log")
with open("test.log", "w") as f:
f.write("line 1")
lt.trace()
output = co.output
assert output.find("line 1") >= 0, output
def test_log_should_not_double_carriage_return(self):
""" """
with CaptureOutputs() as co:
logger = LogsFollower.get_logger()
lt = LogTracer(logger, logging.INFO, "test.log")
with open("test.log", "w") as f:
f.write("line 1\n")
f.write("line 2\n")
lt.trace()
output = co.output
assert output.find("\n\n") == -1, output
def run_pre_processes(self):
""" Runs all the preprocesses
:return:
:raises ExecutionError if an error occurs
"""
TuttleDirectories.create_tuttle_dirs()
TuttleDirectories.empty_extension_dir()
if not self.has_preprocesses():
return
lt = LogsFollower()
WorkflowRunner.print_preprocesses_header()
for process in self.iter_preprocesses():
TuttleDirectories.prepare_and_assign_paths(process)
lt.follow_process(process.log_stdout, process.log_stderr, None)
with lt.trace_in_background(), TuttleEnv():
for preprocess in self.iter_preprocesses():
WorkflowRunner.print_preprocess_header(preprocess, lt._logger)
success = True
error_msg = None
try:
preprocess.set_start()
preprocess.processor.run(preprocess,
preprocess._reserved_path,
preprocess.log_stdout,
preprocess.log_stderr)
except TuttleError as e:
success = False
error_msg = str(e)
raise
except Exception:
exc_info = sys.exc_info()
stacktrace = "".join(format_exception(*exc_info))
error_msg = "An unexpected error have happened in tuttle preprocessor {} : \n" \
"{}\n" \
"Preprocess {} will not complete.".format(preprocess._processor.name, stacktrace, preprocess.id)
finally:
preprocess.set_end(success, error_msg)
self.create_reports()
WorkflowRunner.print_preprocesses_footer()
def run_pre_processes(self):
""" Runs all the preprocesses
:return:
:raises ExecutionError if an error occurs
"""
TuttleDirectories.create_tuttle_dirs()
TuttleDirectories.empty_extension_dir()
if not self.has_preprocesses():
return
lt = LogsFollower()
WorkflowRunner.print_preprocesses_header()
for process in self.iter_preprocesses():
TuttleDirectories.prepare_and_assign_paths(process)
lt.follow_process(process.log_stdout, process.log_stderr, None)
with lt.trace_in_background(), TuttleEnv():
for preprocess in self.iter_preprocesses():
WorkflowRunner.print_preprocess_header(preprocess, lt._logger)
success = True
error_msg = None
try:
preprocess.set_start()
preprocess.processor.run(preprocess, preprocess._reserved_path,
preprocess.log_stdout, preprocess.log_stderr)
except TuttleError as e:
success = False
error_msg = str(e)
raise
except Exception:
exc_info = sys.exc_info()
stacktrace = "".join(format_exception(*exc_info))
error_msg = "An unexpected error have happened in tuttle preprocessor {} : \n" \
"{}\n" \
"Preprocess {} will not complete.".format(preprocess._processor.name, stacktrace, preprocess.id)
finally:
preprocess.set_end(success, error_msg)
self.create_reports()
WorkflowRunner.print_preprocesses_footer()
def test_log_single_file(self):
"""LogTracer should log the content of a file"""
with CaptureOutputs() as co:
logger = LogsFollower.get_logger()
lt = LogTracer(logger, logging.INFO, "test.log")
with open("test.log", "w") as f:
f.write("line 1\n")
f.write("line 2\n")
f.write("line 3\n")
lt.trace()
output = co.output
assert output.find("line 1") >= 0, output
assert output.find("line 2") >= 0, output
assert output.find("line 3") >= 0, output
def test_log_huge_file(self):
"""LogTracer should log the content of a big file in stdout"""
with CaptureOutputs() as co:
logger = LogsFollower.get_logger()
lt = LogTracer(logger, "namespace", "test.log")
with open("test.log", "w") as f:
for i in xrange(5000):
f.write("line {}\n".format(i))
while lt.trace():
pass
output = co.output
assert output.find("line 1") >= 0, output
assert output.find("line 2") >= 0, output
assert output.find("line 3") >= 0, output
assert output.find("line 4999") >= 0, output
def test_log_in_background(self):
"""Should log in background ans stop when foreground processing
is over"""
import time
with CaptureOutputs() as co:
lf = LogsFollower()
lf.follow_process("stdout", "stderr", "process_id")
lf.trace_in_background()
with open("stdout", "w") as fout, \
open("stderr", "w") as ferr:
fout.write("file stdout")
ferr.write("file stderr")
lf.terminate()
assert co.output.find(
"[process_id::stdout] file stdout") >= 0, co.output
assert co.output.find(
"[process_id::stderr] file stderr") >= 0, co.output
def test_log_a_lot_in_background(self):
"""Should log in background ans stop when foreground processing
is over even with a lot a data"""
with CaptureOutputs() as co:
lf = LogsFollower()
lf.follow_process("stdout", "stderr", "process_id")
lf.trace_in_background()
with open("stdout", "w") as fout, \
open("stderr", "w") as ferr:
fout.write("file stdout")
ferr.write("file stderr")
for i in xrange(5000):
fout.write("stdout - line {}\n".format(i))
ferr.write("stderr - line {}\n".format(i))
lf.terminate()
assert co.output.find(
"[process_id::stdout] stdout - line 1") >= 0, co.output
assert co.output.find(
"[process_id::stderr] stderr - line 1") >= 0, co.output
assert co.output.find(
"[process_id::stdout] stdout - line 4999") >= 0, co.output
assert co.output.find(
"[process_id::stderr] stderr - line 4999") >= 0, co.output
def test_log_multiple_files(self):
"""LogTracer should log the content of several files in stdout"""
with CaptureOutputs() as co:
lf = LogsFollower()
lf.follow_process("w1.stdout", "w1.stderr", "process1")
lf.follow_process("w2.stdout", "w2.stderr", "process2")
lf.follow_process("w3.stdout", "w3.stderr", "process3")
with open("w1.stdout", "w") as fo1, \
open("w1.stderr", "w") as fe1, \
open("w2.stdout", "w") as fo2, \
open("w2.stderr", "w") as fe2, \
open("w3.stdout", "w") as fo3, \
open("w3.stderr", "w") as fe3 :
for i in xrange(5000):
fo1.write("w1.stdout - line {}\n".format(i))
fe1.write("w1.stderr - line {}\n".format(i))
fo2.write("w2.stdout - line {}\n".format(i))
fe2.write("w2.stderr - line {}\n".format(i))
fo3.write("w3.stdout - line {}\n".format(i))
fe3.write("w3.stderr - line {}\n".format(i))
while lf.trace_logs():
pass
output = co.output
assert output.find("w1.stderr - line 1") >= 0, output
assert output.find("w1.stdout - line 1") >= 0, output
assert output.find("w2.stderr - line 1") >= 0, output
assert output.find("w2.stdout - line 1") >= 0, output
assert output.find("w3.stdout - line 1") >= 0, output
assert output.find("w3.stderr - line 1") >= 0, output
assert output.find("w1.stderr - line 4999") >= 0, output
assert output.find("w1.stdout - line 4999") >= 0, output
assert output.find("w2.stderr - line 4999") >= 0, output
assert output.find("w2.stdout - line 4999") >= 0, output
assert output.find("w3.stdout - line 4999") >= 0, output
assert output.find("w3.stderr - line 4999") >= 0, output
def test_log_format(self):
"""logs should display log level and message"""
with CaptureOutputs() as co:
logger = LogsFollower.get_logger()
logger.info("MESSAGE")
assert co.output.find("MESSAGE") == 0, co.output
class WorkflowRunner:
@staticmethod
def resources2list(resources):
res = "\n".join(("* {}".format(resource.url) for resource in resources))
return res
def __init__(self, nb_workers):
self._lt = LogsFollower()
self._logger = WorkflowRunner.get_logger()
self._pool = None
if nb_workers == -1:
self._nb_workers = int((cpu_count() + 1) / 2)
else:
self._nb_workers = nb_workers
self._free_workers = None
self._completed_processes = []
def start_process_in_background(self, process):
self.acquire_worker()
def process_run_callback(result):
success, error_msg, signatures = result
process.set_end(success, error_msg)
self.release_worker()
self._completed_processes.append((process, signatures))
process.set_start()
resp = self._pool.apply_async(run_process_without_exception, [process], callback = process_run_callback)
def start_processes_on_available_workers(self, runnables):
started_a_process = False
while self.workers_available() and runnables:
# No error
process = runnables.pop()
self.start_process_in_background(process)
started_a_process = True
return started_a_process
def handle_completed_process(self, workflow, runnables, success_processes, failure_processes):
handled_completed_process = False
while self._completed_processes:
completed_process, signatures = self._completed_processes.pop()
if completed_process.success:
success_processes.append(completed_process)
workflow.update_signatures(signatures)
new_runnables = workflow.discover_runnable_processes(completed_process)
runnables.update(new_runnables)
else:
failure_processes.append(completed_process)
handled_completed_process = True
return handled_completed_process
def run_parallel_workflow(self, workflow, keep_going=False):
""" Runs a workflow by running every process in the right order
:return: success_processes, failure_processes :
list of processes ended with success, list of processes ended with failure
"""
for process in workflow.iter_processes():
if process.start is None:
# Don't display logs if the process has already run
self._lt.follow_process(process.log_stdout, process.log_stderr, process.id)
failure_processes, success_processes = [], []
with self._lt.trace_in_background():
runnables = workflow.runnable_processes()
self.init_workers()
try:
while (keep_going or not failure_processes) and \
(self.active_workers() or self._completed_processes or runnables):
started_a_process = self.start_processes_on_available_workers(runnables)
handled_completed_process = self.handle_completed_process(workflow, runnables,
success_processes, failure_processes)
if handled_completed_process or started_a_process:
workflow.export()
else:
sleep(0.1)
if failure_processes and not keep_going:
self._logger.error("Process {} has failled".format(failure_processes[0].id))
self._logger.warn("Waiting for all processes already started to complete")
while self.active_workers() or self._completed_processes:
if self.handle_completed_process(workflow, runnables, success_processes, failure_processes):
workflow.export()
else:
sleep(0.1)
finally:
self.terminate_workers_and_clean_subprocesses()
self.mark_unfinished_processes_as_failure(workflow)
return success_processes, failure_processes
def init_workers(self):
self._pool = Pool(self._nb_workers)
self._free_workers = self._nb_workers
def terminate_workers_and_clean_subprocesses(self):
direct_procs = set(psutil.Process().children())
all_procs = set(psutil.Process().children(recursive=True))
sub_procs = all_procs - direct_procs
# Terminate cleanly direct procs instanciated by multiprocess
self._pool.terminate()
self._pool.join()
# Then terminate subprocesses that have not been terminated
for p in sub_procs:
try:
p.terminate()
except NoSuchProcess:
pass
gone, still_alive = psutil.wait_procs(sub_procs, timeout=2)
for p in still_alive:
p.kill()
def acquire_worker(self):
assert self._free_workers > 0
self._free_workers -= 1
def release_worker(self):
self._free_workers += 1
def workers_available(self):
return self._free_workers
def active_workers(self):
return self._free_workers != self._nb_workers
@staticmethod
def mark_unfinished_processes_as_failure(workflow):
for process in workflow.iter_processes():
if process.start and not process.end:
error_msg = "This process was aborted"
process.set_end(False, error_msg)
workflow.export()
@staticmethod
def print_preprocess_header(process, logger):
title = "Preprocess : {}".format(process.id)
logger.info("[" + title + "]")
#logger.info(underline(title))
@staticmethod
def print_preprocesses_header():
title = "Running preprocesses".upper()
print("[" + title + "]")
#print(underline(title, '='))
@staticmethod
def print_preprocesses_footer():
title = "End of preprocesses... Running the workflow".upper()
#print(underline(title, '='))
print("[" + title + "]")
@staticmethod
def get_logger():
logger = logging.getLogger(__name__)
formater = logging.Formatter("%(message)s")
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(formater)
handler.setLevel(logging.INFO)
logger.setLevel(logging.INFO)
logger.addHandler(handler)
return logger