Bug 1294109 - Prefix log output with mozharness step name; r?ekyle
We now scan process output for mozharness step data. When we see
the beginning of a mozharness step, we change the line/log prefix
to include the step name. When we see the end of a mozharness step,
we restore the original prefix (which is likely "task").
This makes it much easier for humans to visually scan logs for
specific steps and for automated processes to grep for lines
belonging to certain steps.
If we wanted to, we could print out a summary of time spent
in various steps. But mozharness does that already, so let's
not complicate run-task too much.
MozReview-Commit-ID: 1lcWGxmmWN4
--- a/testing/docker/recipes/run-task
+++ b/testing/docker/recipes/run-task
@@ -22,16 +22,20 @@ import grp
import os
import pwd
import re
import subprocess
import sys
RE_TIME_PREFIX = re.compile('^\d{2}:\d{2}:\d{2}\s+')
+RE_MOZHARNESS_START_STEP = re.compile('\[mozharness:[^\]]+\] Running '
+ '(?P<step>[a-zA-Z0-9_-]+) step')
+RE_MOZHARNESS_END_STEP = re.compile('\[mozharness:[^\]]+\] Finished '
+ '(?P<step>[a-zA-Z0-9_-]+) step')
def print_line(prefix, m):
now = datetime.datetime.utcnow()
print(b'[%s %sZ] %s' % (prefix, now.isoformat(), m), end=b'')
def run_and_prefix_output(prefix, args):
@@ -53,26 +57,41 @@ def run_and_prefix_output(prefix, args):
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
stdin=sys.stdin.fileno(),
cwd='/',
# So \r in progress bars are rendered as multiple
# lines, preserving progress indicators.
universal_newlines=True)
+ step = None
while True:
data = p.stdout.readline()
if data == b'':
break
# Some other process is printing out times. Strip that output since
# our lines are prefixed with the full datetime.
data = RE_TIME_PREFIX.sub(b'', data, count=1)
- print_line(prefix, data)
+ # Detect mozharness steps and change the log prefix to be the step
+ # name. This makes it easier to visually scan and grep logs for
+ # certain steps.
+ m = RE_MOZHARNESS_START_STEP.search(data)
+ if m:
+ step = m.group('step')
+
+ print_line(step or prefix, data)
+
+ # Reset the active step at the end of it so the step doesn't leak
+ # into subsequent lines (in case the next line isn't a begin step
+ # message).
+ m = RE_MOZHARNESS_END_STEP.search(data)
+ if m:
+ step = None
return p.wait()
def vcs_checkout(args):
# TODO get VCS parameters from arguments.
base_repo = os.environ.get('GECKO_BASE_REPOSITORY')
