Merge lp:~le-chi-thu/lava-dispatcher/log_send_and_expect into lp:lava-dispatcher

[Le Chi Thu]

Add logging for sending and expecting statements.

[Michael Hudson-Doyle (mwhudson)]

Seems fine.

review: Approve

[Paul Larson (pwlars)]

Would be nice if it displayed the timeout even if we don't specify one - sometimes the default timeout isn't so obvious. It's easy to get by looking at the timeout property of the proc object. Otherwise, looks ok to merge

[lp:~le-chi-thu/lava-dispatcher/log_send_and_expect]

174. By Le Chi Thu <email address hidden> <email address hidden> on 2011-12-07

Log the default timeout if the timeout is not specified

[Le Chi Thu (le-chi-thu)]

Log the default timeout if the timeout is not specified

review: Needs Resubmitting

[Paul Larson (pwlars)]

65 + if (kw.has_key('timeout')):
66 + timeout = kw['timeout']
67 + else:
68 + timeout = self.proc.timeout
69 +
70 + if len(args) == 1:
71 + logging.debug("expect (%d): '%s'" %(timeout, args[0]))
72 + else:
73 + logging.debug("expect (%d): '%s'" %(timeout, str(args)))

We should combine these two blocks, no need to have this ambiguous check for len(args) == 1 if we just checked whether timeout was specified.

Also, there is a small merge conflict to fix. Otherwise, still looks fine.

review: Approve

[lp:~le-chi-thu/lava-dispatcher/log_send_and_expect]

175. By Le Chi Thu <email address hidden> <email address hidden> on 2011-12-11

Fixed merge conflix with trunk

[Le Chi Thu (le-chi-thu)]

Major args is only one element and Iit will print a string which look
better than to print an array of one element.

Merge conflict is resolved.

>>> args=["hello"]
>>> print "expect '%s'"%args[0]
expect 'hello'
>>> print "expect %s"%str(args)
expect ['hello']

On 9 December 2011 00:22, Paul Larson <email address hidden> wrote:

> Review: Approve
>
> 65 + if (kw.has_key('timeout')):
> 66 + timeout = kw['timeout']
> 67 + else:
> 68 + timeout = self.proc.timeout
> 69 +
> 70 + if len(args) == 1:
> 71 + logging.debug("expect (%d): '%s'" %(timeout, args[0]))
> 72 + else:
> 73 + logging.debug("expect (%d): '%s'" %(timeout, str(args)))
>
> We should combine these two blocks, no need to have this ambiguous check
> for len(args) == 1 if we just checked whether timeout was specified.
>
> Also, there is a small merge conflict to fix. Otherwise, still looks fine.
> --
>
> https://code.launchpad.net/~le-chi-thu/lava-dispatcher/log_send_and_expect/+merge/84673
> You are the owner of lp:~le-chi-thu/lava-dispatcher/log_send_and_expect.
>

=== modified file 'lava_dispatcher/client/base.py'
--- lava_dispatcher/client/base.py	2011-11-30 01:17:02 +0000
+++ lava_dispatcher/client/base.py	2011-12-11 17:18:23 +0000
@@ -59,7 +59,7 @@
         index = 0
         while index == 0:
             index = self._connection.expect(
-                ['.+', pexpect.EOF, pexpect.TIMEOUT], timeout=1)
+                ['.+', pexpect.EOF, pexpect.TIMEOUT], timeout=1,lava_no_logging=1)
 
     def run(self, cmd, response=None, timeout=-1):
         """Run `cmd` and wait for a shell response.
@@ -93,7 +93,7 @@
         self._connection.expect(self._prompt_str, timeout=timeout)
         if self._wait_for_rc:
             match_id = self._connection.expect(
-                ['rc=(\d+\d?\d?)', pexpect.EOF, pexpect.TIMEOUT], timeout=2)
+                ['rc=(\d+\d?\d?)', pexpect.EOF, pexpect.TIMEOUT], timeout=2, lava_no_logging=1)
             if match_id == 0:
                 rc = int(self._connection.match.groups()[0])
             else:

=== modified file 'lava_dispatcher/client/master.py'
--- lava_dispatcher/client/master.py	2011-12-07 01:35:56 +0000
+++ lava_dispatcher/client/master.py	2011-12-11 17:18:23 +0000
@@ -389,7 +389,7 @@
             self.proc.hard_reboot()
             self._in_master_shell(300)
         self.proc.sendline('export PS1="$PS1 [rc=$(echo \$?)]: "')
-        self.proc.expect(self.master_str, timeout=10)
+        self.proc.expect(self.master_str, timeout=10, lava_no_logging=1)
 
     def _format_testpartition(self, session):
         logging.info("Format testboot and testrootfs partitions")
@@ -530,7 +530,7 @@
         """
         self.proc.sendline("")
         match_id = self.proc.expect(
-            [self.master_str, pexpect.TIMEOUT], timeout=timeout)
+            [self.master_str, pexpect.TIMEOUT], timeout=timeout, lava_no_logging=1)
         if match_id == 1:
             raise OperationFailed
         logging.info("System is in master image now")

=== modified file 'lava_dispatcher/connection.py'
--- lava_dispatcher/connection.py	2011-12-09 21:00:57 +0000
+++ lava_dispatcher/connection.py	2011-12-11 17:18:23 +0000
@@ -42,9 +42,29 @@
     # pexpect-like interface.
 
     def sendline(self, *args, **kw):
+        logging.debug("sendline : %s" %args[0])
         return self.proc.sendline(*args, **kw)
 
+    def send(self, *args, **kw):
+        logging.debug("sendline : %s" %args[0])
+        return self.proc.send(*args, **kw)
+
     def expect(self, *args, **kw):
+        # some expect should not be logged because it is so much noise.
+        if kw.has_key('lava_no_logging'):
+            del kw['lava_no_logging']
+            return self.proc.expect(*args, **kw)
+
+        if (kw.has_key('timeout')):
+            timeout = kw['timeout']
+        else:
+            timeout = self.proc.timeout
+
+        if len(args) == 1:
+            logging.debug("expect (%d): '%s'" %(timeout, args[0]))
+        else:
+            logging.debug("expect (%d): '%s'" %(timeout, str(args)))
+    
         return self.proc.expect(*args, **kw)
 
     def sendcontrol(self, *args, **kw):
@@ -58,14 +78,14 @@
     # Extra bits.
 
     def _enter_uboot(self):
-        self.proc.expect("Hit any key to stop autoboot")
-        self.proc.sendline("")
+        self.expect("Hit any key to stop autoboot")
+        self.sendline("")
 
     def soft_reboot(self):
-        self.proc.sendline("reboot")
+        self.sendline("reboot")
         # set soft reboot timeout 120s, or do a hard reset
         logging.info("Rebooting the system")
-        id = self.proc.expect(
+        id = self.expect(
             ['Restarting system.', 'The system is going down for reboot NOW',
                 'Will now restart', pexpect.TIMEOUT], timeout=120)
         if id not in [0,1,2]:
@@ -97,8 +117,8 @@
             logging.exception("_enter_uboot failed")
             self.hard_reboot()
             self._enter_uboot()
-        self.proc.sendline(boot_cmds[0])
+        self.sendline(boot_cmds[0])
         bootloader_prompt = re.escape(self.device_option('bootloader_prompt'))
         for line in range(1, len(boot_cmds)):
-            self.proc.expect(bootloader_prompt, timeout=300)
-            self.proc.sendline(boot_cmds[line])
+            self.expect(bootloader_prompt, timeout=300)
+            self.sendline(boot_cmds[line])