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>
This commit is contained in:
Stefan Stanacar 2013-09-19 15:36:15 +03:00 committed by Richard Purdie
parent cb2496c607
commit f3ab2fc731
1 changed files with 6 additions and 3 deletions

View File

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