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()