Merge lp:~codehelp/lava-dispatcher/multinode into lp:lava-dispatcher/multinode

[Neil Williams]

Add debug to investigate problems with lava_sync not picking up the message over the serial connection.

[lp:~codehelp/lava-dispatcher/multinode]

649. By Neil Williams on 2013-06-26

Fix missing handdown of the context to the test shell.

[Senthil Kumaran S (stylesen)]

review: Approve

=== modified file 'lava/dispatcher/group.py'
--- lava/dispatcher/group.py	2013-06-25 17:35:08 +0000
+++ lava/dispatcher/group.py	2013-06-26 12:50:53 +0000
@@ -51,25 +51,23 @@
             s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
             s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
             try:
-                print "binding"
+                logging.info("binding")
                 s.bind(('localhost', self.group_port))
                 break
             except socket.error as e:
-                print "delay=%d msg=%s" % (self.delay, e.message)
+                logging.warn("Unable to bind, trying again with delay=%d msg=%s" % (self.delay, e.message))
                 time.sleep(self.delay)
                 self.delay *= 2
         s.listen(1)
-        print "listening"
         self.running = True
         while self.running:
-            print "trying to accept"
+            logging.info("waiting to accept new connections")
             self.conn, addr = s.accept()
-            print "Connected", addr
+#            logging.info("Connected", addr)
             data = str(self.conn.recv(self.blocksize))
             try:
                 json_data = json.loads(data)
             except ValueError:
-                print "data", data
                 logging.warn("JSON error for %s" % data)
                 self.conn.close()
                 continue
@@ -144,7 +142,7 @@
             logging.error("Unable to find messageID %s for client %s" % (messageID, client_name))
             self._badRequest()
             return
-        logging.info("Sending message %s to %s" % (messageID, client_name))
+        logging.info("Sending message '%s' to %s in group %s" % (messageID, client_name, self.group['group']))
         self.conn.send(json.dumps({"response": "ack", "message": self.group['messages'][client_name][messageID]}))
         self.conn.close()
         del self.group['messages'][client_name][messageID]
@@ -181,13 +179,13 @@
         Global synchronization primitive. Sends a message and waits for the same
         message from all of the other devices.
         """
-        logging.info("GroupDispatcher:lavaSync %s from %s" %(json.dumps(json_data), client_name))
+        logging.debug("GroupDispatcher:lavaSync %s from %s in group %s" %(json.dumps(json_data), client_name, self.group['group']))
         messageID = self._getMessageID(json_data)
         message = self._getMessage(json_data)
         # FIXME: in _sendMessage, be sure to send the messageID if message is empty
         if not message:
             message = messageID
-        logging.info("LavaSync request for %s at stage %s" % (client_name, messageID))
+        logging.info("LavaSync request for '%s' at stage '%s' in group '%s'" % (client_name, messageID, self.group['group']))
         self.group['syncs'].setdefault(messageID, {})
         self.group['messages'].setdefault(client_name, {}).setdefault(messageID, {})
         if len(self.group['syncs'][messageID]) >= self.group['count']:
@@ -196,8 +194,8 @@
             # mark this client as having picked up the message
             self.group['syncs'][messageID][client_name] = 0
         else:
-            logging.info("waiting: not all clients seen yet %d < %d" %
-                         (len(self.group['syncs'][messageID]), self.group['count']))
+            logging.info("waiting: not all clients in group '%s' have been seen yet %d < %d" %
+                         (self.group['group'], len(self.group['syncs'][messageID]), self.group['count']))
             self.group['messages'][client_name][messageID] = message
             self.group['syncs'][messageID][client_name] = 1
             self._waitResponse()
@@ -209,7 +207,7 @@
             if self.group['syncs'][messageID][pending]:
                 clear_syncs = False
         if clear_syncs:
-            logging.debug("Clearing all sync messages for %s" % messageID)
+            logging.debug("Clearing all sync messages for '%s' in group '%s'" % (messageID, self.group['group']))
             self.group['syncs'][messageID].clear()
 
     def lavaWaitAll(self, json_data, client_name):
@@ -250,7 +248,7 @@
         If lava_wait is called first, the message will be sent when the client reconnects
         """
         message = self._getMessage(json_data)
-        logging.info("lavaSend handler in GroupDispatcher received a message: %s" % message)
+        logging.info("lavaSend handler in GroupDispatcher received a message '%s' for group '%s'" % (message, self.group['group']))
         messageID = self._getMessageID(json_data)
         for client in self.group['clients']:
             if messageID not in self.group['messages'][client]:
@@ -277,7 +275,8 @@
         if request == 'group_data':
             self._setGroupData(json_data)
         elif request == "lava_sync":
-            logging.info("lava_sync: %s request made by %s" % (json.dumps(json_data), client_name))
+            logging.debug("lava_sync: %s request made by '%s' in group '%s'" %
+                          (json.dumps(json_data), client_name, self.group['group']))
             self.lavaSync(json_data, client_name)
         elif request == 'lava_wait_all':
             self.lavaWaitAll(json_data, client_name)
@@ -287,7 +286,8 @@
             logging.info("lava_send: %s" % json_data)
             self.lavaSend(json_data)
         elif request == "complete":
-            logging.info("dispatcher for '%s' communication complete, closing." % client_name)
+            logging.info("dispatcher communication for '%s' in group '%s' is complete, closing." %
+                         (client_name, self.group['group']))
             self.conn.close()
         else:
             self._badRequest()

=== modified file 'lava/dispatcher/node.py'
--- lava/dispatcher/node.py	2013-06-25 17:35:23 +0000
+++ lava/dispatcher/node.py	2013-06-26 12:50:53 +0000
@@ -52,11 +52,11 @@
     blocks = 1024
 
     def __init__(self, data_str):
-        print "Poller init passed json_data", data_str
+        logging.debug("Poller init passed json_data: %s" % data_str)
         try:
             self.json_data = json.loads(data_str)
         except ValueError:
-            print "bad JSON"
+            logging.error("bad JSON")
             exit(1)
         if 'port' in self.json_data:
             self.port = self.json_data['port']
@@ -64,27 +64,27 @@
             self.blocks = self.json_data['blocksize']
 
     def poll(self, msg_str):
-        print "polling %s" % json.dumps(self.json_data)
+        logging.debug("polling %s" % json.dumps(self.json_data))
         self.polling = True
         while self.polling:
             s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
             s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
             try:
-                print "host:%s port:%s" % (self.json_data['host'], self.json_data['port'])
+                logging.debug("socket created for host:%s port:%s" % (self.json_data['host'], self.json_data['port']))
                 s.connect(('localhost', self.json_data['port']))
                 self.delay = 1
             except socket.error as e:
-                print "socket error on connect", e.errno
+                logging.warn("socket error on connect: %d" % e.errno)
                 time.sleep(self.delay)
                 self.delay += 2
                 s.close()
                 continue
-            print "msg %s" % msg_str
+            logging.debug("read message: %s" % msg_str)
             # blocking synchronous call
             try:
                 s.send(msg_str)
             except socket.error as e:
-                print "socket error on send", e.errno
+                logging.warn("socket error '%d' on send" % e.errno)
 #                self.s.shutdown(socket.SHUT_RDWR)
                 s.close()
                 continue
@@ -92,7 +92,7 @@
             try:
                 self.response = s.recv(self.blocks)
             except socket.error as e:
-                print "socket error on response", e.errno
+                logging.warn("socket error '%d' on response" % e.errno)
 #                self.s.shutdown(socket.SHUT_RDWR)
                 s.close()
                 continue
@@ -105,7 +105,7 @@
                 logging.error("response was not JSON %s" % self.response)
                 break
             if json_data['response'] != 'wait':
-                logging.info(json_data['response'])
+                logging.info("Response: %s" % json_data['response'])
                 self.polling = False
                 break
             else:
@@ -166,13 +166,13 @@
     def run(self):
         init_msg = {"request": "group_data", "group_size": self.group_size}
         init_msg.update(self.base_msg)
-        print "NodeDispatcher: init_msg", json.dumps(init_msg)
+        logging.debug("init_msg %s" % json.dumps(init_msg))
         self.poller.poll(json.dumps(init_msg))
         self.run_tests(self.json_data)
 
     def __call__(self, args):
         try:
-            logging.info("transport handler for NodeDispatcher %s" % args)
+            logging.debug("transport handler for NodeDispatcher %s" % args)
             self._select(json.loads(args))
         except KeyError:
             logging.warn("Unable to use callable send in NodeDispatcher")
@@ -186,7 +186,6 @@
             return
         if json_data['request'] == "lava_sync":
             logging.info("requesting lava_sync")
-            # FIXME: pointless redirection unles request_sync does more work eventually.
             self.request_sync(json_data['messageID'])
         elif json_data['request'] == 'lava_wait':
             logging.info("requesting lava_wait")
@@ -276,7 +275,6 @@
         # pass this NodeDispatcher down so that the lava_test_shell can __call__ nodeTransport to write a message
 #        job.run(self.dispatcher)
         job.run(self)
-        logging.info("job.run has returned")
 
     def writeMessage(self):
         """

=== modified file 'lava_dispatcher/actions/lava_test_shell.py'
--- lava_dispatcher/actions/lava_test_shell.py	2013-06-25 10:27:04 +0000
+++ lava_dispatcher/actions/lava_test_shell.py	2013-06-26 12:50:53 +0000
@@ -525,7 +525,7 @@
             logging.debug("Received signal <%s>" % name)
             params = params.split()
             try:
-                signal_director.signal(name, params)
+                signal_director.signal(name, params, self.context)
             except:
                 logging.exception("on_signal failed")
             runner._connection.sendline('echo LAVA_ACK')

=== modified file 'lava_dispatcher/job.py'
--- lava_dispatcher/job.py	2013-06-25 17:35:23 +0000
+++ lava_dispatcher/job.py	2013-06-26 12:50:53 +0000
@@ -248,6 +248,7 @@
                     status = 'fail'
                     action.run(**params)
                 except ADBConnectError as err:
+                    logging.info("ADBConnectError")
                     if cmd.get('command') == 'boot_linaro_android_image':
                         logging.warning(('[ACTION-E] %s failed to create the'
                                          ' adb connection') % (cmd['command']))
@@ -266,6 +267,7 @@
                         ## mark it as pass if the second boot works
                         status = 'pass'
                 except TimeoutError as err:
+                    logging.info("TimeoutError")
                     if cmd.get('command').startswith('lava_android_test'):
                         logging.warning("[ACTION-E] %s times out." % (
                                                 cmd['command']))
@@ -285,15 +287,23 @@
                             self.context.client.proc.sendline("")
                             time.sleep(5)
                             self.context.client.boot_linaro_android_image()
+                    else:
+                        logging.warn("Unhandled timeout condition")
+                        continue
                 except CriticalError as err:
+                    logging.info("CriticalError")
                     raise
                 except (pexpect.TIMEOUT, GeneralError) as err:
+                    logging.warn("pexpect timed out, pass with status %s" % status)
                     pass
                 except Exception as err:
+                    logging.info("General Exception")
                     raise
                 else:
+                    logging.info("setting status pass")
                     status = 'pass'
                 finally:
+                    logging.info("finally status %s" % status)
                     err_msg = ""
                     if status == 'fail':
                         # XXX mwhudson, 2013-01-17: I have no idea what this

=== modified file 'lava_dispatcher/signals/__init__.py'
--- lava_dispatcher/signals/__init__.py	2013-06-26 11:22:13 +0000
+++ lava_dispatcher/signals/__init__.py	2013-06-26 12:50:53 +0000
@@ -177,7 +177,8 @@
         self.context.transport(json.dumps(msg))
         target = self.client.target_device
         with target.runner() as runner:
-            runner._connection.sendline("<LAVA_SYNC_COMPLETE>")
+            ret = runner._connection.sendline("<LAVA_SYNC_COMPLETE>")
+            logging.info("runner._connection.sendline wrote %d bytes" % ret)
 
     def _on_WAIT(self, message_id, message):
         logging.debug("Handling signal <LAVA_WAIT %s>" % message_id)

=== modified file 'lava_test_shell/multi_node/lava-multi-node.lib'
--- lava_test_shell/multi_node/lava-multi-node.lib	2013-06-26 07:50:19 +0000
+++ lava_test_shell/multi_node/lava-multi-node.lib	2013-06-26 12:50:53 +0000
@@ -20,14 +20,15 @@
 }
 
 _lava_multi_node_send () {
-
+echo "<_LAVA_SEND started>"
 result=$(echo $1 | grep "..*=..*")
+echo "<_LAVA_SEND result $result>"
 if [ -n "$1" -a "${result}x" == "x" ] ; then
 	echo ${MESSAGE_HEAD} $@">"
 else
 	exit 1
 fi
-
+echo "<_LAVA_SEND finished>"
 }
 
 _lava_multi_node_print_message () {
@@ -41,9 +42,9 @@
 }
 
 lava_multi_node_send () {
-
+echo "<LAVA_SEND preparing>"
 _lava_multi_node_send $@
-
+echo "<LAVA_SEND waiting for ack>"
 while [ -n "$MESSAGE_NEED_ACK" ] ; do
 	read -t $MESSAGE_TIMEOUT line
 	result=$(echo $line | grep "${MESSAGE_ACK}")
@@ -53,9 +54,13 @@
 	fi
 	_lava_multi_node_send $@
 done
+echo "<LAVA_SEND finished>"
+date
 }
 
 lava_multi_node_wait_for_signal () {
+date
+echo "<LAVA_DEBUG starting to wait>"
 while read line; do
 	result=$(echo $line | grep "${MESSAGE_REPLY}>")
 	if [ "${result}x" != "x" ] ; then
@@ -65,6 +70,8 @@
 		break
 	fi
 done
+echo "<LAVA_DEBUG waiting over>"
+date
 }
 
 lava_multi_node_wait_for_message () {

=== modified file 'lava_test_shell/multi_node/lava-sync'
--- lava_test_shell/multi_node/lava-sync	2013-06-21 13:23:41 +0000
+++ lava_test_shell/multi_node/lava-sync	2013-06-26 12:50:53 +0000
@@ -16,5 +16,6 @@
 source $LAVA_TEST_BIN/lava-multi-node.lib
 
 lava_multi_node_send $1
-
+echo "<LAVA_SYNC_DEBUG send complete>"
 lava_multi_node_wait_for_signal
+echo "<LAVA_SYNC_DEBUG wait complete>"