Closed Bug 809742 Opened 12 years ago Closed 6 years ago

wean "mach reftest" off makefiles

Categories

(Firefox Build System :: Mach Core, enhancement)

enhancement
Not set
normal

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: heycam, Assigned: heycam)

Details

Attachments

(1 file, 1 obsolete file)

I was looking into running reftests from mach without calling into make.  We could do it in one of two ways:

  1. invoking an external "python runreftest.py"
  2. importing runreftest and running it directly

Which way is preferred?  I tried doing #2 just now, and I have it running reftests properly except that:

  (a) the console output doesn't get captured in mach's logging (it doesn't get
      the colourful message times) since we're no longer calling _run_make; and
  (b) it also doesn't write all the output out to objdir/reftest.log, since tha
      was done with a "... | tee reftest.log" from the makefile.

Switching to #1 would solve the issue (a), and I could just stick the tee back in to the shell I invoke to solve issue (b).  But it seems like it'd be nice to avoid going through the shell if it can be helped.
Another ugliness of the #2 approach currently is that I have this:

        reftest_dir = os.path.join(self.absolute_topobjdir, '_tests', 'reftest')
        try:
            from automation import Automation
            from runreftest import RefTest, ReftestOptions
        except ImportError:
            sys.path.insert(0, reftest_dir)
            from automation import Automation
            from runreftest import RefTest, ReftestOptions

in the middle of ReftestRunner.run_reftest_test, since we need automation.py (which is generated in objdir/build and symlinked to from objdir/_tests/reftest) and runreftest.py, which needs to be run from within objdir/_tests/reftest as it assumes some directory relativeness from there to find firefox.
(In reply to Cameron McCormack (:heycam) from comment #0)
>   1. invoking an external "python runreftest.py"
>   2. importing runreftest and running it directly

#2 is preferred. We want as much of the "build system" as possible to be consumable as native Python so tools like mach can easily hook in and do things and new and creative ways. Process execution tends to limit the flexibility compared to a "native" Python API.

>   (a) the console output doesn't get captured in mach's logging (it doesn't
> get
>       the colourful message times) since we're no longer calling _run_make;
> and

I'm not sure how runreftest.py does output.

If it is writing directly to stdout, that could be a problem. For mach to capture output, you'd have to install a fake file object as sys.stdout and intercept the data passed to .write() and re-write it through a) mach logging mechanism (look at the logging mixin) b) the Python logging mechanism and have mach's logger intercept those log messages.

If it is writing to a logger, we are in better shape. Get the mach log manager instance (from the argument passed to the mach command class's __init__) and call .enable_unstructured().

If it isn't writing to a logger, I'd be tempted to rewrite the reftest runner to write everything to a logger so mach can intercept it easier.

>   (b) it also doesn't write all the output out to objdir/reftest.log, since
> tha
>       was done with a "... | tee reftest.log" from the makefile.

Once mach has the raw output, it can do whatever you want, including writing both to stdout and a file.

(In reply to Cameron McCormack (:heycam) from comment #1)
> Another ugliness of the #2 approach currently is that I have this:
> 
>         reftest_dir = os.path.join(self.absolute_topobjdir, '_tests',
> 'reftest')
>         try:
>             from automation import Automation
>             from runreftest import RefTest, ReftestOptions
>         except ImportError:
>             sys.path.insert(0, reftest_dir)
>             from automation import Automation
>             from runreftest import RefTest, ReftestOptions

This isn't *too* bad. I'd like to avoid sys.path munging from within mach command handlers. Instead, you could put those paths in the virtualenv. See build/virtualenv/packages.txt. That's what we did for the xpcshell runner.

> in the middle of ReftestRunner.run_reftest_test, since we need automation.py
> (which is generated in objdir/build and symlinked to from
> objdir/_tests/reftest) and runreftest.py, which needs to be run from within
> objdir/_tests/reftest as it assumes some directory relativeness from there
> to find firefox.

Assuming directory relativeness is quite crappy. I haven't looked at the code, but in the ideal world, the path to firefox would be passed into the test runner. There is Python code floating around to find the firefox binary within an object directory. I've been meaning to incorporate a "path to binary" API somewhere in the Python tree - likely in mozbuild somewhere.

Welcome to the world of tools and the build system! Things aren't as simple as they seem...
See also testing/xpcshell/runxpcshelltests.py for how it does logging. runreftests.py should do it that way.

In my ideal world, all this "run a test" code gets factored out into a common testing Python package, complete with easy-to-consume APIs. Scripts like runxpcshelltests.py or runreftests.py just load a Python module providing the core API and go from there. Or, just remove the standalone scripts and do everything with mach! The important part is everything is a library. That's what opens up new and exciting doors (like mach).
(In reply to Gregory Szorc [:gps] from comment #2)
> #2 is preferred.

OK.

> >   (a) the console output doesn't get captured in mach's logging (it doesn't
> > get
> >       the colourful message times) since we're no longer calling _run_make;
> > and
> 
> I'm not sure how runreftest.py does output.

So it looks like runreftest.py does use a logger, though this:

  http://hg.mozilla.org/mozilla-central/file/tip/build/automation.py.in#l64
  http://hg.mozilla.org/mozilla-central/file/tip/build/automation.py.in#l133

> If it is writing to a logger, we are in better shape. Get the mach log
> manager instance (from the argument passed to the mach command class's
> __init__) and call .enable_unstructured().

I'll try that.

> >   (b) it also doesn't write all the output out to objdir/reftest.log, since
> > tha
> >       was done with a "... | tee reftest.log" from the makefile.
> 
> Once mach has the raw output, it can do whatever you want, including writing
> both to stdout and a file.

OK, cool, so looks like that would be done by having a add_plain_text_handler method on LoggingManager that installs a handler to do that.

> >         reftest_dir = os.path.join(self.absolute_topobjdir, '_tests',
> > 'reftest')
...
> This isn't *too* bad. I'd like to avoid sys.path munging from within mach
> command handlers. Instead, you could put those paths in the virtualenv. See
> build/virtualenv/packages.txt. That's what we did for the xpcshell runner.

How would this work for automation.py?  Not sure how I could reference the objdir/build/automation.py from there to get it copied into the right place under objdir/_virtualenv.

> > in the middle of ReftestRunner.run_reftest_test, since we need automation.py
> > (which is generated in objdir/build and symlinked to from
> > objdir/_tests/reftest) and runreftest.py, which needs to be run from within
> > objdir/_tests/reftest as it assumes some directory relativeness from there
> > to find firefox.
> 
> Assuming directory relativeness is quite crappy. I haven't looked at the
> code, but in the ideal world, the path to firefox would be passed into the
> test runner. There is Python code floating around to find the firefox binary
> within an object directory. I've been meaning to incorporate a "path to
> binary" API somewhere in the Python tree - likely in mozbuild somewhere.

It is possible to pass in the binary to use in the reftest options.  It's just the default that gets set to be relative to objdir/something through some autoconf junk:

  http://hg.mozilla.org/mozilla-central/file/tip/build/automation-build.mk#l15
  http://hg.mozilla.org/mozilla-central/file/tip/build/automation.py.in#l119

(In my automation.py output it's set to "../dist/NightlyDebug.app/Contents/MacOS/firefox-bin".)

> Welcome to the world of tools and the build system! Things aren't as simple
> as they seem...

:)
Note that bug 746246 aims to pretty heavily refactor the reftest harness (we've been blocked on the mozharness rollout, but that's live on the cedar branch at the moment).
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #5)
> Note that bug 746246 aims to pretty heavily refactor the reftest harness
> (we've been blocked on the mozharness rollout, but that's live on the cedar
> branch at the moment).

OK; maybe we can get something working with the current runreftest.py in the meantime though.

I've managed to get automation.py installed in the virtualenv (with a .pth file pointing to objdir/build), but I'll need to wait for bug 794506 before that'll let me use it.
Attached patch WIP (v0.1) (obsolete) — Splinter Review
(In reply to Cameron McCormack (:heycam) from comment #6)
> I've managed to get automation.py installed in the virtualenv (with a .pth
> file pointing to objdir/build), but I'll need to wait for bug 794506 before
> that'll let me use it.

I'm not sure bug 794506 is a prerequisite. If you are missing something from sys.path, you can always munge it in the ./mach file. That being said, if the path is in the object directory, that would be hard and bug 794506 could help.

If you want to edit sys.path from within the mach command handler, I'm fine with that as a temporary workaround.
Attached patch patch (v1)Splinter Review
OK, I'll leave the sys.path editing in there.  I found out that the automation.py in objdir/build/ is actually different from the one in objdir/_tests/reftest -- they have different numbers of "../"s so that they know where the Firefox binary is relative to that directory.  So I'm going to skip the virtualenv changes and just use the automation.py directly in objdir/_tests/reftest again.

I've added only a couple of the runreftest.py arguments to the mach command for the moment.  Not sure which ones we want to have (e.g. is --xre-path really necessary?).
Assignee: nobody → cam
Attachment #679921 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #680475 - Flags: review?(gps)
Comment on attachment 680475 [details] [diff] [review]
patch (v1)

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

Almost there. I'd like to see the feedback addressed before I grant r+.

If it's not too much effort, I'd appreciate if the python/{mach,mozbuild} changes were in a separate patch from the reftest running. You may also want to ask :Ms2ger for feedback (possibly review) of the reftest changes, just to be sure we have blessing from someone who interacts with them a lot.

::: build/automation.py.in
@@ +1162,5 @@
>      else:
>        self.log.info("INFO | automation.py | Cannot install extension, invalid extensionSource at: %s", extensionSource)
> +
> +  def disableDefaultLoggingHandler(self):
> +    self.log.removeHandler(handler)

I hate the use of globals. Alas, it's the easiest way and doesn't involve rewriting automation.py.in to be more import friendly.

::: layout/tools/reftest/mach_commands.py
@@ +3,5 @@
>  # file, You can obtain one at http://mozilla.org/MPL/2.0/.
>  
>  from __future__ import unicode_literals
>  
> +import errno, re, os, sys

One import per line, please.

@@ +26,5 @@
>      This currently contains just the basics for running reftests. We may want
>      to hook up result parsing, etc.
>      """
>  
> +    def __init__(self, topsrcdir, settings, log_manager, topobjdir = None):

Nit: no spaces on either side of the '='

@@ +28,5 @@
>      """
>  
> +    def __init__(self, topsrcdir, settings, log_manager, topobjdir = None):
> +        MozbuildObject.__init__(self, topsrcdir, settings, log_manager, topobjdir)
> +        log_manager.enable_unstructured()

Hmm. We should probably add an empty method to the base class so children don't have to worry about the __init__ signature.

Perhaps we should move enable_unstructured() to run_reftest_test() for now.

@@ +88,5 @@
> +        reftest_dir = os.path.join(self.topobjdir, '_tests', 'reftest')
> +
> +        try:
> +            from automation import Automation
> +        except:

except ImportError:

@@ +102,5 @@
> +        # we want mach to handle the logging output
> +        automation.disableDefaultLoggingHandler()
> +
> +        # get the default arguments
> +        options = parser.parse_args([])[0]

This is screaming for a better API. Probably outside the scope of this bug though.

@@ +121,5 @@
> +        try:
> +            reftest.runTests(path, options)
> +        finally:
> +            self.log_manager.remove_logfile_handler(logHandler)
> +            logFile.close()

Alternatively you could use a context manager for managing open files:

with open(logFilename, 'w') as logFile:
    # Do stuff with file handle

# The file handle is closed when the context manager exits.

@@ +131,5 @@
>          help='Reftest manifest file, or a directory in which to select '
>               'reftest.list. If omitted, the entire test suite is executed.')
> +    @CommandArgument('--setpref', default=None, action='append',
> +        dest='extraPrefs', metavar='PREF=VALUE',
> +        help='Defines an extra user preference.')

If we really wanted to, we could define a custom validator for this that verified values are of the expected 'key=value' form.

@@ +153,2 @@
>          reftest = self._spawn(ReftestRunner)
> +        reftest.run_reftest_test(test_file, args, flavor)

run_reftest_test() could raise if the test is not found. This will result in mach printing the exception stack and claiming there is probably an error in the command handler.

We should probably reserve exceptions for truly exceptional cases or have mach catch non-fatal exceptions and convert them to non-0 exit codes. i.e. the @Command method should only propagate an exception if there is really an unexpected error (not due to bad arguments).

::: layout/tools/reftest/runreftest.py
@@ +127,5 @@
>  
>        # browser environment
>        browserEnv = self.buildBrowserEnv(options, profileDir)
>  
> +      self.automation.log.info("REFTEST INFO | runreftest.py | Running tests: start.")

How much do you want to bet this breaks something? ;)

::: python/mach/mach/logging.py
@@ +214,5 @@
>  
> +    def add_logfile_handler(self, fh, level=logging.INFO):
> +        """Enable logging to the specified file handle."""
> +
> +        formatter = StructuredHumanFormatter(self.start_time)

This will print elapsed time to the files, just like stdout. It /might/ be a better idea to use some formatting of the actual log time (like what the standard file logger from Python does). This could be a follow-up bug.

@@ +216,5 @@
> +        """Enable logging to the specified file handle."""
> +
> +        formatter = StructuredHumanFormatter(self.start_time)
> +
> +        handler = logging.StreamHandler(stream=fh)

Perhaps rename the function to "add_stream_handler?" Maybe it should also take an controlling controlling the formatting? Also reconsider renaming self.logfile_handlers to self.stream_handlers or similar.

@@ +242,5 @@
>              self.terminal_handler.addFilter(self.structured_filter)
>              self.root_logger.addHandler(self.terminal_handler)
> +        for handler in self.logfile_handlers:
> +            handler.addFilter(self.structured_filter)
> +            self.root_logger.addHandler(handler)

FWIW, I'm thinking of refactoring this module to expose both structured and unstructured streams instead of converting everything to structured. The reason behind this would be to differentiate between "logged messages are strings/unicode" vs "logged messages are bytes" which would work around the problems in bug 796875 and elsewhere. This code therefore may be short lived. But, if you commit it before I get around to refactoring how logging works, the burden is on me :)

I don't want to think "oh, I shouldn't be making changes to this module." Instead, I just want to communicate what I've been thinking about so you can have it in mind in case you touch this file again in the near future.

::: python/mozbuild/mozbuild/base.py
@@ +43,5 @@
>  
>          self._config_guess_output = None
>          self._make = None
>          self._topobjdir = topobjdir
> +        self._initialdir = os.getcwd()

This is already defined by the mach driver! The mach.base.CommandContext instance passed into MachCommandBase.__init__ has a `cwd` attribute which you should use. Change MachCommandBase.__init__ and MozbuildObject.__init__ to pass and store this.

@@ +57,5 @@
>          return self._topobjdir
>  
>      @property
> +    def absolute_topobjdir(self):
> +        return os.path.abspath(os.path.join(self._initialdir, self.topobjdir))

Please change topobjdir to store and return absolute paths instead. I want to see our build system start operating in terms of absolute paths as much as possible.
Attachment #680475 - Flags: review?(gps) → feedback+
Comments and two questions below.

(In reply to Gregory Szorc [:gps] from comment #10)
> If it's not too much effort, I'd appreciate if the python/{mach,mozbuild}
> changes were in a separate patch from the reftest running. You may also want
> to ask :Ms2ger for feedback (possibly review) of the reftest changes, just
> to be sure we have blessing from someone who interacts with them a lot.

By the reftest changes, do you mean the removal of the "\n" at the end of the "REFTEST-INFO" line?  (The more major reftest changes are in bug 809312.)

> @@ +28,5 @@
> >      """
> >  
> > +    def __init__(self, topsrcdir, settings, log_manager, topobjdir = None):
> > +        MozbuildObject.__init__(self, topsrcdir, settings, log_manager, topobjdir)
> > +        log_manager.enable_unstructured()
> 
> Hmm. We should probably add an empty method to the base class so children
> don't have to worry about the __init__ signature.
> 
> Perhaps we should move enable_unstructured() to run_reftest_test() for now.

I actually don't need that in there any longer, since I realised there was a log_manager property on self already (which I use later in run_reftest_test).  So I'll remove the __init__ method here altogether.

> @@ +102,5 @@
> > +        # we want mach to handle the logging output
> > +        automation.disableDefaultLoggingHandler()
> > +
> > +        # get the default arguments
> > +        options = parser.parse_args([])[0]
> 
> This is screaming for a better API. Probably outside the scope of this bug
> though.

Yeah, it's a bit crude.

> @@ +121,5 @@
> > +        try:
> > +            reftest.runTests(path, options)
> > +        finally:
> > +            self.log_manager.remove_logfile_handler(logHandler)
> > +            logFile.close()
> 
> Alternatively you could use a context manager for managing open files:
> 
> with open(logFilename, 'w') as logFile:
>     # Do stuff with file handle
> 
> # The file handle is closed when the context manager exits.

That looks nice.  (I'm not much of a Python programmer, so tips on idiomatic Python are appreciated.)  Using "with" there still doesn't let us remove the try..finally block though, since I still need to remove the handler afterwards.

> @@ +131,5 @@
> >          help='Reftest manifest file, or a directory in which to select '
> >               'reftest.list. If omitted, the entire test suite is executed.')
> > +    @CommandArgument('--setpref', default=None, action='append',
> > +        dest='extraPrefs', metavar='PREF=VALUE',
> > +        help='Defines an extra user preference.')
> 
> If we really wanted to, we could define a custom validator for this that
> verified values are of the expected 'key=value' form.

I guess so.  runreftest.py does this checking already though, so it seems a bit wasteful to do it here again.  Maybe once runreftest.py has had some cleanup we could avoid the duplicate arg parsing between it and mach_commands.py.

> @@ +153,2 @@
> >          reftest = self._spawn(ReftestRunner)
> > +        reftest.run_reftest_test(test_file, args, flavor)
> 
> run_reftest_test() could raise if the test is not found. This will result in
> mach printing the exception stack and claiming there is probably an error in
> the command handler.
> 
> We should probably reserve exceptions for truly exceptional cases or have
> mach catch non-fatal exceptions and convert them to non-0 exit codes. i.e.
> the @Command method should only propagate an exception if there is really an
> unexpected error (not due to bad arguments).

OK.  What is the preferred way of reporting problems then that I can replace all of the "throw Exception" lines in this file with?

> ::: layout/tools/reftest/runreftest.py
> @@ +127,5 @@
> >  
> >        # browser environment
> >        browserEnv = self.buildBrowserEnv(options, profileDir)
> >  
> > +      self.automation.log.info("REFTEST INFO | runreftest.py | Running tests: start.")
> 
> How much do you want to bet this breaks something? ;)

Could do. :)  (I thought the output looked a bit ugly with the blue timestamps on the left except on that extra newline.)  I'm trying just with this change here:

  https://tbpl.mozilla.org/?tree=Try&rev=96eb91b266d2

> ::: python/mach/mach/logging.py
> @@ +214,5 @@
> >  
> > +    def add_logfile_handler(self, fh, level=logging.INFO):
> > +        """Enable logging to the specified file handle."""
> > +
> > +        formatter = StructuredHumanFormatter(self.start_time)
> 
> This will print elapsed time to the files, just like stdout. It /might/ be a
> better idea to use some formatting of the actual log time (like what the
> standard file logger from Python does). This could be a follow-up bug.

Wallclock date/time?  To my eyes that might make the log file look a bit busy.  (I was even considering turning off the elapsed times for the log file.)

> @@ +242,5 @@
> >              self.terminal_handler.addFilter(self.structured_filter)
> >              self.root_logger.addHandler(self.terminal_handler)
> > +        for handler in self.logfile_handlers:
> > +            handler.addFilter(self.structured_filter)
> > +            self.root_logger.addHandler(handler)
> 
> FWIW, I'm thinking of refactoring this module to expose both structured and
> unstructured streams instead of converting everything to structured. The
> reason behind this would be to differentiate between "logged messages are
> strings/unicode" vs "logged messages are bytes" which would work around the
> problems in bug 796875 and elsewhere. This code therefore may be short
> lived. But, if you commit it before I get around to refactoring how logging
> works, the burden is on me :)
> 
> I don't want to think "oh, I shouldn't be making changes to this module."
> Instead, I just want to communicate what I've been thinking about so you can
> have it in mind in case you touch this file again in the near future.

Sure.
(In reply to Gregory Szorc [:gps] from comment #10)
> @@ +216,5 @@
> > +        """Enable logging to the specified file handle."""
> > +
> > +        formatter = StructuredHumanFormatter(self.start_time)
> > +
> > +        handler = logging.StreamHandler(stream=fh)
> 
> Perhaps rename the function to "add_stream_handler?" Maybe it should also
> take an controlling controlling the formatting?

I didn't follow this one.  What should it take to control the formatting?
(In reply to Cameron McCormack (:heycam) from comment #11)
> By the reftest changes, do you mean the removal of the "\n" at the end of
> the "REFTEST-INFO" line?  (The more major reftest changes are in bug 809312.)

Well, it's a good time as any to see if someone else has a better idea for how reftests should be executed. I'm not sure if Ms2ger or others have any ideas here.
 
> > @@ +121,5 @@
> > > +        try:
> > > +            reftest.runTests(path, options)
> > > +        finally:
> > > +            self.log_manager.remove_logfile_handler(logHandler)
> > > +            logFile.close()
> > 
> > Alternatively you could use a context manager for managing open files:
> > 
> > with open(logFilename, 'w') as logFile:
> >     # Do stuff with file handle
> > 
> > # The file handle is closed when the context manager exits.
> 
> That looks nice.  (I'm not much of a Python programmer, so tips on idiomatic
> Python are appreciated.)  Using "with" there still doesn't let us remove the
> try..finally block though, since I still need to remove the handler
> afterwards.

Python programmers generally prefer context managers ("with") to try..finally blocks, especially for the kinds of temporary actions like what "add_stream_handler" is doing.

It's possible to turn any regular Python callable into a context manager by using the contextlib.contextmanager decorator (http://docs.python.org/2/library/contextlib.html#contextlib.contextmanager). e.g.

from contextlib import contextmanager

@contextmanager
def add_stream_handler(logger, handler):
    logger.addHandler(handler)
    yield
    logger.removeHandler(handler)

...

with add_stream_handler(my_logger, my_handler):
    # Do stuff


You can also make any class or object a context manager by defining __enter__ and __leave__ methods on it. See also http://docs.python.org/2/reference/datamodel.html#with-statement-context-managers and http://docs.python.org/2/library/stdtypes.html#context-manager-types.

For the problem at hand, you may want to add a @contextmanager decorated method to the log manager class:

  @contextmanager
  def temp_add_handler(self, handler):
      self.root_logger.addHandler(handler)
      yield
      self.root_logger.removeHandler(handler)

...

with self.log_manager.temp_add_handler(my_handler):
    # Do stuff

> 
> > @@ +131,5 @@
> > >          help='Reftest manifest file, or a directory in which to select '
> > >               'reftest.list. If omitted, the entire test suite is executed.')
> > > +    @CommandArgument('--setpref', default=None, action='append',
> > > +        dest='extraPrefs', metavar='PREF=VALUE',
> > > +        help='Defines an extra user preference.')
> > 
> > If we really wanted to, we could define a custom validator for this that
> > verified values are of the expected 'key=value' form.
> 
> I guess so.  runreftest.py does this checking already though, so it seems a
> bit wasteful to do it here again.  Maybe once runreftest.py has had some
> cleanup we could avoid the duplicate arg parsing between it and
> mach_commands.py.

I'm just saying it's possible. I wouldn't worry about it too much right now.

> 
> > @@ +153,2 @@
> > >          reftest = self._spawn(ReftestRunner)
> > > +        reftest.run_reftest_test(test_file, args, flavor)
> > 
> > run_reftest_test() could raise if the test is not found. This will result in
> > mach printing the exception stack and claiming there is probably an error in
> > the command handler.
> > 
> > We should probably reserve exceptions for truly exceptional cases or have
> > mach catch non-fatal exceptions and convert them to non-0 exit codes. i.e.
> > the @Command method should only propagate an exception if there is really an
> > unexpected error (not due to bad arguments).
> 
> OK.  What is the preferred way of reporting problems then that I can replace
> all of the "throw Exception" lines in this file with?

I may have confused you with my previous answer. I made some assumptions about your Python knowledge that you are probably not aware of.

Generally speaking, Python encourages exceptions. Exceptions in Python are pretty cheap (unlike some languages), so it's common to see patterns like:

try:
    bar = foo['bar']
except KeyError:
    bar = None

(Although this example is a bit contrived because a real Python programmer would write this as "bar = foo.get('bar', None)")

Anyway, my point is that exceptions abound in Python.

All userland exceptions derive from the base Exception class (which itself derives from BaseException - see http://docs.python.org/2/library/exceptions.html). It is generally discouraged to raise an Exception directly. Instead, you are encouraged to define your own Exception-derived class for representing specific errors. In practice, laziness abounds and people (myself included) raise Exception instances all the time.

Along that vein, it is discouraged to catch the Exception class. The reason being that it is often too general. The purists will say that the only time you should have an "except Exception" is in the main() handler of your application.

Now, how is this relevant to mach commands?

On one hand, you can think of @Command decorated methods as the main() routine of the application. They should convert exceptions to exit codes. On the other hand, it's nice to be able to distinguish between an exception as a result of e.g. bad input (should be converted to an exit code with no stack trace) and an exception as a result of a code bug (should be converted to a stack trace to aid debugging).

So, waiving my mystical wand, what we want to strive for are two "branches" of Exception-derived classes: 1 for known failures (bad input, test failures, invalid tree state, etc) and 1 for everything else (bugs). @Command methods themselves should do an explicit "except" on the former and let everything else propagate through to the "except Exception" inside the mach driver.

Practically speaking, it will be hard to achieve this utopia because so many systems today throw Exception. The workaround is to install fine-grained try..except blocks which convert all Exception instances to something like a TestRunFailure Exception-derived class and have the @Command catch just TestRunFailure. In other words, from your mach command handler:

class TestRunFailure(Exception):
    pass

@Command(...)
def command(self):
    try:
        ...
        try:
            CallIntoSomeOtherModuleToRunTests()
        except Exception as e:
            raise TestRunFailure(e)

    except TestRunFailure as trf:
        # Do something with the test run failure.
        return 1

    # Let Exception bubble up to mach driver so it can format a stack.

> > ::: layout/tools/reftest/runreftest.py
> > @@ +127,5 @@
> > >  
> > >        # browser environment
> > >        browserEnv = self.buildBrowserEnv(options, profileDir)
> > >  
> > > +      self.automation.log.info("REFTEST INFO | runreftest.py | Running tests: start.")
> > 
> > How much do you want to bet this breaks something? ;)
> 
> Could do. :)  (I thought the output looked a bit ugly with the blue
> timestamps on the left except on that extra newline.)  I'm trying just with
> this change here:
> 
>   https://tbpl.mozilla.org/?tree=Try&rev=96eb91b266d2

I would accept a patch to the mach logging manager which toggled display of times. I think displaying times does not always make sense.

> 
> > ::: python/mach/mach/logging.py
> > @@ +214,5 @@
> > >  
> > > +    def add_logfile_handler(self, fh, level=logging.INFO):
> > > +        """Enable logging to the specified file handle."""
> > > +
> > > +        formatter = StructuredHumanFormatter(self.start_time)
> > 
> > This will print elapsed time to the files, just like stdout. It /might/ be a
> > better idea to use some formatting of the actual log time (like what the
> > standard file logger from Python does). This could be a follow-up bug.
> 
> Wallclock date/time?  To my eyes that might make the log file look a bit
> busy.  (I was even considering turning off the elapsed times for the log
> file.)

It uses whatever the StructuredHumanFormatter is configured to print. By default it is elapsed time since program start. Alternatively it can be time since last event.

(In reply to Cameron McCormack (:heycam) from comment #12)
> (In reply to Gregory Szorc [:gps] from comment #10)
> > @@ +216,5 @@
> > > +        """Enable logging to the specified file handle."""
> > > +
> > > +        formatter = StructuredHumanFormatter(self.start_time)
> > > +
> > > +        handler = logging.StreamHandler(stream=fh)
> > 
> > Perhaps rename the function to "add_stream_handler?" Maybe it should also
> > take an controlling controlling the formatting?
> 
> I didn't follow this one.  What should it take to control the formatting?

Ideally it would easily allow:

1) An instance of a LoggingFormatter to use
2) ability to use StructuredHumanFormatter
3) ability to use the JSON formatter

Perhaps it should take a "formatter" named argument. If isinstance(formatter, LoggingFormatter), that is used. Else if it is a specially-handled string, it instances the proper class and uses that.
> 
> (Although this example is a bit contrived because a real Python programmer would write this as "bar = foo.get('bar', None)")

<pedantic>itym `bar = foo.get('bar')` since 'None' is implied</pedantic>
Product: Core → Firefox Build System
I'm not sure why this stalled, but I'm pretty sure things have moved on in the last 6 years.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: