Improve logging of mozharness tasks in run-task

NEW
Unassigned

Status

Taskcluster
Task Configuration
2 years ago
9 months ago

People

(Reporter: gps, Unassigned)

Tracking

Details

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(4 attachments)

(Reporter)

Description

2 years ago
We'll soon be switching some mozharness tasks to use `run-task` in TaskCluster. For those who don't know, `run-task`  is a very lightweight and generic wrapper to invoke tasks in TaskCluster. See https://hg.mozilla.org/mozilla-central/file/tip/testing/docker/recipes/run-task. I'd like to introduce some smarts in run-task to handle mozharness-based tasks better.

First, mozharness prefixes line output with the time: HH:MM:SS. run-task also prefixes output as a datetime string. These are redundant. I'd like to strip the mozharness timestamp.

Second, mozharness has step data. I'd like to parse the step beginning and end events and encode that in the line prefix.

https://public-artifacts.taskcluster.net/HjNFFgkBTrWwzKVW5r4w9w/0/public/logs/live_backing.log shows an example of what I've done so far.

ekyle, others may have other requests to facilitate log parsing.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 8

2 years ago
mozreview-review
Comment on attachment 8779929 [details]
Bug 1294109 - Use more byte literals;

https://reviewboard.mozilla.org/r/70812/#review68322

I leave it to your discretion, since these happen to be ASC127, or less

::: testing/docker/recipes/run-task:39
(Diff revision 1)
>  def run_and_prefix_output(prefix, args):
>      """Runs a process and prefixes its output with the time.
>  
>      Returns the process exit code.
>      """
> -    print_line(prefix, 'executing %s\n' % args)
> +    print_line(prefix, b'executing %s\n' % args)

Given that `prefix` is being concatenated with byte literals, I suggest you verify it is unicode (all parameters should be unicode, right?) and then convert it to bytes.

Here `prefix` is assigned u'task'

https://dxr.mozilla.org/mozilla-central/source/testing/docker/recipes/run-task#192
Attachment #8779929 - Flags: review?(klahnakoski) → review+

Comment 9

2 years ago
mozreview-review
Comment on attachment 8779866 [details]
Bug 1294109 - Print resource usage of task;

https://reviewboard.mozilla.org/r/70766/#review68348

::: testing/docker/recipes/run-task:224
(Diff revision 2)
> +    try:
> -    return run_and_prefix_output(b'task', task_args)
> +        return run_and_prefix_output(b'task', task_args)
> +    finally:
> +        # Print resource usage of self and children for forensics
> +        # purposes.
> +        self_usage = resource.getrusage(resource.RUSAGE_SELF)

Do these lines raise exceptions?
Attachment #8779866 - Flags: review?(klahnakoski) → review-

Comment 10

2 years ago
mozreview-review
Comment on attachment 8779864 [details]
Bug 1294109 - Strip time prefix from process output;

https://reviewboard.mozilla.org/r/70762/#review68324

::: testing/docker/recipes/run-task:69
(Diff revision 2)
>              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)
> +

This looks like a scary strategy of munging text-to-text.  I am certain you got this particular case right, but in general I suggest letting the redundancy exist, and dealing with it at the source, if ever.
Attachment #8779864 - Flags: review?(klahnakoski) → review-

Comment 11

2 years ago
mozreview-review
Comment on attachment 8779865 [details]
Bug 1294109 - Prefix log output with mozharness step name;

https://reviewboard.mozilla.org/r/70764/#review68340

::: testing/docker/recipes/run-task:78
(Diff revision 2)
>          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)

Transforming text to text looks dangerous.  I beleive the patterns you are loking for are not the only ones; there is a "skipping" variation in the start step, and a "summary" variation in the stop step, that are not captured here. 

The routines processing these logs can be composed to deal with the prefixes applied by each step in the logging chain.  For example, we already have an ETL transform to convert mozharness start/stop steps, we can wrap in code that first removes this code's prefix.

If we are not changing the data stored in thess lines, just the format, then we should leave it alone.
Attachment #8779865 - Flags: review?(klahnakoski) → review-
(Reporter)

Comment 12

2 years ago
mozreview-review
Comment on attachment 8779929 [details]
Bug 1294109 - Use more byte literals;

https://reviewboard.mozilla.org/r/70812/#review68804

I'm going to move this commit to bug 1294234 so I can land that series. I'll fix the u'' for the prefix in flight.
(Reporter)

Comment 13

9 months ago
I'm not actively working on this.
Assignee: gps → nobody
Status: ASSIGNED → NEW
You need to log in before you can comment on or make changes to this bug.