orchestra/console: log output from pexpect commands

in case anything weird is being noticed and communicated by
ipmitool, try to display anything it says

Signed-off-by: Dan Mick <[email protected]>

teuthology/orchestra/console.py

@@ -1,3 +1,4 @@
+import io
 import logging
 import os
 import pexpect
@@ -36,10 +37,11 @@ class PhysicalConsole(RemoteConsole):
     """
     def __init__(self, name, ipmiuser=None, ipmipass=None, ipmidomain=None,
                  logfile=None, timeout=40):
+        # logfile is not used; logging is done with the logging module
         self.name = name
         self.shortname = self.getShortName(name)
         self.timeout = timeout
-        self.logfile = None
+        self.logfile = io.StringIO()
         self.ipmiuser = ipmiuser or config.ipmi_user
         self.ipmipass = ipmipass or config.ipmi_password
         self.ipmidomain = ipmidomain or config.ipmi_domain
@@ -72,10 +74,14 @@ def _pexpect_spawn(self, cmd):
         Run a command using pexpect.spawn(). Return the child object.
         """
         log.debug('pexpect command: %s', cmd)
-        return pexpect.spawn(
+        p = pexpect.spawn(
             cmd,
-            logfile=self.logfile,
+            encoding='utf-8',
         )
+        self.logfile.seek(0)
+        self.logfile.truncate()
+        p.logfile_read = self.logfile
+        return p
 
     def _get_console(self, readonly=True):
         def start():
@@ -129,13 +135,16 @@ def _exit_session(self, child, timeout=None):
                 timeout=t)
             if r != 0:
                 child.kill(15)
+            log.debug('console disconnect output: %s', self.logfile.getvalue().strip())
         else:
             child.send('~.')
             r = child.expect(
                 ['terminated ipmitool', pexpect.TIMEOUT, pexpect.EOF],
                 timeout=t)
+            log.debug('ipmitool disconnect output: %s', self.logfile.getvalue().strip())
             if r != 0:
                 self._pexpect_spawn_ipmi('sol deactivate')
+                log.debug('sol deactivate output: %s', self.logfile.getvalue().strip())
 
     def _wait_for_login(self, timeout=None, attempts=2):
         """
@@ -178,6 +187,7 @@ def check_power(self, state, timeout=None):
                 c = self._pexpect_spawn_ipmi('power status')
                 r = c.expect(['Chassis Power is {s}'.format(
                     s=state), pexpect.EOF, pexpect.TIMEOUT], timeout=1)
+                log.debug('check power output: %s', self.logfile.getvalue().strip())
                 if r == 0:
                     return True
         return False
@@ -204,6 +214,7 @@ def power_cycle(self, timeout=300):
         log.info('Power cycling {s}'.format(s=self.shortname))
         child = self._pexpect_spawn_ipmi('power cycle')
         child.expect('Chassis Power Control: Cycle', timeout=self.timeout)
+        log.debug('power cycle output: %s', self.logfile.getvalue().strip())
         self._wait_for_login(timeout=timeout)
         log.info('Power cycle for {s} completed'.format(s=self.shortname))
 
@@ -218,6 +229,7 @@ def hard_reset(self, wait_for_login=True):
             child = self._pexpect_spawn_ipmi('power reset')
             r = child.expect(['Chassis Power Control: Reset', pexpect.EOF],
                              timeout=self.timeout)
+            log.debug('power reset output: %s', self.logfile.getvalue().strip())
             if r == 0:
                 break
         if wait_for_login:
@@ -234,6 +246,7 @@ def power_on(self):
             child = self._pexpect_spawn_ipmi('power on')
             r = child.expect(['Chassis Power Control: Up/On', pexpect.EOF],
                              timeout=self.timeout)
+            log.debug('power on output: %s', self.logfile.getvalue().strip())
             if r == 0:
                 break
         if self.check_power('on'):
@@ -252,6 +265,7 @@ def power_off(self):
             child = self._pexpect_spawn_ipmi('power off')
             r = child.expect(['Chassis Power Control: Down/Off', pexpect.EOF],
                              timeout=self.timeout)
+            log.debug('power off output: %s', self.logfile.getvalue().strip())
             if r == 0:
                 break
         if self.check_power('off', 60):
@@ -270,10 +284,15 @@ def power_off_for_interval(self, interval=30):
         child = self._pexpect_spawn_ipmi('power off')
         child.expect('Chassis Power Control: Down/Off', timeout=self.timeout)
 
+        log.debug('power off output: %s', self.logfile.getvalue().strip())
+        self.logfile.seek(0)
+        self.logfile.truncate()
+
         time.sleep(interval)
 
         child = self._pexpect_spawn_ipmi('power on')
         child.expect('Chassis Power Control: Up/On', timeout=self.timeout)
+        log.debug('power on output: %s', self.logfile.getvalue().strip())
         self._wait_for_login()
         log.info('Power off for {i} seconds completed'.format(i=interval))