826117 - [mozdevice] Timeout not respected when connecting socket in DeviceManagerSUT

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Mark Côté [:mcote]]

Attachment: Extra debug statements to show connect timeouts

The method of timing out socket.connect() calls in DeviceManagerSUT is broken.  It calls connect() followed by select(); however, connect() is a blocking call, so, without a timeout set explicitly on the socket, it will return at a time of its own choosing, which may be longer than the requested timeout.

The attached patch adds some debug print statements to DeviceManagerSUT to show this problem.  Here's some output when trying to use a default timeout of 15 seconds:

python -c "import mozdevice; mozdevice.DeviceManagerSUT.default_timeout = 15; mozdevice.DeviceManagerSUT('192.168.1.88')"

1357173029.250030 connecting... (timeout 15)
1357173105.115223 socket error
Could not connect; sleeping for 5 seconds.

The host 192.168.1.88 does not exist, so it is using some timeout as determined by the network or kernel or something.  This is much longer than the specified timeout (76 s vs 15 s).

Note that the recv() timeout is not affected by this bug.  It correctly calls select() *before* recv().  This is actually impossible with connect() and a blocking socket; the only solution is to make it a nonblocking socket or use socket.settimeout().  I think the latter is the way to go.

Comment 1

[Mark Côté [:mcote]]

Attachment: Use settimeout with connect

With this patch, we see the correct timeout when trying to connect to an unreachable host:

python -c "import mozdevice; mozdevice.DeviceManagerSUT.default_timeout = 15; mozdevice.DeviceManagerSUT('192.168.1.143')"
1357231390.424417 connecting... (timeout 15)
1357231405.432886 socket error
Could not connect; sleeping for 5 seconds.

It seems that sometimes a retry will fail immediately after an attempt that timed out, but I think that's kernel-level stuff.  You can get the same behaviour out of nc if you try to connect repeatedly to an unreachable host, so I think this is okay.

Comment 2

[Mark Côté [:mcote]]

Try run is ongoing: https://tbpl.mozilla.org/?tree=Try&rev=24935a02828d

Comment 3

[William Lachance (:wlach)]

Comment on attachment 697488 [details] [diff] [review]
Use settimeout with connect

Your solution makes tons of sense to me. Thanks!

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 697488 [details] [diff] [review]
Use settimeout with connect

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

::: mozdevice/mozdevice/devicemanagerSUT.py
@@ +172,5 @@
> +                self._sock.recv(1024)
> +            except socket.error, msg:
> +                self._sock.close()
> +                self._sock = None
> +                raise DMError("Remote Device Error: Unable to connect socket: "+str(msg), fatal=True)

is this the right error to bubble up?  I would think it would be "Remote Device Error: Unable to get a SUT prompt after connecting"

Comment 5

[Mark Côté [:mcote]]

Ah good catch.  Will fix.

Comment 6

[Mozilla RelEng Bot]

Try run for 24935a02828d is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=24935a02828d
Results (out of 19 total builds):
    success: 19
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-24935a02828d

Comment 7

[Mark Côté [:mcote]]

https://github.com/mozilla/mozbase/commit/034431ad892b6a9149ee816cfaa06291f8743321

This'll need a version bump for mozdevice.