579791 - No results shown / report sent when application gets killed due to the global timeout

Status: VERIFIED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: testcase

With bug 504440 fixed we kill the application now after the given amount of seconds. The downside is that we don't show any results on the console and also don't send any report so we are aware of this kill action and have at least the reports from the former tests.

I would propose that we do not sys.exit() immediately but cleanly shutdown the whole process. For the future it would even be better if we could proceed the test-run with the next test. But that would be probably worth another bug.

Use a test like the one in the attachment to check the current behavior.

Comment 1

[Jeff Hammel]

I'm not against being more careful about how things are exited via the fix from bug 504440 .  However, it is mostly meant to be a last-resort timeout.  In most practical cases, the (TBI) per test timeout from https://bugzilla.mozilla.org/show_bug.cgi?id=574871 will be hit first .

We should also, in general, do a better job accumulating logs incrementally vs all at once.  This will be desired for several pieces of functionality, including this one and the ability to pause/resume tests.  In a simple form, this could be done with a stateful logfile that can be read.

Comment 2

[Jeff Hammel]

Attachment: move reporting to its own slot instead of being called from run_tests

This separates out reporting to its own callable `def report()` on Mozmill.  I've cleaned up the control flow a bit.  While the patch is pretty pervasive, it (basically) doesn't affect what is done, and (mostly) only affects when things are done for the case of reporting.  In the future, the control flow should be revisited, probably in conjunction with or after the CLI cleanup.

* add the firePythonCallback listener to MozmillRestart start()

* add a hard kill option for fatal errors

* document get_report method

* factor out reporting to its own method

* make the CLI handling code simpler...its all worth it

* unify stop and stop_runner functions and have stop call stop_runner

* dont bothering raising the TestsFailedException at all since the only result is sys.exit; just call sys.exit

* set self.profile in the right place so that the runner can be created without a ValueError

* removed unused variable "report" from run_dir

* document the behaviour of run_dir

* document the 1-run nature of MozMill

* remove yet another call to super

* output to stdout like everything else instead of stderr

* document run_tests method

* remove unused variable self.report_document

* note poor control flow for Try Except

* move the try: except: into the inner function and eliminate _run entirely; also get rid of the silly warning message for MozmillRestarts CLI class

Comment 3

[Andrew Halberstadt [:ahal]]

Comment on attachment 459858 [details] [diff] [review]
move reporting to its own slot instead of being called from run_tests

>diff --git a/jsbridge/jsbridge/network.py b/jsbridge/jsbridge/network.py
>index fca66f0..a5e3412 100644
>--- a/jsbridge/jsbridge/network.py
>+++ b/jsbridge/jsbridge/network.py
>@@ -153,7 +153,6 @@ class JSBridgeDisconnectError(Exception):
>     """exception raised when an unexpected disconect happens"""
> 
> 
>-
> class Bridge(Telnet):
>     
>     trashes = []
>diff --git a/mozmill/mozmill/__init__.py b/mozmill/mozmill/__init__.py
>index 982e02e..fe5c321 100644
>--- a/mozmill/mozmill/__init__.py
>+++ b/mozmill/mozmill/__init__.py
>@@ -117,9 +117,20 @@ class LoggerListener(object):
> 
> class TestsFailedException(Exception):
>     """exception to be raised when the tests fail"""
>-
>+    # XXX unused
> 
> class MozMill(object):
>+    """
>+    MozMill is a one-shot test runner  You should use MozMill as follows:
>+
>+    m = MozMill(...)
>+    m.start(...)
>+    m.run_tests()
>+    m.stop()
>+
>+    You should *NOT* vary from this order of execution.  If you have need to
>+    run different sets of tests, create a new instantiation of MozMill
>+    """
> 
>     report_type = 'mozmill-test'
> 
>@@ -148,8 +159,12 @@ class MozMill(object):
>         self.shutdownModes = enum('default', 'user_shutdown', 'user_restart')
>         self.currentShutdownMode = self.shutdownModes.default
>         self.userShutdownEnabled = False
>+        self.test = None
>         #self.zombieDetector = ZombieDetector(self.stop)
> 
>+        # test time
>+        self.starttime = self.endtime = None
>+
>         # setup event listeners
>         self.global_listeners = []
>         self.listeners = []
>@@ -206,53 +221,56 @@ class MozMill(object):
>             self.back_channel.add_global_listener(global_listener)
> 
>     def start(self, profile=None, runner=None):
>-        # Reset our Zombie counter
>-        #self.zombieDetector.resetTimer()
> 
>         if not profile:
>             profile = self.profile_class(addons=[jsbridge.extension_path, extension_path])
>+        self.profile = profile
>+
How did this go unnoticed for this long? :p

>         if not runner:
>             runner = self.runner_class(profile=self.profile, 
>                                        cmdargs=["-jsbridge", str(self.jsbridge_port)])
> 
>         self.add_listener(self.firePythonCallback_listener, eventType='mozmill.firePythonCallback')
>-        self.profile = profile;
>         self.runner = runner
>-        self.runner.start()
>-        
>         self.endRunnerCalled = False
>+        
>+        self.runner.start()
>         self.create_network()
>         self.appinfo = self.get_appinfo(self.bridge)
> 
>-    def run_tests(self, test, report=False, sleeptime = 4):
>+        # set the starttime for the tests
>+        # XXX assumes run_tests will be called soon after (currently true)
>+        self.starttime = datetime.utcnow().isoformat()      
What was wrong with the old location of setting starttime?  It seems where it used to be we don't need to make any assumptions.
  
>+
>+    def run_tests(self, test, sleeptime=4):
>+        """
>+        run a test file or directory
>+        - test : test file or directory to run
>+        - report : URL to send a JSON report to
>+        - sleeptime : initial time to sleep [s] (not sure why the default is 4)
>+        """
>+
Forgot to get rid of the 'report' documentation

>         # Reset our Zombie Because we are still active
>         #self.zombieDetector.resetTimer()
You nuked these in the 'start()' method, why not here?

> 
>+        self.test = test
>+
>         frame = jsbridge.JSObject(self.bridge,
>                                   "Components.utils.import('resource://mozmill/modules/frame.js')")
>         sleep(sleeptime)
>-        starttime = datetime.utcnow().isoformat()
> 
>         # transfer persisted data
>         frame.persisted = self.persisted
> 
>+        # run the test directory or file
>         if os.path.isdir(test):
>             frame.runTestDirectory(test)
>         else:
>             frame.runTestFile(test)
> 
>-        endtime = datetime.utcnow().isoformat()
>-
>-        report_document = None
>-        if report:
>-            results = self.get_report(test, starttime, endtime)
>-            report_document = self.send_report(results, report)
>-
>         # Give a second for any callbacks to finish.
>         sleep(1)
> 
>-        return report_document
>-
>     def startTest_listener(self, test):
>         print "TEST-START | %s | %s" % (test['filename'], test['name'])
> 
>@@ -272,11 +290,12 @@ class MozMill(object):
>             self.passes.append(test)
> 
>     def endRunner_listener(self, obj):
>-        self.printStats()
>         self.endRunnerCalled = True
> 
>+    ### methods for reporting
> 
>     def printStats(self):
>+        """print pass/failed/skipped statistics"""
>         print "INFO Passed: %d" % len(self.passes)
>         print "INFO Failed: %d" % len(self.fails)
>         print "INFO Skipped: %d" % len(self.skipped)
>@@ -305,15 +324,22 @@ class MozMill(object):
>             sysinfo['os.version.number'] = platform.mac_ver()[0]
>             sysinfo['os.version.string'] = platform.mac_ver()[0]
>         elif (system == 'linux2') or (system in ('sunos5', 'solaris')):
>-            sysinfo['linux_distrobution'] = platform.linux_distrobution()
>+            sysinfo['linux_distrobution'] = platform.linux_distribution()
Can we change the key name too?

>             sysinfo['libc_ver'] = platform.libc_ver()        
>         return sysinfo
> 
>-    def get_report(self, test, starttime, endtime):
>+    def get_report(self):
>+        """get the report results"""
>+
>+        assert self.test, 'run_tests not called'
>+        assert self.starttime, 'starttime not set; have you started the tests?'
>+        if not self.endtime:
>+            self.endtime = datetime.utcnow().isoformat()
>+        
Same question as setting the starttime value.  I just want to know the reasoning behind moving it out of run_tests.  (Also, not that it's all that important, but this endtime will be 1 second later than it should be due to the sleep in run_tests)

>         results = {'type' : self.report_type,
>-                   'starttime' : starttime, 
>-                   'endtime' :endtime,
>-                   'testPath' : test,
>+                   'starttime' : self.starttime, 
>+                   'endtime' : self.endtime,
>+                   'testPath' : self.test,
>                    'tests' : self.alltests
>                   }
>         results.update(self.appinfo)
>@@ -353,6 +379,7 @@ class MozMill(object):
>             # Check if the report has been created
>             if not data['ok']:
>                 print "Creating report document failed (%s)" % data
>+                return data
> 
>             # Print document location to the console and return
>             print "Report document created at '%s%s'" % (report_url, data['id'])
>@@ -360,31 +387,78 @@ class MozMill(object):
>         except Exception, e:
>             print "Sending results to '%s' failed (%s)." % (report_url, e)
> 
>-    def stop(self, timeout=10):
>+    def report(self, report_url):
>+        """print statistics and send the JSON report"""
>+        self.printStats()
>+
>+        if report_url:
>+            results = self.get_report()
>+            return self.send_report(results, report_url)
Looks good

>+
>+    ### methods for shutting down and cleanup
>+
>+    def stop_runner(self, timeout=30, close_bridge=False, hard=False):
>         sleep(1)
>-        mozmill = jsbridge.JSObject(self.bridge, mozmillModuleJs)
>         try:
>+            mozmill = jsbridge.JSObject(self.bridge, mozmillModuleJs)
>             mozmill.cleanQuit()
>         except (socket.error, JSBridgeDisconnectError):
>             pass
>-        self.runner.wait()
>-        self.back_channel.close()
>-        self.bridge.close()
>-        x = 0
>-        while self.endRunnerCalled is False and x < timeout:
>-            sleep(1);
>-            x += 1
>-        if timeout == x:
>-            print "WARNING | endRunner was never called. There must have been a failure in the framework."
>-            self.runner.profile.cleanup()
>-            sys.exit(1)
>+
>+        if not close_bridge:
>+            starttime = datetime.now()
>+            self.runner.wait(timeout=timeout)
>+            endtime = datetime.now()
>+            if ( endtime - starttime ) > timedelta(seconds=timeout):
>+                try:
>+                    self.runner.stop()
>+                except:
>+                    pass
>+                self.runner.wait()
What case would we want this for?  MozmillRestart?

>+        else: # TODO: unify this logic with the above better
>+            if hard:
>+                self.runner.kill()
>+                self.runner.profile.cleanup()
>+                return
>+
>+            # XXX this call won't actually finish in the specified timeout time
>+            self.runner.wait(timeout=timeout)
>+
>+            self.back_channel.close()
>+            self.bridge.close()
>+            x = 0
>+            while x < timeout:
>+                print x
Left over debug statement?

>+                if self.endRunnerCalled:
>+                    break
>+                sleep(1)
>+                x += 1
>+            else:
>+                print "WARNING | endRunner was never called. There must have been a failure in the framework."
>+                self.runner.kill()
>+                self.runner.profile.cleanup()
>+                sys.exit(1)
Why do we sys.exist(1) here, but above we return if there was a fatal error?  Shouldn't these two cases have similar exit conditions?

>+            
>+
>+    def stop(self, fatal=False):
>+        """cleanup"""
>+
>+        # stop the runner
>+        self.stop_runner(timeout=10, close_bridge=True, hard=fatal)
>+
>+        # cleanup the profile if you need to
>+        if self.runner is not None:
>+            try:
>+                self.runner.profile.cleanup()
>+            except OSError:
>+                pass # assume profile is already cleaned up
Looks good

> 
> class MozMillRestart(MozMill):
> 	
>     report_type = 'mozmill-restart-test'
> 
>     def __init__(self, *args, **kwargs):
>-        super(MozMillRestart, self).__init__(*args, **kwargs)
>+        MozMill.__init__(self, *args, **kwargs)
>         self.python_callbacks = []
> 
>     def add_listener(self, callback, **kwargs):
>@@ -394,15 +468,21 @@ class MozMillRestart(MozMill):
>         self.global_listeners.append(callback)
>     
>     def start(self, runner=None, profile=None):
>+        
>         if not profile:
>             profile = self.profile_class(addons=[jsbridge.extension_path, extension_path])
>+        self.profile = profile
>+        
>         if not runner:
>             runner = self.runner_class(profile=self.profile, 
>                                        cmdargs=["-jsbridge", str(self.jsbridge_port)])
>-        self.profile = profile;
>         self.runner = runner
>-
>         self.endRunnerCalled = False
>+        self.add_listener(self.firePythonCallback_listener, eventType='mozmill.firePythonCallback')
>+
>+        # set the starttime for the tests
>+        # XXX assumes run_tests will be called soon after (currently true)
>+        self.starttime = datetime.utcnow().isoformat()
Same question as Mozmill class

>      
>     def firePythonCallback_listener(self, obj):
>         if obj['fire_now']:
>@@ -411,8 +491,6 @@ class MozMillRestart(MozMill):
>             self.python_callbacks.append(obj)
>         
>     def start_runner(self):
>-        # Reset the zombie counter
>-        #self.zombieDetection.resetTimer()
> 
>         # if user_restart we don't need to start the browser back up
>         if self.currentShutdownMode != self.shutdownModes.user_restart:
>@@ -424,34 +502,14 @@ class MozMillRestart(MozMill):
>                                   "Components.utils.import('resource://mozmill/modules/frame.js')")
>         return frame
>     
>-    def stop_runner(self):
>-        sleep(1)
>-        mozmill = jsbridge.JSObject(self.bridge,
>-                            "Components.utils.import('resource://mozmill/modules/mozmill.js')")
>-        
>-        try:
>-            mozmill.cleanQuit()
>-        except (socket.error, JSBridgeDisconnectError):
>-            pass
>-        # self.back_channel.close()
>-        # self.bridge.close()
>-        starttime = datetime.now()
>-        self.runner.wait(timeout=30)
>-        endtime = datetime.now()
>-        if ( endtime - starttime ) > timedelta(seconds=30):
>-            try: self.runner.stop()
>-            except: pass
>-            self.runner.wait()
>-
>-    def endRunner_listener(self, obj):
>-        self.endRunnerCalled = True
>-
>     def userShutdown_listener(self, obj):
>         if obj in [self.shutdownModes.default, self.shutdownModes.user_restart, self.shutdownModes.user_shutdown]:
>             self.currentShutdownMode = obj
>         self.userShutdownEnabled = not self.userShutdownEnabled
> 
>-    def run_dir(self, test_dir, report=False, sleeptime=4):
>+    def run_dir(self, test_dir, sleeptime=4):
>+        """run a directory of restart tests resetting the profile per directory"""
>+
>         # Reset our Zombie counter on each directory
>         #self.zombieDetection.resetTimer()
Again why not take this out?

> 
>@@ -492,7 +550,7 @@ class MozMillRestart(MozMill):
>                 while not self.endRunnerCalled:
>                     sleep(.25)
>                 self.stop_runner()
>-                sleep(2)
>+                sleep(2) # TODO: document hard-coded constants
>             except JSBridgeDisconnectError:
>                 if not self.userShutdownEnabled:
>                     raise JSBridgeDisconnectError()
>@@ -517,45 +575,34 @@ class MozMillRestart(MozMill):
>             profile.install_addon(extension_path)
>         profile.set_preferences(profile.preferences)
>     
>-    def run_tests(self, test_dir, report=False, sleeptime=4):
>+    def run_tests(self, test_dir, sleeptime=4):
>+
>+        self.test = test_dir
>+        
>         # Zombie Counter Reset
>         #self.zombieDetector.resetTimer()
> 
>-        self.report_document = None
>-
>         # XXX this allows for only one sub-level of test directories
>         # is this a spec or a side-effect?
>         # If the former, it should be documented
>         test_dirs = [d for d in os.listdir(os.path.abspath(os.path.expanduser(test_dir))) 
>                      if d.startswith('test') and os.path.isdir(os.path.join(test_dir, d))]
>-        
>         self.add_listener(self.firePythonCallback_listener, eventType='mozmill.firePythonCallback')
>-        #self.add_listener(self.endRunner_listener, eventType='mozmill.endRunner')
>-
>         if not len(test_dirs):
>             test_dirs = [test_dir]
>         
>-        starttime = datetime.utcnow().isoformat()        
>         for d in test_dirs:
>             d = os.path.abspath(os.path.join(test_dir, d))
>-            self.run_dir(d, report, sleeptime)
>-        endtime = datetime.utcnow().isoformat()
>-        profile = self.runner.profile
>-        profile.cleanup()
>-                
>-        report_document = None
>-        if report:
>-            results = self.get_report(test_dir, starttime, endtime)
>-            report_document = self.send_report(results, report)
>+            self.run_dir(d, sleeptime)
> 
>-        # Set to None to avoid calling .stop
>-        self.runner = None
>-        sleep(1) # Give a second for any pending callbacks to finish
>+        # cleanup the profile
>+        self.runner.profile.cleanup()
> 
>-        # print pass/failed/skipped statistics
>-        self.printStats()
>+        # Give a second for any pending callbacks to finish
>+        sleep(1) 
> 
>-        return report_document
>+    def stop(self, fatal=False):
>+        """MozmillRestart doesn't need to do cleanup as this is already done per directory"""
> 
> 
> class CLI(jsbridge.CLI):
>@@ -611,31 +658,35 @@ class CLI(jsbridge.CLI):
>         profile.install_addon(extension_path)
>         return profile
> 
>-    def _run(self):
>+    def run(self):
>+        # XXX this is a complicated function that should probably be broken up
>+
>+        # create a Mozrunner
>         runner = self.create_runner()
> 
>         # make sure the application starts in the foreground
>         if '-foreground' not in runner.cmdargs:
>             runner.cmdargs.append('-foreground')
>-
>+            
>         self.mozmill.start(runner=runner, profile=runner.profile)
>-        
>+
>         if self.options.test:
>+
>+            # run the tests
>+            disconnected = False
>             try:
>-                self.mozmill.run_tests(self.options.test, self.options.report)
>+                self.mozmill.run_tests(self.options.test)
>             except JSBridgeDisconnectError:
>-                print >> sys.stderr, 'TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed'
>-                if self.mozmill.runner is not None:
>-                    self.mozmill.runner.kill()
>-                    self.mozmill.runner.profile.cleanup()
>-                sys.exit(1)
>+                disconnected = True
>+                print 'TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed'
>+
>+            # print statistics and send the JSON report
>+            self.mozmill.report(self.options.report)
>             
>-            if self.mozmill.runner:
>-                self.mozmill.stop()
>-            if len(self.mozmill.fails) > 0:
>-                if self.mozmill.runner is not None:
>-                    self.mozmill.runner.profile.cleanup()
>-                raise TestsFailedException()
>+            # shutdown the test harness
>+            self.mozmill.stop(fatal=disconnected)
>+            if self.mozmill.fails or disconnected:
>+                sys.exit(1)
>         else:
>             if self.options.shell:
>                 self.start_shell(runner)
>@@ -647,33 +698,21 @@ class CLI(jsbridge.CLI):
>                 except KeyboardInterrupt:
>                     runner.stop()
> 
>-        if self.mozmill.runner is not None:
>-            self.mozmill.runner.profile.cleanup()
>-
>-    def run(self):
>-        try:
>-            self._run()
>-        except TestsFailedException, e:
>-            sys.exit(1)
>-
>+            if self.mozmill.runner is not None:
>+                self.mozmill.runner.profile.cleanup()
>+    
> class RestartCLI(CLI):
>     mozmill_class = MozMillRestart
>-
>     parser_options = copy.copy(CLI.parser_options)
>     parser_options[("-t", "--test",)] = dict(dest="test", default=False, 
>                                              help="Run test directory.")
> 
>-    def run(self, *args, **kwargs):
>-        if len(sys.argv) is 1:
>-            print "Restart test CLI cannot be run without arguments, try --help for usage."
>-            sys.exit(1)
>-        else:
>-            CLI.run(self, *args, **kwargs)
> 
> class ThunderbirdCLI(CLI):
>     profile_class = mozrunner.ThunderbirdProfile
>     runner_class = mozrunner.ThunderbirdRunner
> 
>+
> def enum(*sequential, **named):
>     enums = dict(zip(sequential, range(len(sequential))), **named)
>     return type('Enum', (), enums)
>


I have one more comment about TestsFailedException. Right now it does nothing but call sys.exit(), but we might want to add some additional logging and/or cleanup sometime in the future. I'm pretty impartial about this, but it doesn't seem like we gain anything by taking it out, and by leaving it in we make it easier to add on fail functionality.

Other than that it looks like you've cleaned up a lot of things that we've been thinking about in the back of our minds.  The reporting section seems straight-forward and adding the hard kill seems like a good idea.

I couldn't find any major problems, nice patch.

r=ahalberstadt with the caveat that you answer the questions and read my comments

Comment 4

[Jeff Hammel]

(In reply to comment #3)
> Comment on attachment 459858 [details] [diff] [review]
> move reporting to its own slot instead of being called from run_tests
> 
> >diff --git a/jsbridge/jsbridge/network.py b/jsbridge/jsbridge/network.py
> >index fca66f0..a5e3412 100644
> >--- a/jsbridge/jsbridge/network.py
> >+++ b/jsbridge/jsbridge/network.py
> >@@ -153,7 +153,6 @@ class JSBridgeDisconnectError(Exception):
> >     """exception raised when an unexpected disconect happens"""
> > 
> > 
> >-
> > class Bridge(Telnet):
> >     
> >     trashes = []
> >diff --git a/mozmill/mozmill/__init__.py b/mozmill/mozmill/__init__.py
> >index 982e02e..fe5c321 100644
> >--- a/mozmill/mozmill/__init__.py
> >+++ b/mozmill/mozmill/__init__.py
> >@@ -117,9 +117,20 @@ class LoggerListener(object):
> > 
> > class TestsFailedException(Exception):
> >     """exception to be raised when the tests fail"""
> >-
> >+    # XXX unused
> > 
> > class MozMill(object):
> >+    """
> >+    MozMill is a one-shot test runner  You should use MozMill as follows:
> >+
> >+    m = MozMill(...)
> >+    m.start(...)
> >+    m.run_tests()
> >+    m.stop()
> >+
> >+    You should *NOT* vary from this order of execution.  If you have need to
> >+    run different sets of tests, create a new instantiation of MozMill
> >+    """
> > 
> >     report_type = 'mozmill-test'
> > 
> >@@ -148,8 +159,12 @@ class MozMill(object):
> >         self.shutdownModes = enum('default', 'user_shutdown', 'user_restart')
> >         self.currentShutdownMode = self.shutdownModes.default
> >         self.userShutdownEnabled = False
> >+        self.test = None
> >         #self.zombieDetector = ZombieDetector(self.stop)
> > 
> >+        # test time
> >+        self.starttime = self.endtime = None
> >+
> >         # setup event listeners
> >         self.global_listeners = []
> >         self.listeners = []
> >@@ -206,53 +221,56 @@ class MozMill(object):
> >             self.back_channel.add_global_listener(global_listener)
> > 
> >     def start(self, profile=None, runner=None):
> >-        # Reset our Zombie counter
> >-        #self.zombieDetector.resetTimer()
> > 
> >         if not profile:
> >             profile = self.profile_class(addons=[jsbridge.extension_path, extension_path])
> >+        self.profile = profile
> >+
> How did this go unnoticed for this long? :p

Since there is currently no code-path that would get to this function without a profile internal to mozmill, it hasn't been an issue.

> >         if not runner:
> >             runner = self.runner_class(profile=self.profile, 
> >                                        cmdargs=["-jsbridge", str(self.jsbridge_port)])
> > 
> >         self.add_listener(self.firePythonCallback_listener, eventType='mozmill.firePythonCallback')
> >-        self.profile = profile;
> >         self.runner = runner
> >-        self.runner.start()
> >-        
> >         self.endRunnerCalled = False
> >+        
> >+        self.runner.start()
> >         self.create_network()
> >         self.appinfo = self.get_appinfo(self.bridge)
> > 
> >-    def run_tests(self, test, report=False, sleeptime = 4):
> >+        # set the starttime for the tests
> >+        # XXX assumes run_tests will be called soon after (currently true)
> >+        self.starttime = datetime.utcnow().isoformat()      
> What was wrong with the old location of setting starttime?  It seems where it
> used to be we don't need to make any assumptions.

There are a couple of issues here:

 * the real goal is to move the getting of the report out of run_tests so that it can be called independently

 * run_tests should really just have the procedure for running the tests.  while I could (and maybe should) have put the shared logic in a function that wraps the (class-dependent) run_tests in another function, since mozmill is very serial (see class docstring)...

 * i just put this in start()


> >+
> >+    def run_tests(self, test, sleeptime=4):
> >+        """
> >+        run a test file or directory
> >+        - test : test file or directory to run
> >+        - report : URL to send a JSON report to
> >+        - sleeptime : initial time to sleep [s] (not sure why the default is 4)
> >+        """
> >+
> Forgot to get rid of the 'report' documentation

Thanks; fixed.

> >         # Reset our Zombie Because we are still active
> >         #self.zombieDetector.resetTimer()
> You nuked these in the 'start()' method, why not here?

That was a mistake. I put these back in start.  If we want to purge all of the Zombie detection code, that should probably be separate bug.

> > 
> >+        self.test = test
> >+
> >         frame = jsbridge.JSObject(self.bridge,
> >                                   "Components.utils.import('resource://mozmill/modules/frame.js')")
> >         sleep(sleeptime)
> >-        starttime = datetime.utcnow().isoformat()
> > 
> >         # transfer persisted data
> >         frame.persisted = self.persisted
> > 
> >+        # run the test directory or file
> >         if os.path.isdir(test):
> >             frame.runTestDirectory(test)
> >         else:
> >             frame.runTestFile(test)
> > 
> >-        endtime = datetime.utcnow().isoformat()
> >-
> >-        report_document = None
> >-        if report:
> >-            results = self.get_report(test, starttime, endtime)
> >-            report_document = self.send_report(results, report)
> >-
> >         # Give a second for any callbacks to finish.
> >         sleep(1)
> > 
> >-        return report_document
> >-
> >     def startTest_listener(self, test):
> >         print "TEST-START | %s | %s" % (test['filename'], test['name'])
> > 
> >@@ -272,11 +290,12 @@ class MozMill(object):
> >             self.passes.append(test)
> > 
> >     def endRunner_listener(self, obj):
> >-        self.printStats()
> >         self.endRunnerCalled = True
> > 
> >+    ### methods for reporting
> > 
> >     def printStats(self):
> >+        """print pass/failed/skipped statistics"""
> >         print "INFO Passed: %d" % len(self.passes)
> >         print "INFO Failed: %d" % len(self.fails)
> >         print "INFO Skipped: %d" % len(self.skipped)
> >@@ -305,15 +324,22 @@ class MozMill(object):
> >             sysinfo['os.version.number'] = platform.mac_ver()[0]
> >             sysinfo['os.version.string'] = platform.mac_ver()[0]
> >         elif (system == 'linux2') or (system in ('sunos5', 'solaris')):
> >-            sysinfo['linux_distrobution'] = platform.linux_distrobution()
> >+            sysinfo['linux_distrobution'] = platform.linux_distribution()
> Can we change the key name too?

I'm not sure if this data is used in production yet or not, so that would be a question for :whimboo . OTOH, since this code will raise an error, i'm not sure. (the system checking is also redundant;  we *should* have a generic python utlity for system detection).

> >             sysinfo['libc_ver'] = platform.libc_ver()        
> >         return sysinfo
> > 
> >-    def get_report(self, test, starttime, endtime):
> >+    def get_report(self):
> >+        """get the report results"""
> >+
> >+        assert self.test, 'run_tests not called'
> >+        assert self.starttime, 'starttime not set; have you started the tests?'
> >+        if not self.endtime:
> >+            self.endtime = datetime.utcnow().isoformat()
> >+        
> Same question as setting the starttime value.  I just want to know the
> reasoning behind moving it out of run_tests.  

Again, run_tests should just run the tests.  It should probably be wrapped or decorated with functions that do "this sort of thing" (i.e. generic functionality).  The real reason is that the times should be instance-variables so that the report can be gotten outside of run_tests

> (Also, not that it's all that
> important, but this endtime will be 1 second later than it should be due to the
> sleep in run_tests)

Yes, I realize this.

> 
> >         results = {'type' : self.report_type,
> >-                   'starttime' : starttime, 
> >-                   'endtime' :endtime,
> >-                   'testPath' : test,
> >+                   'starttime' : self.starttime, 
> >+                   'endtime' : self.endtime,
> >+                   'testPath' : self.test,
> >                    'tests' : self.alltests
> >                   }
> >         results.update(self.appinfo)
> >@@ -353,6 +379,7 @@ class MozMill(object):
> >             # Check if the report has been created
> >             if not data['ok']:
> >                 print "Creating report document failed (%s)" % data
> >+                return data
> > 
> >             # Print document location to the console and return
> >             print "Report document created at '%s%s'" % (report_url, data['id'])
> >@@ -360,31 +387,78 @@ class MozMill(object):
> >         except Exception, e:
> >             print "Sending results to '%s' failed (%s)." % (report_url, e)
> > 
> >-    def stop(self, timeout=10):
> >+    def report(self, report_url):
> >+        """print statistics and send the JSON report"""
> >+        self.printStats()
> >+
> >+        if report_url:
> >+            results = self.get_report()
> >+            return self.send_report(results, report_url)
> Looks good
> 
> >+
> >+    ### methods for shutting down and cleanup
> >+
> >+    def stop_runner(self, timeout=30, close_bridge=False, hard=False):
> >         sleep(1)
> >-        mozmill = jsbridge.JSObject(self.bridge, mozmillModuleJs)
> >         try:
> >+            mozmill = jsbridge.JSObject(self.bridge, mozmillModuleJs)
> >             mozmill.cleanQuit()
> >         except (socket.error, JSBridgeDisconnectError):
> >             pass
> >-        self.runner.wait()
> >-        self.back_channel.close()
> >-        self.bridge.close()
> >-        x = 0
> >-        while self.endRunnerCalled is False and x < timeout:
> >-            sleep(1);
> >-            x += 1
> >-        if timeout == x:
> >-            print "WARNING | endRunner was never called. There must have been a failure in the framework."
> >-            self.runner.profile.cleanup()
> >-            sys.exit(1)
> >+
> >+        if not close_bridge:
> >+            starttime = datetime.now()
> >+            self.runner.wait(timeout=timeout)
> >+            endtime = datetime.now()
> >+            if ( endtime - starttime ) > timedelta(seconds=timeout):
> >+                try:
> >+                    self.runner.stop()
> >+                except:
> >+                    pass
> >+                self.runner.wait()
> What case would we want this for?  MozmillRestart?

Yes;  this logic is very messy and should probably be cleaned up.  I wasn't sure of the subtlties of what was actually intended here so I just combined the existing stop function (which now calls stop_runner) and the MozMillRestart.stop_runner function and separated things with an if..else . Its not elegant and needs cleaning up :(

> >+        else: # TODO: unify this logic with the above better
> >+            if hard:
> >+                self.runner.kill()
> >+                self.runner.profile.cleanup()
> >+                return
> >+
> >+            # XXX this call won't actually finish in the specified timeout time
> >+            self.runner.wait(timeout=timeout)
> >+
> >+            self.back_channel.close()
> >+            self.bridge.close()
> >+            x = 0
> >+            while x < timeout:
> >+                print x
> Left over debug statement?

Thanks, cleaned up.

> >+                if self.endRunnerCalled:
> >+                    break
> >+                sleep(1)
> >+                x += 1
> >+            else:
> >+                print "WARNING | endRunner was never called. There must have been a failure in the framework."
> >+                self.runner.kill()
> >+                self.runner.profile.cleanup()
> >+                sys.exit(1)
> Why do we sys.exist(1) here, but above we return if there was a fatal error? 
> Shouldn't these two cases have similar exit conditions?

Probably; these should be cleaned up.  Though to be technical, the fatal flag tells the function that something bad *already* happened.  Again, I just munged the logic the best I could without altering it much, as there are subtlties here I don't really understand.

> >+            
> >+
> >+    def stop(self, fatal=False):
> >+        """cleanup"""
> >+
> >+        # stop the runner
> >+        self.stop_runner(timeout=10, close_bridge=True, hard=fatal)
> >+
> >+        # cleanup the profile if you need to
> >+        if self.runner is not None:
> >+            try:
> >+                self.runner.profile.cleanup()
> >+            except OSError:
> >+                pass # assume profile is already cleaned up
> Looks good
> 
> > 
> > class MozMillRestart(MozMill):
> > 	
> >     report_type = 'mozmill-restart-test'
> > 
> >     def __init__(self, *args, **kwargs):
> >-        super(MozMillRestart, self).__init__(*args, **kwargs)
> >+        MozMill.__init__(self, *args, **kwargs)
> >         self.python_callbacks = []
> > 
> >     def add_listener(self, callback, **kwargs):
> >@@ -394,15 +468,21 @@ class MozMillRestart(MozMill):
> >         self.global_listeners.append(callback)
> >     
> >     def start(self, runner=None, profile=None):
> >+        
> >         if not profile:
> >             profile = self.profile_class(addons=[jsbridge.extension_path, extension_path])
> >+        self.profile = profile
> >+        
> >         if not runner:
> >             runner = self.runner_class(profile=self.profile, 
> >                                        cmdargs=["-jsbridge", str(self.jsbridge_port)])
> >-        self.profile = profile;
> >         self.runner = runner
> >-
> >         self.endRunnerCalled = False
> >+        self.add_listener(self.firePythonCallback_listener, eventType='mozmill.firePythonCallback')
> >+
> >+        # set the starttime for the tests
> >+        # XXX assumes run_tests will be called soon after (currently true)
> >+        self.starttime = datetime.utcnow().isoformat()
> Same question as Mozmill class
> 
> >      
> >     def firePythonCallback_listener(self, obj):
> >         if obj['fire_now']:
> >@@ -411,8 +491,6 @@ class MozMillRestart(MozMill):
> >             self.python_callbacks.append(obj)
> >         
> >     def start_runner(self):
> >-        # Reset the zombie counter
> >-        #self.zombieDetection.resetTimer()
> > 
> >         # if user_restart we don't need to start the browser back up
> >         if self.currentShutdownMode != self.shutdownModes.user_restart:
> >@@ -424,34 +502,14 @@ class MozMillRestart(MozMill):
> >                                   "Components.utils.import('resource://mozmill/modules/frame.js')")
> >         return frame
> >     
> >-    def stop_runner(self):
> >-        sleep(1)
> >-        mozmill = jsbridge.JSObject(self.bridge,
> >-                            "Components.utils.import('resource://mozmill/modules/mozmill.js')")
> >-        
> >-        try:
> >-            mozmill.cleanQuit()
> >-        except (socket.error, JSBridgeDisconnectError):
> >-            pass
> >-        # self.back_channel.close()
> >-        # self.bridge.close()
> >-        starttime = datetime.now()
> >-        self.runner.wait(timeout=30)
> >-        endtime = datetime.now()
> >-        if ( endtime - starttime ) > timedelta(seconds=30):
> >-            try: self.runner.stop()
> >-            except: pass
> >-            self.runner.wait()
> >-
> >-    def endRunner_listener(self, obj):
> >-        self.endRunnerCalled = True
> >-
> >     def userShutdown_listener(self, obj):
> >         if obj in [self.shutdownModes.default, self.shutdownModes.user_restart, self.shutdownModes.user_shutdown]:
> >             self.currentShutdownMode = obj
> >         self.userShutdownEnabled = not self.userShutdownEnabled
> > 
> >-    def run_dir(self, test_dir, report=False, sleeptime=4):
> >+    def run_dir(self, test_dir, sleeptime=4):
> >+        """run a directory of restart tests resetting the profile per directory"""
> >+
> >         # Reset our Zombie counter on each directory
> >         #self.zombieDetection.resetTimer()
> Again why not take this out?

See above.  I think these are slated for the chopping block, but am not 100% sure.  In either case, there are enough of them its probably worth doing in its own bug.

> > 
> >@@ -492,7 +550,7 @@ class MozMillRestart(MozMill):
> >                 while not self.endRunnerCalled:
> >                     sleep(.25)
> >                 self.stop_runner()
> >-                sleep(2)
> >+                sleep(2) # TODO: document hard-coded constants
> >             except JSBridgeDisconnectError:
> >                 if not self.userShutdownEnabled:
> >                     raise JSBridgeDisconnectError()
> >@@ -517,45 +575,34 @@ class MozMillRestart(MozMill):
> >             profile.install_addon(extension_path)
> >         profile.set_preferences(profile.preferences)
> >     
> >-    def run_tests(self, test_dir, report=False, sleeptime=4):
> >+    def run_tests(self, test_dir, sleeptime=4):
> >+
> >+        self.test = test_dir
> >+        
> >         # Zombie Counter Reset
> >         #self.zombieDetector.resetTimer()
> > 
> >-        self.report_document = None
> >-
> >         # XXX this allows for only one sub-level of test directories
> >         # is this a spec or a side-effect?
> >         # If the former, it should be documented
> >         test_dirs = [d for d in os.listdir(os.path.abspath(os.path.expanduser(test_dir))) 
> >                      if d.startswith('test') and os.path.isdir(os.path.join(test_dir, d))]
> >-        
> >         self.add_listener(self.firePythonCallback_listener, eventType='mozmill.firePythonCallback')
> >-        #self.add_listener(self.endRunner_listener, eventType='mozmill.endRunner')
> >-
> >         if not len(test_dirs):
> >             test_dirs = [test_dir]
> >         
> >-        starttime = datetime.utcnow().isoformat()        
> >         for d in test_dirs:
> >             d = os.path.abspath(os.path.join(test_dir, d))
> >-            self.run_dir(d, report, sleeptime)
> >-        endtime = datetime.utcnow().isoformat()
> >-        profile = self.runner.profile
> >-        profile.cleanup()
> >-                
> >-        report_document = None
> >-        if report:
> >-            results = self.get_report(test_dir, starttime, endtime)
> >-            report_document = self.send_report(results, report)
> >+            self.run_dir(d, sleeptime)
> > 
> >-        # Set to None to avoid calling .stop
> >-        self.runner = None
> >-        sleep(1) # Give a second for any pending callbacks to finish
> >+        # cleanup the profile
> >+        self.runner.profile.cleanup()
> > 
> >-        # print pass/failed/skipped statistics
> >-        self.printStats()
> >+        # Give a second for any pending callbacks to finish
> >+        sleep(1) 
> > 
> >-        return report_document
> >+    def stop(self, fatal=False):
> >+        """MozmillRestart doesn't need to do cleanup as this is already done per directory"""
> > 
> > 
> > class CLI(jsbridge.CLI):
> >@@ -611,31 +658,35 @@ class CLI(jsbridge.CLI):
> >         profile.install_addon(extension_path)
> >         return profile
> > 
> >-    def _run(self):
> >+    def run(self):
> >+        # XXX this is a complicated function that should probably be broken up
> >+
> >+        # create a Mozrunner
> >         runner = self.create_runner()
> > 
> >         # make sure the application starts in the foreground
> >         if '-foreground' not in runner.cmdargs:
> >             runner.cmdargs.append('-foreground')
> >-
> >+            
> >         self.mozmill.start(runner=runner, profile=runner.profile)
> >-        
> >+
> >         if self.options.test:
> >+
> >+            # run the tests
> >+            disconnected = False
> >             try:
> >-                self.mozmill.run_tests(self.options.test, self.options.report)
> >+                self.mozmill.run_tests(self.options.test)
> >             except JSBridgeDisconnectError:
> >-                print >> sys.stderr, 'TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed'
> >-                if self.mozmill.runner is not None:
> >-                    self.mozmill.runner.kill()
> >-                    self.mozmill.runner.profile.cleanup()
> >-                sys.exit(1)
> >+                disconnected = True
> >+                print 'TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed'
> >+
> >+            # print statistics and send the JSON report
> >+            self.mozmill.report(self.options.report)
> >             
> >-            if self.mozmill.runner:
> >-                self.mozmill.stop()
> >-            if len(self.mozmill.fails) > 0:
> >-                if self.mozmill.runner is not None:
> >-                    self.mozmill.runner.profile.cleanup()
> >-                raise TestsFailedException()
> >+            # shutdown the test harness
> >+            self.mozmill.stop(fatal=disconnected)
> >+            if self.mozmill.fails or disconnected:
> >+                sys.exit(1)
> >         else:
> >             if self.options.shell:
> >                 self.start_shell(runner)
> >@@ -647,33 +698,21 @@ class CLI(jsbridge.CLI):
> >                 except KeyboardInterrupt:
> >                     runner.stop()
> > 
> >-        if self.mozmill.runner is not None:
> >-            self.mozmill.runner.profile.cleanup()
> >-
> >-    def run(self):
> >-        try:
> >-            self._run()
> >-        except TestsFailedException, e:
> >-            sys.exit(1)
> >-
> >+            if self.mozmill.runner is not None:
> >+                self.mozmill.runner.profile.cleanup()
> >+    
> > class RestartCLI(CLI):
> >     mozmill_class = MozMillRestart
> >-
> >     parser_options = copy.copy(CLI.parser_options)
> >     parser_options[("-t", "--test",)] = dict(dest="test", default=False, 
> >                                              help="Run test directory.")
> > 
> >-    def run(self, *args, **kwargs):
> >-        if len(sys.argv) is 1:
> >-            print "Restart test CLI cannot be run without arguments, try --help for usage."
> >-            sys.exit(1)
> >-        else:
> >-            CLI.run(self, *args, **kwargs)
> > 
> > class ThunderbirdCLI(CLI):
> >     profile_class = mozrunner.ThunderbirdProfile
> >     runner_class = mozrunner.ThunderbirdRunner
> > 
> >+
> > def enum(*sequential, **named):
> >     enums = dict(zip(sequential, range(len(sequential))), **named)
> >     return type('Enum', (), enums)
> >
> 
> 
> I have one more comment about TestsFailedException. Right now it does nothing
> but call sys.exit(), but we might want to add some additional logging and/or
> cleanup sometime in the future. I'm pretty impartial about this, but it doesn't
> seem like we gain anything by taking it out, and by leaving it in we make it
> easier to add on fail functionality.

I'm not sure I understand what you mean.  Leaving in where it is raised or the exception itself?  I kill where it is raised (which is precisely one place) but leave in the class definition.  

In general, I think control-flow of the program will be somethign that should be thought about carefully for 2.0

> Other than that it looks like you've cleaned up a lot of things that we've been
> thinking about in the back of our minds.  The reporting section seems
> straight-forward and adding the hard kill seems like a good idea.
> 
> I couldn't find any major problems, nice patch.
> 
> r=ahalberstadt with the caveat that you answer the questions and read my
> comments

Comment 5

[Jeff Hammel]

pushed to mozauto:

http://github.com/mozautomation/mozmill/commit/36686070c2b64fc616dc57cbeddab6f6a34bf871

http://github.com/mozautomation/mozmill/commit/36686070c2b64fc616dc57cbeddab6f6a34bf871

I also had to merge and resolve conflicts for reasons I don't understand, but then again I never understand what git does:

http://github.com/mozautomation/mozmill/commit/b6e21d68faddf9895a384a02b4250554d9747f8f

http://github.com/k0s/mozmill/commit/dc4e657b56b5a5d4a1254c187cb31362e0e84833

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Looks good so far with Mozmill 1.4.2 beta2. The only problem I see is bug 583893 now. We would really need the kill information in the report.