785129 - Create Autophone tests to run unit tests

Status: RESOLVED FIXED

(Testing Graveyard :: Autophone, defect)

Comment 1

[Bob Clary [:bc] (inactive)]

Attachment: patch

patch to be applied on top of bug 785086's patch:
https://bugzilla.mozilla.org/attachment.cgi?id=654827

This is a work in progress since it just dumps the log to stdout after completing a test but it shows most of the features. You can run the tests by specifying --test-path=./tests/robocop_manifest.ini and can control the numnber of iterations in configs/robocop_settings.ini

I haven't tested it yet with multiple phones yet. Once possible issue is temp.txt file created in the tests directory by devicemanagerXXX.py's getFile when a destination path is not specified. Multiple phones might stomp on each other but it might not matter.

I'm auto guessing the ports to use for the test's web server. I'll need to test this with additional phones etc.

Another possible issue is the use of the default get ip logic in runtestsremote.py without the ability to specify a specific ip address. I think we should add a --ipaddr option to runtestsremote.py so we don't have to disable extra ethernet devices like I have to do on my laptop due to the existence of vmnet{1,8}.

Feedback requested from everyone. Especially about how to handle the results.

Comment 2

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

Comment on attachment 657351 [details] [diff] [review]
patch

Review of attachment 657351 [details] [diff] [review]:
-----------------------------------------------------------------

This looks like a great start.  I think there are a lot of assumptions here that we shouldn't be making which I have called out below.  Of course I wouldn't expect anybody to know those assumptions.

Glad to see we are making good progress on getting tests running on the ark.

::: configs/robocop_settings.ini
@@ +1,4 @@
> +[settings]
> +# obj_dir is the location of the firefox build which contains
> +# the necessary test programs such as xpcshell etc.
> +obj_dir = /work/mozilla/builds/nightly/mozilla/firefox-debug

we might want to add a utility_dir as well, when you have a local build, it is the same as objdir, but when getting a tests.zip file xpcshell in in a bin/ folder and lib*.so is in the application folder (not in tests.zip).

::: tests/robocop_manifest.ini
@@ +1,2 @@
> +[robocoptest.py]
> +config = ../configs/robocop_settings.ini

this seems a bit overkill, maybe this is specific to autophone- if so, ignore this comment:)

::: tests/robocoptest.py
@@ +26,5 @@
> +        cache_build_dir = job["cache_build_dir"]
> +        pathOnDevice = posixpath.join(self.dm.getDeviceRoot(),'robocop.apk')
> +
> +        self.dm.pushFile(os.path.join(cache_build_dir, 'robocop.apk'), pathOnDevice)
> +        self.dm.installApp(pathOnDevice)

we should check for an error here.

@@ +32,5 @@
> +
> +        cfg = ConfigParser.RawConfigParser()
> +        cfg.read(self.config_file)
> +
> +        obj_dir = cfg.get('settings', 'obj_dir')

assuming you have a local build objdir, otherwise we need to do xre_path and utility_path.

@@ +56,5 @@
> +                            'python',
> +                            'mochitest/runtestsremote.py',
> +                            '--deviceIP=%s' % self.phone_cfg['ip'],
> +                            '--devicePort=20701',
> +                            '--app=org.mozilla.fennec',

this is a hardcoded assumption, we have different names for different releases as well as local developer builds (i.e. org.mozilla.fennec_maher)

@@ +61,5 @@
> +                            '--xre-path=%s' % bin_dir,
> +                            '--utility-path=%s' % bin_dir,
> +                            '--certificate-path=certs',
> +                            '--robocop=mochitest/robocop.ini',
> +                            '--robocop-ids=%s/fennec_ids.txt' % cache_build_dir,

another assumption on a local build

@@ +90,5 @@
> +                    break
> +
> +            print 40 * '*'
> +            print 'Iteration %d' % iteration
> +            print stdout

I would like to check for errors in stdout, as well as do a better job looking for hangs.  Not sure if mozprocess is usable inside of autophone, that would be ideal.  I am fine keeping this to avoid scope creep though.

@@ +110,5 @@
> +    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
> +    sock.bind((ipaddr, 0))
> +    port = sock.getsockname()[1]
> +    sock.close()
> +    return port

we have this stuff available in mozdevice.iface(), would be nice to reuse it.

Comment 3

[William Lachance (:wlach)]

Comment on attachment 657351 [details] [diff] [review]
patch

I don't really have much to add beyond jmaher's comments. On the whole this looks very good to me.

Comment 4

[William Lachance (:wlach)]

(In reply to William Lachance (:wlach) from comment #3)
> Comment on attachment 657351 [details] [diff] [review]
> patch
> 
> I don't really have much to add beyond jmaher's comments. On the whole this
> looks very good to me.

(just giving an r- because some of jmaher's comments would be good to address)

Comment 5

[William Lachance (:wlach)]

(In reply to Joel Maher (:jmaher) from comment #2)

> @@ +110,5 @@
> > +    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
> > +    sock.bind((ipaddr, 0))
> > +    port = sock.getsockname()[1]
> > +    sock.close()
> > +    return port
> 
> we have this stuff available in mozdevice.iface(), would be nice to reuse it.

Sort of OT: I much prefer the design here to the one in mozdevice (which involves choosing a seed port then iterating starting at that number until we find an open one). It's simpler and (at least theoretically) faster.

This problem seems to keep on coming up, maybe we ought to create a moznetwork package to encapsulate this functionality. I filed bug 788604 to track this.

Comment 6

[Bob Clary [:bc] (inactive)]

Great, thanks for the feedback everyone. I'm working on the updated patch. I updated my agent and watcher and starting using today's build and seem to be having problems I didn't see with the old cached 8/23 build I was using. I'll have an updated patch soonest.

Comment 7

[Bob Clary [:bc] (inactive)]

Attachment: patch v2

Comment 8

[Bob Clary [:bc] (inactive)]

lost my comment during the attachment.

This is another wip off of the lastest patch in bug 785086 I would appreciate feedback on.

(In reply to Joel Maher (:jmaher) from comment #2)
>
> ::: configs/robocop_settings.ini
> @@ +1,4 @@
> > +[settings]
> > +# obj_dir is the location of the firefox build which contains
> > +# the necessary test programs such as xpcshell etc.
> > +obj_dir = /work/mozilla/builds/nightly/mozilla/firefox-debug
> 
> we might want to add a utility_dir as well, when you have a local build, it
> is the same as objdir, but when getting a tests.zip file xpcshell in in a
> bin/ folder and lib*.so is in the application folder (not in tests.zip).
> 

added xre_path, utility_path to the configs/robocop_settings.ini

> ::: tests/robocop_manifest.ini
> @@ +1,2 @@
> > +[robocoptest.py]
> > +config = ../configs/robocop_settings.ini
> 
> this seems a bit overkill, maybe this is specific to autophone- if so,
> ignore this comment:)
> 

This is the way Autophone works I think. mcote will know more.

> ::: tests/robocoptest.py
> @@ +26,5 @@
> > +        cache_build_dir = job["cache_build_dir"]
> > +        pathOnDevice = posixpath.join(self.dm.getDeviceRoot(),'robocop.apk')
> > +
> > +        self.dm.pushFile(os.path.join(cache_build_dir, 'robocop.apk'), pathOnDevice)
> > +        self.dm.installApp(pathOnDevice)
> 
> we should check for an error here.

I tried but it seems that
         result = self.dm.installApp(pathOnDevice)
is always returning None even though robocop.apk *is* being installed. I don't understand unless this is really a bug in dm.

I'm returning Boolean for the test but this is actually not effective due to the test running in its own process. I need to do more work on communicating failures back to autophone.

> 
> @@ +32,5 @@
> > +
> > +        cfg = ConfigParser.RawConfigParser()
> > +        cfg.read(self.config_file)
> > +
> > +        obj_dir = cfg.get('settings', 'obj_dir')
> 
> assuming you have a local build objdir, otherwise we need to do xre_path and
> utility_path.

now have xre_path, utility_path

> 
> @@ +56,5 @@
> > +                            'python',
> > +                            'mochitest/runtestsremote.py',
> > +                            '--deviceIP=%s' % self.phone_cfg['ip'],
> > +                            '--devicePort=20701',
> > +                            '--app=org.mozilla.fennec',
> 
> this is a hardcoded assumption, we have different names for different
> releases as well as local developer builds (i.e. org.mozilla.fennec_maher)
> 

added a androidprocname to the ini file to override the default assignments in autophone.py

> @@ +61,5 @@
> > +                            '--xre-path=%s' % bin_dir,
> > +                            '--utility-path=%s' % bin_dir,
> > +                            '--certificate-path=certs',
> > +                            '--robocop=mochitest/robocop.ini',
> > +                            '--robocop-ids=%s/fennec_ids.txt' % cache_build_dir,
> 
> another assumption on a local build
> 
> @@ +90,5 @@
> > +                    break
> > +
> > +            print 40 * '*'
> > +            print 'Iteration %d' % iteration
> > +            print stdout
> 
> I would like to check for errors in stdout, as well as do a better job
> looking for hangs.  Not sure if mozprocess is usable inside of autophone,
> that would be ideal.  I am fine keeping this to avoid scope creep though.
> 

I tweaked the socket error detection but need to do more. Should I use moztest to post to autolog the same way that marionette is doing?

> @@ +110,5 @@
> > +    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
> > +    sock.bind((ipaddr, 0))
> > +    port = sock.getsockname()[1]
> > +    sock.close()
> > +    return port
> 
> we have this stuff available in mozdevice.iface(), would be nice to reuse it.

I tried to use it but it kept returning the same ports for different devices. I reverted back to this at least tempoarily.

I also changed the default port for the callback to start at 40000 rather than 30000 since the getCallbackIpAndPort uses 30000 as the starting seed as well.

Comment 9

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

Comment on attachment 658997 [details] [diff] [review]
patch v2

Review of attachment 658997 [details] [diff] [review]:
-----------------------------------------------------------------

::: tests/robocoptest.py
@@ +31,5 @@
> +        if not self.dm.pushFile(os.path.join(cache_build_dir, 'robocop.apk'), pathOnDevice):
> +            self.logger.error('failed to pushFile %s' % pathOnDevice)
> +            return False
> +
> +        result = self.dm.installApp(pathOnDevice)

can we guarantee the application was uninstalled first?  If we don't uninstall there is a cache left behind on the device.

@@ +34,5 @@
> +
> +        result = self.dm.installApp(pathOnDevice)
> +        if result is None:
> +            self.logger.error('failed to install %s' % pathOnDevice)
> +            #return False

if not self.dm.installApp...

Since we done use result.

@@ +113,5 @@
> +                    stdout=subprocess.PIPE,
> +                    stderr=subprocess.STDOUT,
> +                    close_fds=True
> +                )
> +                stdout = proc.communicate()[0]

do we need to parse the results of the test?  we could find it in robocop-%s.log.

Comment 10

[Bob Clary [:bc] (inactive)]

(In reply to Joel Maher (:jmaher) from comment #9)
> Comment on attachment 658997 [details] [diff] [review]
> patch v2
> 
> Review of attachment 658997 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: tests/robocoptest.py
> @@ +31,5 @@
> > +        if not self.dm.pushFile(os.path.join(cache_build_dir, 'robocop.apk'), pathOnDevice):
> > +            self.logger.error('failed to pushFile %s' % pathOnDevice)
> > +            return False
> > +
> > +        result = self.dm.installApp(pathOnDevice)
> 
> can we guarantee the application was uninstalled first?  If we don't
> uninstall there is a cache left behind on the device.
> 

How do I handle the reboot? Create an update.info file with some appropriate information so that the device will callback the server on reboot? Then after the uninstall do a blocking read the callback socket and then delete the update.info? 

Do dm.reboot and dm.updateApp "appear" to block until the device has rebooted? dm.uninstallAppAndReboot doesn't appear to support the callback?


> @@ +34,5 @@
> > +
> > +        result = self.dm.installApp(pathOnDevice)
> > +        if result is None:
> > +            self.logger.error('failed to install %s' % pathOnDevice)
> > +            #return False
> 
> if not self.dm.installApp...
> 
> Since we done use result.

Ok. I initially wrote it thinking the return value contained more information on failure than just None.

> 
> @@ +113,5 @@
> > +                    stdout=subprocess.PIPE,
> > +                    stderr=subprocess.STDOUT,
> > +                    close_fds=True
> > +                )
> > +                stdout = proc.communicate()[0]
> 
> do we need to parse the results of the test?  we could find it in
> robocop-%s.log.

the robocopy-%s.logs contain the results for an individual test but are overwritten after each test listed in the manifest. If I could grab them from inside runtestsremote.py and do something with them that would be ideal, but as it stands grabbing stdout from runtestsremote.py is the only way to get all of the results.

Btw, sometime we will need to deal with Fennec crashing on the device. My Droid Pro will crash everytime and the runtestsremote.py process will just sit there. What is the best way to handle that?

Comment 11

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

for the reboot, install, uninstall cases we have some code in device manager to handle it.  By some code, I am not implying it is going to work for everybody- it is a start though and works for our tbpl automation.

If you look at reboot in devicemanager:
http://mxr.mozilla.org/mozilla-central/source/build/mobile/devicemanagerSUT.py#906

you can pass in an ip address and it will take care of setting the update.info and calling back to a server for you. Here is code in sut_tools (which drives tbpl automation) that calls reboot:
https://hg.mozilla.org/build/tools/file/7c63406fe490/sut_tools/reboot.py

Regarding uninstallAppAndReboot, I am adding a uninstallApp that doesn't reboot.  The sutagent supports that already and we just need a devicemanager api for it.  


The other issue about the logs is just to make sure we are looking for errors and handling the case where we fail.  Maybe this is handled in reporting somewhere else.

For the crash of fennec, we should detect that in runtestsremote because we poll for the process every 5 seconds.  If the process is dead that isn't a good sign and we return with an error message.  There could be a case where we are not able to communicate with the SUTAgent (memory pressures kill off sutagent first, then kill off the fennec process).  In that case we can't connect to the device.  I have been working on some timeout patches for devicemanager which would shorten up the wait time.  That might help out, but I am not sure.

Comment 12

[Mark Côté [:mcote]]

Comment on attachment 658997 [details] [diff] [review]
patch v2

Review of attachment 658997 [details] [diff] [review]:
-----------------------------------------------------------------

So far so good, but I guess you have another patch in the works. Sorry for the late review.

::: tests/robocoptest.py
@@ +22,5 @@
> +            'blddate' not in job or
> +            'bldtype' not in job or
> +            'version' not in job):
> +            self.logger.error('Invalid job configuration: %s' % job)
> +            raise NameError('ERROR: Invalid job configuration: %s' % job)

Might as well refactor this rather than copying it from s1s2test.py. It probably makes sense to check these variables in the AutoPhone object, since there's probably not much any test can do with missing job data.

@@ +31,5 @@
> +        if not self.dm.pushFile(os.path.join(cache_build_dir, 'robocop.apk'), pathOnDevice):
> +            self.logger.error('failed to pushFile %s' % pathOnDevice)
> +            return False
> +
> +        result = self.dm.installApp(pathOnDevice)

Will just filed bug 792072 to have installApp() push the file as well, so maybe a FIXME here to remove some code once that has landed.

@@ +34,5 @@
> +
> +        result = self.dm.installApp(pathOnDevice)
> +        if result is None:
> +            self.logger.error('failed to install %s' % pathOnDevice)
> +            #return False

I'd actually say "if self.dm.installApp(pathOnDevice) is None" just because the API doc says specifically that the return value is None on success. I wouldn't to mask some bug that resulted in, say, an empty string being returned as output.

Comment 14

[Bob Clary [:bc] (inactive)]

Attachment: patch v3

The logging is probably a bit overboard. jgriffin: I would appreciate your feedback on the logparser and mozautolog parts.

Comment 15

[Jonathan Griffin (:jgriffin)]

Comment on attachment 682077 [details] [diff] [review]
patch v3

Review of attachment 682077 [details] [diff] [review]:
-----------------------------------------------------------------

I only looked at the autolog-related parts; those look good.

Comment 16

[Bob Clary [:bc] (inactive)]

Attachment: patch v4

minor tweak to the config files to remove extraneous reference to robocop and one change to fix the improper config file choice for single unit test runs.

Comment 17

[Mark Côté [:mcote]]

I am looking forward to reviewing this, but I'm rushing to get some mozpool stuff done atm and want to give this my full attention. I should be able to get to it by the end of the week.

Comment 18

[Mark Côté [:mcote]]

Comment on attachment 682359 [details] [diff] [review]
patch v4

Review of attachment 682359 [details] [diff] [review]:
-----------------------------------------------------------------

This is cool stuff, really appreciate the documentation in particular.  I am going to set it up on my staging server here as soon as you push.  A few comments and suggestions below, nothing major.

::: INSTALL.md
@@ +77,5 @@
> +minidump_stack via:
> +
> +svn checkout http://google-breakpad.googlecode.com/svn/trunk/ google-breakpad-read-only
> +cd google-breakpad-read-only
> +CXXFLAGS="-g -O1" ./configure

Can we add a note here about how OS X needs "CC=clang CXX=clang++ ./configure"?

@@ +83,5 @@
> +sudo make install
> +
> +If you wish to run a development environment, you will also need to
> +set up an ElasticSearch and Autolog server. See
> +https://wiki.mozilla.org/Auto-tools/Projects/Autolog for more details.

Mention that testdata is not needed.

@@ +87,5 @@
> +https://wiki.mozilla.org/Auto-tools/Projects/Autolog for more details.
> +
> +Once you have the XRE, utility programs and minidump_stack installed, change
> +configs/unittest_default.ini to point to your local environment.
> +

Somewhere we should mention about configuring phones in Autolog's Config.js.

::: builds.py
@@ +223,5 @@
>                  return None
>              os.rename(tmpf.name, build_path)
>          file(os.path.join(cache_build_dir, 'lastused'), 'w')
> +        symbols_path = os.path.join(cache_build_dir, 'symbols')
> +        if (force or not os.path.exists(symbols_path)):

Superfluous parentheses.

@@ +234,5 @@
> +                symbols_zipfile = zipfile.ZipFile(tmpf.name)
> +                symbols_zipfile.extractall(symbols_path)
> +                symbols_zipfile.close()
> +            except IOError:
> +                logging.info('Ignoring Error retrieving symbols: %s.' % symbols_url)

Log specific exception.  I don't really like "Ignoring"... maybe say that the download failed, but that it's not fatal?  Not sure how to word it so that we convey what happened but that it's gonna be okay.

::: tests/runtestsremote.py
@@ +33,5 @@
> +        if ('androidprocname' not in job or
> +            'revision' not in job or
> +            'blddate' not in job or
> +            'bldtype' not in job or
> +            'version' not in job):

Still would like this see this refactored.  Not a show stopper though.

@@ +73,5 @@
> +        elif job_cfg.has_option('runtests', 'test_name'):
> +            # job contains a single unittest
> +            config_files = [self.config_file]
> +        else:
> +            raise Exception('Job configuration does not specify a test')

In the spirit of reusing mozbase where appropriate, do you think a ManifestDestiny file would work here?  We already use it in AutoPhone to get the list of tests.  The logic here is admittedly pretty simple, but if it's as easy to do with ManifestDestiny, we might as well.

@@ +154,5 @@
> +
> +        port_manager = PortManager(host_ip_address)
> +
> +        for this_chunk in range(1, total_chunks + 1):
> +

Mostly because it's really long, I feel like some of this loop should be moved to functions just so that the logic of the central process (setting up, executing, reporting) is a little more separated from how it accomplishes those things.

@@ +374,5 @@
> +
> +        return True
> +
> +
> +class PortManager(object):

This really needs to go into mozbase at some point.  Can you file a bug on that if you don't do it in this commit?

::: worker.py
@@ +240,4 @@
>              # FIXME: reboot() no longer indicates success/failure; instead
>              # we just verify the device root.
>              try:
> +                self.dm.reboot(self.ipaddr, 40000+self.worker_num)

Any reason for the change from 30000 to 40000?

Comment 19

[Bob Clary [:bc] (inactive)]

(In reply to Mark Côté ( :mcote ) from comment #18)
> Comment on attachment 682359 [details] [diff] [review]
> patch v4

> 
> Can we add a note here about how OS X needs "CC=clang CXX=clang++
> ./configure"?
> 

sure.

> > +set up an ElasticSearch and Autolog server. See
> > +https://wiki.mozilla.org/Auto-tools/Projects/Autolog for more details.
> 
> Mention that testdata is not needed.
> 

sure.

>
> Somewhere we should mention about configuring phones in Autolog's Config.js.
> 

I can do it here and also Autolog's readme the next time we update Autolog's js/Config.js to add new phone types.

> > +            except IOError:
> > +                logging.info('Ignoring Error retrieving symbols: %s.' % symbols_url)
> 
> Log specific exception.  I don't really like "Ignoring"... maybe say that
> the download failed, but that it's not fatal?  Not sure how to word it so
> that we convey what happened but that it's gonna be okay.
> 

For the most part the normal case for nightly builds is that there are no symbols. So I can probably detect that and just say there were no symbols found. If there was a real error, I can log the exception for that.

> ::: tests/runtestsremote.py
> @@ +33,5 @@
> > +        if ('androidprocname' not in job or
> > +            'revision' not in job or
> > +            'blddate' not in job or
> > +            'bldtype' not in job or
> > +            'version' not in job):
> 
> Still would like this see this refactored.  Not a show stopper though.
> 

I missed that. I'll think about it some more.

> @@ +73,5 @@
> > +        elif job_cfg.has_option('runtests', 'test_name'):
> > +            # job contains a single unittest
> > +            config_files = [self.config_file]
> > +        else:
> > +            raise Exception('Job configuration does not specify a test')
> 
> In the spirit of reusing mozbase where appropriate, do you think a
> ManifestDestiny file would work here?  We already use it in AutoPhone to get
> the list of tests.  The logic here is admittedly pretty simple, but if it's
> as easy to do with ManifestDestiny, we might as well.
> 

Good point. I think it might. Let me look into it some more.

> @@ +154,5 @@
> > +
> > +        port_manager = PortManager(host_ip_address)
> > +
> > +        for this_chunk in range(1, total_chunks + 1):
> > +
> 
> Mostly because it's really long, I feel like some of this loop should be
> moved to functions just so that the logic of the central process (setting
> up, executing, reporting) is a little more separated from how it
> accomplishes those things.
> 

Ok.

> @@ +374,5 @@
> > +
> > +        return True
> > +
> > +
> > +class PortManager(object):
> 
> This really needs to go into mozbase at some point.  Can you file a bug on
> that if you don't do it in this commit?
> 

wlach filed bug 788604. There was some overall push back on the original code I think but I think this new delayed use solves some of that. I can attach a patch there and use that if/when it gets into mozbase.

> ::: worker.py
> @@ +240,4 @@
> >              # FIXME: reboot() no longer indicates success/failure; instead
> >              # we just verify the device root.
> >              try:
> > +                self.dm.reboot(self.ipaddr, 40000+self.worker_num)
> 
> Any reason for the change from 30000 to 40000?

Yeah. I meant to call that out. The device manager's port selection for reboot, updateApp and _getCallbackIpAndPort all default to beginning their port selection at 30000. If I recall correctly this caused me some problems initially especially with regard to obtaining ports for runtestsremote.py's web servers which I worked around by having the worker request a different port starting point. I'm actually not positive that this change is required now that I am using the PortManager. I can retest without this change to see if it is still necessary to alleviate the problems I saw initially.

Comment 20

[Bob Clary [:bc] (inactive)]

Attachment: patch v5

* update docs
* added Autophone.is_valid_job(job) method.
* added newlogparser.py and a configuration directive to select it.
* refactored runtestsremote.py a bit.
* removed the port change and it appears to work fine without it.
* changed PortManager to not exclude previously used ports.

Comment 21

[Bob Clary [:bc] (inactive)]

Comment on attachment 691034 [details] [diff] [review]
patch v5

>--- /dev/null
>+++ b/tests/runtestsremote.py
>+    def runtest(self, test_parameters):
>+
>+            try:
>+                self.dm.uninstallApp('org.mozilla.roboexample.test')
>+            except:
>+                self.logger.error('runtest: Error uninstalling robocop apk: %s' %
>+                                  traceback.format_exc())
>+                return
>+

This is wrong as it will throw when robocop isn't already installed. I've changed
this locally to just debug log the error and not return.

Comment 22

[Bob Clary [:bc] (inactive)]

Attachment: patch v6

includes update to fix uninstall robocop if it isn't already installed.

Comment 23

[Mark Côté [:mcote]]

Comment on attachment 691034 [details] [diff] [review]
patch v5

Review of attachment 691034 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good.  newlogparser.py is hella complicated but it looks pretty thorough, though I confess to not having examined the details, just the overall structure.  I feel like it could be refactored to improve readability, in particular the state machine built into it, since there is some redundancy around the verification of valid states, but I confess to not having any concrete ideas myself at the moment.  I'll think about it, and maybe we can improve it later.  Anyway I guess the end goal is to make the test logs themselves more structured, which will in turn reduce the complexity here, so we can deal with the temporary insanity.

I wonder if we could also package up some fake logs to test this parser...

Aside from nits below, I think these .ini files should be .ini.example or .ini.dist or something like that, to prevent local changes from being checked in. But overall very good.

::: autophone.py
@@ +208,5 @@
>              logging.debug('Asking for jobs')
>              while not self._jobqueue.empty():
>                  job = self._jobqueue.get()
> +                if not self.is_valid_job(job):
> +                    continue

I just realized that this whole function (AutoPhone.disperse_jobs()) is not used anywhere.  Can you take it out?

@@ +387,4 @@
>      def trigger_jobs(self, data):
>          logging.debug('trigger_jobs: data  %s' % data)
>          job = self.build_job(self.get_build(data))
> +        if self.is_valid_job(job):

Is this check necessary, since start_tests() will check as well?

@@ +499,5 @@
> +            error_message = 'ERROR: Invalid job configuration: %s ' % job + ', '.join(error_list)
> +            self.logger.error(error_message)
> +            raise NameError(error_message)
> +
> +        return True

This whole function is a little overly spacious.  Vertical spacing should be used very conservatively, only to split up logical blocks.

::: configs/unittest_defaults.ini
@@ +40,5 @@
> +
> +# Submit log to Autolog.
> +submit_log = True
> +
> +use_newparser = True

Document this option.

::: tests/newlogparser.py
@@ +1,1 @@
> +import logging

Missing license header.  Also why is this in the tests directory?

@@ +4,5 @@
> +import sys
> +import os
> +import datetime
> +import json
> +#import hashlib

Remove commented-out line.

@@ +5,5 @@
> +import os
> +import datetime
> +import json
> +#import hashlib
> +import uuid

Alphabetize imports, with 'from' imports coming after direct imports.

@@ +13,5 @@
> +    '''
> +
> +    active_test_log = None
> +
> +    def __init__(self, log_filehandle = sys.stdin):

No spacing around = when defining the default value of optional parameters.

@@ +234,5 @@
> +        self.suitename = None
> +        self._suitetype = None
> +        self.passed = 0
> +        self.failed = 0
> +        self.todo   = 0

Extra horizontal spacing.  PEP-8 says not to try to line up variable definitions like this.

@@ +235,5 @@
> +        self._suitetype = None
> +        self.passed = 0
> +        self.failed = 0
> +        self.todo   = 0
> +        self.parsedcounts = { 'passed': 0, 'failed': 0, 'todo' : 0 }

Ditto, no extra spaces around {} or [].

@@ +329,5 @@
> +        #m.update(self.__repr__())
> +        #id = ""
> +        #if 'starttime' in results:
> +        #  id += str(results['starttime']) + '-'
> +        #id += m.hexdigest()

Why is this here?

@@ +1725,5 @@
> +
> +    return test_log
> +
> +def main(options):
> +

Remove blank line.

::: tests/runtestsremote.py
@@ +89,5 @@
> +
> +        self.logger.debug('runtestsremote.py runjob exit')
> +
> +    def load_test_parameters(self, test_parameters, config_file):
> +

Blank line.

@@ +216,5 @@
> +
> +        return args
> +
> +    def process_test_log(self, test_parameters, logfilehandle):
> +

Ditto.

@@ +387,5 @@
> +                        stdout=logfilehandle,
> +                        stderr=subprocess.STDOUT,
> +                        close_fds=True
> +                    )
> +                    proc.wait()

This is out of scope for this bug but something to think about--it would be really nice to have autophone exit somewhat reliably in response to a ctrl-c/sigterm.  I don't really know the best way of doing this, but it probably involves the worker catching signals and trying to shutdown nicely, if possible, and otherwise force killing its subprocess.  Mainly I just want to avoid having orphan processes around, which seems to happen at least some of the time when I try to stop a test run half-way through.

@@ +476,5 @@
> +        '''
> +        Prepare a reserved port for use by
> +        closing its socket and returning the
> +        port.
> +        '''

Strange line breaks...

Comment 24

[Bob Clary [:bc] (inactive)]

Mark, I've made the following changes to my local patch and will test it before attaching the patch to make sure that I haven't introduced new bugs. One good thing is the python-check (which I should have done previously anyway) caught some bugs. I'll attach my new patch after I complete testing it.

There are a couple of things I haven't changed yet in response to your comments, so please read my replies and let me know what you think.

(In reply to Mark Côté ( :mcote ) from comment #23)
> Comment on attachment 691034 [details] [diff] [review]
> patch v5
> 
> Review of attachment 691034 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good.  newlogparser.py is hella complicated but it looks pretty
> thorough, though I confess to not having examined the details, just the
> overall structure.  I feel like it could be refactored to improve
> readability, in particular the state machine built into it, since there is
> some redundancy around the verification of valid states, but I confess to
> not having any concrete ideas myself at the moment.  I'll think about it,
> and maybe we can improve it later.  Anyway I guess the end goal is to make
> the test logs themselves more structured, which will in turn reduce the
> complexity here, so we can deal with the temporary insanity.
> 

Apart from my lack of skill, the major reason I blame for the horrendous set of conditionals in one function has to do with the variety of output the various test frameworks can emit. I suppose we might clean it up or consolidate the logic, but I was more concerned with dealing correctly with potential one-off variations between the different test suite's outputs. I was afraid that too early code consolidation would lead me into a dead end that would be hard to get out of.

> I wonder if we could also package up some fake logs to test this parser...
> 

logparser has a test suite which we can add to when we are ready to convert it to using the 'new' log parser. I'm not sure if it would be that helpful here but I can do it here if you like.

> Aside from nits below, I think these .ini files should be .ini.example or
> .ini.dist or something like that, to prevent local changes from being
> checked in. But overall very good.
> 

All of them? Or just configs/unittest_default.ini ? unittest_default.ini is the only one that contains settings that would need to be customized.

> ::: autophone.py
> @@ +208,5 @@
> >              logging.debug('Asking for jobs')
> >              while not self._jobqueue.empty():
> >                  job = self._jobqueue.get()
> > +                if not self.is_valid_job(job):
> > +                    continue
> 
> I just realized that this whole function (AutoPhone.disperse_jobs()) is not
> used anywhere.  Can you take it out?
> 

done.

> @@ +387,4 @@
> >      def trigger_jobs(self, data):
> >          logging.debug('trigger_jobs: data  %s' % data)
> >          job = self.build_job(self.get_build(data))
> > +        if self.is_valid_job(job):
> 
> Is this check necessary, since start_tests() will check as well?
> 

Not absolutely necessary but it helps prevent a log message "Adding user-specified job" when we won't actually add it.

> @@ +499,5 @@
> > +            error_message = 'ERROR: Invalid job configuration: %s ' % job + ', '.join(error_list)
> > +            self.logger.error(error_message)
> > +            raise NameError(error_message)
> > +
> > +        return True
> 
> This whole function is a little overly spacious.  Vertical spacing should be
> used very conservatively, only to split up logical blocks.
> 

I did this as a result of emacs improperly reformatting a bunch of my code when I attempted a reformat on a rather large section of code. It seemed to have problems with a series of if statements like:

if blah1:
    foo1
if blah2:
    foo2

which it converted to:

if blah1:
    foo1
    if blah2:
        foo2

I felt that adding a blank line after if statements was helpful to prevent such inadvertent format changes. I can remove the blank lines if it is something that you think matters.

> ::: configs/unittest_defaults.ini
> @@ +40,5 @@
> > +
> > +# Submit log to Autolog.
> > +submit_log = True
> > +
> > +use_newparser = True
> 
> Document this option.
> 

Is this sufficient?

# Set use_newparser to True to parse the logs using newlogparser.py
# instead of logparser/logparser.py. Set it to False to use
# logparser/logparser.py.
use_newparser = True

> ::: tests/newlogparser.py
> @@ +1,1 @@
> > +import logging
> 
> Missing license header.  Also why is this in the tests directory?

Fixed header. I put it in the tests directory along side of runtestsremote.py since it is only used by it and since it will be removed entirely when the 'new' parser is incorporated into logparser. Is there a better place?

> 
> @@ +4,5 @@
> > +import sys
> > +import os
> > +import datetime
> > +import json
> > +#import hashlib
> 
> Remove commented-out line.
> 

done

> @@ +5,5 @@
> > +import os
> > +import datetime
> > +import json
> > +#import hashlib
> > +import uuid
> 
> Alphabetize imports, with 'from' imports coming after direct imports.
> 

done

> No spacing around = when defining the default value of optional parameters.
> Extra horizontal spacing.  PEP-8 says not to try to line up variable
> definitions like this.
> Ditto, no extra spaces around {} or [].
> Remove blank line.

It is now pep8 clean according to python-check with the exceptions of:

pychecker.sh newlogparser.py
newlogparser.py:254: redefinition of function 'state' from line 250
newlogparser.py:269: redefinition of function 'suitetype' from line 265
newlogparser.py:1121: local variable 'prev_test_run' is assigned to but never used

> 
> @@ +329,5 @@
> > +        #m.update(self.__repr__())
> > +        #id = ""
> > +        #if 'starttime' in results:
> > +        #  id += str(results['starttime']) + '-'
> > +        #id += m.hexdigest()
> 
> Why is this here?

This is a remnant of logparser's test run id calculation which I initially copied from logparser but which I replaced with the hex uuid calculation. The need to actually calculate the hash of the str representation was a problem for test runs that contained passing tests since the str could be very very large and isn't really needed if the only requirement is a unique id. So I removed it. I need to talk to jgriffin about this but I think it will be ok.

> 
> @@ +387,5 @@
> > +                        stdout=logfilehandle,
> > +                        stderr=subprocess.STDOUT,
> > +                        close_fds=True
> > +                    )
> > +                    proc.wait()
> 
> This is out of scope for this bug but something to think about--it would be
> really nice to have autophone exit somewhat reliably in response to a
> ctrl-c/sigterm.  I don't really know the best way of doing this, but it
> probably involves the worker catching signals and trying to shutdown nicely,
> if possible, and otherwise force killing its subprocess.  Mainly I just want
> to avoid having orphan processes around, which seems to happen at least some
> of the time when I try to stop a test run half-way through.
> 

Yeah. I've hit that too. Ok, I'll think about it some more.

> @@ +476,5 @@
> Strange line breaks...

fixed.

Comment 25

[Mark Côté [:mcote]]

(In reply to Bob Clary [:bc:] from comment #24)
> (In reply to Mark Côté ( :mcote ) from comment #23)
> > Comment on attachment 691034 [details] [diff] [review]
> > patch v5
> > 
> > Review of attachment 691034 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > Looks good.  newlogparser.py is hella complicated but it looks pretty
> > thorough, though I confess to not having examined the details, just the
> > overall structure.  I feel like it could be refactored to improve
> > readability, in particular the state machine built into it, since there is
> > some redundancy around the verification of valid states, but I confess to
> > not having any concrete ideas myself at the moment.  I'll think about it,
> > and maybe we can improve it later.  Anyway I guess the end goal is to make
> > the test logs themselves more structured, which will in turn reduce the
> > complexity here, so we can deal with the temporary insanity.
> > 
> 
> Apart from my lack of skill, the major reason I blame for the horrendous set
> of conditionals in one function has to do with the variety of output the
> various test frameworks can emit. I suppose we might clean it up or
> consolidate the logic, but I was more concerned with dealing correctly with
> potential one-off variations between the different test suite's outputs. I
> was afraid that too early code consolidation would lead me into a dead end
> that would be hard to get out of.

Yeah, sorry I didn't mean to sound like I was criticizing; I just had a hard time reviewing it and so got thinking about whether it was possible to refactor.  But I don't have any good ideas for refactoring right now either.  This is fine as it is.

> 
> > I wonder if we could also package up some fake logs to test this parser...
> > 
> 
> logparser has a test suite which we can add to when we are ready to convert
> it to using the 'new' log parser. I'm not sure if it would be that helpful
> here but I can do it here if you like.

Oh cool, okay, no need to do it now.

> 
> > Aside from nits below, I think these .ini files should be .ini.example or
> > .ini.dist or something like that, to prevent local changes from being
> > checked in. But overall very good.
> > 
> 
> All of them? Or just configs/unittest_default.ini ? unittest_default.ini is
> the only one that contains settings that would need to be customized.

Sure, just the one that needs to be customized then.  I just don't want to cherry pick or branch or something to avoid checking in local settings.  Please mention in the docs that it needs to be copied over and edited too.

> > @@ +387,4 @@
> > >      def trigger_jobs(self, data):
> > >          logging.debug('trigger_jobs: data  %s' % data)
> > >          job = self.build_job(self.get_build(data))
> > > +        if self.is_valid_job(job):
> > 
> > Is this check necessary, since start_tests() will check as well?
> > 
> 
> Not absolutely necessary but it helps prevent a log message "Adding
> user-specified job" when we won't actually add it.

Hm, well, conversely, it might be nice to know that the system accepted your job request but then determined it was poorly formed, to differentiate from the system not accepting the job because it's hung or something.  Maybe we can just change the log message to "Received user-specified job" or something, to avoid implying that it's ok when we haven't yet verified it.

> 
> > @@ +499,5 @@
> > > +            error_message = 'ERROR: Invalid job configuration: %s ' % job + ', '.join(error_list)
> > > +            self.logger.error(error_message)
> > > +            raise NameError(error_message)
> > > +
> > > +        return True
> > 
> > This whole function is a little overly spacious.  Vertical spacing should be
> > used very conservatively, only to split up logical blocks.
> > 
> 
> I did this as a result of emacs improperly reformatting a bunch of my code
> when I attempted a reformat on a rather large section of code. It seemed to
> have problems with a series of if statements like:
> 
> if blah1:
>     foo1
> if blah2:
>     foo2
> 
> which it converted to:
> 
> if blah1:
>     foo1
>     if blah2:
>         foo2
> 
> I felt that adding a blank line after if statements was helpful to prevent
> such inadvertent format changes. I can remove the blank lines if it is
> something that you think matters.

Okay.  The very first blank line, after the "def" statement, should be removed in any case.

> > Document this option.
> > 
> 
> Is this sufficient?
> 
> # Set use_newparser to True to parse the logs using newlogparser.py
> # instead of logparser/logparser.py. Set it to False to use
> # logparser/logparser.py.
> use_newparser = True

Sure.

> > ::: tests/newlogparser.py
> > @@ +1,1 @@
> > > +import logging
> > 
> > Missing license header.  Also why is this in the tests directory?
> 
> Fixed header. I put it in the tests directory along side of
> runtestsremote.py since it is only used by it and since it will be removed
> entirely when the 'new' parser is incorporated into logparser. Is there a
> better place?

Hm it was just a bit confusing because everything other .py file in there is a test.  I guess I would have put it in the main autophone dir or a subdir, but yeah it's temporary so that's fine.

> > No spacing around = when defining the default value of optional parameters.
> > Extra horizontal spacing.  PEP-8 says not to try to line up variable
> > definitions like this.
> > Ditto, no extra spaces around {} or [].
> > Remove blank line.
> 
> It is now pep8 clean according to python-check with the exceptions of:
> 
> pychecker.sh newlogparser.py
> newlogparser.py:254: redefinition of function 'state' from line 250
> newlogparser.py:269: redefinition of function 'suitetype' from line 265
> newlogparser.py:1121: local variable 'prev_test_run' is assigned to but
> never used

Okay any reason for keeping the prev_test_run var then?

Comment 26

[Bob Clary [:bc] (inactive)]

(In reply to Mark Côté ( :mcote ) from comment #25)

> 
> Yeah, sorry I didn't mean to sound like I was criticizing; I just had a hard
> time reviewing it and so got thinking about whether it was possible to
> refactor.  But I don't have any good ideas for refactoring right now either.
> This is fine as it is.

np. I didn't take it as negative criticism.

> > 
> > All of them? Or just configs/unittest_default.ini ? unittest_default.ini is
> > the only one that contains settings that would need to be customized.
> 
> Sure, just the one that needs to be customized then.  I just don't want to
> cherry pick or branch or something to avoid checking in local settings. 
> Please mention in the docs that it needs to be copied over and edited too.

sure.

> 
> > > @@ +387,4 @@
> > > >      def trigger_jobs(self, data):
> > > >          logging.debug('trigger_jobs: data  %s' % data)
> > > >          job = self.build_job(self.get_build(data))
> > > > +        if self.is_valid_job(job):
> > > 
> > > Is this check necessary, since start_tests() will check as well?
> > > 
> > 
> > Not absolutely necessary but it helps prevent a log message "Adding
> > user-specified job" when we won't actually add it.
> 
> Hm, well, conversely, it might be nice to know that the system accepted your
> job request but then determined it was poorly formed, to differentiate from
> the system not accepting the job because it's hung or something.  Maybe we
> can just change the log message to "Received user-specified job" or
> something, to avoid implying that it's ok when we haven't yet verified it.
> 

Ok. One note is the is_valid_job() will emit an error log message if the job is not None and is malformed but not when it is just None. I'll change the message to Recieved though.

> 
> Okay.  The very first blank line, after the "def" statement, should be
> removed in any case.

right.

> > It is now pep8 clean according to python-check with the exceptions of:
> > 
> > pychecker.sh newlogparser.py
> > newlogparser.py:254: redefinition of function 'state' from line 250
> > newlogparser.py:269: redefinition of function 'suitetype' from line 265
> > newlogparser.py:1121: local variable 'prev_test_run' is assigned to but
> > never used
> 
> Okay any reason for keeping the prev_test_run var then?

In my new patch I added a comment about that. I'd like to keep it for two reasons. 1) when debugging I did use it a bit to compare the current to the prev test runs. 2) Like much of the rest of parse_logs() it is scattered about and I thought it better to keep it in case I found a reason for it later and I wouldn't need to find all of the places it should be updated.

Comment 27

[Mark Côté [:mcote]]

(In reply to Bob Clary [:bc:] from comment #26)
All sounds good.  If there aren't too many big changes feel free to just commit directly, or I can rereview if you want.

Comment 28

[Bob Clary [:bc] (inactive)]

Attachment: patch v7

I think this cover everything. If you want to do a quick interdiff that would be great.

Comment 29

[Mark Côté [:mcote]]

Comment on attachment 694022 [details] [diff] [review]
patch v7

Review of attachment 694022 [details] [diff] [review]:
-----------------------------------------------------------------

Just one comment.

::: autophone.py
@@ +364,5 @@
>      def trigger_jobs(self, data):
>          logging.debug('trigger_jobs: data  %s' % data)
>          job = self.build_job(self.get_build(data))
> +        if self.is_valid_job(job):
> +            logging.info('Received user-specified job: %s' % job)

Ah, so, I meant that, by changing from "Adding" to "Received" we could omit the extra is_valid_job() check, since it won't be misleading anymore.

Comment 30

[Bob Clary [:bc] (inactive)]

https://github.com/mozilla/autophone/commit/5d632feb44121ef01ac473ad2746d6d375d1ccf1

did i mention I hate git?