blob: abbc7f7d1f6605c981de585ba2768ae8147c1c96 [file] [log] [blame]
Brad Bishopc342db32019-05-15 21:57:59 -04001#
Patrick Williamsc124f4f2015-09-15 14:41:29 -05002# Copyright (C) 2013 Intel Corporation
3#
Brad Bishopc342db32019-05-15 21:57:59 -04004# SPDX-License-Identifier: MIT
5#
Patrick Williamsc124f4f2015-09-15 14:41:29 -05006
7# This module provides a class for starting qemu images using runqemu.
8# It's used by testimage.bbclass.
9
10import subprocess
11import os
Brad Bishop6e60e8b2018-02-01 10:27:11 -050012import sys
Patrick Williamsc124f4f2015-09-15 14:41:29 -050013import time
14import signal
15import re
16import socket
17import select
18import errno
Patrick Williamsf1e5d692016-03-30 15:21:19 -050019import string
Patrick Williamsc124f4f2015-09-15 14:41:29 -050020import threading
Patrick Williamsf1e5d692016-03-30 15:21:19 -050021import codecs
Patrick Williamsc124f4f2015-09-15 14:41:29 -050022import logging
Andrew Geisslerc926e172021-05-07 16:11:35 -050023import tempfile
Brad Bishopd7bf8c12018-02-25 22:55:05 -050024from oeqa.utils.dump import HostDumper
Andrew Geissler82c905d2020-04-13 13:39:40 -050025from collections import defaultdict
Andrew Geisslerc926e172021-05-07 16:11:35 -050026import importlib
Patrick Williamsc124f4f2015-09-15 14:41:29 -050027
Patrick Williamsf1e5d692016-03-30 15:21:19 -050028# Get Unicode non printable control chars
Patrick Williamsc0f7c042017-02-23 20:41:17 -060029control_range = list(range(0,32))+list(range(127,160))
30control_chars = [chr(x) for x in control_range
31 if chr(x) not in string.printable]
Patrick Williamsf1e5d692016-03-30 15:21:19 -050032re_control_char = re.compile('[%s]' % re.escape("".join(control_chars)))
33
Patrick Williamsc124f4f2015-09-15 14:41:29 -050034class QemuRunner:
35
Brad Bishop19323692019-04-05 15:28:33 -040036 def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds,
Andrew Geissler3b8a17c2021-04-15 15:55:55 -050037 use_kvm, logger, use_slirp=False, serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None):
Patrick Williamsc124f4f2015-09-15 14:41:29 -050038
39 # Popen object for runqemu
40 self.runqemu = None
Andrew Geissler82c905d2020-04-13 13:39:40 -050041 self.runqemu_exited = False
Patrick Williamsc124f4f2015-09-15 14:41:29 -050042 # pid of the qemu process that runqemu will start
43 self.qemupid = None
Brad Bishop6e60e8b2018-02-01 10:27:11 -050044 # target ip - from the command line or runqemu output
Patrick Williamsc124f4f2015-09-15 14:41:29 -050045 self.ip = None
46 # host ip - where qemu is running
47 self.server_ip = None
Brad Bishop6e60e8b2018-02-01 10:27:11 -050048 # target ip netmask
49 self.netmask = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -050050
51 self.machine = machine
52 self.rootfs = rootfs
53 self.display = display
54 self.tmpdir = tmpdir
55 self.deploy_dir_image = deploy_dir_image
56 self.logfile = logfile
57 self.boottime = boottime
58 self.logged = False
59 self.thread = None
Patrick Williamsc0f7c042017-02-23 20:41:17 -060060 self.use_kvm = use_kvm
Andrew Geissler82c905d2020-04-13 13:39:40 -050061 self.use_ovmf = use_ovmf
Brad Bishop19323692019-04-05 15:28:33 -040062 self.use_slirp = use_slirp
Andrew Geissler82c905d2020-04-13 13:39:40 -050063 self.serial_ports = serial_ports
Brad Bishopd7bf8c12018-02-25 22:55:05 -050064 self.msg = ''
Andrew Geissler82c905d2020-04-13 13:39:40 -050065 self.boot_patterns = boot_patterns
Andrew Geissler3b8a17c2021-04-15 15:55:55 -050066 self.tmpfsdir = tmpfsdir
Patrick Williamsc124f4f2015-09-15 14:41:29 -050067
Andrew Geissler09036742021-06-25 14:25:14 -050068 self.runqemutime = 300
Andrew Geisslerb7d28612020-07-24 16:15:54 -050069 if not workdir:
70 workdir = os.getcwd()
71 self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid())
Patrick Williamsc124f4f2015-09-15 14:41:29 -050072 self.host_dumper = HostDumper(dump_host_cmds, dump_dir)
Brad Bishop15ae2502019-06-18 21:44:24 -040073 self.monitorpipe = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -050074
Brad Bishopd7bf8c12018-02-25 22:55:05 -050075 self.logger = logger
William A. Kennington IIIac69b482021-06-02 12:28:27 -070076 # Whether we're expecting an exit and should show related errors
77 self.canexit = False
Brad Bishopd7bf8c12018-02-25 22:55:05 -050078
Andrew Geissler82c905d2020-04-13 13:39:40 -050079 # Enable testing other OS's
80 # Set commands for target communication, and default to Linux ALWAYS
81 # Other OS's or baremetal applications need to provide their
82 # own implementation passing it through QemuRunner's constructor
83 # or by passing them through TESTIMAGE_BOOT_PATTERNS[flag]
84 # provided variables, where <flag> is one of the mentioned below.
85 accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished']
86 default_boot_patterns = defaultdict(str)
87 # Default to the usual paterns used to communicate with the target
88 default_boot_patterns['search_reached_prompt'] = b' login:'
89 default_boot_patterns['send_login_user'] = 'root\n'
90 default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#"
91 default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#"
92
93 # Only override patterns that were set e.g. login user TESTIMAGE_BOOT_PATTERNS[send_login_user] = "webserver\n"
94 for pattern in accepted_patterns:
95 if not self.boot_patterns[pattern]:
96 self.boot_patterns[pattern] = default_boot_patterns[pattern]
97
Patrick Williamsc124f4f2015-09-15 14:41:29 -050098 def create_socket(self):
99 try:
100 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
101 sock.setblocking(0)
102 sock.bind(("127.0.0.1",0))
103 sock.listen(2)
104 port = sock.getsockname()[1]
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500105 self.logger.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500106 return (sock, port)
107
108 except socket.error:
109 sock.close()
110 raise
111
112 def log(self, msg):
113 if self.logfile:
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500114 # It is needed to sanitize the data received from qemu
115 # because is possible to have control characters
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500116 msg = msg.decode("utf-8", errors='ignore')
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600117 msg = re_control_char.sub('', msg)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500118 self.msg += msg
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500119 with codecs.open(self.logfile, "a", encoding="utf-8") as f:
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500120 f.write("%s" % msg)
121
122 def getOutput(self, o):
123 import fcntl
124 fl = fcntl.fcntl(o, fcntl.F_GETFL)
125 fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK)
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600126 return os.read(o.fileno(), 1000000).decode("utf-8")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500127
128
129 def handleSIGCHLD(self, signum, frame):
130 if self.runqemu and self.runqemu.poll():
131 if self.runqemu.returncode:
Andrew Geissler82c905d2020-04-13 13:39:40 -0500132 self.logger.error('runqemu exited with code %d' % self.runqemu.returncode)
133 self.logger.error('Output from runqemu:\n%s' % self.getOutput(self.runqemu.stdout))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500134 self.stop()
135 self._dump_host()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500136
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500137 def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500138 env = os.environ.copy()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500139 if self.display:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500140 env["DISPLAY"] = self.display
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500141 # Set this flag so that Qemu doesn't do any grabs as SDL grabs
142 # interact badly with screensavers.
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500143 env["QEMU_DONT_GRAB"] = "1"
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500144 if not os.path.exists(self.rootfs):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500145 self.logger.error("Invalid rootfs %s" % self.rootfs)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500146 return False
147 if not os.path.exists(self.tmpdir):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500148 self.logger.error("Invalid TMPDIR path %s" % self.tmpdir)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500149 return False
150 else:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500151 env["OE_TMPDIR"] = self.tmpdir
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500152 if not os.path.exists(self.deploy_dir_image):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500153 self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500154 return False
155 else:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500156 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500157
Andrew Geissler3b8a17c2021-04-15 15:55:55 -0500158 if self.tmpfsdir:
159 env["RUNQEMU_TMPFS_DIR"] = self.tmpfsdir
160
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500161 if not launch_cmd:
Brad Bishop08902b02019-08-20 09:16:51 -0400162 launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500163 if self.use_kvm:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500164 self.logger.debug('Using kvm for runqemu')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500165 launch_cmd += ' kvm'
166 else:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500167 self.logger.debug('Not using kvm for runqemu')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500168 if not self.display:
169 launch_cmd += ' nographic'
Brad Bishop19323692019-04-05 15:28:33 -0400170 if self.use_slirp:
171 launch_cmd += ' slirp'
Andrew Geissler82c905d2020-04-13 13:39:40 -0500172 if self.use_ovmf:
173 launch_cmd += ' ovmf'
Brad Bishop08902b02019-08-20 09:16:51 -0400174 launch_cmd += ' %s %s %s' % (runqemuparams, self.machine, self.rootfs)
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500175
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500176 return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env)
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500177
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500178 def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None):
Andrew Geisslerc926e172021-05-07 16:11:35 -0500179 # use logfile to determine the recipe-sysroot-native path and
180 # then add in the site-packages path components and add that
181 # to the python sys.path so qmp.py can be found.
182 python_path = os.path.dirname(os.path.dirname(self.logfile))
183 python_path += "/recipe-sysroot-native/usr/lib/python3.9/site-packages"
184 sys.path.append(python_path)
185 importlib.invalidate_caches()
186 try:
187 qmp = importlib.import_module("qmp")
188 except:
189 self.logger.error("qemurunner: qmp.py missing, please ensure it's installed")
190 return False
191 # Path relative to tmpdir used as cwd for qemu below to avoid unix socket path length issues
192 qmp_file = "." + next(tempfile._get_candidate_names())
193 qmp_param = ' -S -qmp unix:./%s,server,wait' % (qmp_file)
194 qmp_port = self.tmpdir + "/" + qmp_file
Andrew Geissler09036742021-06-25 14:25:14 -0500195 # Create a second socket connection for debugging use,
196 # note this will NOT cause qemu to block waiting for the connection
197 qmp_file2 = "." + next(tempfile._get_candidate_names())
198 qmp_param += ' -qmp unix:./%s,server,nowait' % (qmp_file2)
199 qmp_port2 = self.tmpdir + "/" + qmp_file2
200 self.logger.info("QMP Available for connection at %s" % (qmp_port2))
Andrew Geisslerc926e172021-05-07 16:11:35 -0500201
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500202 try:
Andrew Geissler82c905d2020-04-13 13:39:40 -0500203 if self.serial_ports >= 2:
204 self.threadsock, threadport = self.create_socket()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500205 self.server_socket, self.serverport = self.create_socket()
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600206 except socket.error as msg:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500207 self.logger.error("Failed to create listening socket: %s" % msg[1])
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500208 return False
209
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500210 bootparams = ' printk.time=1'
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600211 if extra_bootparams:
212 bootparams = bootparams + ' ' + extra_bootparams
213
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500214 # Ask QEMU to store the QEMU process PID in file, this way we don't have to parse running processes
215 # and analyze descendents in order to determine it.
216 if os.path.exists(self.qemu_pidfile):
217 os.remove(self.qemu_pidfile)
Andrew Geisslerc926e172021-05-07 16:11:35 -0500218 self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1} {2}"'.format(bootparams, self.qemu_pidfile, qmp_param)
219
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500220 if qemuparams:
221 self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"'
222
Andrew Geissler82c905d2020-04-13 13:39:40 -0500223 if self.serial_ports >= 2:
224 launch_cmd += ' tcpserial=%s:%s %s' % (threadport, self.serverport, self.qemuparams)
225 else:
226 launch_cmd += ' tcpserial=%s %s' % (self.serverport, self.qemuparams)
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500227
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500228 self.origchldhandler = signal.getsignal(signal.SIGCHLD)
229 signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
230
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500231 self.logger.debug('launchcmd=%s'%(launch_cmd))
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600232
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500233 # FIXME: We pass in stdin=subprocess.PIPE here to work around stty
234 # blocking at the end of the runqemu script when using this within
235 # oe-selftest (this makes stty error out immediately). There ought
236 # to be a proper fix but this will suffice for now.
Andrew Geisslerc926e172021-05-07 16:11:35 -0500237 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)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500238 output = self.runqemu.stdout
239
240 #
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600241 # We need the preexec_fn above so that all runqemu processes can easily be killed
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500242 # (by killing their process group). This presents a problem if this controlling
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600243 # process itself is killed however since those processes don't notice the death
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500244 # of the parent and merrily continue on.
245 #
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600246 # Rather than hack runqemu to deal with this, we add something here instead.
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500247 # Basically we fork off another process which holds an open pipe to the parent
248 # and also is setpgrp. If/when the pipe sees EOF from the parent dieing, it kills
249 # the process group. This is like pctrl's PDEATHSIG but for a process group
250 # rather than a single process.
251 #
252 r, w = os.pipe()
253 self.monitorpid = os.fork()
254 if self.monitorpid:
255 os.close(r)
256 self.monitorpipe = os.fdopen(w, "w")
257 else:
258 # child process
259 os.setpgrp()
260 os.close(w)
261 r = os.fdopen(r)
262 x = r.read()
263 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
264 sys.exit(0)
265
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500266 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
Brad Bishop316dfdd2018-06-25 12:45:53 -0400267 self.logger.debug("waiting at most %s seconds for qemu pid (%s)" %
268 (self.runqemutime, time.strftime("%D %H:%M:%S")))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500269 endtime = time.time() + self.runqemutime
270 while not self.is_alive() and time.time() < endtime:
271 if self.runqemu.poll():
Andrew Geissler82c905d2020-04-13 13:39:40 -0500272 if self.runqemu_exited:
Andrew Geisslerc926e172021-05-07 16:11:35 -0500273 self.logger.warning("runqemu during is_alive() test")
Andrew Geissler82c905d2020-04-13 13:39:40 -0500274 return False
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500275 if self.runqemu.returncode:
276 # No point waiting any longer
Brad Bishop96ff1982019-08-19 13:50:42 -0400277 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500278 self._dump_host()
Brad Bishop96ff1982019-08-19 13:50:42 -0400279 self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output))
Brad Bishopf86d0552018-12-04 14:18:15 -0800280 self.stop()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500281 return False
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500282 time.sleep(0.5)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500283
Andrew Geissler82c905d2020-04-13 13:39:40 -0500284 if self.runqemu_exited:
Andrew Geisslerc926e172021-05-07 16:11:35 -0500285 self.logger.warning("runqemu after timeout")
Andrew Geissler82c905d2020-04-13 13:39:40 -0500286
Andrew Geisslerc926e172021-05-07 16:11:35 -0500287 if self.runqemu.returncode:
288 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
Andrew Geisslerc926e172021-05-07 16:11:35 -0500289
290 if not self.is_alive():
William A. Kennington IIIac69b482021-06-02 12:28:27 -0700291 self.logger.error("Qemu pid didn't appear in %s seconds (%s)" %
292 (self.runqemutime, time.strftime("%D %H:%M:%S")))
293
294 qemu_pid = None
295 if os.path.isfile(self.qemu_pidfile):
296 with open(self.qemu_pidfile, 'r') as f:
297 qemu_pid = f.read().strip()
298
299 self.logger.error("Status information, poll status: %s, pidfile exists: %s, pidfile contents %s, proc pid exists %s"
300 % (self.runqemu.poll(), os.path.isfile(self.qemu_pidfile), str(qemu_pid), os.path.exists("/proc/" + str(qemu_pid))))
301
302 # Dump all processes to help us to figure out what is going on...
303 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0]
304 processes = ps.decode("utf-8")
305 self.logger.debug("Running processes:\n%s" % processes)
306 self._dump_host()
307 op = self.getOutput(output)
308 self.stop()
309 if op:
310 self.logger.error("Output from runqemu:\n%s" % op)
311 else:
312 self.logger.error("No output from runqemu.\n")
Andrew Geisslerc926e172021-05-07 16:11:35 -0500313 return False
314
315 # Create the client socket for the QEMU Monitor Control Socket
316 # This will allow us to read status from Qemu if the the process
317 # is still alive
318 self.logger.debug("QMP Initializing to %s" % (qmp_port))
319 # chdir dance for path length issues with unix sockets
320 origpath = os.getcwd()
321 try:
322 os.chdir(os.path.dirname(qmp_port))
323 try:
324 self.qmp = qmp.QEMUMonitorProtocol(os.path.basename(qmp_port))
325 except OSError as msg:
326 self.logger.warning("Failed to initialize qemu monitor socket: %s File: %s" % (msg, msg.filename))
327 return False
328
329 self.logger.debug("QMP Connecting to %s" % (qmp_port))
330 if not os.path.exists(qmp_port) and self.is_alive():
331 self.logger.debug("QMP Port does not exist waiting for it to be created")
332 endtime = time.time() + self.runqemutime
333 while not os.path.exists(qmp_port) and self.is_alive() and time.time() < endtime:
334 self.logger.info("QMP port does not exist yet!")
335 time.sleep(0.5)
336 if not os.path.exists(qmp_port) and self.is_alive():
337 self.logger.warning("QMP Port still does not exist but QEMU is alive")
338 return False
339
340 try:
341 self.qmp.connect()
342 except OSError as msg:
343 self.logger.warning("Failed to connect qemu monitor socket: %s File: %s" % (msg, msg.filename))
344 return False
345 except qmp.QMPConnectError as msg:
346 self.logger.warning("Failed to communicate with qemu monitor: %s" % (msg))
347 return False
348 finally:
349 os.chdir(origpath)
350
Andrew Geissler09036742021-06-25 14:25:14 -0500351 # We worry that mmap'd libraries may cause page faults which hang the qemu VM for periods
352 # causing failures. Before we "start" qemu, read through it's mapped files to try and
353 # ensure we don't hit page faults later
354 mapdir = "/proc/" + str(self.qemupid) + "/map_files/"
355 try:
356 for f in os.listdir(mapdir):
357 linktarget = os.readlink(os.path.join(mapdir, f))
358 if not linktarget.startswith("/") or linktarget.startswith("/dev") or "deleted" in linktarget:
359 continue
360 with open(linktarget, "rb") as readf:
361 data = True
362 while data:
363 data = readf.read(4096)
364 # Centos7 doesn't allow us to read /map_files/
365 except PermissionError:
366 pass
367
368 # Release the qemu process to continue running
Andrew Geisslerc926e172021-05-07 16:11:35 -0500369 self.run_monitor('cont')
370
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500371 # We are alive: qemu is running
372 out = self.getOutput(output)
373 netconf = False # network configuration is not required by default
Brad Bishop316dfdd2018-06-25 12:45:53 -0400374 self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" %
375 (time.time() - (endtime - self.runqemutime),
376 self.qemupid, time.strftime("%D %H:%M:%S")))
Andrew Geissler82c905d2020-04-13 13:39:40 -0500377 cmdline = ''
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500378 if get_ip:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500379 with open('/proc/%s/cmdline' % self.qemupid) as p:
380 cmdline = p.read()
381 # It is needed to sanitize the data received
382 # because is possible to have control characters
383 cmdline = re_control_char.sub(' ', cmdline)
384 try:
Brad Bishop19323692019-04-05 15:28:33 -0400385 if self.use_slirp:
386 tcp_ports = cmdline.split("hostfwd=tcp::")[1]
387 host_port = tcp_ports[:tcp_ports.find('-')]
388 self.ip = "localhost:%s" % host_port
389 else:
390 ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
391 self.ip = ips[0]
392 self.server_ip = ips[1]
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500393 self.logger.debug("qemu cmdline used:\n{}".format(cmdline))
394 except (IndexError, ValueError):
395 # Try to get network configuration from runqemu output
Andrew Geissler4ed12e12020-06-05 18:00:41 -0500396 match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+)$.*',
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500397 out, re.MULTILINE|re.DOTALL)
398 if match:
399 self.ip, self.server_ip, self.netmask = match.groups()
400 # network configuration is required as we couldn't get it
401 # from the runqemu command line, so qemu doesn't run kernel
402 # and guest networking is not configured
403 netconf = True
404 else:
405 self.logger.error("Couldn't get ip from qemu command line and runqemu output! "
406 "Here is the qemu command line used:\n%s\n"
407 "and output from runqemu:\n%s" % (cmdline, out))
408 self._dump_host()
409 self.stop()
410 return False
411
412 self.logger.debug("Target IP: %s" % self.ip)
413 self.logger.debug("Server IP: %s" % self.server_ip)
414
Andrew Geissler82c905d2020-04-13 13:39:40 -0500415 if self.serial_ports >= 2:
416 self.thread = LoggingThread(self.log, self.threadsock, self.logger)
417 self.thread.start()
418 if not self.thread.connection_established.wait(self.boottime):
419 self.logger.error("Didn't receive a console connection from qemu. "
420 "Here is the qemu command line used:\n%s\nand "
421 "output from runqemu:\n%s" % (cmdline, out))
422 self.stop_thread()
423 return False
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500424
425 self.logger.debug("Output from runqemu:\n%s", out)
Brad Bishop316dfdd2018-06-25 12:45:53 -0400426 self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
427 (self.boottime, time.strftime("%D %H:%M:%S")))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500428 endtime = time.time() + self.boottime
429 socklist = [self.server_socket]
430 reachedlogin = False
431 stopread = False
432 qemusock = None
433 bootlog = b''
434 data = b''
435 while time.time() < endtime and not stopread:
436 try:
437 sread, swrite, serror = select.select(socklist, [], [], 5)
438 except InterruptedError:
439 continue
440 for sock in sread:
441 if sock is self.server_socket:
442 qemusock, addr = self.server_socket.accept()
443 qemusock.setblocking(0)
444 socklist.append(qemusock)
445 socklist.remove(self.server_socket)
446 self.logger.debug("Connection from %s:%s" % addr)
447 else:
448 data = data + sock.recv(1024)
449 if data:
450 bootlog += data
Andrew Geissler82c905d2020-04-13 13:39:40 -0500451 if self.serial_ports < 2:
452 # this socket has mixed console/kernel data, log it to logfile
453 self.log(data)
454
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500455 data = b''
Andrew Geissler82c905d2020-04-13 13:39:40 -0500456 if self.boot_patterns['search_reached_prompt'] in bootlog:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500457 self.server_socket = qemusock
458 stopread = True
459 reachedlogin = True
Brad Bishop316dfdd2018-06-25 12:45:53 -0400460 self.logger.debug("Reached login banner in %s seconds (%s)" %
461 (time.time() - (endtime - self.boottime),
462 time.strftime("%D %H:%M:%S")))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500463 else:
Brad Bishop316dfdd2018-06-25 12:45:53 -0400464 # no need to check if reachedlogin unless we support multiple connections
465 self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" %
466 time.strftime("%D %H:%M:%S"))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500467 socklist.remove(sock)
468 sock.close()
469 stopread = True
470
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500471 if not reachedlogin:
Brad Bishop316dfdd2018-06-25 12:45:53 -0400472 if time.time() >= endtime:
Brad Bishop96ff1982019-08-19 13:50:42 -0400473 self.logger.warning("Target didn't reach login banner in %d seconds (%s)" %
Brad Bishop316dfdd2018-06-25 12:45:53 -0400474 (self.boottime, time.strftime("%D %H:%M:%S")))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500475 tail = lambda l: "\n".join(l.splitlines()[-25:])
Brad Bishopd89cb5f2019-04-10 09:02:41 -0400476 bootlog = bootlog.decode("utf-8")
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500477 # in case bootlog is empty, use tail qemu log store at self.msg
478 lines = tail(bootlog if bootlog else self.msg)
Brad Bishop96ff1982019-08-19 13:50:42 -0400479 self.logger.warning("Last 25 lines of text:\n%s" % lines)
480 self.logger.warning("Check full boot log: %s" % self.logfile)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500481 self._dump_host()
482 self.stop()
483 return False
484
485 # If we are not able to login the tests can continue
486 try:
Andrew Geisslerc3d88e42020-10-02 09:45:00 -0500487 (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120)
Andrew Geissler82c905d2020-04-13 13:39:40 -0500488 if re.search(self.boot_patterns['search_login_succeeded'], output):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500489 self.logged = True
490 self.logger.debug("Logged as root in serial console")
491 if netconf:
492 # configure guest networking
493 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
494 output = self.run_serial(cmd, raw=True)[1]
Brad Bishopf86d0552018-12-04 14:18:15 -0800495 if re.search(r"root@[a-zA-Z0-9\-]+:~#", output):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500496 self.logger.debug("configured ip address %s", self.ip)
497 else:
498 self.logger.debug("Couldn't configure guest networking")
499 else:
Brad Bishop96ff1982019-08-19 13:50:42 -0400500 self.logger.warning("Couldn't login into serial console"
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500501 " as root using blank password")
Brad Bishop96ff1982019-08-19 13:50:42 -0400502 self.logger.warning("The output:\n%s" % output)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500503 except:
Brad Bishop96ff1982019-08-19 13:50:42 -0400504 self.logger.warning("Serial console failed while trying to login")
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500505 return True
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500506
507 def stop(self):
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500508 if hasattr(self, "origchldhandler"):
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500509 signal.signal(signal.SIGCHLD, self.origchldhandler)
Brad Bishop1a4b7ee2018-12-16 17:11:34 -0800510 self.stop_thread()
511 self.stop_qemu_system()
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500512 if self.runqemu:
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600513 if hasattr(self, "monitorpid"):
514 os.kill(self.monitorpid, signal.SIGKILL)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500515 self.logger.debug("Sending SIGTERM to runqemu")
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600516 try:
517 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
518 except OSError as e:
519 if e.errno != errno.ESRCH:
520 raise
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500521 endtime = time.time() + self.runqemutime
522 while self.runqemu.poll() is None and time.time() < endtime:
523 time.sleep(1)
524 if self.runqemu.poll() is None:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500525 self.logger.debug("Sending SIGKILL to runqemu")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500526 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
Brad Bishopf86d0552018-12-04 14:18:15 -0800527 self.runqemu.stdin.close()
528 self.runqemu.stdout.close()
Andrew Geissler82c905d2020-04-13 13:39:40 -0500529 self.runqemu_exited = True
Brad Bishopf86d0552018-12-04 14:18:15 -0800530
Andrew Geisslerc926e172021-05-07 16:11:35 -0500531 if hasattr(self, 'qmp') and self.qmp:
532 self.qmp.close()
533 self.qmp = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500534 if hasattr(self, 'server_socket') and self.server_socket:
535 self.server_socket.close()
536 self.server_socket = None
Brad Bishopf86d0552018-12-04 14:18:15 -0800537 if hasattr(self, 'threadsock') and self.threadsock:
538 self.threadsock.close()
539 self.threadsock = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500540 self.qemupid = None
541 self.ip = None
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500542 if os.path.exists(self.qemu_pidfile):
Andrew Geissler82c905d2020-04-13 13:39:40 -0500543 try:
544 os.remove(self.qemu_pidfile)
545 except FileNotFoundError as e:
546 # We raced, ignore
547 pass
Brad Bishopf86d0552018-12-04 14:18:15 -0800548 if self.monitorpipe:
549 self.monitorpipe.close()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500550
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500551 def stop_qemu_system(self):
552 if self.qemupid:
553 try:
554 # qemu-system behaves well and a SIGTERM is enough
555 os.kill(self.qemupid, signal.SIGTERM)
556 except ProcessLookupError as e:
Brad Bishop1a4b7ee2018-12-16 17:11:34 -0800557 self.logger.warning('qemu-system ended unexpectedly')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500558
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500559 def stop_thread(self):
560 if self.thread and self.thread.is_alive():
561 self.thread.stop()
562 self.thread.join()
563
Andrew Geisslerc926e172021-05-07 16:11:35 -0500564 def allowexit(self):
William A. Kennington IIIac69b482021-06-02 12:28:27 -0700565 self.canexit = True
Andrew Geisslerc926e172021-05-07 16:11:35 -0500566 if self.thread:
567 self.thread.allowexit()
568
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500569 def restart(self, qemuparams = None):
Brad Bishop96ff1982019-08-19 13:50:42 -0400570 self.logger.warning("Restarting qemu process")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500571 if self.runqemu.poll() is None:
572 self.stop()
573 if self.start(qemuparams):
574 return True
575 return False
576
577 def is_alive(self):
Andrew Geissler82c905d2020-04-13 13:39:40 -0500578 if not self.runqemu or self.runqemu.poll() is not None or self.runqemu_exited:
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500579 return False
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500580 if os.path.isfile(self.qemu_pidfile):
Brad Bishop96ff1982019-08-19 13:50:42 -0400581 # when handling pidfile, qemu creates the file, stat it, lock it and then write to it
582 # so it's possible that the file has been created but the content is empty
583 pidfile_timeout = time.time() + 3
584 while time.time() < pidfile_timeout:
585 with open(self.qemu_pidfile, 'r') as f:
586 qemu_pid = f.read().strip()
587 # file created but not yet written contents
588 if not qemu_pid:
589 time.sleep(0.5)
590 continue
591 else:
592 if os.path.exists("/proc/" + qemu_pid):
593 self.qemupid = int(qemu_pid)
594 return True
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500595 return False
596
Andrew Geisslerc926e172021-05-07 16:11:35 -0500597 def run_monitor(self, command, timeout=60):
598 return self.qmp.cmd(command)
599
Brad Bishop977dc1a2019-02-06 16:01:43 -0500600 def run_serial(self, command, raw=False, timeout=60):
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500601 # We assume target system have echo to get command status
602 if not raw:
603 command = "%s; echo $?\n" % command
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500604
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500605 data = ''
606 status = 0
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600607 self.server_socket.sendall(command.encode('utf-8'))
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500608 start = time.time()
609 end = start + timeout
610 while True:
611 now = time.time()
612 if now >= end:
613 data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
614 break
615 try:
616 sread, _, _ = select.select([self.server_socket],[],[], end - now)
617 except InterruptedError:
618 continue
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500619 if sread:
620 answer = self.server_socket.recv(1024)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500621 if answer:
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600622 data += answer.decode('utf-8')
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500623 # Search the prompt to stop
Andrew Geissler82c905d2020-04-13 13:39:40 -0500624 if re.search(self.boot_patterns['search_cmd_finished'], data):
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500625 break
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500626 else:
William A. Kennington IIIac69b482021-06-02 12:28:27 -0700627 if self.canexit:
628 return (1, "")
629 raise Exception("No data on serial console socket, connection closed?")
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500630
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500631 if data:
632 if raw:
633 status = 1
634 else:
635 # Remove first line (command line) and last line (prompt)
636 data = data[data.find('$?\r\n')+4:data.rfind('\r\n')]
637 index = data.rfind('\r\n')
638 if index == -1:
639 status_cmd = data
640 data = ""
641 else:
642 status_cmd = data[index+2:]
643 data = data[:index]
644 if (status_cmd == "0"):
645 status = 1
646 return (status, str(data))
647
648
649 def _dump_host(self):
650 self.host_dumper.create_dir("qemu")
Brad Bishop1a4b7ee2018-12-16 17:11:34 -0800651 self.logger.warning("Qemu ended unexpectedly, dump data from host"
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500652 " is in %s" % self.host_dumper.dump_dir)
653 self.host_dumper.dump_host()
654
655# This class is for reading data from a socket and passing it to logfunc
656# to be processed. It's completely event driven and has a straightforward
657# event loop. The mechanism for stopping the thread is a simple pipe which
658# will wake up the poll and allow for tearing everything down.
659class LoggingThread(threading.Thread):
660 def __init__(self, logfunc, sock, logger):
661 self.connection_established = threading.Event()
662 self.serversock = sock
663 self.logfunc = logfunc
664 self.logger = logger
665 self.readsock = None
666 self.running = False
Andrew Geisslerc926e172021-05-07 16:11:35 -0500667 self.canexit = False
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500668
669 self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
670 self.readevents = select.POLLIN | select.POLLPRI
671
672 threading.Thread.__init__(self, target=self.threadtarget)
673
674 def threadtarget(self):
675 try:
676 self.eventloop()
677 finally:
678 self.teardown()
679
680 def run(self):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500681 self.logger.debug("Starting logging thread")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500682 self.readpipe, self.writepipe = os.pipe()
683 threading.Thread.run(self)
684
685 def stop(self):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500686 self.logger.debug("Stopping logging thread")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500687 if self.running:
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600688 os.write(self.writepipe, bytes("stop", "utf-8"))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500689
690 def teardown(self):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500691 self.logger.debug("Tearing down logging thread")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500692 self.close_socket(self.serversock)
693
694 if self.readsock is not None:
695 self.close_socket(self.readsock)
696
697 self.close_ignore_error(self.readpipe)
698 self.close_ignore_error(self.writepipe)
699 self.running = False
700
Andrew Geisslerc926e172021-05-07 16:11:35 -0500701 def allowexit(self):
702 self.canexit = True
703
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500704 def eventloop(self):
705 poll = select.poll()
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500706 event_read_mask = self.errorevents | self.readevents
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500707 poll.register(self.serversock.fileno())
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500708 poll.register(self.readpipe, event_read_mask)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500709
710 breakout = False
711 self.running = True
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500712 self.logger.debug("Starting thread event loop")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500713 while not breakout:
714 events = poll.poll()
715 for event in events:
716 # An error occurred, bail out
717 if event[1] & self.errorevents:
718 raise Exception(self.stringify_event(event[1]))
719
720 # Event to stop the thread
721 if self.readpipe == event[0]:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500722 self.logger.debug("Stop event received")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500723 breakout = True
724 break
725
726 # A connection request was received
727 elif self.serversock.fileno() == event[0]:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500728 self.logger.debug("Connection request received")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500729 self.readsock, _ = self.serversock.accept()
730 self.readsock.setblocking(0)
731 poll.unregister(self.serversock.fileno())
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500732 poll.register(self.readsock.fileno(), event_read_mask)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500733
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500734 self.logger.debug("Setting connection established event")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500735 self.connection_established.set()
736
737 # Actual data to be logged
738 elif self.readsock.fileno() == event[0]:
739 data = self.recv(1024)
740 self.logfunc(data)
741
742 # Since the socket is non-blocking make sure to honor EAGAIN
743 # and EWOULDBLOCK.
744 def recv(self, count):
745 try:
746 data = self.readsock.recv(count)
747 except socket.error as e:
748 if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
William A. Kennington IIIac69b482021-06-02 12:28:27 -0700749 return b''
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500750 else:
751 raise
752
753 if data is None:
754 raise Exception("No data on read ready socket")
755 elif not data:
756 # This actually means an orderly shutdown
757 # happened. But for this code it counts as an
758 # error since the connection shouldn't go away
759 # until qemu exits.
Andrew Geisslerc926e172021-05-07 16:11:35 -0500760 if not self.canexit:
761 raise Exception("Console connection closed unexpectedly")
William A. Kennington IIIac69b482021-06-02 12:28:27 -0700762 return b''
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500763
764 return data
765
766 def stringify_event(self, event):
767 val = ''
768 if select.POLLERR == event:
769 val = 'POLLER'
770 elif select.POLLHUP == event:
771 val = 'POLLHUP'
772 elif select.POLLNVAL == event:
773 val = 'POLLNVAL'
774 return val
775
776 def close_socket(self, sock):
777 sock.shutdown(socket.SHUT_RDWR)
778 sock.close()
779
780 def close_ignore_error(self, fd):
781 try:
782 os.close(fd)
783 except OSError:
784 pass