949740 - Intermittent Android x86 We have not been able to establish a telnet connection with the emulator

Status: RESOLVED FIXED

(Infrastructure & Operations Graveyard :: CIDuty, task)

Description

[Geoff Brown [:gbrown]]

Consider: 

https://tbpl.mozilla.org/?tree=Cedar&showall=1&rev=5dc615915eb6

There are 3 instances of this error in 22 runs of S4.

We can probably live with that, but I wonder if we could do better.

Comment 1

[Geoff Brown [:gbrown]]

15:15:30     INFO - #####
15:15:30     INFO - ##### Running start-emulators step.
15:15:30     INFO - #####
15:15:30     INFO - Running pre-action listener: _resource_record_pre_action
15:15:30     INFO - Running main action method: start_emulators
15:15:30     INFO - Let's kill every process called compiz
15:15:30     INFO - Killing pid 2393.
15:15:30     INFO - Created temp file /tmp/tmpzo7j_0.
15:15:30     INFO - Trying to start the emulator with this command: emulator -avd test-1 -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -port 5554 -qemu -m 1024 -enable-kvm
15:15:30     INFO - Sleeping 10 seconds
15:15:40     INFO -   Attempt #1 to redirect ports: (5554, 20701, 20700)
15:15:40     INFO - Trying again after exception: [Errno 111] Connection refused
15:15:40     INFO - Sleeping 30 seconds
15:16:10     INFO -   Attempt #2 to redirect ports: (5554, 20701, 20700)
15:16:10     INFO - Trying again after exception: [Errno 111] Connection refused
15:16:10     INFO - Sleeping 30 seconds
15:16:40     INFO -   Attempt #3 to redirect ports: (5554, 20701, 20700)
15:16:40     INFO - Trying again after exception: [Errno 111] Connection refused
15:16:40     INFO - Sleeping 30 seconds
15:17:10     INFO -   Attempt #4 to redirect ports: (5554, 20701, 20700)
15:17:10     INFO - Trying again after exception: [Errno 111] Connection refused
15:17:10     INFO - Sleeping 30 seconds
15:17:40     INFO -   Attempt #5 to redirect ports: (5554, 20701, 20700)
15:17:40     INFO - Trying again after exception: [Errno 111] Connection refused
15:17:40    FATAL - We have not been able to establish a telnet connection with the emulator
15:17:40    FATAL - Running post_fatal callback...
15:17:40     INFO - Let's kill every process called emulator64-x86
15:17:40     INFO - Killing pid 2718.
15:17:40    FATAL - Exiting -1

Comment 2

[Geoff Brown [:gbrown]]

In comparison, this seems typical on success:

09:23:19     INFO - #####
09:23:19     INFO - ##### Running start-emulators step.
09:23:19     INFO - #####
09:23:19     INFO - Running pre-action listener: _resource_record_pre_action
09:23:19     INFO - Running main action method: start_emulators
09:23:19     INFO - Let's kill every process called compiz
09:23:19     INFO - Killing pid 2415.
09:23:19     INFO - Created temp file /tmp/tmpgzGPNu.
09:23:19     INFO - Trying to start the emulator with this command: emulator -avd test-1 -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -port 5554 -qemu -m 1024 -enable-kvm
09:23:19     INFO - Sleeping 10 seconds
09:23:29     INFO -   Attempt #1 to redirect ports: (5554, 20701, 20700)
09:23:29     INFO - test-1: 5554; sut port: 20701/20700
09:23:29     INFO - Created temp file /tmp/tmpXjYJmL.
09:23:29     INFO - Trying to start the emulator with this command: emulator -avd test-2 -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -port 5556 -qemu -m 1024 -enable-kvm
09:23:29     INFO - Sleeping 10 seconds
09:23:39     INFO -   Attempt #1 to redirect ports: (5556, 20703, 20702)
09:23:39     INFO - test-2: 5556; sut port: 20703/20702
09:23:39     INFO - Created temp file /tmp/tmpqkRu5X.
09:23:39     INFO - Trying to start the emulator with this command: emulator -avd test-3 -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -port 5558 -qemu -m 1024 -enable-kvm
09:23:39     INFO - Sleeping 10 seconds
09:23:49     INFO -   Attempt #1 to redirect ports: (5558, 20705, 20704)
09:23:49     INFO - test-3: 5558; sut port: 20705/20704
09:23:49     INFO - Created temp file /tmp/tmp49YwFe.
09:23:49     INFO - Trying to start the emulator with this command: emulator -avd test-4 -debug init,console,gles,memcheck,adbserver,adbclient,adb,avd_config,socket -port 5560 -qemu -m 1024 -enable-kvm
09:23:49     INFO - Sleeping 10 seconds
09:23:59     INFO -   Attempt #1 to redirect ports: (5560, 20707, 20706)
09:23:59     INFO - test-4: 5560; sut port: 20707/20706

Comment 3

[Geoff Brown [:gbrown]]

Attachment: (1) dump emulator log if _redirectSUT fails

I wonder if the emulator log would show anything interesting in this case: let's dump it.

Comment 4

[Geoff Brown [:gbrown]]

https://hg.mozilla.org/build/mozharness/rev/563ce5d8cef5

Comment 5

[Geoff Brown [:gbrown]]

Attachment: (2) fix emulator logging if redirect fails

That first patch didn't quite work: https://tbpl.mozilla.org/php/getParsedLog.php?id=32032518&tree=Cedar&full=1#error1

That's because emulator_procs has not been populated yet. A little re-arranging of the logic should get this working.

Comment 6

[Geoff Brown [:gbrown]]

Attachment: (2) fix emulator logging if redirect fails

oops - attached the wrong patch

Comment 7

[Geoff Brown [:gbrown]]

(2) https://hg.mozilla.org/build/mozharness/rev/b74d08c2bc86

Comment 8

[Geoff Brown [:gbrown]]

That worked:

https://tbpl.mozilla.org/php/getParsedLog.php?id=32040209&tree=Cedar&full=1#error0

Comment 9

[Geoff Brown [:gbrown]]

The failed emulator log (comment 8) shows:

...                 ioctl(KVM_CREATE_VM) failed: Interrupted system call
12:32:10     INFO - ko:failed to initialize KVM

Comment 10

[Geoff Brown [:gbrown]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=32051383&tree=Cedar

(looks the same as Comment 8).

Comment 11

[John Hopkins (:jhopkins)]

in production

Comment 12

[Geoff Brown [:gbrown]]

I checked the permissions on /dev/kvm; for both the passing and failing cases, permissions are the same:

crw-rw----+ 1 root kvm 10, 232 Dec 18 14:05 /dev/kvm

Comment 13

[Geoff Brown [:gbrown]]

Delaying the launch of the emulators can virtually eliminate this error. Normally I am seeing the emulator launch fail about 1 time in 10. If we sleep for 3 minutes before trying to launch the emulators, this still happens, but only ~1 time in 100. If the sleep is reduced to 1 minute, I see about 1 failure in 50. Below 1 minute, failures increase significantly.

Comment 14

[Geoff Brown [:gbrown]]

In light of comment 13, I thought I would try retrying: If an emulator is launched but cannot be contacted for port redirection, kill any running emulators, wait for a while, and then try launching the emulators again. A pause of 30 seconds between retries and up to 3 retries seems to effectively resolve this bug.

Here is an example where we fail (with the ioctl(KVM_CREATE_VM) message), retry, and succeed:

https://tbpl.mozilla.org/php/getParsedLog.php?id=32254143&tree=Ash&full=1

Comment 15

[Geoff Brown [:gbrown]]

Attachment: (3) retry as described in Comment 14

Comment 16

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=32439677&tree=Cedar
Android 4.2 x86 Emulator cedar opt test androidx86-set-3 on 2013-12-30 22:56:00
revision: 1802ef305927
slave: talos-linux64-ix-021

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 17

[Armen [:armenzg]]

Comment on attachment 8350759 [details] [diff] [review]
(3) retry as described in Comment 14

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

::: scripts/android_emulator_unittest.py
@@ +471,5 @@
>          self._kill_processes("compiz")
> +
> +        attempts = 0
> +        redirect_failed = True
> +        while attempts < 3 and redirect_failed:

Mind adding a comment on this while block to help future readers know what we're doing.

Comment 18

[Geoff Brown [:gbrown]]

With block comment added:

https://hg.mozilla.org/build/mozharness/rev/7de07ccc4e04

Comment 19

[Geoff Brown [:gbrown]]

Patch (3) is an effective solution: https://tbpl.mozilla.org/?tree=Cedar&showall=1&rev=36c8eeaf1589

Comment 20

[Armen [:armenzg]]

Merged mozharness.

Comment 21

[Legacy TBPL/Treeherder Robot]

:gbrown
https://tbpl.mozilla.org/php/getParsedLog.php?id=32742458&tree=Cedar
Android 4.2 x86 Emulator cedar opt test androidx86-set-4 on 2014-01-08 21:33:32
revision: 2b964df2cac7
slave: talos-linux64-ix-018

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 22

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=34784028&tree=Fx-Team
Android 4.2 x86 Emulator fx-team opt test androidx86-set-4 on 2014-02-17 04:28:22
revision: 7273e402c9e6
slave: talos-linux64-ix-018

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 23

[Legacy TBPL/Treeherder Robot]

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=35666336&tree=Mozilla-Inbound
Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4 on 2014-03-05 09:02:28
revision: b6d23f380d7d
slave: talos-linux64-ix-009

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 24

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=35998112&tree=Fx-Team
Android 4.2 x86 Emulator fx-team opt test androidx86-set-4 on 2014-03-12 06:36:31
revision: 3a8c5cbeccea
slave: talos-linux64-ix-031

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 25

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=41312131&tree=Mozilla-Inbound
Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4 on 2014-06-08 06:38:38
revision: 229dc47b5059
slave: talos-linux64-ix-065

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 26

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=44428573&tree=Mozilla-Central
Android 4.2 x86 Emulator mozilla-central opt test androidx86-set-4 on 2014-07-23 03:50:16
revision: 82df3654cd80
slave: talos-linux64-ix-099

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 27

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=45092028&tree=Mozilla-Inbound
Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4 on 2014-08-01 15:17:13
revision: 09425d87715d
slave: talos-linux64-ix-032

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 28

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=48521715&tree=Mozilla-Inbound
Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4 on 2014-09-19 20:21:52
revision: e8b6a242343d
slave: talos-linux64-ix-056

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1

Comment 29

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=7075808
repository: mozilla-inbound
start_time: 2015-02-27T17:31:23
who: rvandermeulen[at]mozilla[dot]com
machine: talos-linux64-ix-066
buildname: Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4
revision: 6b232bc4c75a

We have not been able to establish a telnet connection with the emulator
Running post_fatal callback...
Exiting -1