diff --git a/teuthology/orchestra/console.py b/teuthology/orchestra/console.py index d339f3cb7..6361cd428 100644 --- a/teuthology/orchestra/console.py +++ b/teuthology/orchestra/console.py @@ -39,6 +39,7 @@ def __init__(self, name, ipmiuser=None, ipmipass=None, ipmidomain=None, timeout=40): self.name = name self.shortname = self.getShortName(name) + self.log = log.getChild(self.shortname) self.timeout = timeout self.ipmiuser = ipmiuser or config.ipmi_user self.ipmipass = ipmipass or config.ipmi_password @@ -71,7 +72,7 @@ def _pexpect_spawn(self, cmd): """ Run a command using pexpect.spawn(). Return the child object. """ - log.debug('pexpect command: %s', cmd) + self.log.debug('pexpect command: %s', cmd) p = pexpect.spawn( cmd, encoding='utf-8', @@ -86,7 +87,7 @@ def start(): child = start() if self.has_conserver and not child.isalive(): - log.error("conserver failed to get the console; will try ipmitool") + self.log.error("conserver failed to get the console; will try ipmitool") self.has_conserver = False child = start() return child @@ -116,7 +117,7 @@ def _ipmi_command(self, subcommand): def _check_ipmi_credentials(self): if not self.has_ipmi_credentials: - log.error( + self.log.error( "Must set ipmi_user, ipmi_password, and ipmi_domain in " ".teuthology.yaml" ) @@ -131,37 +132,36 @@ def _exit_session(self, child, timeout=None): timeout=t) if r != 0: child.kill(15) - log.debug('console disconnect output: %s', child.logfile_read.getvalue().strip()) + self.log.debug('console disconnect output: %s', child.logfile_read.getvalue().strip()) else: child.send('~.') r = child.expect( ['terminated ipmitool', pexpect.TIMEOUT, pexpect.EOF], timeout=t) - log.debug('ipmitool disconnect output: %s', child.logfile_read.getvalue().strip()) + self.log.debug('ipmitool disconnect output: %s', child.logfile_read.getvalue().strip()) if r != 0: self._pexpect_spawn_ipmi('sol deactivate') - log.debug('sol deactivate output: %s', child.logfile_read.getvalue().strip()) + self.log.debug('sol deactivate output: %s', child.logfile_read.getvalue().strip()) def _wait_for_login(self, timeout=None, attempts=2): """ Wait for login. Retry if timeouts occur on commands. """ t = timeout or self.timeout - log.debug('Waiting for login prompt on {s}'.format(s=self.shortname)) + self.log.debug('Waiting for login prompt') # wait for login prompt to indicate boot completed for i in range(0, attempts): start = time.time() while time.time() - start < t: child = self._get_console(readonly=False) child.send('\n') - log.debug('expect: {s} login'.format(s=self.shortname)) r = child.expect( ['{s} login: '.format(s=self.shortname), pexpect.TIMEOUT, pexpect.EOF], timeout=(t - (time.time() - start))) - log.debug('expect before: {b}'.format(b=child.before)) - log.debug('expect after: {a}'.format(a=child.after)) + self.log.debug('expect before: {b}'.format(b=child.before)) + self.log.debug('expect after: {a}'.format(a=child.after)) self._exit_session(child) if r == 0: @@ -183,7 +183,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', c.logfile_read.getvalue().strip()) + self.log.debug('check power output: %s', c.logfile_read.getvalue().strip()) if r == 0: return True return False @@ -197,8 +197,7 @@ def check_status(self, timeout=None): self._wait_for_login(timeout) return True except Exception as e: - log.info('Failed to get ipmi console status for {s}: {e}'.format( - s=self.shortname, e=e)) + self.log.info('Failed to get ipmi console status: {e}'.format(e=e)) return False def power_cycle(self, timeout=300): @@ -207,46 +206,46 @@ def power_cycle(self, timeout=300): :param timeout: How long to wait for login """ - log.info('Power cycling {s}'.format(s=self.shortname)) + self.log.info('Power cycling') child = self._pexpect_spawn_ipmi('power cycle') child.expect('Chassis Power Control: Cycle', timeout=self.timeout) - log.debug('power cycle output: %s', child.logfile_read.getvalue().strip()) + self.log.debug('power cycle output: %s', child.logfile_read.getvalue().strip()) self._wait_for_login(timeout=timeout) - log.info('Power cycle for {s} completed'.format(s=self.shortname)) + self.log.info('Power cycle completed') def hard_reset(self, wait_for_login=True): """ Perform physical hard reset. Retry if EOF returned from read and wait for login when complete. """ - log.info('Performing hard reset of {s}'.format(s=self.shortname)) + self.log.info('Performing hard reset') start = time.time() while time.time() - start < self.timeout: 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', child.logfile_read.getvalue().strip()) + self.log.debug('power reset output: %s', child.logfile_read.getvalue().strip()) if r == 0: break if wait_for_login: self._wait_for_login() - log.info('Hard reset for {s} completed'.format(s=self.shortname)) + self.log.info('Hard reset completed') def power_on(self): """ Physical power on. Loop checking cmd return. """ - log.info('Power on {s}'.format(s=self.shortname)) + self.log.info('Power on') start = time.time() while time.time() - start < self.timeout: 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', child.logfile_read.getvalue().strip()) + self.log.debug('power on output: %s', child.logfile_read.getvalue().strip()) if r == 0: break if self.check_power('on'): - log.info('Power on for {s} completed'.format(s=self.shortname)) + self.log.info('Power on completed') else: err_msg = 'Failed to power on {s}'.format(s=self.shortname) raise RuntimeError(err_msg) @@ -255,19 +254,19 @@ def power_off(self): """ Physical power off. Loop checking cmd return. """ - log.info('Power off {s}'.format(s=self.shortname)) + self.log.info('Power off') start = time.time() while time.time() - start < self.timeout: 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', child.logfile_read.getvalue().strip()) + self.log.debug('power off output: %s', child.logfile_read.getvalue().strip()) if r == 0: break if self.check_power('off', 60): - log.info('Power off for {s} completed'.format(s=self.shortname)) + self.log.info('Power off completed') else: - log.error('Failed to power off {s}'.format(s=self.shortname)) + self.log.error('Failed to power off') def power_off_for_interval(self, interval=30): """ @@ -275,12 +274,11 @@ def power_off_for_interval(self, interval=30): :param interval: Length of power-off period. """ - log.info('Power off {s} for {i} seconds'.format( - s=self.shortname, i=interval)) + self.log.info('Power off for {i} seconds'.format(i=interval)) child = self._pexpect_spawn_ipmi('power off') child.expect('Chassis Power Control: Down/Off', timeout=self.timeout) - log.debug('power off output: %s', child.logfile_read.getvalue().strip()) + self.log.debug('power off output: %s', child.logfile_read.getvalue().strip()) child.logfile_read.seek(0) child.logfile_read.truncate() @@ -288,9 +286,9 @@ def power_off_for_interval(self, interval=30): child = self._pexpect_spawn_ipmi('power on') child.expect('Chassis Power Control: Up/On', timeout=self.timeout) - log.debug('power on output: %s', child.logfile_read.getvalue().strip()) + self.log.debug('power on output: %s', child.logfile_read.getvalue().strip()) self._wait_for_login() - log.info('Power off for {i} seconds completed'.format(i=interval)) + self.log.info('Power off for {i} seconds completed'.format(i=interval)) def spawn_sol_log(self, dest_path): """ @@ -323,7 +321,7 @@ def start(): proc = start() if self.has_conserver and proc.poll() is not None: - log.error("conserver failed to get the console; will try ipmitool") + self.log.error("conserver failed to get the console; will try ipmitool") self.has_conserver = False proc = start() return proc @@ -338,6 +336,7 @@ def __init__(self, name): raise RuntimeError("libvirt not found") self.shortname = self.getShortName(name) + self.log = log.getChild(self.shortname) status_info = teuthology.lock.query.get_status(self.shortname) try: if teuthology.lock.query.is_vm(status=status_info): @@ -395,9 +394,8 @@ def power_off_for_interval(self, interval=30): """ Simiulate power off for an interval. """ - log.info('Power off {s} for {i} seconds'.format( - s=self.shortname, i=interval)) + self.log.info('Power off for {i} seconds'.format(i=interval)) self.vm_domain.info().destroy() time.sleep(interval) self.vm_domain.info().create() - log.info('Power off for {i} seconds completed'.format(i=interval)) + self.log.info('Power off for {i} seconds completed'.format(i=interval))