From 93dca833c624f4a49526ca83a14673fb986470b3 Mon Sep 17 00:00:00 2001 From: Deb McLemore Date: Fri, 22 Feb 2019 20:50:27 -0600 Subject: [PATCH] OpTestFastReboot: PTY handling Tweak the timing of pexpect buffer management and add some debug logging to help aide problem determination when pty buffering issues. Signed-off-by: Deb McLemore --- testcases/OpTestFastReboot.py | 36 ++++++++++++++++++++++++++++------- 1 file changed, 29 insertions(+), 7 deletions(-) diff --git a/testcases/OpTestFastReboot.py b/testcases/OpTestFastReboot.py index 6b723f4a6..fb45120c3 100644 --- a/testcases/OpTestFastReboot.py +++ b/testcases/OpTestFastReboot.py @@ -59,11 +59,14 @@ def setUp(self): self.cv_HOST = conf.host() self.cv_IPMI = conf.ipmi() self.cv_SYSTEM = conf.system() + self.timeout = 30 def number_reboots_to_do(self): return 2 def boot_to_os(self): + self.timeout = 15 + self.target = OpSystemState.IPLing return False def get_fast_reset_count(self, c): @@ -91,8 +94,10 @@ def runTest(self): getting executed in both petitboot and host OS ''' if self.boot_to_os(): + self.cv_SYSTEM.sys_set_bootdev_no_override() self.cv_SYSTEM.goto_state(OpSystemState.OS) else: + self.cv_SYSTEM.sys_set_bootdev_setup() self.cv_SYSTEM.goto_state(OpSystemState.PETITBOOT_SHELL) c = self.cv_SYSTEM.console @@ -114,7 +119,7 @@ def runTest(self): "grep '^cpu' /proc/cpuinfo|uniq|sed -e 's/^.*: //;s/[,]* .*//;'")) log.debug(repr(cpu)) if cpu not in ["POWER9", "POWER8", "POWER8E"]: - self.skipTest("Fast Reboot not supported on %s" % cpu) + self.skipTest("Fast Reboot not supported on {}".format(cpu)) if not self.cv_SYSTEM.has_mtd_pnor_access(): self.skipTest("OpTestSystem does not have MTD PNOR access," @@ -128,34 +133,49 @@ def runTest(self): self.assertIn("feeling-lucky", res, "Failed to set the fast-reset mode") initialResetCount = self.get_fast_reset_count(c) - log.debug("INITIAL reset count: %d" % initialResetCount) + log.debug("FASTREBOOT initialResetCount={}".format(initialResetCount)) for i in range(0, self.number_reboots_to_do()): loopResetCount = self.get_fast_reset_count(c) # We do some funny things with the raw pty here, as # 'reboot' isn't meant to return self.pty = self.cv_SYSTEM.console.get_console() + log.debug("FASTREBOOT Expect Buffer ID={}".format(hex(id(self.pty)))) self.pty.sendline("reboot") - self.cv_SYSTEM.set_state(OpSystemState.IPLing) + self.cv_SYSTEM.set_state(self.target) + self.cv_SYSTEM.util.clear_state(self.cv_SYSTEM) # We're looking for a skiboot log message, that it's doing fast # reboot. We *may* not get this, as on some systems (notably IBM # FSP based systems) the skiboot log is *not* printed to IPMI # console if self.cv_SYSTEM.skiboot_log_on_console(): + log.debug("FASTREBOOT looking for RESET: Initiating fast reboot") + # timeout is only long enough, if we wait too long the expect + # buffer will not get the data to keep things moving rc = self.pty.expect([" RESET: Initiating fast reboot", pexpect.TIMEOUT, pexpect.EOF], - timeout=100) + timeout=self.timeout) + log.debug("FASTREBOOT rc={} (0=We found RESET 1=TIMEOUT 2=EOF)".format(rc)) + log.debug("FASTREBOOT before={}".format(self.pty.before)) + log.debug("FASTREBOOT after={}".format(self.pty.after)) if rc in [1, 2]: + log.debug("FASTREBOOT CLOSE Expect Buffer ID={}".format(hex(id(self.pty)))) c.close() # close the console obj if self.boot_to_os(): + log.debug("FASTREBOOT marker, we're now going to boot to OS") + self.cv_SYSTEM.sys_set_bootdev_no_override() self.cv_SYSTEM.goto_state(OpSystemState.OS) else: + log.debug("FASTREBOOT marker, we're now going to boot to PS") + self.cv_SYSTEM.sys_set_bootdev_setup() self.cv_SYSTEM.goto_state(OpSystemState.PETITBOOT_SHELL) newResetCount = self.get_fast_reset_count(c) self.assertTrue(loopResetCount < newResetCount, - "Did not do fast reboot") + "FASTREBOOT encountered a problem, loopResetCount {} >= newResetCount {}, check the debug logs" + .format(loopResetCount, newResetCount)) self.assertTrue(initialResetCount < newResetCount, - "Did not do fast reboot") - log.debug("Completed Fast reboot cycle %d" % i) + "FASTREBOOT encountered a problem, initialResetCount {} >= newResetCount {}, check the debug logs" + .format(initialResetCount, newResetCount)) + log.debug("FASTREBOOT completed cycle i={}".format(i)) c.run_command(BMC_CONST.NVRAM_DISABLE_FAST_RESET_MODE) try: @@ -170,11 +190,13 @@ def runTest(self): class FastRebootHost(OpTestFastReboot): def boot_to_os(self): + self.target = OpSystemState.BOOTING return True class FastRebootHostTorture(FastRebootHost): def boot_to_os(self): + self.target = OpSystemState.BOOTING return True def number_reboots_to_do(self):