def boot_to_login_prompt(domain,
console,
timeout=(STARTUP_TIMEOUT + LOGIN_TIMEOUT)):
retried = False
while True:
if console:
domain.reboot()
else:
console = _start(domain)
lapsed_time = timing.Lapsed()
domain.logger.info("waiting %s seconds for login prompt", timeout)
if console.expect_exact([pexpect.TIMEOUT, "login: "******"login prompt appeared after %s", lapsed_time)
return console
if retried:
domain.logger.error("domain failed to boot after %s, giving up",
laped_time)
raise pexpect.TIMEOUT("domain %d failed to boot" % domain)
retried = True
domain.logger.error(
"domain failed to boot after %s, waiting %d seconds for it to power down",
lapsed_time, SHUTDOWN_TIMEOUT)
shutdown_time = timing.Lapsed()
domain.shutdown()
if console.expect_exact([pexpect.TIMEOUT, pexpect.EOF],
timeout=SHUTDOWN_TIMEOUT):
domain.logger.info("domain powered down after %s", shutdown_time)
console = None
continue
domain.logger.error(
"domain failed to power down after %s, waiting %d seconds for the power cord to be pulled",
shutdown_time, SHUTDOWN_TIMEOUT)
shutdown_time = timing.Lapsed()
domain.destroy()
if console.expect_exact([pexpect.TIMEOUT, pexpect.EOF],
timeout=SHUTDOWN_TIMEOUT):
domain.logger.info("domain appears to have switched off after %s",
shutdown_time)
console = None
continue
domain.logger.error("domain failed to switch off after %s, giving up",
shutdown_time)
raise pexpect.TIMEOUT("Domain %s is wedged" % domain)
def _login(domain, console, username, password, login_timeout, password_timeout, shell_timeout):
lapsed_time = timing.Lapsed()
domain.logger.info("waiting %s seconds for login prompt; %s seconds for password prompt; %s seconds for shell prompt",
login_timeout, password_timeout, shell_timeout)
domain.logger.debug("console prompt: %s", console.prompt.pattern)
domain.logger.debug("sending control-c+carriage return, waiting %s seconds for login or shell prompt", login_timeout)
console.sendintr()
console.sendline("")
if _wait_for_login_prompt(domain, console, timeout=login_timeout,
also_expect=[console.prompt]) == 1:
# shell prompt
domain.logger.info("We're in after %s! Someone forgot to log out ...", lapsed_time)
return
domain.logger.debug("sending username '%s' waiting %s seconds for password or shell prompt", \
username, password_timeout)
console.sendline(username)
if console.expect(["Password: "******"We're in after %s! No password ...", lapsed_time)
return
domain.logger.debug("sending password '%s', waiting %s seconds for shell prompt",
password, shell_timeout)
console.sendline(password)
console.expect(console.prompt, timeout=shell_timeout)
domain.logger.info("We're in after %s!", lapsed_time)
def expect(self, expect, timeout=TIMEOUT, searchwindowsize=-1):
timer = timing.Lapsed()
match = self.child.expect(expect,
timeout=timeout,
searchwindowsize=searchwindowsize)
self.logger.debug("%s matched after %s", ascii(expect[match]), timer)
return match
def _reboot_to_login_prompt(domain, console):
# Drain any existing output.
domain.logger.debug("draining any existing output")
console.expect(pexpect.TIMEOUT, timeout=0)
#
# The reboot pattern needs to match all the output upto the point
# where the machine is reset. That way, the next pattern below
# can detect that the reset did something and the machine is
# probably rebooting.
timeouts = [SHUTDOWN_TIMEOUT, START_TIMEOUT, LOGIN_PROMPT_TIMEOUT]
timeout = 0
for t in timeouts:
timeout += t
domain.logger.info("waiting %s seconds for reboot and login prompt",
timeout)
domain.reboot()
timer = timing.Lapsed()
for timeout in timeouts:
# pexpect's pattern matcher is buggy and, if there is too much
# output, it may not match "reboot".
match = _wait_for_login_prompt(
domain,
console,
timeout=timeout,
also_expect=["reboot: Power down\r\n", pexpect.TIMEOUT])
if match == 0:
return console
elif match == 1:
domain.logger.info("domain rebooted after %s", timer)
elif console.child.buffer == "":
# HACK!
domain.logger.error(
"domain appears stuck, no output received after waiting %d seconds",
timeout)
break
# On some Fedora releases (F23, F24), instead of resetting, the
# domain will hang. Either it spontaneously suspends (PAUSED) or
# it just sits there wedged.
destroy = True
if domain.state() == virsh.STATE.PAUSED:
destroy = False
domain.logger.error("domain suspended, trying resume")
status, output = domain.resume()
if status:
domain.logger.error("domain resume failed: %s", output)
destroy = True
if destroy:
domain.logger.error("domain hung, trying to pull the power cord")
domain.destroy()
console.expect_exact(pexpect.EOF, timeout=SHUTDOWN_TIMEOUT)
console = _start(domain, timeout=START_TIMEOUT)
# Now wait for login prompt.
_wait_for_login_prompt(domain, console, timeout=LOGIN_PROMPT_TIMEOUT)
return console
def expect(self, expect, timeout=TIMEOUT, searchwindowsize=-1):
timer = timing.Lapsed()
print('\n' * 10)
print(expect)
print(type(expect), '\n\n')
match = self.child.expect(expect,
timeout=TIMEOUT,
searchwindowsize=searchwindowsize)
print(match)
self.logger.debug("%s matched after %s", ascii(expect[match]), timer)
return match
def boot_and_login(domain, console, login=LOGIN, password=PASSWORD):
console = boot_to_login_prompt(domain, console)
if not console:
domain.logger.error("domain not running")
return None
# try to login
timeout = PASSWORD_TIMEOUT
domain.logger.info("got login prompt; sending '%s' and waiting %s seconds for password (or shell) prompt", \
login, timeout)
console.sendline(login)
return _login(domain, console, login=login, password=password,
lapsed_time=timing.Lapsed(), timeout=timeout)
def _startup(domain, console, timeout=STARTUP_TIMEOUT):
expected = "Started Login Service"
# XXX: While searchwindowsize=len(expected) should technically be
# sufficient to speed up matching, it isn't. In fact, when more
# than searchwindowsize is read as a single block, pexpect only
# searchs the last searchwindowsize characters missing anything
# before it.
#
# See: https://github.com/pexpect/pexpect/issues/203
domain.logger.info("waiting %d seconds for domain to start (%s)", timeout,
expected)
lapsed_time = timing.Lapsed()
console.expect_exact(expected, timeout=timeout)
domain.logger.info("domain started after %s", lapsed_time)
def _wait_for_login_prompt(domain, console, timeout, also_expect=[]):
# If match is non-empty, append it, so the first index is 1
timer = timing.Lapsed()
# Create a new list, otherwise the default [] ends up containing
# lots of login prompts ...
matches = ["login: "******"waiting %d seconds for %s",
timeout, " or ".join(ascii(match) for match in matches))
match = console.expect(matches, timeout=timeout)
# always report a prompt match, let caller decide if other cases
# should be verbose.
domain.logger.log(match == 0 and logutil.INFO or logutil.DEBUG,
"%s matched after %s", ascii(matches[match]), timer)
return match
def login(domain, console, login=LOGIN, password=PASSWORD):
if not console:
domain.logger.error("domain not running")
return None
lapsed_time = timing.Lapsed()
timeout=LOGIN_TIMEOUT
domain.logger.info("sending control-c+carriage return, waiting %s seconds for login (or shell) prompt",
timeout)
console.sendintr()
console.sendline("")
# try to login
return _login(domain, console, login=login, password=password,
lapsed_time=lapsed_time, timeout=timeout)
def shutdown(domain, console=None, shutdown_timeout=SHUTDOWN_TIMEOUT):
lapsed_time = timing.Lapsed()
console = console or domain.console()
if not console:
domain.logger.error("domain already shutdown")
return None
domain.logger.info("waiting %d seconds for domain to shutdown", shutdown_timeout)
domain.shutdown()
if console.expect([pexpect.EOF,pexpect.TIMEOUT], timeout=shutdown_timeout):
domain.logger.error("timeout waiting for shutdown, destroying it")
domain.destroy()
if console.expect([pexpect.EOF,pexpect.TIMEOUT], timeout=shutdown_timeout):
domain.logger.error("timeout waiting for destroy, giving up")
return True
return False
domain.logger.info("domain shutdown after %s", lapsed_time)
return False
def reboot(domain,
console=None,
shutdown_timeout=SHUTDOWN_TIMEOUT,
startup_timeout=STARTUP_TIMEOUT):
console = console or domain.console()
if not console:
domain.logger.error("domain is shutdown")
return None
domain.logger.info("waiting %d seconds for domain to reboot",
shutdown_timeout)
lapsed_time = timing.Lapsed()
domain.reboot()
try:
console.expect("\[\s*[0-9]+\.[0-9]+]\s+reboot:",
timeout=SHUTDOWN_TIMEOUT)
domain.logger.info("domain rebooted after %s", lapsed_time)
except pexpect.TIMEOUT:
domain.logger.error("domain failed to reboot after %s, resetting it",
lapsed_time)
domain.reset()
# give the domain extra time to start
startup_timeout = startup_timeout * 4
try:
_startup(domain, console, timeout=startup_timeout)
return console
except pexpect.TIMEOUT:
domain.logger.error(
"domain failed to start after %s, power cycling it", lapsed_time)
# On F23 the domain sometimes becomes wedged in the PAUSED
# state. When it does, give it a full reset.
if domain.state() == virsh.STATE.PAUSED:
domain.destroy()
else:
domain.shutdown()
console.expect(pexpect.EOF, timeout=shutdown_timeout)
return start(domain)
def shutdown(self, timeout=SHUTDOWN_TIMEOUT):
"""Use the console to detect the shutdown - if/when the domain stops
it will exit giving an EOF.
"""
console = self.console()
if not console:
self.logger.error("domain already shutdown")
return True
self.logger.info("waiting %d seconds for domain to shutdown", timeout)
lapsed_time = timing.Lapsed()
self._shutdown()
if console.expect([pexpect.EOF, pexpect.TIMEOUT],
timeout=timeout) == 0:
self.logger.info("domain shutdown after %s", lapsed_time)
self._console = False
self.logger.info("domain state is: %s", self.state())
return True
self.logger.error("timeout shutting down domain")
return self.destroy()
def destroy(self, timeout=DESTROY_TIMEOUT):
"""Use the console to detect a destroyed domain - if/when the domain
stops it will exit giving an EOF.
"""
console = self.console()
if not console:
self.logger.error("domain already destroyed")
return True
self.logger.info("waiting %d seconds for domain to be destroyed",
timeout)
lapsed_time = timing.Lapsed()
self._destroy()
if console.expect([pexpect.EOF, pexpect.TIMEOUT],
timeout=timeout) == 0:
self.logger.info("domain destroyed after %s", lapsed_time)
self._console = False
return True
self.logger.error("timeout destroying domain, giving up")
self._console = None
return False
def debug_time(self, fmt, *args, logfile=None, loglevel=DEBUG, timer=None):
return DebugTime(logger_adapter=self,
logfile=logfile,
loglevel=loglevel,
action=(fmt % args),
timer=(timer or timing.Lapsed()))
def _reboot_to_login_prompt(domain, console):
# Drain any existing output.
console.drain()
# The reboot pattern needs to match all the output up to the point
# where the machine is reset. That way, the next pattern below
# can detect that the reset did something and the machine is
# probably rebooting.
timeouts = [SHUTDOWN_TIMEOUT, START_TIMEOUT, LOGIN_PROMPT_TIMEOUT]
timeout = 0
for t in timeouts:
timeout += t
domain.logger.info("waiting %s seconds for reboot and login prompt",
timeout)
domain.reboot()
timer = timing.Lapsed()
for timeout in timeouts:
# pexpect's pattern matcher is buggy and, if there is too much
# output, it may not match "reboot". virsh's behaviour is
# also buggy, see further down.
match = console.expect([
LOGIN_PROMPT, "reboot: Power down\r\n", pexpect.EOF,
pexpect.TIMEOUT
],
timeout=timeout)
if match == 0:
# login prompt (reboot message was missed)
return console
elif match == 1:
# reboot message
domain.logger.info("domain rebooted after %s", timer)
elif match == 2:
# On F26, in response to the reset(?), virsh will
# spontaneously disconnect.
domain.logger.error("domain disconnected spontaneously after %s",
timer)
break
elif match == 3 and console.child.buffer == "":
# On F23, F24, F25, instead of resetting, the domain will
# hang. The symptoms are a .TIMEOUT and an empty buffer
# (HACK!).
domain.logger.error(
"domain appears stuck, no output received after waiting %d seconds",
timeout)
break
# Things aren't going well. Per above Fedora can screw up or the
# domain is just really slow. Try destroying the domain and then
# cold booting it.
destroy = True
if domain.state() == virsh.STATE.PAUSED:
destroy = False
domain.logger.error("domain suspended, trying resume")
status, output = domain.resume()
if status:
domain.logger.error("domain resume failed: %s", output)
destroy = True
if destroy:
domain.logger.error("domain hung, trying to pull the power cord")
domain.destroy()
console.expect_exact(pexpect.EOF, timeout=SHUTDOWN_TIMEOUT)
console = _start(domain, timeout=START_TIMEOUT)
# Now wait for login prompt. If this second attempt fails then
# either a .TIMEOUT or a .EOF exception will be thrown and the
# test will be aborted (marked as unresolved).
console.expect([LOGIN_PROMPT], timeout=LOGIN_PROMPT_TIMEOUT)
return console
def __init__(self, logger, prefix, runtimes=None):
logging.LoggerAdapter.__init__(self, logger, {prefix: prefix})
self.debug_handler = DebugHandler()
self.logger.addHandler(self.debug_handler)
self.runtimes = runtimes or [timing.Lapsed()]
self.prefix = prefix
def __init__(self, logger_adapter, loglevel, action):
self.logger_adapter = logger_adapter
self.action = action
self.timer = timing.Lapsed()
self.loglevel = loglevel
def time(self, fmt, *args, loglevel=INFO, timer=None):
return LogTime(self,
loglevel=loglevel,
action=(fmt % args),
timer=(timer or timing.Lapsed()))
def __init__(self, prefix):
self.name = prefix
self.runtimes = [timing.Lapsed(timing.START_TIME)]
self.debug_handler = DebugHandler()
