diff options
Diffstat (limited to 'meta/lib/oeqa/utils/qemurunner.py')
-rw-r--r-- | meta/lib/oeqa/utils/qemurunner.py | 689 |
1 files changed, 484 insertions, 205 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index df73120254..05385763ac 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -1,12 +1,15 @@ +# # Copyright (C) 2013 Intel Corporation # -# Released under the MIT license (see COPYING.MIT) +# SPDX-License-Identifier: MIT +# # This module provides a class for starting qemu images using runqemu. # It's used by testimage.bbclass. import subprocess import os +import sys import time import signal import re @@ -16,10 +19,11 @@ import errno import string import threading import codecs -from oeqa.utils.dump import HostDumper - import logging -logger = logging.getLogger("BitBake.QemuRunner") +import tempfile +from oeqa.utils.dump import HostDumper +from collections import defaultdict +import importlib # Get Unicode non printable control chars control_range = list(range(0,32))+list(range(127,160)) @@ -29,16 +33,20 @@ re_control_char = re.compile('[%s]' % re.escape("".join(control_chars))) class QemuRunner: - def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds): + def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds, + use_kvm, logger, use_slirp=False, serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None): # Popen object for runqemu self.runqemu = None + self.runqemu_exited = False # pid of the qemu process that runqemu will start self.qemupid = None - # target ip - from the command line + # target ip - from the command line or runqemu output self.ip = None # host ip - where qemu is running self.server_ip = None + # target ip netmask + self.netmask = None self.machine = machine self.rootfs = rootfs @@ -49,9 +57,43 @@ class QemuRunner: self.boottime = boottime self.logged = False self.thread = None - - self.runqemutime = 60 + self.use_kvm = use_kvm + self.use_ovmf = use_ovmf + self.use_slirp = use_slirp + self.serial_ports = serial_ports + self.msg = '' + self.boot_patterns = boot_patterns + self.tmpfsdir = tmpfsdir + + self.runqemutime = 300 + if not workdir: + workdir = os.getcwd() + self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid()) self.host_dumper = HostDumper(dump_host_cmds, dump_dir) + self.monitorpipe = None + + self.logger = logger + # Whether we're expecting an exit and should show related errors + self.canexit = False + + # Enable testing other OS's + # Set commands for target communication, and default to Linux ALWAYS + # Other OS's or baremetal applications need to provide their + # own implementation passing it through QemuRunner's constructor + # or by passing them through TESTIMAGE_BOOT_PATTERNS[flag] + # provided variables, where <flag> is one of the mentioned below. + accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished'] + default_boot_patterns = defaultdict(str) + # Default to the usual paterns used to communicate with the target + default_boot_patterns['search_reached_prompt'] = ' login:' + default_boot_patterns['send_login_user'] = 'root\n' + default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#" + default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#" + + # Only override patterns that were set e.g. login user TESTIMAGE_BOOT_PATTERNS[send_login_user] = "webserver\n" + for pattern in accepted_patterns: + if not self.boot_patterns[pattern]: + self.boot_patterns[pattern] = default_boot_patterns[pattern] def create_socket(self): try: @@ -60,19 +102,23 @@ 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.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) return (sock, port) except socket.error: sock.close() raise + def decode_qemulog(self, todecode): + # Sanitize the data received from qemu as it may contain control characters + msg = todecode.decode("utf-8", errors='ignore') + msg = re_control_char.sub('', msg) + return msg + def log(self, msg): if self.logfile: - # It is needed to sanitize the data received from qemu - # because is possible to have control characters - msg = msg.decode("utf-8") - msg = re_control_char.sub('', msg) + msg = self.decode_qemulog(msg) + self.msg += msg with codecs.open(self.logfile, "a", encoding="utf-8") as f: f.write("%s" % msg) @@ -80,74 +126,135 @@ class QemuRunner: import fcntl fl = fcntl.fcntl(o, fcntl.F_GETFL) fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK) - return os.read(o.fileno(), 1000000).decode("utf-8") + try: + return os.read(o.fileno(), 1000000).decode("utf-8") + except BlockingIOError: + return "" 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.error('runqemu exited with code %d' % self.runqemu.returncode) + self.logger.error('Output from runqemu:\n%s' % self.getOutput(self.runqemu.stdout)) self.stop() self._dump_host() - raise SystemExit - def start(self, qemuparams = None, get_ip = True, extra_bootparams = None): + def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True): + env = os.environ.copy() if self.display: - os.environ["DISPLAY"] = self.display + env["DISPLAY"] = self.display # Set this flag so that Qemu doesn't do any grabs as SDL grabs # interact badly with screensavers. - os.environ["QEMU_DONT_GRAB"] = "1" + env["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 + env["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 + env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image + + if self.tmpfsdir: + env["RUNQEMU_TMPFS_DIR"] = self.tmpfsdir + + if not launch_cmd: + launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '') + if self.use_kvm: + self.logger.debug('Using kvm for runqemu') + launch_cmd += ' kvm' + else: + self.logger.debug('Not using kvm for runqemu') + if not self.display: + launch_cmd += ' nographic' + if self.use_slirp: + launch_cmd += ' slirp' + if self.use_ovmf: + launch_cmd += ' ovmf' + launch_cmd += ' %s %s' % (runqemuparams, self.machine) + if self.rootfs.endswith('.vmdk'): + self.logger.debug('Bypassing VMDK rootfs for runqemu') + else: + launch_cmd += ' %s' % (self.rootfs) + + return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env) + + def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None): + # use logfile to determine the recipe-sysroot-native path and + # then add in the site-packages path components and add that + # to the python sys.path so qmp.py can be found. + python_path = os.path.dirname(os.path.dirname(self.logfile)) + python_path += "/recipe-sysroot-native/usr/lib/qemu-python" + sys.path.append(python_path) + importlib.invalidate_caches() + try: + qmp = importlib.import_module("qmp") + except Exception as e: + self.logger.error("qemurunner: qmp.py missing, please ensure it's installed (%s)" % str(e)) + return False + # Path relative to tmpdir used as cwd for qemu below to avoid unix socket path length issues + qmp_file = "." + next(tempfile._get_candidate_names()) + qmp_param = ' -S -qmp unix:./%s,server,wait' % (qmp_file) + qmp_port = self.tmpdir + "/" + qmp_file + # Create a second socket connection for debugging use, + # note this will NOT cause qemu to block waiting for the connection + qmp_file2 = "." + next(tempfile._get_candidate_names()) + qmp_param += ' -qmp unix:./%s,server,nowait' % (qmp_file2) + qmp_port2 = self.tmpdir + "/" + qmp_file2 + self.logger.info("QMP Available for connection at %s" % (qmp_port2)) try: - threadsock, threadport = self.create_socket() + if self.serial_ports >= 2: + self.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' + bootparams = ' printk.time=1' if extra_bootparams: bootparams = bootparams + ' ' + extra_bootparams - self.qemuparams = 'bootparams="{0}" qemuparams="-serial tcp:127.0.0.1:{1}"'.format(bootparams, threadport) - if not self.display: - self.qemuparams = 'nographic ' + self.qemuparams + # Ask QEMU to store the QEMU process PID in file, this way we don't have to parse running processes + # and analyze descendents in order to determine it. + if os.path.exists(self.qemu_pidfile): + os.remove(self.qemu_pidfile) + self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1} {2}"'.format(bootparams, self.qemu_pidfile, qmp_param) + if qemuparams: self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"' + if self.serial_ports >= 2: + launch_cmd += ' tcpserial=%s:%s %s' % (threadport, self.serverport, self.qemuparams) + else: + launch_cmd += ' tcpserial=%s %s' % (self.serverport, self.qemuparams) + self.origchldhandler = signal.getsignal(signal.SIGCHLD) signal.signal(signal.SIGCHLD, self.handleSIGCHLD) - launch_cmd = 'runqemu tcpserial=%s %s %s %s' % (self.serverport, self.machine, self.rootfs, self.qemuparams) + self.logger.debug('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 # oe-selftest (this makes stty error out immediately). There ought # to be a proper fix but this will suffice for now. - self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp) + self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir) output = self.runqemu.stdout + launch_time = time.time() # - # We need the preexec_fn above so that all runqemu processes can easily be killed + # We need the preexec_fn above so that all runqemu processes can easily be killed # (by killing their process group). This presents a problem if this controlling - # process itself is killed however since those processes don't notice the death + # process itself is killed however since those processes don't notice the death # of the parent and merrily continue on. # - # Rather than hack runqemu to deal with this, we add something here instead. + # Rather than hack runqemu to deal with this, we add something here instead. # Basically we fork off another process which holds an open pipe to the parent # and also is setpgrp. If/when the pipe sees EOF from the parent dieing, it kills # the process group. This is like pctrl's PDEATHSIG but for a process group @@ -165,157 +272,336 @@ class QemuRunner: r = os.fdopen(r) x = r.read() os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) - sys.exit(0) + os._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.debug("runqemu started, pid is %s" % self.runqemu.pid) + self.logger.debug("waiting at most %s seconds for qemu pid (%s)" % + (self.runqemutime, time.strftime("%D %H:%M:%S"))) endtime = time.time() + self.runqemutime while not self.is_alive() and time.time() < endtime: if self.runqemu.poll(): + if self.runqemu_exited: + self.logger.warning("runqemu during is_alive() test") + return False if self.runqemu.returncode: # No point waiting any longer - logger.info('runqemu exited with code %d' % self.runqemu.returncode) + self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) self._dump_host() + self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output)) self.stop() - logger.info("Output from runqemu:\n%s" % self.getOutput(output)) return False - time.sleep(1) - - if self.is_alive(): - logger.info("qemu started - qemu procces pid is %s" % self.qemupid) - if get_ip: - cmdline = '' - with open('/proc/%s/cmdline' % self.qemupid) as p: - cmdline = p.read() - # It is needed to sanitize the data received - # because is possible to have control characters - cmdline = re_control_char.sub('', cmdline) + time.sleep(0.5) + + if self.runqemu_exited: + self.logger.warning("runqemu after timeout") + + if self.runqemu.returncode: + self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) + + if not self.is_alive(): + self.logger.error("Qemu pid didn't appear in %s seconds (%s)" % + (self.runqemutime, time.strftime("%D %H:%M:%S"))) + + qemu_pid = None + if os.path.isfile(self.qemu_pidfile): + with open(self.qemu_pidfile, 'r') as f: + qemu_pid = f.read().strip() + + self.logger.error("Status information, poll status: %s, pidfile exists: %s, pidfile contents %s, proc pid exists %s" + % (self.runqemu.poll(), os.path.isfile(self.qemu_pidfile), str(qemu_pid), os.path.exists("/proc/" + str(qemu_pid)))) + + # Dump all processes to help us to figure out what is going on... + ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0] + processes = ps.decode("utf-8") + self.logger.debug("Running processes:\n%s" % processes) + self._dump_host() + op = self.getOutput(output) + self.stop() + if op: + self.logger.error("Output from runqemu:\n%s" % op) + else: + self.logger.error("No output from runqemu.\n") + return False + + # Create the client socket for the QEMU Monitor Control Socket + # This will allow us to read status from Qemu if the the process + # is still alive + self.logger.debug("QMP Initializing to %s" % (qmp_port)) + # chdir dance for path length issues with unix sockets + origpath = os.getcwd() + try: + os.chdir(os.path.dirname(qmp_port)) + try: + from qmp.legacy import QEMUMonitorProtocol + self.qmp = QEMUMonitorProtocol(os.path.basename(qmp_port)) + except OSError as msg: + self.logger.warning("Failed to initialize qemu monitor socket: %s File: %s" % (msg, msg.filename)) + return False + + self.logger.debug("QMP Connecting to %s" % (qmp_port)) + if not os.path.exists(qmp_port) and self.is_alive(): + self.logger.debug("QMP Port does not exist waiting for it to be created") + endtime = time.time() + self.runqemutime + while not os.path.exists(qmp_port) and self.is_alive() and time.time() < endtime: + self.logger.info("QMP port does not exist yet!") + time.sleep(0.5) + if not os.path.exists(qmp_port) and self.is_alive(): + self.logger.warning("QMP Port still does not exist but QEMU is alive") + return False + + try: + # set timeout value for all QMP calls + self.qmp.settimeout(self.runqemutime) + self.qmp.connect() + connect_time = time.time() + self.logger.info("QMP connected to QEMU at %s and took %s seconds" % + (time.strftime("%D %H:%M:%S"), + time.time() - launch_time)) + except OSError as msg: + self.logger.warning("Failed to connect qemu monitor socket: %s File: %s" % (msg, msg.filename)) + return False + except qmp.legacy.QMPError as msg: + self.logger.warning("Failed to communicate with qemu monitor: %s" % (msg)) + return False + finally: + os.chdir(origpath) + + # We worry that mmap'd libraries may cause page faults which hang the qemu VM for periods + # causing failures. Before we "start" qemu, read through it's mapped files to try and + # ensure we don't hit page faults later + mapdir = "/proc/" + str(self.qemupid) + "/map_files/" + try: + for f in os.listdir(mapdir): try: - ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) - if not ips or len(ips) != 3: - raise ValueError - else: - self.ip = ips[0] - self.server_ip = ips[1] - except (IndexError, ValueError): - logger.info("Couldn't get ip from qemu process arguments! Here is the qemu command line used:\n%s\nand output from runqemu:\n%s" % (cmdline, self.getOutput(output))) + linktarget = os.readlink(os.path.join(mapdir, f)) + if not linktarget.startswith("/") or linktarget.startswith("/dev") or "deleted" in linktarget: + continue + with open(linktarget, "rb") as readf: + data = True + while data: + data = readf.read(4096) + except FileNotFoundError: + continue + # Centos7 doesn't allow us to read /map_files/ + except PermissionError: + pass + + # Release the qemu process to continue running + self.run_monitor('cont') + self.logger.info("QMP released QEMU at %s and took %s seconds from connect" % + (time.strftime("%D %H:%M:%S"), + time.time() - connect_time)) + + # We are alive: qemu is running + out = self.getOutput(output) + netconf = False # network configuration is not required by default + self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" % + (time.time() - (endtime - self.runqemutime), + self.qemupid, time.strftime("%D %H:%M:%S"))) + cmdline = '' + if get_ip: + with open('/proc/%s/cmdline' % self.qemupid) as p: + cmdline = p.read() + # It is needed to sanitize the data received + # because is possible to have control characters + cmdline = re_control_char.sub(' ', cmdline) + try: + if self.use_slirp: + tcp_ports = cmdline.split("hostfwd=tcp:")[1] + ip, tcp_ports = tcp_ports.split(":")[:2] + host_port = tcp_ports[:tcp_ports.find('-')] + self.ip = "%s:%s" % (ip, host_port) + else: + ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) + self.ip = ips[0] + self.server_ip = ips[1] + self.logger.debug("qemu cmdline used:\n{}".format(cmdline)) + except (IndexError, ValueError): + # Try to get network configuration from runqemu output + match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+).*', + out, re.MULTILINE|re.DOTALL) + if match: + self.ip, self.server_ip, self.netmask = match.groups() + # network configuration is required as we couldn't get it + # from the runqemu command line, so qemu doesn't run kernel + # and guest networking is not configured + netconf = True + else: + 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("qemu cmdline used:\n{}".format(cmdline)) - logger.info("Target IP: %s" % self.ip) - logger.info("Server IP: %s" % self.server_ip) - self.thread = LoggingThread(self.log, threadsock, logger) + self.logger.debug("Target IP: %s" % self.ip) + self.logger.debug("Server IP: %s" % self.server_ip) + + if self.serial_ports >= 2: + self.thread = LoggingThread(self.log, self.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, - self.getOutput(output))) + "output from runqemu:\n%s" % (cmdline, out)) self.stop_thread() return False - logger.info("Output from runqemu:\n%s", self.getOutput(output)) - logger.info("Waiting at most %d seconds for login banner" % self.boottime) - endtime = time.time() + self.boottime - socklist = [self.server_socket] - reachedlogin = False - stopread = False - qemusock = None - bootlog = '' - data = b'' - while time.time() < endtime and not stopread: - sread, swrite, serror = select.select(socklist, [], [], 5) - for sock in sread: - if sock is self.server_socket: - qemusock, addr = self.server_socket.accept() - qemusock.setblocking(0) - socklist.append(qemusock) - socklist.remove(self.server_socket) - logger.info("Connection from %s:%s" % addr) - else: - data = data + sock.recv(1024) - if data: - try: - data = data.decode("utf-8", errors="surrogateescape") - bootlog += data - data = b'' - if re.search(".* login:", bootlog): - self.server_socket = qemusock - stopread = True - reachedlogin = True - logger.info("Reached login banner") - except UnicodeDecodeError: - continue - else: - socklist.remove(sock) - sock.close() - stopread = True - - if not reachedlogin: - 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._dump_host() - self.stop() - return False - - # If we are not able to login the tests can continue + self.logger.debug("Output from runqemu:\n%s", out) + self.logger.debug("Waiting at most %d seconds for login banner (%s)" % + (self.boottime, time.strftime("%D %H:%M:%S"))) + endtime = time.time() + self.boottime + socklist = [self.server_socket] + reachedlogin = False + stopread = False + qemusock = None + bootlog = b'' + data = b'' + while time.time() < endtime and not stopread: try: - (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") + sread, swrite, serror = select.select(socklist, [], [], 5) + except InterruptedError: + continue + for sock in sread: + if sock is self.server_socket: + qemusock, addr = self.server_socket.accept() + qemusock.setblocking(0) + socklist.append(qemusock) + socklist.remove(self.server_socket) + self.logger.debug("Connection from %s:%s" % addr) else: - logger.info("Couldn't login into serial console" - " as root using blank password") - except: - logger.info("Serial console failed while trying to login") - - else: - logger.info("Qemu pid didn't appeared in %s seconds" % self.runqemutime) + # try to avoid reading only a single character at a time + time.sleep(0.1) + data = data + sock.recv(1024) + if data: + bootlog += data + if self.serial_ports < 2: + # this socket has mixed console/kernel data, log it to logfile + self.log(data) + + data = b'' + + decodedlog = self.decode_qemulog(bootlog) + if self.boot_patterns['search_reached_prompt'] in decodedlog: + self.server_socket = qemusock + stopread = True + reachedlogin = True + self.logger.debug("Reached login banner in %s seconds (%s, %s)" % + (time.time() - (endtime - self.boottime), + time.strftime("%D %H:%M:%S"), time.time())) + else: + # no need to check if reachedlogin unless we support multiple connections + self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" % + time.strftime("%D %H:%M:%S")) + socklist.remove(sock) + sock.close() + stopread = True + + if not reachedlogin: + if time.time() >= endtime: + self.logger.warning("Target didn't reach login banner in %d seconds (%s)" % + (self.boottime, time.strftime("%D %H:%M:%S"))) + tail = lambda l: "\n".join(l.splitlines()[-25:]) + bootlog = self.decode_qemulog(bootlog) + # in case bootlog is empty, use tail qemu log store at self.msg + lines = tail(bootlog if bootlog else self.msg) + self.logger.warning("Last 25 lines of text (%d):\n%s" % (len(bootlog), lines)) + self.logger.warning("Check full boot log: %s" % self.logfile) self._dump_host() self.stop() - logger.info("Output from runqemu:\n%s" % self.getOutput(output)) return False - return self.is_alive() + # If we are not able to login the tests can continue + try: + (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120) + if re.search(self.boot_patterns['search_login_succeeded'], output): + self.logged = True + self.logger.debug("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(r"root@[a-zA-Z0-9\-]+:~#", output): + self.logger.debug("configured ip address %s", self.ip) + else: + self.logger.debug("Couldn't configure guest networking") + else: + self.logger.warning("Couldn't login into serial console" + " as root using blank password") + self.logger.warning("The output:\n%s" % output) + except: + self.logger.warning("Serial console failed while trying to login") + return True def stop(self): - self.stop_thread() if hasattr(self, "origchldhandler"): signal.signal(signal.SIGCHLD, self.origchldhandler) + self.stop_thread() + self.stop_qemu_system() if self.runqemu: if hasattr(self, "monitorpid"): os.kill(self.monitorpid, signal.SIGKILL) - logger.info("Sending SIGTERM to runqemu") + self.logger.debug("Sending SIGTERM to runqemu") try: os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) except OSError as e: if e.errno != errno.ESRCH: raise - endtime = time.time() + self.runqemutime - 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") + try: + outs, errs = self.runqemu.communicate(timeout = self.runqemutime) + if outs: + self.logger.info("Output from runqemu:\n%s", outs.decode("utf-8")) + if errs: + self.logger.info("Stderr from runqemu:\n%s", errs.decode("utf-8")) + except TimeoutExpired: + self.logger.debug("Sending SIGKILL to runqemu") os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) - self.runqemu = None + if not self.runqemu.stdout.closed: + self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) + self.runqemu.stdin.close() + self.runqemu.stdout.close() + self.runqemu_exited = True + + if hasattr(self, 'qmp') and self.qmp: + self.qmp.close() + self.qmp = None if hasattr(self, 'server_socket') and self.server_socket: self.server_socket.close() self.server_socket = None + if hasattr(self, 'threadsock') and self.threadsock: + self.threadsock.close() + self.threadsock = None self.qemupid = None self.ip = None + if os.path.exists(self.qemu_pidfile): + try: + os.remove(self.qemu_pidfile) + except FileNotFoundError as e: + # We raced, ignore + pass + if self.monitorpipe: + self.monitorpipe.close() + + def stop_qemu_system(self): + if self.qemupid: + try: + # qemu-system behaves well and a SIGTERM is enough + os.kill(self.qemupid, signal.SIGTERM) + except ProcessLookupError as e: + self.logger.warning('qemu-system ended unexpectedly') def stop_thread(self): if self.thread and self.thread.is_alive(): self.thread.stop() self.thread.join() + def allowexit(self): + self.canexit = True + if self.thread: + self.thread.allowexit() + def restart(self, qemuparams = None): - logger.info("Restarting qemu process") + self.logger.warning("Restarting qemu process") if self.runqemu.poll() is None: self.stop() if self.start(qemuparams): @@ -323,59 +609,36 @@ class QemuRunner: return False def is_alive(self): - if not self.runqemu: + if not self.runqemu or self.runqemu.poll() is not None or self.runqemu_exited: return False - qemu_child = self.find_child(str(self.runqemu.pid)) - if qemu_child: - self.qemupid = qemu_child[0] - if os.path.exists("/proc/" + str(self.qemupid)): - return True + if os.path.isfile(self.qemu_pidfile): + # when handling pidfile, qemu creates the file, stat it, lock it and then write to it + # so it's possible that the file has been created but the content is empty + pidfile_timeout = time.time() + 3 + while time.time() < pidfile_timeout: + with open(self.qemu_pidfile, 'r') as f: + qemu_pid = f.read().strip() + # file created but not yet written contents + if not qemu_pid: + time.sleep(0.5) + continue + else: + if os.path.exists("/proc/" + qemu_pid): + self.qemupid = int(qemu_pid) + return True return False - def find_child(self,parent_pid): - # - # Walk the process tree from the process specified looking for a qemu-system. Return its [pid'cmd] - # - ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command'], stdout=subprocess.PIPE).communicate()[0] - processes = ps.decode("utf-8").split('\n') - nfields = len(processes[0].split()) - 1 - pids = {} - commands = {} - for row in processes[1:]: - data = row.split(None, nfields) - if len(data) != 3: - continue - if data[1] not in pids: - pids[data[1]] = [] - - pids[data[1]].append(data[0]) - commands[data[0]] = data[2] - - if parent_pid not in pids: - return [] - - parents = [] - newparents = pids[parent_pid] - while newparents: - next = [] - for p in newparents: - if p in pids: - for n in pids[p]: - if n not in parents and n not in next: - next.append(n) - if p not in parents: - parents.append(p) - newparents = next - #print("Children matching %s:" % str(parents)) - for p in parents: - # Need to be careful here since runqemu-internal runs "ldd qemu-system-xxxx" - # Also, old versions of ldd (2.11) run "LD_XXXX qemu-system-xxxx" - basecmd = commands[p].split()[0] - basecmd = os.path.basename(basecmd) - if "qemu-system" in basecmd and "-serial tcp" in commands[p]: - return [int(p),commands[p]] - - def run_serial(self, command, raw=False): + def run_monitor(self, command, args=None, timeout=60): + if hasattr(self, 'qmp') and self.qmp: + self.qmp.settimeout(timeout) + if args is not None: + return self.qmp.cmd(command, args) + else: + return self.qmp.cmd(command) + + def run_serial(self, command, raw=False, timeout=60): + # Returns (status, output) where status is 1 on success and 0 on error + # We assume target system have echo to get command status if not raw: command = "%s; echo $?\n" % command @@ -383,20 +646,30 @@ class QemuRunner: data = '' status = 0 self.server_socket.sendall(command.encode('utf-8')) - keepreading = True - while keepreading: - sread, _, _ = select.select([self.server_socket],[],[],5) + start = time.time() + end = start + timeout + while True: + now = time.time() + if now >= end: + data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout + break + try: + sread, _, _ = select.select([self.server_socket],[],[], end - now) + except InterruptedError: + continue if sread: + # try to avoid reading single character at a time + time.sleep(0.1) answer = self.server_socket.recv(1024) if answer: data += answer.decode('utf-8') # Search the prompt to stop - if re.search("[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#", data): - keepreading = False + if re.search(self.boot_patterns['search_cmd_finished'], data): + break else: - raise Exception("No data on serial console socket") - else: - keepreading = False + if self.canexit: + return (1, "") + raise Exception("No data on serial console socket, connection closed?") if data: if raw: @@ -418,7 +691,7 @@ class QemuRunner: def _dump_host(self): self.host_dumper.create_dir("qemu") - logger.warn("Qemu ended unexpectedly, dump data from host" + self.logger.warning("Qemu ended unexpectedly, dump data from host" " is in %s" % self.host_dumper.dump_dir) self.host_dumper.dump_host() @@ -434,6 +707,7 @@ class LoggingThread(threading.Thread): self.logger = logger self.readsock = None self.running = False + self.canexit = False self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL self.readevents = select.POLLIN | select.POLLPRI @@ -447,17 +721,17 @@ class LoggingThread(threading.Thread): self.teardown() def run(self): - self.logger.info("Starting logging thread") + self.logger.debug("Starting logging thread") self.readpipe, self.writepipe = os.pipe() threading.Thread.run(self) def stop(self): - self.logger.info("Stopping logging thread") + self.logger.debug("Stopping logging thread") if self.running: os.write(self.writepipe, bytes("stop", "utf-8")) def teardown(self): - self.logger.info("Tearing down logging thread") + self.logger.debug("Tearing down logging thread") self.close_socket(self.serversock) if self.readsock is not None: @@ -467,6 +741,9 @@ class LoggingThread(threading.Thread): self.close_ignore_error(self.writepipe) self.running = False + def allowexit(self): + self.canexit = True + def eventloop(self): poll = select.poll() event_read_mask = self.errorevents | self.readevents @@ -475,7 +752,7 @@ class LoggingThread(threading.Thread): breakout = False self.running = True - self.logger.info("Starting thread event loop") + self.logger.debug("Starting thread event loop") while not breakout: events = poll.poll() for event in events: @@ -485,19 +762,19 @@ class LoggingThread(threading.Thread): # Event to stop the thread if self.readpipe == event[0]: - self.logger.info("Stop event received") + self.logger.debug("Stop event received") breakout = True break # A connection request was received elif self.serversock.fileno() == event[0]: - self.logger.info("Connection request received") + self.logger.debug("Connection request received") self.readsock, _ = self.serversock.accept() self.readsock.setblocking(0) poll.unregister(self.serversock.fileno()) poll.register(self.readsock.fileno(), event_read_mask) - self.logger.info("Setting connection established event") + self.logger.debug("Setting connection established event") self.connection_established.set() # Actual data to be logged @@ -512,7 +789,7 @@ class LoggingThread(threading.Thread): data = self.readsock.recv(count) except socket.error as e: if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK: - return '' + return b'' else: raise @@ -523,7 +800,9 @@ class LoggingThread(threading.Thread): # happened. But for this code it counts as an # error since the connection shouldn't go away # until qemu exits. - raise Exception("Console connection closed unexpectedly") + if not self.canexit: + raise Exception("Console connection closed unexpectedly") + return b'' return data |