mozharness process times are wrong because of output buffering

RESOLVED FIXED

Status

Release Engineering
Applications: MozharnessCore
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: gps, Assigned: gps)

Tracking

unspecified

Firefox Tracking Flags

(firefox52 fixed)

Details

MozReview Requests

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

Attachments

(1 attachment)

(Assignee)

Description

2 years ago
I was looking at logs for mozharness jobs and noticed something like the following:

22:01:13     INFO - Running command: ['hg', '--config', 'ui.merge=internal:merge', '--config', 'extensions.robustcheckout=/builds/slave/test/scripts/external_tools/robustcheckout.py', 'robustcheckout', 'https://hg.mozilla.org/try', '/builds/slave/test/checkout', '--sharebase', '/builds/slave/test/hg-shared', '--purge', '--upstream', 'https://hg.mozilla.org/mozilla-unified', '--revision', '7874c8d355735e359597697127f6ea31045c4c35']
22:01:13     INFO - Copy/paste: hg --config ui.merge=internal:merge --config extensions.robustcheckout=/builds/slave/test/scripts/external_tools/robustcheckout.py robustcheckout https://hg.mozilla.org/try /builds/slave/test/checkout --sharebase /builds/slave/test/hg-shared --purge --upstream https://hg.mozilla.org/mozilla-unified --revision 7874c8d355735e359597697127f6ea31045c4c35
22:01:13     INFO -  ensuring https://hg.mozilla.org/try@7874c8d355735e359597697127f6ea31045c4c35 is available at /builds/slave/test/checkout
22:01:13     INFO -  (cloning from upstream repo https://hg.mozilla.org/mozilla-unified)
22:01:13     INFO -  (sharing from new pooled repository 8ba995b74e18334ab3707f27e9eb8f4e37ba3d29)
22:01:13     INFO -  applying clone bundle from https://s3-us-west-2.amazonaws.com/moz-hg-bundles-us-west-2/mozilla-unified/0750ccffec1e67c071071fe053acde164b53aa1d.gzip-v2.hg
22:01:13     INFO -  warning: s3-us-west-2.amazonaws.com certificate with fingerprint 9d:35:10:89:3f:58:cb:5b:7a:89:54:d2:25:9c:67:84:c4:a9:8e:01 not verified (check hostfingerprints or web.cacerts config setting)
22:15:58     INFO -  adding changesets
22:15:58     INFO -  adding manifests
22:15:58     INFO -  adding file changes
22:15:58     INFO -  added 346454 changesets with 1849381 changes to 263038 files (+10 heads)
22:16:04     INFO -  finished applying clone bundle

Those times are wrong: several minutes should pass between the "adding changesets" and "adding file changes" lines but they all have the same timestamp. The underlying reason is ScriptMixin.run_command buffering process output.

The fix is simple.
Comment hidden (mozreview-request)

Comment 2

2 years ago
mozreview-review
Comment on attachment 8793176 [details]
Bug 1304282 - Disable output buffering from mozharness spawned processes;

https://reviewboard.mozilla.org/r/79982/#review79468
Attachment #8793176 - Flags: review?(ted) → review+

Comment 3

2 years ago
Pushed by gszorc@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/27a183a2527c
Disable output buffering from mozharness spawned processes; r=ted

Comment 4

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/27a183a2527c
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
status-firefox52: --- → fixed
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.