Open Bug 1453576 Opened 6 years ago Updated 10 months ago

"run_command" should log relative and not absolute paths

Categories

(Release Engineering :: Applications: MozharnessCore, enhancement)

enhancement

Tracking

(Not tracked)

People

(Reporter: whimboo, Unassigned)

References

Details

(In reply to Chris AtLee [:catlee] from bug 1436237 comment #26)
> (In reply to Henrik Skupin (:whimboo) from comment #25)
> > (In reply to Ed Morley [:emorley] from comment #24)
> > > * The error line contains parts that will always be unique (eg
> > > "task_1522889138" in the path), so never get correct suggestions. The
> > > harness should be only outputting relative paths in error messages.
> > 
> > Those lines are not from the individual harnesses but from mozharness. I'm
> > not sure why we log those with the absolute path and not the relative one.
> > Maybe to see which exact binaries are used? If we could agree to have
> > relative paths as output by mozharness, we could indeed make things better
> > for Treeherder.
> > 
> > Chris, what do you think?
> 
> Without looking at the code, I would assume that we're logging the full
> commandline run, rather than making an explicit decision about whether to
> log absolute or relative paths.
> 
> If we can switch mozharness to use relative paths for the commandline, then
> I'm sure the logging will be improved.

Here an example:

https://treeherder.mozilla.org/logviewer.html#?job_id=173196711&repo=autoland&lineNumber=1824

> 03:55:42     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['C:\\Users\\task_1523503878\\build\\venv\\Scripts\\python', '-u', 'C:\\Users\\task_1523503878\\build\\tests\\reftest\\runreftest.py', '--total-chunks', '4', '--this-chunk', '3', '--appname=C:\\Users\\task_1523503878\\build\\application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=C:\\Users\\task_1523503878\\build\\symbols', '--log-raw=C:\\Users\\task_1523503878\\build\\blobber_upload_dir\\reftest_raw.log', '--log-errorsummary=C:\\Users\\task_1523503878\\build\\blobber_upload_dir\\reftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=C:\\Users\\task_1523503878\\build', '--suite=reftest', '--', 'tests/reftest/tests/layout/reftests/reftest.list']

I'm not sure what CWD currently is but I would assume it's `C:\\Users\\task_1523503878\\build`. That way we could reduce it to just:

> 03:55:42     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['venv\\Scripts\\python', '-u', 'tests\\reftest\\runreftest.py', '--total-chunks', '4', '--this-chunk', '3', '--appname=application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=symbols', '--log-raw=blobber_upload_dir\\reftest_raw.log', '--log-errorsummary=blobber_upload_dir\\reftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=C:\\Users\\task_1523503878\\build', '--suite=reftest', '--', 'tests/reftest/tests/layout/reftests/reftest.list']

And also always logging slashes instead of backslashes on Windows would make the error line exactly the same across all platforms:

> 03:55:42     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['venv/Scripts/python', '-u', 'tests/reftest/runreftest.py', '--total-chunks', '4', '--this-chunk', '3', '--appname=application/firefox/firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=symbols', '--log-raw=blobber_upload_dir/reftest_raw.log', '--log-errorsummary=blobber_upload_dir/reftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=C:/Users/task_1523503878/build', '--suite=reftest', '--', 'tests/reftest/tests/layout/reftests/reftest.list']

Ed, would that be a problem if the path for the python command differs a bit? It would be `venv/Scripts/python` vs. `venv/bin/python`? If yes we might only log `python` given that we know in which virtualenv we are based on former log entries.
Flags: needinfo?(emorley)
Perhaps we can log a proper string instead of a list as well?  It
would make it easier to copy.
We could make a distinction between the command run and the command reported in errors. That is, one possibility is to keep running and reporting the same command:

03:38:36     INFO - Calling ['C:\\Users\\task_1523503878\\build\\venv\\Scripts\\python', '-u', 'C:\\Users\\task_1523503878\\build\\tests\\reftest\\runreftest.py', '--total-chunks', '4', '--this-chunk', '3', '--appname=C:\\Users\\task_1523503878\\build\\application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=C:\\Users\\task_1523503878\\build\\symbols', '--log-raw=C:\\Users\\task_1523503878\\build\\blobber_upload_dir\\reftest_raw.log', '--log-errorsummary=C:\\Users\\task_1523503878\\build\\blobber_upload_dir\\reftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=C:\\Users\\task_1523503878\\build', '--suite=reftest', '--', 'tests/reftest/tests/layout/reftests/reftest.list'] with output_timeout 1000
03:38:37     INFO -  REFTEST INFO | Running with e10s: True
...

but sanitize the command before logging an error:

03:55:42     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['.../python', '-u', '.../runreftest.py', ...]

That way all 1000 second timeouts of runreftest.py would be logged the same and filed under the same bug, but the full paths and all the command arguments would still be available in each log.

Just a thought...
(In reply to Henrik Skupin (:whimboo) from comment #0)
> Ed, would that be a problem if the path for the python command differs a
> bit? It would be `venv/Scripts/python` vs. `venv/bin/python`? 

It's hard to say, since it depends on how exactly the full text search tokenization interacts with it. Ideally the paths would have as few permutations as possible, but if there were a couple, then sheriffs could at least enter both forms in the bug summary. (The main problem at the moment is that there are millions of combinations given randomly generated path names)
Flags: needinfo?(emorley)
(In reply to Andreas Tolfsen ‹:ato› from comment #1)
> Perhaps we can log a proper string instead of a list as well?  It
> would make it easier to copy.

This is already done in mozharness:

https://dxr.mozilla.org/mozilla-central/rev/325ef357e5b73d63794e47c02c7f8e7cf58ccb48/testing/mozharness/mozharness/base/script.py#1376-1377

Do you have examples where this is not happening?
Flags: needinfo?(ato)
Changes to make the logging relative path to happen need to be done here:

https://dxr.mozilla.org/mozilla-central/rev/325ef357e5b73d63794e47c02c7f8e7cf58ccb48/testing/mozharness/mozharness/base/script.py#1365-1377

Chris, do you think this is a bug someone from your team can mentor?
Flags: needinfo?(catlee)
(In reply to Henrik Skupin (:whimboo) from comment #4)
> (In reply to Andreas Tolfsen ‹:ato› from comment #1)
> > Perhaps we can log a proper string instead of a list as well?  It
> > would make it easier to copy.
> 
> This is already done in mozharness:
> 
> https://dxr.mozilla.org/mozilla-central/rev/
> 325ef357e5b73d63794e47c02c7f8e7cf58ccb48/testing/mozharness/mozharness/base/
> script.py#1376-1377
> 
> Do you have examples where this is not happening?

The above log you pasted.
Flags: needinfo?(ato)
That was only an excerpt and misses preceding and following lines.
Flags: needinfo?(catlee)
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.