1304282 - mozharness process times are wrong because of output buffering

Status: RESOLVED FIXED

(Release Engineering :: Applications: MozharnessCore, defect)

Description

[Gregory Szorc [:gps]]

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 1

[Gregory Szorc [:gps]]

Attachment: Bug 1304282 - Disable output buffering from mozharness spawned processes;

Without this, process output is buffered by default. This means
timestamps that mozharness prefixes to process output aren't
accurate unless the process is spewing enough output to flush the
output buffer.

Output buffering could lead to bad things. For example, a process
could emit output that would cause mozharness's output monitor to
abort the process. However, if that output is caught in limbo in
the output buffer, mozharness may take several seconds or even
minutes to react.

With this change, the mozharness process receives process output
as soon as that process writes to its standard file descriptors.
Once a newline is seen, mozharness will process it immediately.

Note that this only impacts the case where there is no output
timeout, as the existing code for output timeout uses mozprocess
and I'm pretty sure mozharness doesn't buffer output.

Review commit: https://reviewboard.mozilla.org/r/79982/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/79982/

Comment 2

[(not currently active) Ted Mielczarek]

Comment on attachment 8793176 [details]
Bug 1304282 - Disable output buffering from mozharness spawned processes;

https://reviewboard.mozilla.org/r/79982/#review79468

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/27a183a2527c
Disable output buffering from mozharness spawned processes; r=ted

Comment 4

[Iris Hsiao [:ihsiao]]

https://hg.mozilla.org/mozilla-central/rev/27a183a2527c