1048858 - Show intermediate pushlogs when bisecting integration branches and/or when mozregression is interrupted with ctrl-c/kill

Status: RESOLVED FIXED

(Testing :: mozregression, defect)

Description

[:Gijs (he/him)]

Quite often, I find myself annoyed because I suspect that a bisection has narrowed things down far enough - but I can't ctrl-c mozregression because then I won't get a regression range as output, nor do I get an "intermediate" range while the bisection is ongoing. The information is all there, but if I had, say, 3 subsequent "bad" builds, I have to scroll a lot and find the info in my terminal spew.

It would be nice if immediately after typing good/bad/broken/skip, the current range was output, before starting to download the next build.

Comment 1

[William Lachance (:wlach)]

Yeah, this would be good to have. Not too difficult either I don't think.

Comment 2

[Vaibhav (:vaibhav1994)]

Attachment: print-pushlog

I have tested this patch and it is printing the pushlog after good/bad/broken/skip command, however I am not sure if we need this or something else too?

Comment 3

[William Lachance (:wlach)]

Comment on attachment 8532166 [details] [review]
print-pushlog

This doesn't look quite right to me. I think we want to print out the range just before we call bisect_inbound again, that way we incorporate the new revision range we get from evaluating the verdict.

Comment 4

[Vaibhav (:vaibhav1994)]

Attachment: print-pushlog

Ok, so I have added print_range() calls before bisect_inbound() and bisect_nightlies(). Would like your views on this..

Comment 5

[William Lachance (:wlach)]

Comment on attachment 8532520 [details] [review]
print-pushlog

This is better, but I still think there's a lot of unnecessary duplication in here. After looking at the code in more detail, I'd probably just insert a call to print_range inside print_inbound_regression_progress and print_nightly_regression_progress.

Comment 6

[Vaibhav (:vaibhav1994)]

Attachment: print-pushlog

Yes, I was also feeling it was repeated many times. Made the changes suggested by you.

Comment 7

[William Lachance (:wlach)]

Comment on attachment 8533791 [details] [review]
print-pushlog

Hmm, this seems to be working for inbound builds, but for m-c builds I'm seeing this during the bisection process:

 1:42.72 LOG: MainThread Bisector INFO Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?startdate=None&enddate=None

We need to figure out how to print something sensible here. I think we need to be saving the mozilla-central revisions somehow.

Comment 8

[Julien Pagès (:parkouss)]

Yup, I have an idea for this one, should be simple enough. Now that nightlies are checked like inbound, we just have to add read_txt_content=True as a parameter for the call BuildFolderInfoFetcher.find_build_info in the NightlyBuildData class.

https://github.com/mozilla/mozregression/blob/master/mozregression/build_data.py#L396

This way we will have changeset information before downloading/testing the build so we are able to make it act like inbounds.

Comment 9

[Julien Pagès (:parkouss)]

I have done this for bug 999022. So we now have the revisions from mozilla-central at any time.

Vaibhav, do you still want to work on this ? Note that the codebase has changed, and you will probably have to rewrite the patch from scratch. I think that now you will have to work in the bisector.py file.

If you're interested, you can address the reviews to me, as William is busy with other things now.

Comment 10

[Vaibhav (:vaibhav1994)]

Julien, thanks for fixing up the revisions from mozilla-central. I am interested in completing this bug, and will look up the changed code and address the review to you :)

Thanks!

Comment 11

[Joel Maher ( :jmaher ) (UTC -8)]

hey Vaibhav, doing a drive by here, see that you were going to address some issues- do you have enough information to finish this up?

Comment 12

[Vaibhav (:vaibhav1994)]

I tried pulling the latest source code and running it. I am getting this error:

(venv)vaibhav@vaibhav:~/mozregression$ mozregression --bits=32 --profile e10s --inbound-branch=fx-team --inbound --good-rev=88adcf8fef83 --bad-rev=6bd2071b373f
 0:00.00 LOG: MainThread Bisector INFO Getting inbound builds between 88adcf8fef83 and 6bd2071b373f
 0:17.04 LOG: MainThread Test Runner INFO Testing inbound build with timestamp 1414495907, revision f26373e6
 0:17.04 LOG: MainThread Test Runner INFO Downloading build from: http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/fx-team-linux/1414495907/firefox-36.0a1.en-US.linux-i686.tar.bz2
===== Downloaded 100% =====
['/tmp/tmpS6MJQz/firefox/firefox', '-profile', '/home/vaibhav/mozregression/e10s']
Traceback (most recent call last):
  File "/home/vaibhav/mozregression/venv/bin/mozregression", line 9, in <module>
    load_entry_point('mozregression==0.33', 'console_scripts', 'mozregression')()
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/main.py", line 258, in cli
    sys.exit(bisect(runner, logger))
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/main.py", line 162, in bisect_inbound
    options.first_bad_revision)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/bisector.py", line 403, in bisect_inbound
    range=60*60*12)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/bisector.py", line 250, in bisect
    return self._bisect(handler, build_data)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/bisector.py", line 274, in _bisect
    allow_back=bool(previous_data))
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/test_runner.py", line 131, in evaluate
    launcher.start(**self.launcher_kwargs)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/launchers.py", line 66, in start
    self._start(**kwargs)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozregression/launchers.py", line 126, in _start
    self.runner.start()
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozrunner/base/browser.py", line 67, in start
    BaseRunner.start(self, *args, **kwargs)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozrunner/base/runner.py", line 102, in start
    self.process_handler.run(self.timeout, self.output_timeout)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 669, in run
    self.proc = self.Process([self.cmd] + self.args, **args)
  File "/home/vaibhav/mozregression/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 97, in __init__
    universal_newlines, startupinfo, creationflags)
  File "/usr/lib/python2.7/subprocess.py", line 710, in __init__
    errread, errwrite)
  File "/usr/lib/python2.7/subprocess.py", line 1335, in _execute_child
    raise child_exception
OSError: [Errno 2] No such file or directory


Unassigning myself from the bug for now, as I am busy with other bugs. Will take a look at it again when I find time.

Comment 13

[Julien Pagès (:parkouss)]

(In reply to Vaibhav (:vaibhav1994) from comment #12)
> I tried pulling the latest source code and running it. I am getting this
> error:

I am not able to reproduce you error with mozregression 0.33 on my archlinux 64.

mozregression --bits=32 --inbound-branch=fx-team --inbound --good-rev=88adcf8fef83 --bad-rev=6bd2071b373f --profile e10s

Works well for me.

If you are sure that you got error with the latest mozregression (non modified, as I see there is some print statements that are not from the current mozreg codebase), please open a bug with enough information for us to reproduce it if possible.

Comment 14

[Vaibhav (:vaibhav1994)]

It is working well for me on my home machine on Ubuntu 14.04. Weirdly, it was not working on my work machine during the day. I will check again tomorrow on the work machine, and see if the error persists.

Comment 15

[Vaibhav (:vaibhav1994)]

Ok, I did a fresh clone of mozregression(0.33) and am able to produce the same error on Ubuntu 14.10 64bit. I will file a bug for the same.

Comment 16

[Julien Pagès (:parkouss)]

Attachment: print pushlog on keyboardinterrupt (ctrl-c)

Hey,

Will, I would like your feedback on this. This is printing pushlog on Ctrl-C interrupt (as the bug title suggest) - but not on every good/bad answer (I wonder if it is useful since it will be printed on ctrl-c interruptions, you tell me).

It could be easily updated to provide the full command line to re run in case of any other errors, and this may be good for bug 1087986 for example.

Here is a raw output:


mozregression -g 2014-11-10 -b2014-11-20 --http-cache-dir cache/ 
 0:02.65 LOG: MainThread Test Runner INFO Running nightly for 2014-11-15
 0:02.65 LOG: MainThread Test Runner INFO Downloading build from: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/11/2014-11-15-03-02-05-mozilla-central/firefox-36.0a1.en-US.linux-x86_64.tar.bz2
===== Downloaded 100% =====
^C
Interrupted.
 0:07.11 LOG: Dummy-14 Bisector INFO Last good revision: d380166816dd
 0:07.11 LOG: Dummy-14 Bisector INFO First bad revision: 6ce1b906c690
 0:07.11 LOG: Dummy-14 Bisector INFO Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d380166816dd&tochange=6ce1b906c690


(By the way, Dummy-14 is strange, but that's another log-related story)

Comment 17

[William Lachance (:wlach)]

Comment on attachment 8566489 [details] [review]
print pushlog on keyboardinterrupt (ctrl-c)

Yes, this sounds useful! Even more useful would adding information on how to resume where you left off.

Comment 18

[Julien Pagès (:parkouss)]

Attachment: print pushlogurl on keyboard interrupt exit

Ok, I took your comment into account. Now the patch print the pushlog and the resume info on some known exceptions (and when information is available).

Here is a log of a run (sorry, it's a bit long):

------------------------------------------------------------

mozregression -g 2014-11-10 -b2014-11-11 --http-cache-dir cache/
 0:03.13 LOG: MainThread Bisector INFO Got as far as we can go bisecting nightlies...
 0:03.13 LOG: MainThread Bisector INFO Last good revision: d380166816dd
 0:03.13 LOG: MainThread Bisector INFO First bad revision: cbe6afcae26c
 0:03.13 LOG: MainThread Bisector INFO Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d380166816dd&tochange=cbe6afcae26c

 0:03.13 LOG: MainThread Bisector INFO ... attempting to bisect inbound builds (starting from 4 days ago, to make sure no inbound revision is missed)
 0:04.78 LOG: MainThread Bisector INFO Getting inbound builds between 2114ef80f6ae and cbe6afcae26c
 0:52.54 LOG: MainThread Test Runner INFO Testing inbound build with timestamp 1415376367, revision 02f36604
 0:52.54 LOG: MainThread Test Runner INFO Downloading build from: http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-linux64/1415376367/firefox-36.0a1.en-US.linux-x86_64.tar.bz2
===== Downloaded 100% =====
10:10.37 LOG: MainThread Test Runner INFO Launching /tmp/tmpW7mG1t/firefox/firefox
10:10.38 LOG: MainThread mozversion INFO application_buildid: 20141107080607
10:10.38 LOG: MainThread mozversion INFO application_changeset: 02f36604f77b
10:10.38 LOG: MainThread mozversion INFO application_display_name: Nightly
10:10.38 LOG: MainThread mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
10:10.38 LOG: MainThread mozversion INFO application_name: Firefox
10:10.38 LOG: MainThread mozversion INFO application_remotingname: firefox
10:10.38 LOG: MainThread mozversion INFO application_repository: https://hg.mozilla.org/integration/mozilla-inbound
10:10.38 LOG: MainThread mozversion INFO application_vendor: Mozilla
10:10.38 LOG: MainThread mozversion INFO application_version: 36.0a1
10:10.38 LOG: MainThread mozversion INFO platform_buildid: 20141107080607
10:10.38 LOG: MainThread mozversion INFO platform_changeset: 02f36604f77b
10:10.38 LOG: MainThread mozversion INFO platform_repository: https://hg.mozilla.org/integration/mozilla-inbound
10:10.38 LOG: MainThread mozversion INFO platform_version: 36.0a1
Was this inbound build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry' or 'exit' and press Enter): g
13:52.82 LOG: MainThread Bisector INFO Narrowed inbound regression window from [808d06b9, 524ebd4d] (156 revisions) to [02f36604, 524ebd4d] (78 revisions) (~6 steps left)
13:58.06 LOG: MainThread Test Runner INFO Testing inbound build with timestamp 1415592789, revision 095f5e23
13:58.06 LOG: MainThread Test Runner INFO Downloading build from: http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-linux64/1415592789/firefox-36.0a1.en-US.linux-x86_64.tar.bz2
^C=== Downloaded 0% =====
Interrupted.
14:00.52 LOG: Dummy-72 Bisector INFO Last good revision: 02f36604f77b
14:00.52 LOG: Dummy-72 Bisector INFO First bad revision: 524ebd4de640
14:00.52 LOG: Dummy-72 Bisector INFO Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=02f36604f77b&tochange=524ebd4de640

14:00.52 LOG: Dummy-72 Bisector INFO To resume, run:
14:00.52 LOG: Dummy-72 Bisector INFO mozregression --inbound --good-rev=02f36604f77b --bad-rev=524ebd4de640 --app=firefox  --bits=64

------------------------------------------------------------

This seems to works well, and is useful. It may be good to test it under windows, I'm not sure if the atexit.register behaves in the same way (it should but I would check that temp dirs are still cleaned for example).


Also, this is not directly related, but there are two things that I would like to improve:

- the resume info is incomplete. Here, it is missing my --http-cache argument. This is not the first time I see this kind of things - it seems hard to maintain an up to date resume info function. Not sure what to do for that, but I'm thinking that we should consider to: 1. print less information (not the exact command to type, just what is really useful) or 2. find a way to automatically catch that we are not up to date with the resume info function.

- the log statements are verbose. I'm thinking that we could replace:

14:00.52 LOG: Dummy-72 Bisector INFO To resume, run:

with:

14:00.52 Bisector INFO To resume, run:

ie, remove the LOG: and the thread info. I wonder if the thread information is useful anyway for standard use (maybe we could activate this with a command line argument)

Comment 19

[William Lachance (:wlach)]

Comment on attachment 8567003 [details] [review]
print pushlogurl on keyboard interrupt exit

This looks good, I don't see why it shouldn't work on Windows... I can give it a quick test later if you like, just needinfo me.

Comment 20

[William Lachance (:wlach)]

needinfo'ing myself to test this tomorrow

Comment 21

[Julien Pagès (:parkouss)]

So, I tested it on windows (I had some time), and this works fine. :) I merged this in.

So for next mozregression version, a Ctrl-C exit or some know error (including network related error) will print the pushlog url and how to resume, given that we have enough information to do that.

I think this fix the issue here, so I close the bug. Feel free to reopen it if it is not the case.