Merge lp:~asac/lava-dispatcher/TIME_WAIT-before-fastmodel-start into lp:lava-dispatcher

[Alexander Sack]

workaround fix for TIME_WAIT fast model bustage as discussed in: https://bugs.launchpad.net/lava-dispatcher/+bug/1034809

here we wait till TIME_WAIT is gone, which will fix that we sometimes cant connect adb after rebooting fastmodel.

see https://code.launchpad.net/~asac/lava-dispatcher/logged-commands-getstatusoutput-wrapper-util/+merge/119029 for prereq merge proposal.

[Alexander Sack (asac)]

example log with this patch applied:

<LAVA_DISPATCHER>2012-08-09 08:32:57 PM INFO: Execute adb command on host: adb disconnect 127.0.0.1

<LAVA_DISPATCHER>2012-08-09 08:32:57 PM INFO: [ACTION-E] lava_android_test_run is finished successfully.
<LAVA_DISPATCHER>2012-08-09 08:32:57 PM INFO: [ACTION-B] boot_linaro_android_image is started with {}
<LAVA_DISPATCHER>2012-08-09 08:32:58 PM INFO: NOW: waiting for TIME_WAIT 5555 socket to finish - see lp:1034809
<LAVA_DISPATCHER>2012-08-09 08:32:58 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:01 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:04 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:07 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:10 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:13 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:16 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:19 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:22 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:25 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:28 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:31 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:34 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:37 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:40 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:43 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:46 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:49 PM INFO: waiting for TIME_WAIT 5555 socket to finish
<LAVA_DISPATCHER>2012-08-09 08:33:52 PM INFO: launching fastmodel with command u"/home/ubuntu/RTSM_A15-A7x14_VE/Linux64_RTSM_VE_Cortex-A15x4-A7x4/RTSM_VE_Cortex-A15x4-A7x4 -a coretile.cluster0.*=/linaro/images/tmp/tmp9FwvnR/linux-system-ISW.axf -C motherboard.smsc_91c111.enabled=1 -C motherboard.hostbridge.userNetworking=1 -C motherboard.mmc.p_mmc_file=/linaro/images/tmp/tmp9FwvnR/android.img -C coretile.cache_state_modelled=0 -C coretile.cluster0.cpu0.semihosting-enable=1 -C motherboard.hostbridge.userNetPorts='5555=5555'"

... in this case it wouldn't have managed to reconnect to adb.

[Michael Hudson-Doyle (mwhudson)]

I don't really understand why the socket ends up in TIME_WAIT and the grep is a bit ugly, but I guess it solves the problem...

review: Approve

[Alexander Sack (asac)]

thanks. its the right decision to approve this. its a workaound until fastmodel folks fix their underlying issue (see bug); hence it doesnt need to be beautiful und gettng the same info from kernel directly that netstat gives us will also not be much nicer :)

[Alexander Sack (asac)]

please also sign off the prerequisite branch... otherwise i will just merge it along... :)

Unmerged revisions

368. By Alexander Sack on 2012-08-09

implement workaround for lp:1034809 - wait till socket is released from TIME_WAIT state before launching fast model

367. By Alexander Sack on 2012-08-09

add logged commands.getstatuswrapper (logging_commands__getstatusoutput) to utils.py

=== modified file 'lava_dispatcher/client/fastmodel.py'
--- lava_dispatcher/client/fastmodel.py	2012-08-02 23:18:23 +0000
+++ lava_dispatcher/client/fastmodel.py	2012-08-09 20:26:26 +0000
@@ -28,6 +28,7 @@
 import shutil
 import stat
 import threading
+import time
 
 from lava_dispatcher.client.base import (
     CommandRunner,
@@ -48,6 +49,7 @@
 from lava_dispatcher.utils import (
     logging_spawn,
     logging_system,
+    logging_commands__getstatusoutput,
     )
 
 
@@ -236,6 +238,11 @@
         self._fix_perms()
         sim_cmd = self._get_sim_cmd()
 
+        logging.info ("NOW: waiting for TIME_WAIT 5555 socket to finish - see lp:1034809")
+        while logging_commands__getstatusoutput ("sh -c 'netstat -an | grep 5555.*TIME_WAIT'")[0] == 0:
+            logging.info ("waiting for TIME_WAIT 5555 socket to finish")
+            time.sleep(3)
+
         # the simulator proc only has stdout/stderr about the simulator
         # we hook up into a telnet port which emulates a serial console
         logging.info('launching fastmodel with command %r' % sim_cmd)