795427 - More useful error messages

Status: RESOLVED FIXED

(Firefox Build System :: Mach Core, enhancement)

Description

[Gregory Szorc [:gps]]

In the case of exception in mach, error messages are not that useful:

./mach build
No handlers could be found for logger "pymake.data"
0.18 /usr/bin/make -f client.mk -j8 -s
0.25 Adding client.mk options from /home/gps/src/mozilla-central/.mozconfig:
0.25     MOZ_OBJDIR=$(TOPSRCDIR)/objdir
0.25     MOZ_MAKE_FLAGS=-j10 -s -w
0.45 TEST-PASS | check-sync-dirs.py | /home/gps/src/mozilla-central/js/src/config <= /home/gps/src/mozilla-central/config
0.46 make[2]: Entering directory `/home/gps/src/mozilla-central/objdir'
0.46 make[2]: warning: -jN forced in submake: disabling jobserver mode.
1.50 make[3]: Entering directory `/home/gps/src/mozilla-central/objdir'
1.62 tier_base:  config build probes mfbt  memory/mozjemalloc memory/build modules/zlib mozglue memory/mozalloc
1.63 make[4]: Entering directory `/home/gps/src/mozilla-central/objdir'
1.75 export_tier_base
1.86 make[5]: Entering directory `/home/gps/src/mozilla-central/objdir/config'
1.94 make[5]: Leaving directory `/home/gps/src/mozilla-central/objdir/config'
^CTraceback (most recent call last):
  File "./mach", line 48, in <module>
    mach.run(sys.argv[1:])
  File "/home/gps/src/mozilla-central/python/mach/mach/main.py", line 105, in run
    self._run(argv)
  File "/home/gps/src/mozilla-central/python/mach/mach/main.py", line 161, in _run
    fn(**stripped)
  File "/home/gps/src/mozilla-central/python/mach/mach/build.py", line 45, in build
    log=False, print_directory=False)
  File "/home/gps/src/mozilla-central/python/mozbuild/mozbuild/base.py", line 256, in _run_make
    fn(**params)
  File "/home/gps/src/mozilla-central/python/mozbuild/mozbuild/base.py", line 279, in _run_command_in_srcdir
    self._run_command(cwd=self.topsrcdir, **args)
  File "/home/gps/src/mozilla-central/python/mozbuild/mozbuild/base.py", line 333, in _run_command
    status = p.wait()
  File "/home/gps/src/mozilla-central/testing/mozbase/mozprocess/mozprocess/processhandler.py", line 717, in wait
    self.outThread.join(timeout=1)
  File "/usr/lib/python2.7/threading.py", line 674, in join
    self.__block.wait(delay)
  File "/usr/lib/python2.7/threading.py", line 262, in wait
    _sleep(delay)
KeyboardInterrupt

So many lines of useless stack traces just for C-c. IMO we should swallow the stack trace on C-c. Now, this may throw away useful information for debugging purposes (you may want to see where a process stalled). A less drastic solution is to cut off the stack below _run_command() in case of KeyboardInterrupt because, well, I see extremely few scenarios where that is useful.

Additionally, if we do have a legitimate Python exception (not KeyboardInterrupt), I think mach should sanitize the output a bit.

If the stack is inside mach itself (not mozbuild or elsewhere) or at most 1 frame into a call, it is almost certainly a mach bug. We can print a link to the Bugzilla component for mach with instructions to paste the output, etc.

If the stack is inside mozbuild/elsewhere, it's likely not a mach bug and we can print a link to the Core :: Build Config or other Bugzilla component.

In all scenarios, we can save ~6 lines from the output by not printing frames below the fn(**stripped) call. I can think of no scenarios where these frames would be important (unless you were a mach core developer - and for that we can add an environment variable backdoor or something).

As part of this, I may just create a mapping somewhere between Python package/module names and Bugzilla components. We could then have a guess_bugzilla_component_for_stack(exc) function that could be leveraged for more effective bug filing. Is that a crazy good idea or crazy bad idea?

Comment 1

[Jeff Hammel]

I can't speak for everything, but catching KeyboardInterupt at some top-level and exiting (with some code) sounds good to me

Comment 2

[Gregory Szorc [:gps]]

Attachment: Catch KeyboardInterrupt and exit somewhat quietly, v1

This makes SIGINT/C-c much quieter:

> 3.48 Making all in include
> 3.50 Making all in testsuite
> 3.50 Making all in man
> 4.39 Generating LALR tables
> ^Cmach interrupted by signal or user action. Stopping.

In the case of hung processes, one can argue that a stack might be useful. We could certainly go with first C-c prints stack, second exits. Or, we could always print an abridged stack on C-c. However, "abridged" is an interesting problem to define. I kinda like the simplicity of this patch, especially for non-advanced solutions.

If we really care about stacks on hung processes, perhaps we could install a signal handler for SIGUSR1 and use that to print stacks. Although, I'm not sure if you can get at the proper stack from a signal handler in Python. Things to explore...

Next patch will contain crazy stack walking code. Prepare yourselves!

Comment 3

[Gregory Szorc [:gps]]

Attachment: Part 1: Proper exit codes from mach, v1

Mach's run() method now returns an integer exit code instead of nothing.

Comment 4

[Gregory Szorc [:gps]]

Attachment: Part 2: Catch KeyboardInterrupt, v2

Same patch as before. Now using proper return code API and not calling sys.exit() directly because mach is a library, not a script.

Comment 5

[Jeff Hammel]

Comment on attachment 668110 [details] [diff] [review]
Part 1: Proper exit codes from mach, v1

+        if not result:
+            result = 0
+        else:
+            assert isinstance(result, int)

I'd prefer not to have the 'else' clause and just de-indent the assertion

Other than that, looks fine

Comment 6

[Jeff Hammel]

Comment on attachment 668112 [details] [diff] [review]
Part 2: Catch KeyboardInterrupt, v2



lgtm

Comment 7

[Gregory Szorc [:gps]]

Parts 1 and 2:

https://hg.mozilla.org/mozilla-central/rev/a7619ca2db7e
https://hg.mozilla.org/mozilla-central/rev/c24a0fd08031

I still have a part 3 I'm working on.

Comment 8

[Gregory Szorc [:gps]]

Attachment: Part 3: More friendly exception messages, v1

I implemented a lot of what I talked about in the original comment. We now differentiate between exceptions:

1) in mach itself
2) in a mach command module
3) in something called by a mach command module

Each case gets a slightly different error message. Where it makes sense, we truncate the displayed stack to eliminate irrelevant details from mach itself.

Included with this patch are some unit tests! I could have monkeypatched sys.{stdin,stdout,stderr} from the test runner. But, I decided that making an API for mach where you could optionally pass in the file objects would be easier in the long run.

Comment 9

[Jeff Hammel]

Comment on attachment 668690 [details] [diff] [review]
Part 3: More friendly exception messages, v1

+Please consider filing a bug against mach by going to the URL:
+
+    https://bugzilla.mozilla.org/enter_bug.cgi?product=Core&component=mach
+

Once we have bugzilla goodness in the tree, it would be nice if we changed this to (optionally) post a bug (or comment to an existing bug) automagically.

+        stdin = sys.stdin if stdin is None else stdin
+        stdout = sys.stdout if stdout is None else stdout
+        stderr = sys.stderr if stderr is None else stderr
+
         orig_stdin = sys.stdin
         orig_stdout = sys.stdout
         orig_stderr = sys.stderr
 
+        sys.stdin = stdin
+        sys.stdout = stdout
+        sys.stderr = stderr
...etc

Too bad we can't require python 3 where locals() is writable....this entire function could be much simpler :/

-        result = fn(**stripped)
+        try:
+            result = fn(**stripped)
 
-        if not result:
-            result = 0
+            if not result:
+                result = 0
 
-        assert isinstance(result, int)
+            assert isinstance(result, int)
 
-        return result
+            return result
+        except KeyboardInterrupt as ki:
+            raise ki
+        except Exception as e:

Is something funky with indentation here?

diff --git a/python/mach/mach/test/common2.py b/python/mach/mach/test/common2.py
new file mode 100644
--- /dev/null
+++ b/python/mach/mach/test/common2.py
@@ -0,0 +1,9 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+def throw_deep(message):
+    return throw_real(message)
+
+def throw_real(message):
+    raise Exception(message)

Why have a separate module/file for this?

Comment 10

[Gregory Szorc [:gps]]

(In reply to Jeff Hammel [:jhammel] from comment #9)
> -        result = fn(**stripped)
> +        try:
> +            result = fn(**stripped)
>  
> -        if not result:
> -            result = 0
> +            if not result:
> +                result = 0
>  
> -        assert isinstance(result, int)
> +            assert isinstance(result, int)
>  
> -        return result
> +            return result
> +        except KeyboardInterrupt as ki:
> +            raise ki
> +        except Exception as e:
> 
> Is something funky with indentation here?

I added a try so all the indentation changed.

> diff --git a/python/mach/mach/test/common2.py
> b/python/mach/mach/test/common2.py
> new file mode 100644
> --- /dev/null
> +++ b/python/mach/mach/test/common2.py
> @@ -0,0 +1,9 @@
> +# This Source Code Form is subject to the terms of the Mozilla Public
> +# License, v. 2.0. If a copy of the MPL was not distributed with this
> +# file, You can obtain one at http://mozilla.org/MPL/2.0/.
> +
> +def throw_deep(message):
> +    return throw_real(message)
> +
> +def throw_real(message):
> +    raise Exception(message)
> 
> Why have a separate module/file for this?

This is to trigger the difference between COMMAND_ERROR and MODULE_ERROR. I'll add a comment to the file.

Comment 11

[Jeff Hammel]

(In reply to Gregory Szorc [:gps] from comment #10)
> (In reply to Jeff Hammel [:jhammel] from comment #9)
> > -        result = fn(**stripped)
> > +        try:
> > +            result = fn(**stripped)
> >  
> > -        if not result:
> > -            result = 0
> > +            if not result:
> > +                result = 0
> >  
> > -        assert isinstance(result, int)
> > +            assert isinstance(result, int)
> >  
> > -        return result
> > +            return result
> > +        except KeyboardInterrupt as ki:
> > +            raise ki
> > +        except Exception as e:
> > 
> > Is something funky with indentation here?
> 
> I added a try so all the indentation changed.

Ah, I just misread it.  Thanks.

> > diff --git a/python/mach/mach/test/common2.py
> > b/python/mach/mach/test/common2.py
> > new file mode 100644
> > --- /dev/null
> > +++ b/python/mach/mach/test/common2.py
> > @@ -0,0 +1,9 @@
> > +# This Source Code Form is subject to the terms of the Mozilla Public
> > +# License, v. 2.0. If a copy of the MPL was not distributed with this
> > +# file, You can obtain one at http://mozilla.org/MPL/2.0/.
> > +
> > +def throw_deep(message):
> > +    return throw_real(message)
> > +
> > +def throw_real(message):
> > +    raise Exception(message)
> > 
> > Why have a separate module/file for this?
> 
> This is to trigger the difference between COMMAND_ERROR and MODULE_ERROR.
> I'll add a comment to the file.

Please do.  I strongly dislike module sequels

Comment 12

[Gregory Szorc [:gps]]

https://hg.mozilla.org/mozilla-central/rev/623863bc7f79