1310868 - Automation Error: mozprocess timed out after 2400 seconds running ['python2.7', 'mach', '--log-no-times', 'build', '-v'] if configure fails

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Gregory Szorc [:gps]]

One of glandium's pushes triggered a 2400 second timeout in automation:

[task 2016-10-17T22:14:42.657729Z] 22:14:42     INFO -  Traceback (most recent call last):
[task 2016-10-17T22:14:42.657919Z] 22:14:42     INFO -    File "/home/worker/workspace/build/src/configure.py", line 107, in <module>
[task 2016-10-17T22:14:42.658070Z] 22:14:42     INFO -      sys.exit(main(sys.argv))
[task 2016-10-17T22:14:42.658256Z] 22:14:42     INFO -    File "/home/worker/workspace/build/src/configure.py", line 26, in main
[task 2016-10-17T22:14:42.658412Z] 22:14:42     INFO -      sandbox.run(os.path.join(os.path.dirname(__file__), 'moz.configure'))
[task 2016-10-17T22:14:42.658585Z] 22:14:42     INFO -    File "/home/worker/workspace/build/src/python/mozbuild/mozbuild/configure/__init__.py", line 341, in run
[task 2016-10-17T22:14:42.658715Z] 22:14:42     INFO -      self._value_for(option)
[task 2016-10-17T22:14:42.658895Z] 22:14:42     INFO -    File "/home/worker/workspace/build/src/python/mozbuild/mozbuild/configure/__init__.py", line 406, in _value_for
[task 2016-10-17T22:14:42.659050Z] 22:14:42     INFO -      return self._value_for_option(obj)
[task 2016-10-17T22:14:42.659214Z] 22:14:42     INFO -    File "/home/worker/workspace/build/src/python/mozbuild/mozbuild/util.py", line 924, in method_call
[task 2016-10-17T22:14:42.659365Z] 22:14:42     INFO -      cache[args] = self.func(instance, *args)
[task 2016-10-17T22:14:42.659550Z] 22:14:42     INFO -    File "/home/worker/workspace/build/src/python/mozbuild/mozbuild/configure/__init__.py", line 479, in _value_for_option
[task 2016-10-17T22:14:42.659704Z] 22:14:42     INFO -      '%s is not available in this configuration' % option_string)
[task 2016-10-17T22:14:42.659853Z] 22:14:42     INFO -  mozbuild.configure.options.InvalidOptionError: MOZ_PGO= is not available in this configuration
[task 2016-10-17T22:14:42.674491Z] 22:14:42     INFO -  *** Fix above errors and then restart with\
[task 2016-10-17T22:14:42.674677Z] 22:14:42     INFO -                 "/usr/bin/gmake -f client.mk build"
[task 2016-10-17T22:14:42.674838Z] 22:14:42     INFO -  gmake: *** [configure] Error 1
[task 2016-10-17T22:54:42.775419Z] 22:54:42     INFO - Automation Error: mozprocess timed out after 2400 seconds running ['python2.7', 'mach', '--log-no-times', 'build', '-v']
[task 2016-10-17T22:54:42.822098Z] 22:54:42    ERROR - timed out after 2400 seconds of no output
[task 2016-10-17T22:54:42.822354Z] 22:54:42    ERROR - Return code: -9
[task 2016-10-17T22:54:42.822626Z] 22:54:42  WARNING - setting return code to 2
[task 2016-10-17T22:54:42.822837Z] 22:54:42    FATAL - 'mach build' did not run successfully. Please check log for errors.
[task 2016-10-17T22:54:42.823111Z] 22:54:42    FATAL - Running post_fatal callback...

I was able to reproduce locally in Docker. The problem is related to the resource monitor collection process not being finalized.

Patch forthcoming...

Comment 1

[Gregory Szorc [:gps]]

Attachment: Bug 1310868 - Tie resource collection to lifetime of context manager;

Both BuildMonitor and BuildOutputManager are doing similar things and
wrapping the build with forms of monitoring. These classes are only
used in the `mach build` command.

Since the BuildOutputManager takes an instance of BuildMonitor as an
argument and since BuildOutputManager behaves as a context manager,
it makes sense for BuildOutputManager to control the lifetime of
BuildMonitor's collection.

So, we teach BuildOutputManager's context manager to start the
BuildMonitor and ensure its resource collection is stopped when it
exits.

Review commit: https://reviewboard.mozilla.org/r/86522/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/86522/

Comment 2

[Mike Hommey [:glandium]]

Comment on attachment 8801935 [details]
Bug 1310868 - Tie resource collection to lifetime of context manager;

https://reviewboard.mozilla.org/r/86522/#review86452

::: python/mozbuild/mozbuild/controller/building.py:249
(Diff revision 1)
>  
> +        self._resources_started = False
> +
> +    def finish(self, record_usage=True):
> +        """Record the end of the build."""
> +        self.end_time = time.time()

I guess there's not going to be enough stuff happening between stop_resource_recording called from __exit__ and finish here to really matter, but there's a theoretical concern.

Comment 3

[Mike Hommey [:glandium]]

Comment on attachment 8801935 [details]
Bug 1310868 - Tie resource collection to lifetime of context manager;

https://reviewboard.mozilla.org/r/86522/#review86454

Comment 4

[Gregory Szorc [:gps]]

Comment on attachment 8801935 [details]
Bug 1310868 - Tie resource collection to lifetime of context manager;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/86522/diff/1-2/

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4bb2763b8710
Tie resource collection to lifetime of context manager; r=glandium

Comment 6

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4bb2763b8710