blob: 77ec939ad7253cb6d4bf0bbf539a88b8af91dc45 [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
Brad Bishopd7bf8c12018-02-25 22:55:05 -050023from oeqa.utils.dump import HostDumper
Andrew Geissler82c905d2020-04-13 13:39:40 -050024from collections import defaultdict
Patrick Williamsc124f4f2015-09-15 14:41:29 -050025
Patrick Williamsf1e5d692016-03-30 15:21:19 -050026# Get Unicode non printable control chars
Patrick Williamsc0f7c042017-02-23 20:41:17 -060027control_range = list(range(0,32))+list(range(127,160))
28control_chars = [chr(x) for x in control_range
29 if chr(x) not in string.printable]
Patrick Williamsf1e5d692016-03-30 15:21:19 -050030re_control_char = re.compile('[%s]' % re.escape("".join(control_chars)))
31
Patrick Williamsc124f4f2015-09-15 14:41:29 -050032class QemuRunner:
33
Brad Bishop19323692019-04-05 15:28:33 -040034 def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds,
Andrew Geisslerb7d28612020-07-24 16:15:54 -050035 use_kvm, logger, use_slirp=False, serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None):
Patrick Williamsc124f4f2015-09-15 14:41:29 -050036
37 # Popen object for runqemu
38 self.runqemu = None
Andrew Geissler82c905d2020-04-13 13:39:40 -050039 self.runqemu_exited = False
Patrick Williamsc124f4f2015-09-15 14:41:29 -050040 # pid of the qemu process that runqemu will start
41 self.qemupid = None
Brad Bishop6e60e8b2018-02-01 10:27:11 -050042 # target ip - from the command line or runqemu output
Patrick Williamsc124f4f2015-09-15 14:41:29 -050043 self.ip = None
44 # host ip - where qemu is running
45 self.server_ip = None
Brad Bishop6e60e8b2018-02-01 10:27:11 -050046 # target ip netmask
47 self.netmask = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -050048
49 self.machine = machine
50 self.rootfs = rootfs
51 self.display = display
52 self.tmpdir = tmpdir
53 self.deploy_dir_image = deploy_dir_image
54 self.logfile = logfile
55 self.boottime = boottime
56 self.logged = False
57 self.thread = None
Patrick Williamsc0f7c042017-02-23 20:41:17 -060058 self.use_kvm = use_kvm
Andrew Geissler82c905d2020-04-13 13:39:40 -050059 self.use_ovmf = use_ovmf
Brad Bishop19323692019-04-05 15:28:33 -040060 self.use_slirp = use_slirp
Andrew Geissler82c905d2020-04-13 13:39:40 -050061 self.serial_ports = serial_ports
Brad Bishopd7bf8c12018-02-25 22:55:05 -050062 self.msg = ''
Andrew Geissler82c905d2020-04-13 13:39:40 -050063 self.boot_patterns = boot_patterns
Patrick Williamsc124f4f2015-09-15 14:41:29 -050064
Brad Bishopd7bf8c12018-02-25 22:55:05 -050065 self.runqemutime = 120
Andrew Geisslerb7d28612020-07-24 16:15:54 -050066 if not workdir:
67 workdir = os.getcwd()
68 self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid())
Patrick Williamsc124f4f2015-09-15 14:41:29 -050069 self.host_dumper = HostDumper(dump_host_cmds, dump_dir)
Brad Bishop15ae2502019-06-18 21:44:24 -040070 self.monitorpipe = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -050071
Brad Bishopd7bf8c12018-02-25 22:55:05 -050072 self.logger = logger
73
Andrew Geissler82c905d2020-04-13 13:39:40 -050074 # Enable testing other OS's
75 # Set commands for target communication, and default to Linux ALWAYS
76 # Other OS's or baremetal applications need to provide their
77 # own implementation passing it through QemuRunner's constructor
78 # or by passing them through TESTIMAGE_BOOT_PATTERNS[flag]
79 # provided variables, where <flag> is one of the mentioned below.
80 accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished']
81 default_boot_patterns = defaultdict(str)
82 # Default to the usual paterns used to communicate with the target
83 default_boot_patterns['search_reached_prompt'] = b' login:'
84 default_boot_patterns['send_login_user'] = 'root\n'
85 default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#"
86 default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#"
87
88 # Only override patterns that were set e.g. login user TESTIMAGE_BOOT_PATTERNS[send_login_user] = "webserver\n"
89 for pattern in accepted_patterns:
90 if not self.boot_patterns[pattern]:
91 self.boot_patterns[pattern] = default_boot_patterns[pattern]
92
Patrick Williamsc124f4f2015-09-15 14:41:29 -050093 def create_socket(self):
94 try:
95 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
96 sock.setblocking(0)
97 sock.bind(("127.0.0.1",0))
98 sock.listen(2)
99 port = sock.getsockname()[1]
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500100 self.logger.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500101 return (sock, port)
102
103 except socket.error:
104 sock.close()
105 raise
106
107 def log(self, msg):
108 if self.logfile:
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500109 # It is needed to sanitize the data received from qemu
110 # because is possible to have control characters
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500111 msg = msg.decode("utf-8", errors='ignore')
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600112 msg = re_control_char.sub('', msg)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500113 self.msg += msg
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500114 with codecs.open(self.logfile, "a", encoding="utf-8") as f:
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500115 f.write("%s" % msg)
116
117 def getOutput(self, o):
118 import fcntl
119 fl = fcntl.fcntl(o, fcntl.F_GETFL)
120 fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK)
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600121 return os.read(o.fileno(), 1000000).decode("utf-8")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500122
123
124 def handleSIGCHLD(self, signum, frame):
125 if self.runqemu and self.runqemu.poll():
126 if self.runqemu.returncode:
Andrew Geissler82c905d2020-04-13 13:39:40 -0500127 self.logger.error('runqemu exited with code %d' % self.runqemu.returncode)
128 self.logger.error('Output from runqemu:\n%s' % self.getOutput(self.runqemu.stdout))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500129 self.stop()
130 self._dump_host()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500131
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500132 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 -0500133 env = os.environ.copy()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500134 if self.display:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500135 env["DISPLAY"] = self.display
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500136 # Set this flag so that Qemu doesn't do any grabs as SDL grabs
137 # interact badly with screensavers.
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500138 env["QEMU_DONT_GRAB"] = "1"
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500139 if not os.path.exists(self.rootfs):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500140 self.logger.error("Invalid rootfs %s" % self.rootfs)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500141 return False
142 if not os.path.exists(self.tmpdir):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500143 self.logger.error("Invalid TMPDIR path %s" % self.tmpdir)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500144 return False
145 else:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500146 env["OE_TMPDIR"] = self.tmpdir
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500147 if not os.path.exists(self.deploy_dir_image):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500148 self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500149 return False
150 else:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500151 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500152
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500153 if not launch_cmd:
Brad Bishop08902b02019-08-20 09:16:51 -0400154 launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500155 if self.use_kvm:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500156 self.logger.debug('Using kvm for runqemu')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500157 launch_cmd += ' kvm'
158 else:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500159 self.logger.debug('Not using kvm for runqemu')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500160 if not self.display:
161 launch_cmd += ' nographic'
Brad Bishop19323692019-04-05 15:28:33 -0400162 if self.use_slirp:
163 launch_cmd += ' slirp'
Andrew Geissler82c905d2020-04-13 13:39:40 -0500164 if self.use_ovmf:
165 launch_cmd += ' ovmf'
Brad Bishop08902b02019-08-20 09:16:51 -0400166 launch_cmd += ' %s %s %s' % (runqemuparams, self.machine, self.rootfs)
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500167
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500168 return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env)
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500169
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500170 def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None):
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500171 try:
Andrew Geissler82c905d2020-04-13 13:39:40 -0500172 if self.serial_ports >= 2:
173 self.threadsock, threadport = self.create_socket()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500174 self.server_socket, self.serverport = self.create_socket()
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600175 except socket.error as msg:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500176 self.logger.error("Failed to create listening socket: %s" % msg[1])
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500177 return False
178
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600179 bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1'
180 if extra_bootparams:
181 bootparams = bootparams + ' ' + extra_bootparams
182
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500183 # Ask QEMU to store the QEMU process PID in file, this way we don't have to parse running processes
184 # and analyze descendents in order to determine it.
185 if os.path.exists(self.qemu_pidfile):
186 os.remove(self.qemu_pidfile)
Brad Bishop15ae2502019-06-18 21:44:24 -0400187 self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1}"'.format(bootparams, self.qemu_pidfile)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500188 if qemuparams:
189 self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"'
190
Andrew Geissler82c905d2020-04-13 13:39:40 -0500191 if self.serial_ports >= 2:
192 launch_cmd += ' tcpserial=%s:%s %s' % (threadport, self.serverport, self.qemuparams)
193 else:
194 launch_cmd += ' tcpserial=%s %s' % (self.serverport, self.qemuparams)
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500195
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500196 self.origchldhandler = signal.getsignal(signal.SIGCHLD)
197 signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
198
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500199 self.logger.debug('launchcmd=%s'%(launch_cmd))
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600200
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500201 # FIXME: We pass in stdin=subprocess.PIPE here to work around stty
202 # blocking at the end of the runqemu script when using this within
203 # oe-selftest (this makes stty error out immediately). There ought
204 # to be a proper fix but this will suffice for now.
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500205 self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500206 output = self.runqemu.stdout
207
208 #
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600209 # We need the preexec_fn above so that all runqemu processes can easily be killed
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500210 # (by killing their process group). This presents a problem if this controlling
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600211 # process itself is killed however since those processes don't notice the death
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500212 # of the parent and merrily continue on.
213 #
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600214 # Rather than hack runqemu to deal with this, we add something here instead.
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500215 # Basically we fork off another process which holds an open pipe to the parent
216 # and also is setpgrp. If/when the pipe sees EOF from the parent dieing, it kills
217 # the process group. This is like pctrl's PDEATHSIG but for a process group
218 # rather than a single process.
219 #
220 r, w = os.pipe()
221 self.monitorpid = os.fork()
222 if self.monitorpid:
223 os.close(r)
224 self.monitorpipe = os.fdopen(w, "w")
225 else:
226 # child process
227 os.setpgrp()
228 os.close(w)
229 r = os.fdopen(r)
230 x = r.read()
231 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
232 sys.exit(0)
233
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500234 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
Brad Bishop316dfdd2018-06-25 12:45:53 -0400235 self.logger.debug("waiting at most %s seconds for qemu pid (%s)" %
236 (self.runqemutime, time.strftime("%D %H:%M:%S")))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500237 endtime = time.time() + self.runqemutime
238 while not self.is_alive() and time.time() < endtime:
239 if self.runqemu.poll():
Andrew Geissler82c905d2020-04-13 13:39:40 -0500240 if self.runqemu_exited:
241 return False
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500242 if self.runqemu.returncode:
243 # No point waiting any longer
Brad Bishop96ff1982019-08-19 13:50:42 -0400244 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500245 self._dump_host()
Brad Bishop96ff1982019-08-19 13:50:42 -0400246 self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output))
Brad Bishopf86d0552018-12-04 14:18:15 -0800247 self.stop()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500248 return False
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500249 time.sleep(0.5)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500250
Andrew Geissler82c905d2020-04-13 13:39:40 -0500251 if self.runqemu_exited:
252 return False
253
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500254 if not self.is_alive():
Brad Bishop316dfdd2018-06-25 12:45:53 -0400255 self.logger.error("Qemu pid didn't appear in %s seconds (%s)" %
256 (self.runqemutime, time.strftime("%D %H:%M:%S")))
Andrew Geisslerb7d28612020-07-24 16:15:54 -0500257
258 qemu_pid = None
259 if os.path.isfile(self.qemu_pidfile):
260 with open(self.qemu_pidfile, 'r') as f:
261 qemu_pid = f.read().strip()
262
263 self.logger.error("Status information, poll status: %s, pidfile exists: %s, pidfile contents %s, proc pid exists %s"
264 % (self.runqemu.poll(), os.path.isfile(self.qemu_pidfile), str(qemu_pid), os.path.exists("/proc/" + str(qemu_pid))))
265
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500266 # Dump all processes to help us to figure out what is going on...
Andrew Geisslerb7d28612020-07-24 16:15:54 -0500267 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0]
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500268 processes = ps.decode("utf-8")
269 self.logger.debug("Running processes:\n%s" % processes)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500270 self._dump_host()
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500271 op = self.getOutput(output)
Brad Bishopf86d0552018-12-04 14:18:15 -0800272 self.stop()
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500273 if op:
274 self.logger.error("Output from runqemu:\n%s" % op)
275 else:
276 self.logger.error("No output from runqemu.\n")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500277 return False
278
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500279 # We are alive: qemu is running
280 out = self.getOutput(output)
281 netconf = False # network configuration is not required by default
Brad Bishop316dfdd2018-06-25 12:45:53 -0400282 self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" %
283 (time.time() - (endtime - self.runqemutime),
284 self.qemupid, time.strftime("%D %H:%M:%S")))
Andrew Geissler82c905d2020-04-13 13:39:40 -0500285 cmdline = ''
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500286 if get_ip:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500287 with open('/proc/%s/cmdline' % self.qemupid) as p:
288 cmdline = p.read()
289 # It is needed to sanitize the data received
290 # because is possible to have control characters
291 cmdline = re_control_char.sub(' ', cmdline)
292 try:
Brad Bishop19323692019-04-05 15:28:33 -0400293 if self.use_slirp:
294 tcp_ports = cmdline.split("hostfwd=tcp::")[1]
295 host_port = tcp_ports[:tcp_ports.find('-')]
296 self.ip = "localhost:%s" % host_port
297 else:
298 ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
299 self.ip = ips[0]
300 self.server_ip = ips[1]
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500301 self.logger.debug("qemu cmdline used:\n{}".format(cmdline))
302 except (IndexError, ValueError):
303 # Try to get network configuration from runqemu output
Andrew Geissler4ed12e12020-06-05 18:00:41 -0500304 match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+)$.*',
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500305 out, re.MULTILINE|re.DOTALL)
306 if match:
307 self.ip, self.server_ip, self.netmask = match.groups()
308 # network configuration is required as we couldn't get it
309 # from the runqemu command line, so qemu doesn't run kernel
310 # and guest networking is not configured
311 netconf = True
312 else:
313 self.logger.error("Couldn't get ip from qemu command line and runqemu output! "
314 "Here is the qemu command line used:\n%s\n"
315 "and output from runqemu:\n%s" % (cmdline, out))
316 self._dump_host()
317 self.stop()
318 return False
319
320 self.logger.debug("Target IP: %s" % self.ip)
321 self.logger.debug("Server IP: %s" % self.server_ip)
322
Andrew Geissler82c905d2020-04-13 13:39:40 -0500323 if self.serial_ports >= 2:
324 self.thread = LoggingThread(self.log, self.threadsock, self.logger)
325 self.thread.start()
326 if not self.thread.connection_established.wait(self.boottime):
327 self.logger.error("Didn't receive a console connection from qemu. "
328 "Here is the qemu command line used:\n%s\nand "
329 "output from runqemu:\n%s" % (cmdline, out))
330 self.stop_thread()
331 return False
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500332
333 self.logger.debug("Output from runqemu:\n%s", out)
Brad Bishop316dfdd2018-06-25 12:45:53 -0400334 self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
335 (self.boottime, time.strftime("%D %H:%M:%S")))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500336 endtime = time.time() + self.boottime
337 socklist = [self.server_socket]
338 reachedlogin = False
339 stopread = False
340 qemusock = None
341 bootlog = b''
342 data = b''
343 while time.time() < endtime and not stopread:
344 try:
345 sread, swrite, serror = select.select(socklist, [], [], 5)
346 except InterruptedError:
347 continue
348 for sock in sread:
349 if sock is self.server_socket:
350 qemusock, addr = self.server_socket.accept()
351 qemusock.setblocking(0)
352 socklist.append(qemusock)
353 socklist.remove(self.server_socket)
354 self.logger.debug("Connection from %s:%s" % addr)
355 else:
356 data = data + sock.recv(1024)
357 if data:
358 bootlog += data
Andrew Geissler82c905d2020-04-13 13:39:40 -0500359 if self.serial_ports < 2:
360 # this socket has mixed console/kernel data, log it to logfile
361 self.log(data)
362
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500363 data = b''
Andrew Geissler82c905d2020-04-13 13:39:40 -0500364 if self.boot_patterns['search_reached_prompt'] in bootlog:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500365 self.server_socket = qemusock
366 stopread = True
367 reachedlogin = True
Brad Bishop316dfdd2018-06-25 12:45:53 -0400368 self.logger.debug("Reached login banner in %s seconds (%s)" %
369 (time.time() - (endtime - self.boottime),
370 time.strftime("%D %H:%M:%S")))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500371 else:
Brad Bishop316dfdd2018-06-25 12:45:53 -0400372 # no need to check if reachedlogin unless we support multiple connections
373 self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" %
374 time.strftime("%D %H:%M:%S"))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500375 socklist.remove(sock)
376 sock.close()
377 stopread = True
378
379
380 if not reachedlogin:
Brad Bishop316dfdd2018-06-25 12:45:53 -0400381 if time.time() >= endtime:
Brad Bishop96ff1982019-08-19 13:50:42 -0400382 self.logger.warning("Target didn't reach login banner in %d seconds (%s)" %
Brad Bishop316dfdd2018-06-25 12:45:53 -0400383 (self.boottime, time.strftime("%D %H:%M:%S")))
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500384 tail = lambda l: "\n".join(l.splitlines()[-25:])
Brad Bishopd89cb5f2019-04-10 09:02:41 -0400385 bootlog = bootlog.decode("utf-8")
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500386 # in case bootlog is empty, use tail qemu log store at self.msg
387 lines = tail(bootlog if bootlog else self.msg)
Brad Bishop96ff1982019-08-19 13:50:42 -0400388 self.logger.warning("Last 25 lines of text:\n%s" % lines)
389 self.logger.warning("Check full boot log: %s" % self.logfile)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500390 self._dump_host()
391 self.stop()
392 return False
393
394 # If we are not able to login the tests can continue
395 try:
Andrew Geisslerc3d88e42020-10-02 09:45:00 -0500396 (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120)
Andrew Geissler82c905d2020-04-13 13:39:40 -0500397 if re.search(self.boot_patterns['search_login_succeeded'], output):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500398 self.logged = True
399 self.logger.debug("Logged as root in serial console")
400 if netconf:
401 # configure guest networking
402 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
403 output = self.run_serial(cmd, raw=True)[1]
Brad Bishopf86d0552018-12-04 14:18:15 -0800404 if re.search(r"root@[a-zA-Z0-9\-]+:~#", output):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500405 self.logger.debug("configured ip address %s", self.ip)
406 else:
407 self.logger.debug("Couldn't configure guest networking")
408 else:
Brad Bishop96ff1982019-08-19 13:50:42 -0400409 self.logger.warning("Couldn't login into serial console"
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500410 " as root using blank password")
Brad Bishop96ff1982019-08-19 13:50:42 -0400411 self.logger.warning("The output:\n%s" % output)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500412 except:
Brad Bishop96ff1982019-08-19 13:50:42 -0400413 self.logger.warning("Serial console failed while trying to login")
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500414 return True
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500415
416 def stop(self):
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500417 if hasattr(self, "origchldhandler"):
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500418 signal.signal(signal.SIGCHLD, self.origchldhandler)
Brad Bishop1a4b7ee2018-12-16 17:11:34 -0800419 self.stop_thread()
420 self.stop_qemu_system()
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500421 if self.runqemu:
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600422 if hasattr(self, "monitorpid"):
423 os.kill(self.monitorpid, signal.SIGKILL)
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500424 self.logger.debug("Sending SIGTERM to runqemu")
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600425 try:
426 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
427 except OSError as e:
428 if e.errno != errno.ESRCH:
429 raise
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500430 endtime = time.time() + self.runqemutime
431 while self.runqemu.poll() is None and time.time() < endtime:
432 time.sleep(1)
433 if self.runqemu.poll() is None:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500434 self.logger.debug("Sending SIGKILL to runqemu")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500435 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
Brad Bishopf86d0552018-12-04 14:18:15 -0800436 self.runqemu.stdin.close()
437 self.runqemu.stdout.close()
Andrew Geissler82c905d2020-04-13 13:39:40 -0500438 self.runqemu_exited = True
Brad Bishopf86d0552018-12-04 14:18:15 -0800439
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500440 if hasattr(self, 'server_socket') and self.server_socket:
441 self.server_socket.close()
442 self.server_socket = None
Brad Bishopf86d0552018-12-04 14:18:15 -0800443 if hasattr(self, 'threadsock') and self.threadsock:
444 self.threadsock.close()
445 self.threadsock = None
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500446 self.qemupid = None
447 self.ip = None
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500448 if os.path.exists(self.qemu_pidfile):
Andrew Geissler82c905d2020-04-13 13:39:40 -0500449 try:
450 os.remove(self.qemu_pidfile)
451 except FileNotFoundError as e:
452 # We raced, ignore
453 pass
Brad Bishopf86d0552018-12-04 14:18:15 -0800454 if self.monitorpipe:
455 self.monitorpipe.close()
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500456
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500457 def stop_qemu_system(self):
458 if self.qemupid:
459 try:
460 # qemu-system behaves well and a SIGTERM is enough
461 os.kill(self.qemupid, signal.SIGTERM)
462 except ProcessLookupError as e:
Brad Bishop1a4b7ee2018-12-16 17:11:34 -0800463 self.logger.warning('qemu-system ended unexpectedly')
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500464
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500465 def stop_thread(self):
466 if self.thread and self.thread.is_alive():
467 self.thread.stop()
468 self.thread.join()
469
470 def restart(self, qemuparams = None):
Brad Bishop96ff1982019-08-19 13:50:42 -0400471 self.logger.warning("Restarting qemu process")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500472 if self.runqemu.poll() is None:
473 self.stop()
474 if self.start(qemuparams):
475 return True
476 return False
477
478 def is_alive(self):
Andrew Geissler82c905d2020-04-13 13:39:40 -0500479 if not self.runqemu or self.runqemu.poll() is not None or self.runqemu_exited:
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500480 return False
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500481 if os.path.isfile(self.qemu_pidfile):
Brad Bishop96ff1982019-08-19 13:50:42 -0400482 # when handling pidfile, qemu creates the file, stat it, lock it and then write to it
483 # so it's possible that the file has been created but the content is empty
484 pidfile_timeout = time.time() + 3
485 while time.time() < pidfile_timeout:
486 with open(self.qemu_pidfile, 'r') as f:
487 qemu_pid = f.read().strip()
488 # file created but not yet written contents
489 if not qemu_pid:
490 time.sleep(0.5)
491 continue
492 else:
493 if os.path.exists("/proc/" + qemu_pid):
494 self.qemupid = int(qemu_pid)
495 return True
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500496 return False
497
Brad Bishop977dc1a2019-02-06 16:01:43 -0500498 def run_serial(self, command, raw=False, timeout=60):
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500499 # We assume target system have echo to get command status
500 if not raw:
501 command = "%s; echo $?\n" % command
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500502
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500503 data = ''
504 status = 0
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600505 self.server_socket.sendall(command.encode('utf-8'))
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500506 start = time.time()
507 end = start + timeout
508 while True:
509 now = time.time()
510 if now >= end:
511 data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
512 break
513 try:
514 sread, _, _ = select.select([self.server_socket],[],[], end - now)
515 except InterruptedError:
516 continue
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500517 if sread:
518 answer = self.server_socket.recv(1024)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500519 if answer:
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600520 data += answer.decode('utf-8')
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500521 # Search the prompt to stop
Andrew Geissler82c905d2020-04-13 13:39:40 -0500522 if re.search(self.boot_patterns['search_cmd_finished'], data):
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500523 break
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500524 else:
525 raise Exception("No data on serial console socket")
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500526
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500527 if data:
528 if raw:
529 status = 1
530 else:
531 # Remove first line (command line) and last line (prompt)
532 data = data[data.find('$?\r\n')+4:data.rfind('\r\n')]
533 index = data.rfind('\r\n')
534 if index == -1:
535 status_cmd = data
536 data = ""
537 else:
538 status_cmd = data[index+2:]
539 data = data[:index]
540 if (status_cmd == "0"):
541 status = 1
542 return (status, str(data))
543
544
545 def _dump_host(self):
546 self.host_dumper.create_dir("qemu")
Brad Bishop1a4b7ee2018-12-16 17:11:34 -0800547 self.logger.warning("Qemu ended unexpectedly, dump data from host"
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500548 " is in %s" % self.host_dumper.dump_dir)
549 self.host_dumper.dump_host()
550
551# This class is for reading data from a socket and passing it to logfunc
552# to be processed. It's completely event driven and has a straightforward
553# event loop. The mechanism for stopping the thread is a simple pipe which
554# will wake up the poll and allow for tearing everything down.
555class LoggingThread(threading.Thread):
556 def __init__(self, logfunc, sock, logger):
557 self.connection_established = threading.Event()
558 self.serversock = sock
559 self.logfunc = logfunc
560 self.logger = logger
561 self.readsock = None
562 self.running = False
563
564 self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
565 self.readevents = select.POLLIN | select.POLLPRI
566
567 threading.Thread.__init__(self, target=self.threadtarget)
568
569 def threadtarget(self):
570 try:
571 self.eventloop()
572 finally:
573 self.teardown()
574
575 def run(self):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500576 self.logger.debug("Starting logging thread")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500577 self.readpipe, self.writepipe = os.pipe()
578 threading.Thread.run(self)
579
580 def stop(self):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500581 self.logger.debug("Stopping logging thread")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500582 if self.running:
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600583 os.write(self.writepipe, bytes("stop", "utf-8"))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500584
585 def teardown(self):
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500586 self.logger.debug("Tearing down logging thread")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500587 self.close_socket(self.serversock)
588
589 if self.readsock is not None:
590 self.close_socket(self.readsock)
591
592 self.close_ignore_error(self.readpipe)
593 self.close_ignore_error(self.writepipe)
594 self.running = False
595
596 def eventloop(self):
597 poll = select.poll()
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500598 event_read_mask = self.errorevents | self.readevents
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500599 poll.register(self.serversock.fileno())
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500600 poll.register(self.readpipe, event_read_mask)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500601
602 breakout = False
603 self.running = True
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500604 self.logger.debug("Starting thread event loop")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500605 while not breakout:
606 events = poll.poll()
607 for event in events:
608 # An error occurred, bail out
609 if event[1] & self.errorevents:
610 raise Exception(self.stringify_event(event[1]))
611
612 # Event to stop the thread
613 if self.readpipe == event[0]:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500614 self.logger.debug("Stop event received")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500615 breakout = True
616 break
617
618 # A connection request was received
619 elif self.serversock.fileno() == event[0]:
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500620 self.logger.debug("Connection request received")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500621 self.readsock, _ = self.serversock.accept()
622 self.readsock.setblocking(0)
623 poll.unregister(self.serversock.fileno())
Patrick Williamsf1e5d692016-03-30 15:21:19 -0500624 poll.register(self.readsock.fileno(), event_read_mask)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500625
Brad Bishopd7bf8c12018-02-25 22:55:05 -0500626 self.logger.debug("Setting connection established event")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500627 self.connection_established.set()
628
629 # Actual data to be logged
630 elif self.readsock.fileno() == event[0]:
631 data = self.recv(1024)
632 self.logfunc(data)
633
634 # Since the socket is non-blocking make sure to honor EAGAIN
635 # and EWOULDBLOCK.
636 def recv(self, count):
637 try:
638 data = self.readsock.recv(count)
639 except socket.error as e:
640 if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
641 return ''
642 else:
643 raise
644
645 if data is None:
646 raise Exception("No data on read ready socket")
647 elif not data:
648 # This actually means an orderly shutdown
649 # happened. But for this code it counts as an
650 # error since the connection shouldn't go away
651 # until qemu exits.
652 raise Exception("Console connection closed unexpectedly")
653
654 return data
655
656 def stringify_event(self, event):
657 val = ''
658 if select.POLLERR == event:
659 val = 'POLLER'
660 elif select.POLLHUP == event:
661 val = 'POLLHUP'
662 elif select.POLLNVAL == event:
663 val = 'POLLNVAL'
664 return val
665
666 def close_socket(self, sock):
667 sock.shutdown(socket.SHUT_RDWR)
668 sock.close()
669
670 def close_ignore_error(self, fd):
671 try:
672 os.close(fd)
673 except OSError:
674 pass