oeqa/qemurunner: Improve logging
Python unittest intercepts stdout and stderr however qemurunner sets up a streamhandler before that interception occurs, hence the messages spam the unittest output. By moving the logging init to the class init time, we use the unittest stdout/stderr and this means unittest can only show the log output upon failure. This cleans up the selftest and testimage output whilst still showing logging upon failure. (From OE-Core rev: 9099cecc727fe0ae5f1559582426d30ba7a9f4d3) (From OE-Core rev: ee13216284c4d49b762eaab488f21de573d2079d) Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org> Signed-off-by: Armin Kuster <akuster808@gmail.com> Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
This commit is contained in:
Richard Purdie
parent
8f35c388b4
commit
50750e1572
|
|
@ -17,11 +17,8 @@ import errno
|
|||
import string
|
||||
import threading
|
||||
import codecs
|
||||
from oeqa.utils.dump import HostDumper
|
||||
|
||||
import logging
|
||||
logger = logging.getLogger("BitBake.QemuRunner")
|
||||
logger.addHandler(logging.StreamHandler())
|
||||
from oeqa.utils.dump import HostDumper
|
||||
|
||||
# Get Unicode non printable control chars
|
||||
control_range = list(range(0,32))+list(range(127,160))
|
||||
|
|
@ -58,6 +55,9 @@ class QemuRunner:
|
|||
self.runqemutime = 120
|
||||
self.host_dumper = HostDumper(dump_host_cmds, dump_dir)
|
||||
|
||||
self.logger = logging.getLogger("BitBake.QemuRunner")
|
||||
self.logger.addHandler(logging.StreamHandler(sys.stdout))
|
||||
|
||||
def create_socket(self):
|
||||
try:
|
||||
sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
|
||||
|
|
@ -65,7 +65,7 @@ class QemuRunner:
|
|||
sock.bind(("127.0.0.1",0))
|
||||
sock.listen(2)
|
||||
port = sock.getsockname()[1]
|
||||
logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port)
|
||||
self.logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port)
|
||||
return (sock, port)
|
||||
|
||||
except socket.error:
|
||||
|
|
@ -91,8 +91,8 @@ class QemuRunner:
|
|||
def handleSIGCHLD(self, signum, frame):
|
||||
if self.runqemu and self.runqemu.poll():
|
||||
if self.runqemu.returncode:
|
||||
logger.info('runqemu exited with code %d' % self.runqemu.returncode)
|
||||
logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout))
|
||||
self.logger.info('runqemu exited with code %d' % self.runqemu.returncode)
|
||||
self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout))
|
||||
self.stop()
|
||||
self._dump_host()
|
||||
raise SystemExit
|
||||
|
|
@ -104,15 +104,15 @@ class QemuRunner:
|
|||
# interact badly with screensavers.
|
||||
os.environ["QEMU_DONT_GRAB"] = "1"
|
||||
if not os.path.exists(self.rootfs):
|
||||
logger.error("Invalid rootfs %s" % self.rootfs)
|
||||
self.logger.error("Invalid rootfs %s" % self.rootfs)
|
||||
return False
|
||||
if not os.path.exists(self.tmpdir):
|
||||
logger.error("Invalid TMPDIR path %s" % self.tmpdir)
|
||||
self.logger.error("Invalid TMPDIR path %s" % self.tmpdir)
|
||||
return False
|
||||
else:
|
||||
os.environ["OE_TMPDIR"] = self.tmpdir
|
||||
if not os.path.exists(self.deploy_dir_image):
|
||||
logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
|
||||
self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
|
||||
return False
|
||||
else:
|
||||
os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
|
||||
|
|
@ -120,10 +120,10 @@ class QemuRunner:
|
|||
if not launch_cmd:
|
||||
launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams)
|
||||
if self.use_kvm:
|
||||
logger.info('Using kvm for runqemu')
|
||||
self.logger.info('Using kvm for runqemu')
|
||||
launch_cmd += ' kvm'
|
||||
else:
|
||||
logger.info('Not using kvm for runqemu')
|
||||
self.logger.info('Not using kvm for runqemu')
|
||||
if not self.display:
|
||||
launch_cmd += ' nographic'
|
||||
launch_cmd += ' %s %s' % (self.machine, self.rootfs)
|
||||
|
|
@ -135,7 +135,7 @@ class QemuRunner:
|
|||
threadsock, threadport = self.create_socket()
|
||||
self.server_socket, self.serverport = self.create_socket()
|
||||
except socket.error as msg:
|
||||
logger.error("Failed to create listening socket: %s" % msg[1])
|
||||
self.logger.error("Failed to create listening socket: %s" % msg[1])
|
||||
return False
|
||||
|
||||
bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1'
|
||||
|
|
@ -151,7 +151,7 @@ class QemuRunner:
|
|||
self.origchldhandler = signal.getsignal(signal.SIGCHLD)
|
||||
signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
|
||||
|
||||
logger.info('launchcmd=%s'%(launch_cmd))
|
||||
self.logger.info('launchcmd=%s'%(launch_cmd))
|
||||
|
||||
# FIXME: We pass in stdin=subprocess.PIPE here to work around stty
|
||||
# blocking at the end of the runqemu script when using this within
|
||||
|
|
@ -186,24 +186,24 @@ class QemuRunner:
|
|||
os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
|
||||
sys.exit(0)
|
||||
|
||||
logger.info("runqemu started, pid is %s" % self.runqemu.pid)
|
||||
logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime)
|
||||
self.logger.info("runqemu started, pid is %s" % self.runqemu.pid)
|
||||
self.logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime)
|
||||
endtime = time.time() + self.runqemutime
|
||||
while not self.is_alive() and time.time() < endtime:
|
||||
if self.runqemu.poll():
|
||||
if self.runqemu.returncode:
|
||||
# No point waiting any longer
|
||||
logger.info('runqemu exited with code %d' % self.runqemu.returncode)
|
||||
self.logger.info('runqemu exited with code %d' % self.runqemu.returncode)
|
||||
self._dump_host()
|
||||
self.stop()
|
||||
logger.info("Output from runqemu:\n%s" % self.getOutput(output))
|
||||
self.logger.info("Output from runqemu:\n%s" % self.getOutput(output))
|
||||
return False
|
||||
time.sleep(1)
|
||||
|
||||
out = self.getOutput(output)
|
||||
netconf = False # network configuration is not required by default
|
||||
if self.is_alive():
|
||||
logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid))
|
||||
self.logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid))
|
||||
if get_ip:
|
||||
cmdline = ''
|
||||
with open('/proc/%s/cmdline' % self.qemupid) as p:
|
||||
|
|
@ -215,7 +215,7 @@ class QemuRunner:
|
|||
ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
|
||||
self.ip = ips[0]
|
||||
self.server_ip = ips[1]
|
||||
logger.info("qemu cmdline used:\n{}".format(cmdline))
|
||||
self.logger.info("qemu cmdline used:\n{}".format(cmdline))
|
||||
except (IndexError, ValueError):
|
||||
# Try to get network configuration from runqemu output
|
||||
match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*',
|
||||
|
|
@ -227,27 +227,27 @@ class QemuRunner:
|
|||
# and guest networking is not configured
|
||||
netconf = True
|
||||
else:
|
||||
logger.error("Couldn't get ip from qemu command line and runqemu output! "
|
||||
self.logger.error("Couldn't get ip from qemu command line and runqemu output! "
|
||||
"Here is the qemu command line used:\n%s\n"
|
||||
"and output from runqemu:\n%s" % (cmdline, out))
|
||||
self._dump_host()
|
||||
self.stop()
|
||||
return False
|
||||
|
||||
logger.info("Target IP: %s" % self.ip)
|
||||
logger.info("Server IP: %s" % self.server_ip)
|
||||
self.logger.info("Target IP: %s" % self.ip)
|
||||
self.logger.info("Server IP: %s" % self.server_ip)
|
||||
|
||||
self.thread = LoggingThread(self.log, threadsock, logger)
|
||||
self.thread = LoggingThread(self.log, threadsock, self.logger)
|
||||
self.thread.start()
|
||||
if not self.thread.connection_established.wait(self.boottime):
|
||||
logger.error("Didn't receive a console connection from qemu. "
|
||||
self.logger.error("Didn't receive a console connection from qemu. "
|
||||
"Here is the qemu command line used:\n%s\nand "
|
||||
"output from runqemu:\n%s" % (cmdline, out))
|
||||
self.stop_thread()
|
||||
return False
|
||||
|
||||
logger.info("Output from runqemu:\n%s", out)
|
||||
logger.info("Waiting at most %d seconds for login banner" % self.boottime)
|
||||
self.logger.info("Output from runqemu:\n%s", out)
|
||||
self.logger.info("Waiting at most %d seconds for login banner" % self.boottime)
|
||||
endtime = time.time() + self.boottime
|
||||
socklist = [self.server_socket]
|
||||
reachedlogin = False
|
||||
|
|
@ -266,7 +266,7 @@ class QemuRunner:
|
|||
qemusock.setblocking(0)
|
||||
socklist.append(qemusock)
|
||||
socklist.remove(self.server_socket)
|
||||
logger.info("Connection from %s:%s" % addr)
|
||||
self.logger.info("Connection from %s:%s" % addr)
|
||||
else:
|
||||
data = data + sock.recv(1024)
|
||||
if data:
|
||||
|
|
@ -278,7 +278,7 @@ class QemuRunner:
|
|||
self.server_socket = qemusock
|
||||
stopread = True
|
||||
reachedlogin = True
|
||||
logger.info("Reached login banner")
|
||||
self.logger.info("Reached login banner")
|
||||
except UnicodeDecodeError:
|
||||
continue
|
||||
else:
|
||||
|
|
@ -287,10 +287,10 @@ class QemuRunner:
|
|||
stopread = True
|
||||
|
||||
if not reachedlogin:
|
||||
logger.info("Target didn't reached login boot in %d seconds" % self.boottime)
|
||||
self.logger.info("Target didn't reached login boot in %d seconds" % self.boottime)
|
||||
lines = "\n".join(bootlog.splitlines()[-25:])
|
||||
logger.info("Last 25 lines of text:\n%s" % lines)
|
||||
logger.info("Check full boot log: %s" % self.logfile)
|
||||
self.logger.info("Last 25 lines of text:\n%s" % lines)
|
||||
self.logger.info("Check full boot log: %s" % self.logfile)
|
||||
self._dump_host()
|
||||
self.stop()
|
||||
return False
|
||||
|
|
@ -300,30 +300,30 @@ class QemuRunner:
|
|||
(status, output) = self.run_serial("root\n", raw=True)
|
||||
if re.search("root@[a-zA-Z0-9\-]+:~#", output):
|
||||
self.logged = True
|
||||
logger.info("Logged as root in serial console")
|
||||
self.logger.info("Logged as root in serial console")
|
||||
if netconf:
|
||||
# configure guest networking
|
||||
cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
|
||||
output = self.run_serial(cmd, raw=True)[1]
|
||||
if re.search("root@[a-zA-Z0-9\-]+:~#", output):
|
||||
logger.info("configured ip address %s", self.ip)
|
||||
self.logger.info("configured ip address %s", self.ip)
|
||||
else:
|
||||
logger.info("Couldn't configure guest networking")
|
||||
self.logger.info("Couldn't configure guest networking")
|
||||
else:
|
||||
logger.info("Couldn't login into serial console"
|
||||
self.logger.info("Couldn't login into serial console"
|
||||
" as root using blank password")
|
||||
except:
|
||||
logger.info("Serial console failed while trying to login")
|
||||
self.logger.info("Serial console failed while trying to login")
|
||||
|
||||
else:
|
||||
logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime)
|
||||
self.logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime)
|
||||
self._dump_host()
|
||||
self.stop()
|
||||
op = self.getOutput(output)
|
||||
if op:
|
||||
logger.error("Output from runqemu:\n%s" % op)
|
||||
self.logger.error("Output from runqemu:\n%s" % op)
|
||||
else:
|
||||
logger.error("No output from runqemu.\n")
|
||||
self.logger.error("No output from runqemu.\n")
|
||||
return False
|
||||
|
||||
return self.is_alive()
|
||||
|
|
@ -336,7 +336,7 @@ class QemuRunner:
|
|||
if self.runqemu:
|
||||
if hasattr(self, "monitorpid"):
|
||||
os.kill(self.monitorpid, signal.SIGKILL)
|
||||
logger.info("Sending SIGTERM to runqemu")
|
||||
self.logger.info("Sending SIGTERM to runqemu")
|
||||
try:
|
||||
os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
|
||||
except OSError as e:
|
||||
|
|
@ -346,7 +346,7 @@ class QemuRunner:
|
|||
while self.runqemu.poll() is None and time.time() < endtime:
|
||||
time.sleep(1)
|
||||
if self.runqemu.poll() is None:
|
||||
logger.info("Sending SIGKILL to runqemu")
|
||||
self.logger.info("Sending SIGKILL to runqemu")
|
||||
os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
|
||||
self.runqemu = None
|
||||
if hasattr(self, 'server_socket') and self.server_socket:
|
||||
|
|
@ -361,7 +361,7 @@ class QemuRunner:
|
|||
# qemu-system behaves well and a SIGTERM is enough
|
||||
os.kill(self.qemupid, signal.SIGTERM)
|
||||
except ProcessLookupError as e:
|
||||
logger.warn('qemu-system ended unexpectedly')
|
||||
self.logger.warn('qemu-system ended unexpectedly')
|
||||
|
||||
def stop_thread(self):
|
||||
if self.thread and self.thread.is_alive():
|
||||
|
|
@ -369,7 +369,7 @@ class QemuRunner:
|
|||
self.thread.join()
|
||||
|
||||
def restart(self, qemuparams = None):
|
||||
logger.info("Restarting qemu process")
|
||||
self.logger.info("Restarting qemu process")
|
||||
if self.runqemu.poll() is None:
|
||||
self.stop()
|
||||
if self.start(qemuparams):
|
||||
|
|
@ -478,7 +478,7 @@ class QemuRunner:
|
|||
|
||||
def _dump_host(self):
|
||||
self.host_dumper.create_dir("qemu")
|
||||
logger.warn("Qemu ended unexpectedly, dump data from host"
|
||||
self.logger.warn("Qemu ended unexpectedly, dump data from host"
|
||||
" is in %s" % self.host_dumper.dump_dir)
|
||||
self.host_dumper.dump_host()
|
||||
|
||||
|
|
|
|||
Loading…
Reference in New Issue