1256300 - Intermittent Android "command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py'..."

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown]]

As reported in bug 1051908 for the last 2 weeks. Maybe a hang in tooltool.py?

Comment 1

[Geoff Brown [:gbrown]]

https://bugzilla.mozilla.org/show_bug.cgi?id=1237706#c41

Comment 2

[Intermittent Failures Robot]

5 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 2
* mozilla-central: 1
* mozilla-aurora: 1
* fx-team: 1

Platform breakdown:
* android-4-3-armv7-api15: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256300&startday=2016-03-14&endday=2016-03-20&tree=all

Comment 3

[Intermittent Failures Robot]

11 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 7
* try: 2
* mozilla-aurora: 1
* fx-team: 1

Platform breakdown:
* android-4-3-armv7-api15: 11

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256300&startday=2016-03-21&endday=2016-03-27&tree=all

Comment 4

[Intermittent Failures Robot]

6 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 2
* mozilla-central: 2
* try: 1
* mozilla-aurora: 1

Platform breakdown:
* android-4-3-armv7-api15: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256300&startday=2016-04-25&endday=2016-05-01&tree=all

Comment 5

[Geoff Brown [:gbrown]]

Attachment: use output_timeout when running tooltool

There is variability in the 2400 second timeout logs collected in this bug, so there may be multiple issues at play here. A few logs (the minority), like https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=3785227#L848, look like:

 04:14:56     INFO - Copy/paste: /tools/tooltool.py --url https://api.pub.build.mozilla.org/tooltool/ --authentication-file /builds/relengapi.tok fetch -m /builds/slave/test/build/tooltool.tt -o -c /builds/tooltool_cache
 04:14:56     INFO -  INFO - File android-sdk_r24.0.2-linux.tgz not present in local cache folder /builds/tooltool_cache
 04:14:56     INFO -  INFO - Attempting to fetch from 'https://api.pub.build.mozilla.org/tooltool/'...
 
 command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm_4_3.py', '--test-suite', 'mochitest-1', '--blob-upload-branch', 'mozilla-central', '--download-symbols', 'ondemand'], attempting to kill
 process killed by signal 9
 program finished with exit code -1
 elapsedTime=2417.380167

I think tooltool might be hung. At any rate, it seems possible that tooltool could hang, or download very, very slowly sometimes. I'd prefer to see these cases fail with a specific mozharness timeout rather than wait for the buildbot timeout.

A random sampling of test logs suggest tooltool completes in less than 30 seconds for most of our current downloads, so this 600 second output timeout seems reasonably safe.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=610594efd242d3f5534534acd33886bc544ec48a suggests this does no harm.


I intend to leave-open for follow-up on other timeout causes.

Comment 6

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b9079ed81182

Comment 7

[Geoff Brown [:gbrown]]

The other, more common, log variation is:

 09:38:17     INFO - Writing buildbot properties ['build_url'] to /builds/slave/test/properties/build_url
 09:38:17     INFO - Writing to file /builds/slave/test/properties/build_url
 09:38:17     INFO - Contents:
 09:38:17     INFO -  build_url:https://queue.taskcluster.net/v1/task/b0gIAvQVTUuQuR06YXr4zw/artifacts/public/build/fennec-49.0a1.en-US.android-arm.apk
 
 command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm_4_3.py', '--test-suite', 'mochitest-16', '--blob-upload-branch', 'mozilla-inbound', '--download-symbols', 'ondemand'], attempting to kill
 process killed by signal 9
 program finished with exit code -1
 elapsedTime=2449.852416

The final "build_url:" log comes from:

  _download_and_extract
    _download_installer
      set_buildbot_properties
        dump_buildbot_properties
          write_to_file

Note that this variation occurs for both opt and debug jobs. For debug, the next non-trivial operation is to download symbols; for opt, the next non-trivial operation is downloading host utilities.

The first, next, missing log statement is the "proxxy config: ..." reported by get_proxies_for_url.

Comment 8

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/b9079ed81182

Comment 9

[Geoff Brown [:gbrown]]

Attachment: add timeout to urllib2.urlopen call

This is a speculative fix for the log variation shown in Comment 7. A hang in urllib2.urlopen() here would be consistent with those logs for both opt and debug cases.

Most (all?) other urllib2.urlopen calls in mozharness use a timeout parameter, typically between 10 and 60 seconds. In this case, additional logging in treeherder logs show urlopen taking approximately 20 seconds in the majority of cases - https://treeherder.mozilla.org/#/jobs?repo=try&revision=9087cd124b23 - so I've opted for the longer 120 second timeout.

On timeout, I see urllib2.urlopen throwing an SSLError, which is a socket.error, but there may be some variation across urllib2 implementations, and I note other mozharness code handling socket.timeout also, so I've included that as well.

Comment 10

[Jordan Lund (:jlund)]

Comment on attachment 8751366 [details] [diff] [review]
add timeout to urllib2.urlopen call

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

looks good to me. just one comment about proposing to fold up exception blocks

::: testing/mozharness/mozharness/mozilla/testing/testbase.py
@@ +201,5 @@
>              except urllib2.URLError:
>                  self.warning("Can't figure out symbols_url from installer_url: %s!" %
>                               self.installer_url)
> +            except socket.timeout, e:
> +                self.warning("Can't figure out symbols_url from installer_url: %s - %s" %

so exception message and error_level is the same each time? I wonder if we should fold up all of these into one except block. and also use self.exception[1] that will grab/log traceback for us.

e.g.

except (urllib2.URLError, socket.error, socket.timeout):
    self.exception("Can't figure out symbols_url from installer_url: %s!" % self.installer_url, level=WARNING)


[1] https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/mozharness/base/log.py#157

Comment 11

[Geoff Brown [:gbrown]]

Great idea - thanks jlund!

Comment 12

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/bf088a188e27

Comment 13

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/537ad1398c52

Comment 14

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/bf088a188e27
https://hg.mozilla.org/mozilla-central/rev/537ad1398c52

Comment 15

[Intermittent Failures Robot]

7 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 3
* mozilla-aurora: 2
* mozilla-central: 1
* fx-team: 1

Platform breakdown:
* android-4-3-armv7-api15: 6
* android-4-2-x86: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256300&startday=2016-05-10&endday=2016-05-16&tree=all

Comment 16

[Geoff Brown [:gbrown]]

Failures continue on mozilla-aurora (48). It looks like this has never been reported on 47; I wonder why?

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/53d94e77fd50