lib/oeqa/utils: sshcontrol: log how long the last command take

It might be useful for debugging to have in the ssh log
the number of seconds a command has run.

(From OE-Core rev: 48b9e45b9716130b015ae2ab7398d6aa243933dc)

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>

1 files changed, 6 insertions, 3 deletions

diff --git a/meta/lib/oeqa/utils/sshcontrol.py b/meta/lib/oeqa/utils/sshcontrol.py
index 643d0ad362..1539ff2a37 100644
--- a/meta/lib/oeqa/utils/sshcontrol.py
+++ b/meta/lib/oeqa/utils/sshcontrol.py
@@ -15,6 +15,7 @@ class SSHControl(object):
     def __init__(self, host=None, timeout=300, logfile=None):
         self.host = host
         self.timeout = timeout
+        self._starttime = None
         self._out = ''
         self._ret = 126
         self.logfile = logfile
@@ -35,6 +36,7 @@ class SSHControl(object):
         cmd = ". /etc/profile; " + cmd
         command = self.ssh + [self.host, cmd]
         self.log("[Running]$ %s" % " ".join(command))
+        self._starttime = time.time()
         # ssh hangs without os.setsid
         proc = subprocess.Popen(command, shell=False, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, preexec_fn=os.setsid)
         return proc
@@ -58,7 +60,7 @@ class SSHControl(object):
                 tdelta = self.timeout
             else:
                 tdelta = timeout
-            endtime = time.time() + tdelta
+            endtime = self._starttime + tdelta
             while sshconn.poll() is None and time.time() < endtime:
                 time.sleep(1)
             # process hasn't returned yet
@@ -69,23 +71,24 @@ class SSHControl(object):
                 self._out = sshconn.stdout.read()
                 sshconn.stdout.close()
                 self._out += "\n[!!! SSH command timed out after %d seconds and it was killed]" % tdelta
-                self.log("[!!! SSH command timed out after %d seconds and it was killed]" % tdelta)
             else:
                 self._out = sshconn.stdout.read()
                 self._ret = sshconn.poll()
         # strip the last LF so we can test the output
         self._out = self._out.rstrip()
         self.log("%s" % self._out)
-        self.log("[SSH command returned]: %s" % self._ret)
+        self.log("[SSH command returned after %d seconds]: %s" % (time.time() - self._starttime, self._ret))
         return (self._ret, self._out)
 
     def _internal_scp(self, cmd):
         cmd = ['scp'] + self.ssh_options + cmd
         self.log("[Running SCP]$ %s" % " ".join(cmd))
+        self._starttime = time.time()
         scpconn = subprocess.Popen(cmd, shell=False, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, preexec_fn=os.setsid)
         out = scpconn.communicate()[0]
         ret = scpconn.poll()
         self.log("%s" % out)
+        self.log("[SCP command returned after %d seconds]: %s" % (time.time() - self._starttime, ret))
         if ret != 0:
             # we raise an exception so that tests fail in setUp and setUpClass without a need for an assert
             raise Exception("Error running %s, output: %s" % ( " ".join(cmd), out))