Skip to content

Commit

Permalink
orchestra.console: Scope loggers to shortname
Browse files Browse the repository at this point in the history 
This will make reading console debug logging easier.

Signed-off-by: Zack Cerza <[email protected]>
  • Loading branch information
@zmc
zmc committed Jul 27, 2023
1 parent 407880c commit 845d8fb
Showing 1 changed file with 33 additions and 35 deletions.
68 changes: 33 additions & 35 deletions teuthology/orchestra/console.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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',
Expand All @@ -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
Expand Down Expand Up @@ -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"
)
Expand All @@ -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:
Expand All @@ -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
Expand All @@ -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):
Expand All @@ -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)
Expand All @@ -255,42 +254,41 @@ 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):
"""
Physical power off for an interval. Wait for login when complete.
: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()

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', 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):
"""
Expand Down Expand Up @@ -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
Expand All @@ -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):
Expand Down Expand Up @@ -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))

0 comments on commit 845d8fb

Please sign in to comment.