From b47a8631bbc4fcc9ebbd8b8a62032246effd6f5c Mon Sep 17 00:00:00 2001 From: John Chilton Date: Tue, 1 Jan 2019 14:36:03 -0500 Subject: [PATCH] Track job failure reasons in a more structured way. --- lib/galaxy/jobs/output_checker.py | 83 ++++++++++--------- lib/galaxy/model/__init__.py | 5 +- lib/galaxy/model/mapping.py | 2 + .../migrate/versions/0147_job_messages.py | 54 ++++++++++++ lib/galaxy/tools/linters/tests.py | 2 +- lib/galaxy/tools/verify/interactor.py | 29 ++++++- lib/galaxy/webapps/galaxy/api/jobs.py | 2 +- templates/show_params.mako | 7 ++ test/api/test_jobs.py | 6 ++ test/functional/tools/samples_tool_conf.xml | 1 + test/unit/tools/test_parsing.py | 14 ++++ 11 files changed, 162 insertions(+), 43 deletions(-) create mode 100644 lib/galaxy/model/migrate/versions/0147_job_messages.py diff --git a/lib/galaxy/jobs/output_checker.py b/lib/galaxy/jobs/output_checker.py index eb33590ad24..d2a7eea41b7 100644 --- a/lib/galaxy/jobs/output_checker.py +++ b/lib/galaxy/jobs/output_checker.py @@ -14,22 +14,23 @@ DETECTED_JOB_STATE = Bunch( GENERIC_ERROR='generic_error', ) +ERROR_PEAK = 2000 -def check_output_regex(job, regex, stream, stream_append, max_error_level): + +def check_output_regex(job, regex, stream, stream_name, job_messages, max_error_level): """ check a single regex against a stream regex the regex to check stream the stream to search in - stream_append a list where the descriptions of the detected regexes can be appended + job_messages a list where the descriptions of the detected regexes can be appended max_error_level the maximum error level that has been detected so far returns the max of the error_level of the regex and the given max_error_level """ regex_match = re.search(regex.match, stream, re.IGNORECASE) if regex_match: - rexmsg = __regex_err_msg(regex_match, regex) - log.info("Job %s: %s" % (job.get_id_tag(), rexmsg)) - stream_append.append(rexmsg) + reason = __regex_err_msg(regex_match, stream_name, regex) + job_messages.append(reason) return max(max_error_level, regex.error_level) return max_error_level @@ -51,9 +52,6 @@ def check_output_regex_byline(job, regex, stream, stream_append, max_error_level return max_error_level -ERROR_PEAK = 2000 - - def check_output(tool, stdout, stderr, tool_exit_code, job): """ Check the output of a tool - given the stdout, stderr, and the tool's @@ -77,8 +75,9 @@ def check_output(tool, stdout, stderr, tool_exit_code, job): # to be prepended to the stdout/stderr after all exit code and regex tests # are done (otherwise added messages are searched again). # messages are added it the order of detection - stderr_toolmsg = [] - stdout_toolmsg = [] + + # If job is failed, track why. + job_messages = [] try: # Check exit codes and match regular expressions against stdout and @@ -104,12 +103,19 @@ def check_output(tool, stdout, stderr, tool_exit_code, job): code_desc = stdio_exit_code.desc if None is code_desc: code_desc = "" - tool_msg = ("%s: Exit code %d (%s)" % ( + desc = "%s: Exit code %d (%s)" % ( StdioErrorLevel.desc(stdio_exit_code.error_level), tool_exit_code, - code_desc)) - log.info("Job %s: %s" % (job.get_id_tag(), tool_msg)) - stderr_toolmsg.append(tool_msg) + code_desc) + reason = { + 'type': 'exit_code', + 'desc': desc, + 'exit_code': tool_exit_code, + 'code_desc': code_desc, + 'error_level': stdio_exit_code.error_level, + } + log.info("Job %s: %s" % (job.get_id_tag(), reason)) + job_messages.append(reason) max_error_level = max(max_error_level, stdio_exit_code.error_level) if max_error_level >= StdioErrorLevel.MAX: @@ -130,15 +136,13 @@ def check_output(tool, stdout, stderr, tool_exit_code, job): # - Run the regex's match pattern against stdout # - If it matched, then determine the error level. # o If it was fatal, then we're done - break. - # Repeat the stdout stuff for stderr. - # TODO could test for stderr first? Reason: I would expect it to be smaller and contain the errors - if regex.stdout_match: - max_error_level = check_output_regex_byline(job, regex, stdout, stdout_toolmsg, max_error_level) + if regex.stderr_match: + max_error_level = check_output_regex(job, regex, stderr, 'stderr', job_messages, max_error_level) if max_error_level >= StdioErrorLevel.MAX: break - if regex.stderr_match: - max_error_level = check_output_regex_byline(job, regex, stderr, stderr_toolmsg, max_error_level) + if regex.stdout_match: + max_error_level = check_output_regex(job, regex, stdout, 'stdout', job_messages, max_error_level) if max_error_level >= StdioErrorLevel.MAX: break @@ -177,35 +181,38 @@ def check_output(tool, stdout, stderr, tool_exit_code, job): state = DETECTED_JOB_STATE.OK # Store the modified stdout and stderr in the job: - if len(stdout_toolmsg) > 0: - stdout = "%s\n### END of messages added by Galaxy AND START of original stdout\n%s" % ("\n".join(stdout_toolmsg), stdout) - if len(stderr_toolmsg) > 0: - stderr = "%s\n### END of messages added by Galaxy AND START of original stderr\n%s" % ("\n".join(stderr_toolmsg), stderr) if job is not None: - job.set_streams(stdout, stderr) + job.set_streams(stdout, stderr, job_messages=job_messages) return state -def __regex_err_msg(match, regex): +def __regex_err_msg(match, stream, regex): """ Return a message about the match on tool output using the given ToolStdioRegex regex object. The regex_match is a MatchObject that will contain the string matched on. """ # Get the description for the error level: - err_msg = StdioErrorLevel.desc(regex.error_level) + ": " + desc = StdioErrorLevel.desc(regex.error_level) + ": " + mstart = match.start() + mend = match.end() + if mend - mstart > 256: + match_str = match.string[mstart : mstart + 256] + "..." + else: + match_str = match.string[mstart: mend] + # If there's a description for the regular expression, then use it. # Otherwise, we'll take the first 256 characters of the match. - if None is not regex.desc: - err_msg += regex.desc + if regex.desc is not None: + desc += regex.desc else: - mstart = match.start() - mend = match.end() - err_msg += "Matched on " - # TODO: Move the constant 256 somewhere else besides here. - if mend - mstart > 256: - err_msg += match.string[mstart : mstart + 256] + "..." - else: - err_msg += match.string[mstart: mend] - return err_msg + desc += "Matched on %s" % match_str + return { + "type": "regex", + "stream": stream, + "desc": desc, + "code_desc": regex.desc, + "match": match_str, + "error_level": regex.error_level, + } diff --git a/lib/galaxy/model/__init__.py b/lib/galaxy/model/__init__.py index 10707240552..21f7637f5ee 100644 --- a/lib/galaxy/model/__init__.py +++ b/lib/galaxy/model/__init__.py @@ -230,7 +230,7 @@ class JobLike(object): # TODO: Make iterable, concatenate with chain return self.text_metrics + self.numeric_metrics - def set_streams(self, stdout, stderr): + def set_streams(self, stdout, stderr, job_messages=None): stdout = galaxy.util.unicodify(stdout) or u'' stderr = galaxy.util.unicodify(stderr) or u'' if (len(stdout) > galaxy.util.DATABASE_MAX_STRING_SIZE): @@ -241,6 +241,8 @@ class JobLike(object): stderr = galaxy.util.shrink_string_by_size(stderr, galaxy.util.DATABASE_MAX_STRING_SIZE, join_by="\n..\n", left_larger=True, beginning_on_size_error=True) log.info("stderr for %s %d is greater than %s, only a portion will be logged to database", type(self), self.id, galaxy.util.DATABASE_MAX_STRING_SIZE_PRETTY) self.stderr = stderr + if job_messages is not None: + self.job_messages = job_messages def log_str(self): extra = "" @@ -607,6 +609,7 @@ class Job(JobLike, UsesCreateAndUpdateTime, Dictifiable, RepresentById): self.imported = False self.handler = None self.exit_code = None + self.job_messages = None self._init_metrics() self.state_history.append(JobStateHistory(self)) diff --git a/lib/galaxy/model/mapping.py b/lib/galaxy/model/mapping.py index 55df76e797e..d761f393113 100644 --- a/lib/galaxy/model/mapping.py +++ b/lib/galaxy/model/mapping.py @@ -527,6 +527,7 @@ model.Job.table = Table( Column("copied_from_job_id", Integer, nullable=True), Column("command_line", TEXT), Column("dependencies", JSONType, nullable=True), + Column("job_messages", JSONType, nullable=True), Column("param_filename", String(1024)), Column("runner_name", String(255)), Column("stdout", TEXT), @@ -724,6 +725,7 @@ model.Task.table = Table( Column("stdout", TEXT), Column("stderr", TEXT), Column("exit_code", Integer, nullable=True), + Column("job_messages", JSONType, nullable=True), Column("info", TrimmedString(255)), Column("traceback", TEXT), Column("job_id", Integer, ForeignKey("job.id"), index=True, nullable=False), diff --git a/lib/galaxy/model/migrate/versions/0147_job_messages.py b/lib/galaxy/model/migrate/versions/0147_job_messages.py new file mode 100644 index 00000000000..484681b450c --- /dev/null +++ b/lib/galaxy/model/migrate/versions/0147_job_messages.py @@ -0,0 +1,54 @@ +""" +Add structured failure reason column to jobs table +""" +from __future__ import print_function + +import logging + +from sqlalchemy import Column, MetaData, Table + +from galaxy.model.custom_types import JSONType + +log = logging.getLogger(__name__) +job_messages_column = Column("job_messages", JSONType, nullable=True) +task_job_messages_column = Column("job_messages", JSONType, nullable=True) + + +def upgrade(migrate_engine): + print(__doc__) + metadata = MetaData() + metadata.bind = migrate_engine + metadata.reflect() + + try: + jobs_table = Table("job", metadata, autoload=True) + job_messages_column.create(jobs_table) + assert job_messages_column is jobs_table.c.job_messages + except Exception: + log.exception("Adding column 'job_messages' to job table failed.") + + try: + tasks_table = Table("task", metadata, autoload=True) + task_job_messages_column.create(tasks_table) + assert task_job_messages_column is tasks_table.c.job_messages + except Exception: + log.exception("Adding column 'job_messages' to task table failed.") + + +def downgrade(migrate_engine): + metadata = MetaData() + metadata.bind = migrate_engine + metadata.reflect() + + try: + jobs_table = Table("job", metadata, autoload=True) + job_messages = jobs_table.c.job_messages + job_messages.drop() + except Exception: + log.exception("Dropping 'job_messages' column from job table failed.") + try: + tasks_table = Table("task", metadata, autoload=True) + job_messages = tasks_table.c.job_messages + job_messages.drop() + except Exception: + log.exception("Dropping 'job_messages' column from task table failed.") diff --git a/lib/galaxy/tools/linters/tests.py b/lib/galaxy/tools/linters/tests.py index 73c230566d1..aca2351e7a8 100644 --- a/lib/galaxy/tools/linters/tests.py +++ b/lib/galaxy/tools/linters/tests.py @@ -19,7 +19,7 @@ def lint_tsts(tool_xml, lint_ctx): has_test = True if len(test.findall("assert_stdout")) > 0: has_test = True - if len(test.findall("assert_stdout")) > 0: + if len(test.findall("assert_stderr")) > 0: has_test = True if len(test.findall("assert_command")) > 0: has_test = True diff --git a/lib/galaxy/tools/verify/interactor.py b/lib/galaxy/tools/verify/interactor.py index 55bf2578e5b..8d50869f094 100644 --- a/lib/galaxy/tools/verify/interactor.py +++ b/lib/galaxy/tools/verify/interactor.py @@ -883,11 +883,36 @@ def _verify_outputs(testdef, history, jobs, tool_id, data_list, data_collection_ "stdout": "Standard output of the job", "stderr": "Standard error of the job", } + # TODO: Only hack the stdio like this for older profkle, for newer tool profiles + # add some syntax for asserting job messages maybe - or just drop this because exit + # code and regex on stdio can be tested directly - so this is really testing Galaxy + # core handling more than the tool. + job_messages = job_stdio.get("job_messages") or [] + stdout_prefix = "" + stderr_prefix = "" + for job_message in job_messages: + message_type = job_message.get("type") + if message_type == "regex" and job_message.get("stream") == "stderr": + stderr_prefix += (job_message.get("desc") or '') + "\n" + elif message_type == "regex" and job_message.get("stream") == "stdout": + stdout_prefix += (job_message.get("desc") or '') + "\n" + elif message_type == "exit_code": + stderr_prefix += (job_message.get("desc") or '') + "\n" + else: + raise Exception("Unknown job message type [%s] in [%s]" % (message_type, job_message)) + for what, description in other_checks.items(): if getattr(testdef, what, None) is not None: try: - data = job_stdio[what] - verify_assertions(data, getattr(testdef, what)) + raw_data = job_stdio[what] + assertions = getattr(testdef, what) + if what == "stdout": + data = stdout_prefix + raw_data + elif what == "stderr": + data = stderr_prefix + raw_data + else: + data = raw_data + verify_assertions(data, assertions) except AssertionError as err: errmsg = '%s different than expected\n' % description errmsg += str(err) diff --git a/lib/galaxy/webapps/galaxy/api/jobs.py b/lib/galaxy/webapps/galaxy/api/jobs.py index db25f4c479c..180a8579fb7 100644 --- a/lib/galaxy/webapps/galaxy/api/jobs.py +++ b/lib/galaxy/webapps/galaxy/api/jobs.py @@ -134,7 +134,7 @@ class JobController(BaseAPIController, UsesLibraryMixinItems): job_dict = self.encode_all_ids(trans, job.to_dict('element', system_details=is_admin), True) full_output = util.asbool(kwd.get('full', 'false')) if full_output: - job_dict.update(dict(stderr=job.stderr, stdout=job.stdout)) + job_dict.update(dict(stderr=job.stderr, stdout=job.stdout, job_messages=job.job_messages)) if is_admin: if job.user: job_dict['user_email'] = job.user.email diff --git a/templates/show_params.mako b/templates/show_params.mako index 6e60bcf3c5e..daeeb837d84 100644 --- a/templates/show_params.mako +++ b/templates/show_params.mako @@ -173,6 +173,13 @@ Tool Standard Error:stderr %if job: Tool Exit Code:${ job.exit_code | h } + %if job.job_messages: + Job Messages