summaryrefslogtreecommitdiffstats
path: root/meta/lib/oeqa/utils/qemurunner.py
diff options
context:
space:
mode:
Diffstat (limited to 'meta/lib/oeqa/utils/qemurunner.py')
-rw-r--r--meta/lib/oeqa/utils/qemurunner.py447
1 files changed, 329 insertions, 118 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py
index 77ec939ad7..cda43aad8c 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -19,9 +19,11 @@ import errno
19import string 19import string
20import threading 20import threading
21import codecs 21import codecs
22import logging 22import tempfile
23from oeqa.utils.dump import HostDumper
24from collections import defaultdict 23from collections import defaultdict
24from contextlib import contextmanager
25import importlib
26import traceback
25 27
26# Get Unicode non printable control chars 28# Get Unicode non printable control chars
27control_range = list(range(0,32))+list(range(127,160)) 29control_range = list(range(0,32))+list(range(127,160))
@@ -29,10 +31,19 @@ control_chars = [chr(x) for x in control_range
29 if chr(x) not in string.printable] 31 if chr(x) not in string.printable]
30re_control_char = re.compile('[%s]' % re.escape("".join(control_chars))) 32re_control_char = re.compile('[%s]' % re.escape("".join(control_chars)))
31 33
34def getOutput(o):
35 import fcntl
36 fl = fcntl.fcntl(o, fcntl.F_GETFL)
37 fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK)
38 try:
39 return os.read(o.fileno(), 1000000).decode("utf-8")
40 except BlockingIOError:
41 return ""
42
32class QemuRunner: 43class QemuRunner:
33 44
34 def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds, 45 def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, use_kvm, logger, use_slirp=False,
35 use_kvm, logger, use_slirp=False, serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None): 46 serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None):
36 47
37 # Popen object for runqemu 48 # Popen object for runqemu
38 self.runqemu = None 49 self.runqemu = None
@@ -55,21 +66,24 @@ class QemuRunner:
55 self.boottime = boottime 66 self.boottime = boottime
56 self.logged = False 67 self.logged = False
57 self.thread = None 68 self.thread = None
69 self.threadsock = None
58 self.use_kvm = use_kvm 70 self.use_kvm = use_kvm
59 self.use_ovmf = use_ovmf 71 self.use_ovmf = use_ovmf
60 self.use_slirp = use_slirp 72 self.use_slirp = use_slirp
61 self.serial_ports = serial_ports 73 self.serial_ports = serial_ports
62 self.msg = '' 74 self.msg = ''
63 self.boot_patterns = boot_patterns 75 self.boot_patterns = boot_patterns
76 self.tmpfsdir = tmpfsdir
64 77
65 self.runqemutime = 120 78 self.runqemutime = 300
66 if not workdir: 79 if not workdir:
67 workdir = os.getcwd() 80 workdir = os.getcwd()
68 self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid()) 81 self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid())
69 self.host_dumper = HostDumper(dump_host_cmds, dump_dir)
70 self.monitorpipe = None 82 self.monitorpipe = None
71 83
72 self.logger = logger 84 self.logger = logger
85 # Whether we're expecting an exit and should show related errors
86 self.canexit = False
73 87
74 # Enable testing other OS's 88 # Enable testing other OS's
75 # Set commands for target communication, and default to Linux ALWAYS 89 # Set commands for target communication, and default to Linux ALWAYS
@@ -80,7 +94,7 @@ class QemuRunner:
80 accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished'] 94 accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished']
81 default_boot_patterns = defaultdict(str) 95 default_boot_patterns = defaultdict(str)
82 # Default to the usual paterns used to communicate with the target 96 # Default to the usual paterns used to communicate with the target
83 default_boot_patterns['search_reached_prompt'] = b' login:' 97 default_boot_patterns['search_reached_prompt'] = ' login:'
84 default_boot_patterns['send_login_user'] = 'root\n' 98 default_boot_patterns['send_login_user'] = 'root\n'
85 default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#" 99 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\-]+:~#" 100 default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#"
@@ -94,6 +108,7 @@ class QemuRunner:
94 try: 108 try:
95 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) 109 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
96 sock.setblocking(0) 110 sock.setblocking(0)
111 sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
97 sock.bind(("127.0.0.1",0)) 112 sock.bind(("127.0.0.1",0))
98 sock.listen(2) 113 sock.listen(2)
99 port = sock.getsockname()[1] 114 port = sock.getsockname()[1]
@@ -104,30 +119,24 @@ class QemuRunner:
104 sock.close() 119 sock.close()
105 raise 120 raise
106 121
107 def log(self, msg): 122 def decode_qemulog(self, todecode):
108 if self.logfile: 123 # Sanitize the data received from qemu as it may contain control characters
109 # It is needed to sanitize the data received from qemu 124 msg = todecode.decode("utf-8", errors='backslashreplace')
110 # because is possible to have control characters 125 msg = re_control_char.sub('', msg)
111 msg = msg.decode("utf-8", errors='ignore') 126 return msg
112 msg = re_control_char.sub('', msg)
113 self.msg += msg
114 with codecs.open(self.logfile, "a", encoding="utf-8") as f:
115 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)
121 return os.read(o.fileno(), 1000000).decode("utf-8")
122 127
128 def log(self, msg, extension=""):
129 if self.logfile:
130 with codecs.open(self.logfile + extension, "ab") as f:
131 f.write(msg)
132 self.msg += self.decode_qemulog(msg)
123 133
124 def handleSIGCHLD(self, signum, frame): 134 def handleSIGCHLD(self, signum, frame):
125 if self.runqemu and self.runqemu.poll(): 135 if self.runqemu and self.runqemu.poll():
126 if self.runqemu.returncode: 136 if self.runqemu.returncode:
127 self.logger.error('runqemu exited with code %d' % self.runqemu.returncode) 137 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)) 138 self.logger.error('Output from runqemu:\n%s' % getOutput(self.runqemu.stdout))
129 self.stop() 139 self.stop()
130 self._dump_host()
131 140
132 def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True): 141 def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True):
133 env = os.environ.copy() 142 env = os.environ.copy()
@@ -150,6 +159,9 @@ class QemuRunner:
150 else: 159 else:
151 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image 160 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
152 161
162 if self.tmpfsdir:
163 env["RUNQEMU_TMPFS_DIR"] = self.tmpfsdir
164
153 if not launch_cmd: 165 if not launch_cmd:
154 launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '') 166 launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '')
155 if self.use_kvm: 167 if self.use_kvm:
@@ -163,11 +175,38 @@ class QemuRunner:
163 launch_cmd += ' slirp' 175 launch_cmd += ' slirp'
164 if self.use_ovmf: 176 if self.use_ovmf:
165 launch_cmd += ' ovmf' 177 launch_cmd += ' ovmf'
166 launch_cmd += ' %s %s %s' % (runqemuparams, self.machine, self.rootfs) 178 launch_cmd += ' %s %s' % (runqemuparams, self.machine)
179 if self.rootfs.endswith('.vmdk'):
180 self.logger.debug('Bypassing VMDK rootfs for runqemu')
181 else:
182 launch_cmd += ' %s' % (self.rootfs)
167 183
168 return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env) 184 return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env)
169 185
170 def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None): 186 def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None):
187 # use logfile to determine the recipe-sysroot-native path and
188 # then add in the site-packages path components and add that
189 # to the python sys.path so the qmp module can be found.
190 python_path = os.path.dirname(os.path.dirname(self.logfile))
191 python_path += "/recipe-sysroot-native/usr/lib/qemu-python"
192 sys.path.append(python_path)
193 importlib.invalidate_caches()
194 try:
195 qmp = importlib.import_module("qmp")
196 except Exception as e:
197 self.logger.error("qemurunner: qmp module missing, please ensure it's installed in %s (%s)" % (python_path, str(e)))
198 return False
199 # Path relative to tmpdir used as cwd for qemu below to avoid unix socket path length issues
200 qmp_file = "." + next(tempfile._get_candidate_names())
201 qmp_param = ' -S -qmp unix:./%s,server,wait' % (qmp_file)
202 qmp_port = self.tmpdir + "/" + qmp_file
203 # Create a second socket connection for debugging use,
204 # note this will NOT cause qemu to block waiting for the connection
205 qmp_file2 = "." + next(tempfile._get_candidate_names())
206 qmp_param += ' -qmp unix:./%s,server,nowait' % (qmp_file2)
207 qmp_port2 = self.tmpdir + "/" + qmp_file2
208 self.logger.info("QMP Available for connection at %s" % (qmp_port2))
209
171 try: 210 try:
172 if self.serial_ports >= 2: 211 if self.serial_ports >= 2:
173 self.threadsock, threadport = self.create_socket() 212 self.threadsock, threadport = self.create_socket()
@@ -176,7 +215,7 @@ class QemuRunner:
176 self.logger.error("Failed to create listening socket: %s" % msg[1]) 215 self.logger.error("Failed to create listening socket: %s" % msg[1])
177 return False 216 return False
178 217
179 bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1' 218 bootparams = ' printk.time=1'
180 if extra_bootparams: 219 if extra_bootparams:
181 bootparams = bootparams + ' ' + extra_bootparams 220 bootparams = bootparams + ' ' + extra_bootparams
182 221
@@ -184,7 +223,8 @@ class QemuRunner:
184 # and analyze descendents in order to determine it. 223 # and analyze descendents in order to determine it.
185 if os.path.exists(self.qemu_pidfile): 224 if os.path.exists(self.qemu_pidfile):
186 os.remove(self.qemu_pidfile) 225 os.remove(self.qemu_pidfile)
187 self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1}"'.format(bootparams, self.qemu_pidfile) 226 self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1} {2}"'.format(bootparams, self.qemu_pidfile, qmp_param)
227
188 if qemuparams: 228 if qemuparams:
189 self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"' 229 self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"'
190 230
@@ -196,14 +236,15 @@ class QemuRunner:
196 self.origchldhandler = signal.getsignal(signal.SIGCHLD) 236 self.origchldhandler = signal.getsignal(signal.SIGCHLD)
197 signal.signal(signal.SIGCHLD, self.handleSIGCHLD) 237 signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
198 238
199 self.logger.debug('launchcmd=%s'%(launch_cmd)) 239 self.logger.debug('launchcmd=%s' % (launch_cmd))
200 240
201 # FIXME: We pass in stdin=subprocess.PIPE here to work around stty 241 # 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 242 # blocking at the end of the runqemu script when using this within
203 # oe-selftest (this makes stty error out immediately). There ought 243 # oe-selftest (this makes stty error out immediately). There ought
204 # to be a proper fix but this will suffice for now. 244 # to be a proper fix but this will suffice for now.
205 self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env) 245 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)
206 output = self.runqemu.stdout 246 output = self.runqemu.stdout
247 launch_time = time.time()
207 248
208 # 249 #
209 # We need the preexec_fn above so that all runqemu processes can easily be killed 250 # We need the preexec_fn above so that all runqemu processes can easily be killed
@@ -229,30 +270,33 @@ class QemuRunner:
229 r = os.fdopen(r) 270 r = os.fdopen(r)
230 x = r.read() 271 x = r.read()
231 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) 272 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
232 sys.exit(0) 273 os._exit(0)
233 274
234 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid) 275 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
235 self.logger.debug("waiting at most %s seconds for qemu pid (%s)" % 276 self.logger.debug("waiting at most %d seconds for qemu pid (%s)" %
236 (self.runqemutime, time.strftime("%D %H:%M:%S"))) 277 (self.runqemutime, time.strftime("%D %H:%M:%S")))
237 endtime = time.time() + self.runqemutime 278 endtime = time.time() + self.runqemutime
238 while not self.is_alive() and time.time() < endtime: 279 while not self.is_alive() and time.time() < endtime:
239 if self.runqemu.poll(): 280 if self.runqemu.poll():
240 if self.runqemu_exited: 281 if self.runqemu_exited:
282 self.logger.warning("runqemu during is_alive() test")
241 return False 283 return False
242 if self.runqemu.returncode: 284 if self.runqemu.returncode:
243 # No point waiting any longer 285 # No point waiting any longer
244 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) 286 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
245 self._dump_host() 287 self.logger.warning("Output from runqemu:\n%s" % getOutput(output))
246 self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output))
247 self.stop() 288 self.stop()
248 return False 289 return False
249 time.sleep(0.5) 290 time.sleep(0.5)
250 291
251 if self.runqemu_exited: 292 if self.runqemu_exited:
252 return False 293 self.logger.warning("runqemu after timeout")
294
295 if self.runqemu.returncode:
296 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode)
253 297
254 if not self.is_alive(): 298 if not self.is_alive():
255 self.logger.error("Qemu pid didn't appear in %s seconds (%s)" % 299 self.logger.error("Qemu pid didn't appear in %d seconds (%s)" %
256 (self.runqemutime, time.strftime("%D %H:%M:%S"))) 300 (self.runqemutime, time.strftime("%D %H:%M:%S")))
257 301
258 qemu_pid = None 302 qemu_pid = None
@@ -267,8 +311,7 @@ class QemuRunner:
267 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0] 311 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0]
268 processes = ps.decode("utf-8") 312 processes = ps.decode("utf-8")
269 self.logger.debug("Running processes:\n%s" % processes) 313 self.logger.debug("Running processes:\n%s" % processes)
270 self._dump_host() 314 op = getOutput(output)
271 op = self.getOutput(output)
272 self.stop() 315 self.stop()
273 if op: 316 if op:
274 self.logger.error("Output from runqemu:\n%s" % op) 317 self.logger.error("Output from runqemu:\n%s" % op)
@@ -276,10 +319,79 @@ class QemuRunner:
276 self.logger.error("No output from runqemu.\n") 319 self.logger.error("No output from runqemu.\n")
277 return False 320 return False
278 321
322 # Create the client socket for the QEMU Monitor Control Socket
323 # This will allow us to read status from Qemu if the the process
324 # is still alive
325 self.logger.debug("QMP Initializing to %s" % (qmp_port))
326 # chdir dance for path length issues with unix sockets
327 origpath = os.getcwd()
328 try:
329 os.chdir(os.path.dirname(qmp_port))
330 try:
331 from qmp.legacy import QEMUMonitorProtocol
332 self.qmp = QEMUMonitorProtocol(os.path.basename(qmp_port))
333 except OSError as msg:
334 self.logger.warning("Failed to initialize qemu monitor socket: %s File: %s" % (msg, msg.filename))
335 return False
336
337 self.logger.debug("QMP Connecting to %s" % (qmp_port))
338 if not os.path.exists(qmp_port) and self.is_alive():
339 self.logger.debug("QMP Port does not exist waiting for it to be created")
340 endtime = time.time() + self.runqemutime
341 while not os.path.exists(qmp_port) and self.is_alive() and time.time() < endtime:
342 self.logger.info("QMP port does not exist yet!")
343 time.sleep(0.5)
344 if not os.path.exists(qmp_port) and self.is_alive():
345 self.logger.warning("QMP Port still does not exist but QEMU is alive")
346 return False
347
348 try:
349 # set timeout value for all QMP calls
350 self.qmp.settimeout(self.runqemutime)
351 self.qmp.connect()
352 connect_time = time.time()
353 self.logger.info("QMP connected to QEMU at %s and took %.2f seconds" %
354 (time.strftime("%D %H:%M:%S"),
355 time.time() - launch_time))
356 except OSError as msg:
357 self.logger.warning("Failed to connect qemu monitor socket: %s File: %s" % (msg, msg.filename))
358 return False
359 except qmp.legacy.QMPError as msg:
360 self.logger.warning("Failed to communicate with qemu monitor: %s" % (msg))
361 return False
362 finally:
363 os.chdir(origpath)
364
365 # We worry that mmap'd libraries may cause page faults which hang the qemu VM for periods
366 # causing failures. Before we "start" qemu, read through it's mapped files to try and
367 # ensure we don't hit page faults later
368 mapdir = "/proc/" + str(self.qemupid) + "/map_files/"
369 try:
370 for f in os.listdir(mapdir):
371 try:
372 linktarget = os.readlink(os.path.join(mapdir, f))
373 if not linktarget.startswith("/") or linktarget.startswith("/dev") or "deleted" in linktarget:
374 continue
375 with open(linktarget, "rb") as readf:
376 data = True
377 while data:
378 data = readf.read(4096)
379 except FileNotFoundError:
380 continue
381 # Centos7 doesn't allow us to read /map_files/
382 except PermissionError:
383 pass
384
385 # Release the qemu process to continue running
386 self.run_monitor('cont')
387 self.logger.info("QMP released QEMU at %s and took %.2f seconds from connect" %
388 (time.strftime("%D %H:%M:%S"),
389 time.time() - connect_time))
390
279 # We are alive: qemu is running 391 # We are alive: qemu is running
280 out = self.getOutput(output) 392 out = getOutput(output)
281 netconf = False # network configuration is not required by default 393 netconf = False # network configuration is not required by default
282 self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" % 394 self.logger.debug("qemu started in %.2f seconds - qemu procces pid is %s (%s)" %
283 (time.time() - (endtime - self.runqemutime), 395 (time.time() - (endtime - self.runqemutime),
284 self.qemupid, time.strftime("%D %H:%M:%S"))) 396 self.qemupid, time.strftime("%D %H:%M:%S")))
285 cmdline = '' 397 cmdline = ''
@@ -291,9 +403,10 @@ class QemuRunner:
291 cmdline = re_control_char.sub(' ', cmdline) 403 cmdline = re_control_char.sub(' ', cmdline)
292 try: 404 try:
293 if self.use_slirp: 405 if self.use_slirp:
294 tcp_ports = cmdline.split("hostfwd=tcp::")[1] 406 tcp_ports = cmdline.split("hostfwd=tcp:")[1]
407 ip, tcp_ports = tcp_ports.split(":")[:2]
295 host_port = tcp_ports[:tcp_ports.find('-')] 408 host_port = tcp_ports[:tcp_ports.find('-')]
296 self.ip = "localhost:%s" % host_port 409 self.ip = "%s:%s" % (ip, host_port)
297 else: 410 else:
298 ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) 411 ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
299 self.ip = ips[0] 412 self.ip = ips[0]
@@ -301,8 +414,8 @@ class QemuRunner:
301 self.logger.debug("qemu cmdline used:\n{}".format(cmdline)) 414 self.logger.debug("qemu cmdline used:\n{}".format(cmdline))
302 except (IndexError, ValueError): 415 except (IndexError, ValueError):
303 # Try to get network configuration from runqemu output 416 # Try to get network configuration from runqemu output
304 match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+)$.*', 417 match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+).*',
305 out, re.MULTILINE|re.DOTALL) 418 out, re.MULTILINE | re.DOTALL)
306 if match: 419 if match:
307 self.ip, self.server_ip, self.netmask = match.groups() 420 self.ip, self.server_ip, self.netmask = match.groups()
308 # network configuration is required as we couldn't get it 421 # network configuration is required as we couldn't get it
@@ -313,16 +426,16 @@ class QemuRunner:
313 self.logger.error("Couldn't get ip from qemu command line and runqemu output! " 426 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" 427 "Here is the qemu command line used:\n%s\n"
315 "and output from runqemu:\n%s" % (cmdline, out)) 428 "and output from runqemu:\n%s" % (cmdline, out))
316 self._dump_host()
317 self.stop() 429 self.stop()
318 return False 430 return False
319 431
320 self.logger.debug("Target IP: %s" % self.ip) 432 self.logger.debug("Target IP: %s" % self.ip)
321 self.logger.debug("Server IP: %s" % self.server_ip) 433 self.logger.debug("Server IP: %s" % self.server_ip)
322 434
435 self.thread = LoggingThread(self.log, self.threadsock, self.logger, self.runqemu.stdout)
436 self.thread.start()
437
323 if self.serial_ports >= 2: 438 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): 439 if not self.thread.connection_established.wait(self.boottime):
327 self.logger.error("Didn't receive a console connection from qemu. " 440 self.logger.error("Didn't receive a console connection from qemu. "
328 "Here is the qemu command line used:\n%s\nand " 441 "Here is the qemu command line used:\n%s\nand "
@@ -334,7 +447,7 @@ class QemuRunner:
334 self.logger.debug("Waiting at most %d seconds for login banner (%s)" % 447 self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
335 (self.boottime, time.strftime("%D %H:%M:%S"))) 448 (self.boottime, time.strftime("%D %H:%M:%S")))
336 endtime = time.time() + self.boottime 449 endtime = time.time() + self.boottime
337 socklist = [self.server_socket] 450 filelist = [self.server_socket]
338 reachedlogin = False 451 reachedlogin = False
339 stopread = False 452 stopread = False
340 qemusock = None 453 qemusock = None
@@ -342,61 +455,82 @@ class QemuRunner:
342 data = b'' 455 data = b''
343 while time.time() < endtime and not stopread: 456 while time.time() < endtime and not stopread:
344 try: 457 try:
345 sread, swrite, serror = select.select(socklist, [], [], 5) 458 sread, swrite, serror = select.select(filelist, [], [], 5)
346 except InterruptedError: 459 except InterruptedError:
347 continue 460 continue
348 for sock in sread: 461 for file in sread:
349 if sock is self.server_socket: 462 if file is self.server_socket:
350 qemusock, addr = self.server_socket.accept() 463 qemusock, addr = self.server_socket.accept()
351 qemusock.setblocking(0) 464 qemusock.setblocking(False)
352 socklist.append(qemusock) 465 filelist.append(qemusock)
353 socklist.remove(self.server_socket) 466 filelist.remove(self.server_socket)
354 self.logger.debug("Connection from %s:%s" % addr) 467 self.logger.debug("Connection from %s:%s" % addr)
355 else: 468 else:
356 data = data + sock.recv(1024) 469 # try to avoid reading only a single character at a time
470 time.sleep(0.1)
471 if hasattr(file, 'read'):
472 read = file.read(1024)
473 elif hasattr(file, 'recv'):
474 read = file.recv(1024)
475 else:
476 self.logger.error('Invalid file type: %s\n%s' % (file))
477 read = b''
478
479 self.logger.debug2('Partial boot log:\n%s' % (read.decode('utf-8', errors='backslashreplace')))
480 data = data + read
357 if data: 481 if data:
358 bootlog += data 482 bootlog += data
359 if self.serial_ports < 2: 483 self.log(data, extension = ".2")
360 # this socket has mixed console/kernel data, log it to logfile
361 self.log(data)
362
363 data = b'' 484 data = b''
364 if self.boot_patterns['search_reached_prompt'] in bootlog: 485
486 if bytes(self.boot_patterns['search_reached_prompt'], 'utf-8') in bootlog:
487 self.server_socket.close()
365 self.server_socket = qemusock 488 self.server_socket = qemusock
366 stopread = True 489 stopread = True
367 reachedlogin = True 490 reachedlogin = True
368 self.logger.debug("Reached login banner in %s seconds (%s)" % 491 self.logger.debug("Reached login banner in %.2f seconds (%s)" %
369 (time.time() - (endtime - self.boottime), 492 (time.time() - (endtime - self.boottime),
370 time.strftime("%D %H:%M:%S"))) 493 time.strftime("%D %H:%M:%S")))
371 else: 494 else:
372 # no need to check if reachedlogin unless we support multiple connections 495 # no need to check if reachedlogin unless we support multiple connections
373 self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" % 496 self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" %
374 time.strftime("%D %H:%M:%S")) 497 time.strftime("%D %H:%M:%S"))
375 socklist.remove(sock) 498 filelist.remove(file)
376 sock.close() 499 file.close()
377 stopread = True 500 stopread = True
378 501
379
380 if not reachedlogin: 502 if not reachedlogin:
381 if time.time() >= endtime: 503 if time.time() >= endtime:
382 self.logger.warning("Target didn't reach login banner in %d seconds (%s)" % 504 self.logger.warning("Target didn't reach login banner in %d seconds (%s)" %
383 (self.boottime, time.strftime("%D %H:%M:%S"))) 505 (self.boottime, time.strftime("%D %H:%M:%S")))
384 tail = lambda l: "\n".join(l.splitlines()[-25:]) 506 tail = lambda l: "\n".join(l.splitlines()[-25:])
385 bootlog = bootlog.decode("utf-8") 507 bootlog = self.decode_qemulog(bootlog)
386 # in case bootlog is empty, use tail qemu log store at self.msg 508 self.logger.warning("Last 25 lines of login console (%d):\n%s" % (len(bootlog), tail(bootlog)))
387 lines = tail(bootlog if bootlog else self.msg) 509 self.logger.warning("Last 25 lines of all logging (%d):\n%s" % (len(self.msg), tail(self.msg)))
388 self.logger.warning("Last 25 lines of text:\n%s" % lines)
389 self.logger.warning("Check full boot log: %s" % self.logfile) 510 self.logger.warning("Check full boot log: %s" % self.logfile)
390 self._dump_host()
391 self.stop() 511 self.stop()
512 data = True
513 while data:
514 try:
515 time.sleep(1)
516 data = qemusock.recv(1024)
517 self.log(data, extension = ".2")
518 self.logger.warning('Extra log data read: %s\n' % (data.decode('utf-8', errors='backslashreplace')))
519 except Exception as e:
520 self.logger.warning('Extra log data exception %s' % repr(e))
521 data = None
522 self.thread.serial_lock.release()
392 return False 523 return False
393 524
525 with self.thread.serial_lock:
526 self.thread.set_serialsock(self.server_socket)
527
394 # If we are not able to login the tests can continue 528 # If we are not able to login the tests can continue
395 try: 529 try:
396 (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120) 530 (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120)
397 if re.search(self.boot_patterns['search_login_succeeded'], output): 531 if re.search(self.boot_patterns['search_login_succeeded'], output):
398 self.logged = True 532 self.logged = True
399 self.logger.debug("Logged as root in serial console") 533 self.logger.debug("Logged in as %s in serial console" % self.boot_patterns['send_login_user'].replace("\n", ""))
400 if netconf: 534 if netconf:
401 # configure guest networking 535 # configure guest networking
402 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) 536 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
@@ -407,7 +541,7 @@ class QemuRunner:
407 self.logger.debug("Couldn't configure guest networking") 541 self.logger.debug("Couldn't configure guest networking")
408 else: 542 else:
409 self.logger.warning("Couldn't login into serial console" 543 self.logger.warning("Couldn't login into serial console"
410 " as root using blank password") 544 " as %s using blank password" % self.boot_patterns['send_login_user'].replace("\n", ""))
411 self.logger.warning("The output:\n%s" % output) 545 self.logger.warning("The output:\n%s" % output)
412 except: 546 except:
413 self.logger.warning("Serial console failed while trying to login") 547 self.logger.warning("Serial console failed while trying to login")
@@ -427,16 +561,24 @@ class QemuRunner:
427 except OSError as e: 561 except OSError as e:
428 if e.errno != errno.ESRCH: 562 if e.errno != errno.ESRCH:
429 raise 563 raise
430 endtime = time.time() + self.runqemutime 564 try:
431 while self.runqemu.poll() is None and time.time() < endtime: 565 outs, errs = self.runqemu.communicate(timeout=self.runqemutime)
432 time.sleep(1) 566 if outs:
433 if self.runqemu.poll() is None: 567 self.logger.info("Output from runqemu:\n%s", outs.decode("utf-8"))
568 if errs:
569 self.logger.info("Stderr from runqemu:\n%s", errs.decode("utf-8"))
570 except subprocess.TimeoutExpired:
434 self.logger.debug("Sending SIGKILL to runqemu") 571 self.logger.debug("Sending SIGKILL to runqemu")
435 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) 572 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
573 if not self.runqemu.stdout.closed:
574 self.logger.info("Output from runqemu:\n%s" % getOutput(self.runqemu.stdout))
436 self.runqemu.stdin.close() 575 self.runqemu.stdin.close()
437 self.runqemu.stdout.close() 576 self.runqemu.stdout.close()
438 self.runqemu_exited = True 577 self.runqemu_exited = True
439 578
579 if hasattr(self, 'qmp') and self.qmp:
580 self.qmp.close()
581 self.qmp = None
440 if hasattr(self, 'server_socket') and self.server_socket: 582 if hasattr(self, 'server_socket') and self.server_socket:
441 self.server_socket.close() 583 self.server_socket.close()
442 self.server_socket = None 584 self.server_socket = None
@@ -467,6 +609,11 @@ class QemuRunner:
467 self.thread.stop() 609 self.thread.stop()
468 self.thread.join() 610 self.thread.join()
469 611
612 def allowexit(self):
613 self.canexit = True
614 if self.thread:
615 self.thread.allowexit()
616
470 def restart(self, qemuparams = None): 617 def restart(self, qemuparams = None):
471 self.logger.warning("Restarting qemu process") 618 self.logger.warning("Restarting qemu process")
472 if self.runqemu.poll() is None: 619 if self.runqemu.poll() is None:
@@ -483,8 +630,12 @@ class QemuRunner:
483 # so it's possible that the file has been created but the content is empty 630 # so it's possible that the file has been created but the content is empty
484 pidfile_timeout = time.time() + 3 631 pidfile_timeout = time.time() + 3
485 while time.time() < pidfile_timeout: 632 while time.time() < pidfile_timeout:
486 with open(self.qemu_pidfile, 'r') as f: 633 try:
487 qemu_pid = f.read().strip() 634 with open(self.qemu_pidfile, 'r') as f:
635 qemu_pid = f.read().strip()
636 except FileNotFoundError:
637 # Can be used to detect shutdown so the pid file can disappear
638 return False
488 # file created but not yet written contents 639 # file created but not yet written contents
489 if not qemu_pid: 640 if not qemu_pid:
490 time.sleep(0.5) 641 time.sleep(0.5)
@@ -495,34 +646,49 @@ class QemuRunner:
495 return True 646 return True
496 return False 647 return False
497 648
649 def run_monitor(self, command, args=None, timeout=60):
650 if hasattr(self, 'qmp') and self.qmp:
651 self.qmp.settimeout(timeout)
652 if args is not None:
653 return self.qmp.cmd_raw(command, args)
654 else:
655 return self.qmp.cmd_raw(command)
656
498 def run_serial(self, command, raw=False, timeout=60): 657 def run_serial(self, command, raw=False, timeout=60):
658 # Returns (status, output) where status is 1 on success and 0 on error
659
499 # We assume target system have echo to get command status 660 # We assume target system have echo to get command status
500 if not raw: 661 if not raw:
501 command = "%s; echo $?\n" % command 662 command = "%s; echo $?\n" % command
502 663
503 data = '' 664 data = ''
504 status = 0 665 status = 0
505 self.server_socket.sendall(command.encode('utf-8')) 666 with self.thread.serial_lock:
506 start = time.time() 667 self.server_socket.sendall(command.encode('utf-8'))
507 end = start + timeout 668 start = time.time()
508 while True: 669 end = start + timeout
509 now = time.time() 670 while True:
510 if now >= end: 671 now = time.time()
511 data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout 672 if now >= end:
512 break 673 data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
513 try: 674 break
514 sread, _, _ = select.select([self.server_socket],[],[], end - now) 675 try:
515 except InterruptedError: 676 sread, _, _ = select.select([self.server_socket],[],[], end - now)
516 continue 677 except InterruptedError:
517 if sread: 678 continue
518 answer = self.server_socket.recv(1024) 679 if sread:
519 if answer: 680 # try to avoid reading single character at a time
520 data += answer.decode('utf-8') 681 time.sleep(0.1)
521 # Search the prompt to stop 682 answer = self.server_socket.recv(1024)
522 if re.search(self.boot_patterns['search_cmd_finished'], data): 683 if answer:
523 break 684 data += answer.decode('utf-8')
524 else: 685 # Search the prompt to stop
525 raise Exception("No data on serial console socket") 686 if re.search(self.boot_patterns['search_cmd_finished'], data):
687 break
688 else:
689 if self.canexit:
690 return (1, "")
691 raise Exception("No data on serial console socket, connection closed?")
526 692
527 if data: 693 if data:
528 if raw: 694 if raw:
@@ -541,34 +707,46 @@ class QemuRunner:
541 status = 1 707 status = 1
542 return (status, str(data)) 708 return (status, str(data))
543 709
544 710@contextmanager
545 def _dump_host(self): 711def nonblocking_lock(lock):
546 self.host_dumper.create_dir("qemu") 712 locked = lock.acquire(False)
547 self.logger.warning("Qemu ended unexpectedly, dump data from host" 713 try:
548 " is in %s" % self.host_dumper.dump_dir) 714 yield locked
549 self.host_dumper.dump_host() 715 finally:
716 if locked:
717 lock.release()
550 718
551# This class is for reading data from a socket and passing it to logfunc 719# 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 720# 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 721# 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. 722# will wake up the poll and allow for tearing everything down.
555class LoggingThread(threading.Thread): 723class LoggingThread(threading.Thread):
556 def __init__(self, logfunc, sock, logger): 724 def __init__(self, logfunc, sock, logger, qemuoutput):
557 self.connection_established = threading.Event() 725 self.connection_established = threading.Event()
726 self.serial_lock = threading.Lock()
727
558 self.serversock = sock 728 self.serversock = sock
729 self.serialsock = None
730 self.qemuoutput = qemuoutput
559 self.logfunc = logfunc 731 self.logfunc = logfunc
560 self.logger = logger 732 self.logger = logger
561 self.readsock = None 733 self.readsock = None
562 self.running = False 734 self.running = False
735 self.canexit = False
563 736
564 self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL 737 self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
565 self.readevents = select.POLLIN | select.POLLPRI 738 self.readevents = select.POLLIN | select.POLLPRI
566 739
567 threading.Thread.__init__(self, target=self.threadtarget) 740 threading.Thread.__init__(self, target=self.threadtarget)
568 741
742 def set_serialsock(self, serialsock):
743 self.serialsock = serialsock
744
569 def threadtarget(self): 745 def threadtarget(self):
570 try: 746 try:
571 self.eventloop() 747 self.eventloop()
748 except Exception as e:
749 self.logger.warning("Exception %s in logging thread" % traceback.format_exception(e))
572 finally: 750 finally:
573 self.teardown() 751 self.teardown()
574 752
@@ -584,7 +762,8 @@ class LoggingThread(threading.Thread):
584 762
585 def teardown(self): 763 def teardown(self):
586 self.logger.debug("Tearing down logging thread") 764 self.logger.debug("Tearing down logging thread")
587 self.close_socket(self.serversock) 765 if self.serversock:
766 self.close_socket(self.serversock)
588 767
589 if self.readsock is not None: 768 if self.readsock is not None:
590 self.close_socket(self.readsock) 769 self.close_socket(self.readsock)
@@ -593,30 +772,37 @@ class LoggingThread(threading.Thread):
593 self.close_ignore_error(self.writepipe) 772 self.close_ignore_error(self.writepipe)
594 self.running = False 773 self.running = False
595 774
775 def allowexit(self):
776 self.canexit = True
777
596 def eventloop(self): 778 def eventloop(self):
597 poll = select.poll() 779 poll = select.poll()
598 event_read_mask = self.errorevents | self.readevents 780 event_read_mask = self.errorevents | self.readevents
599 poll.register(self.serversock.fileno()) 781 if self.serversock:
782 poll.register(self.serversock.fileno())
783 serial_registered = False
784 poll.register(self.qemuoutput.fileno())
600 poll.register(self.readpipe, event_read_mask) 785 poll.register(self.readpipe, event_read_mask)
601 786
602 breakout = False 787 breakout = False
603 self.running = True 788 self.running = True
604 self.logger.debug("Starting thread event loop") 789 self.logger.debug("Starting thread event loop")
605 while not breakout: 790 while not breakout:
606 events = poll.poll() 791 events = poll.poll(2)
607 for event in events: 792 for fd, event in events:
793
608 # An error occurred, bail out 794 # An error occurred, bail out
609 if event[1] & self.errorevents: 795 if event & self.errorevents:
610 raise Exception(self.stringify_event(event[1])) 796 raise Exception(self.stringify_event(event))
611 797
612 # Event to stop the thread 798 # Event to stop the thread
613 if self.readpipe == event[0]: 799 if self.readpipe == fd:
614 self.logger.debug("Stop event received") 800 self.logger.debug("Stop event received")
615 breakout = True 801 breakout = True
616 break 802 break
617 803
618 # A connection request was received 804 # A connection request was received
619 elif self.serversock.fileno() == event[0]: 805 elif self.serversock and self.serversock.fileno() == fd:
620 self.logger.debug("Connection request received") 806 self.logger.debug("Connection request received")
621 self.readsock, _ = self.serversock.accept() 807 self.readsock, _ = self.serversock.accept()
622 self.readsock.setblocking(0) 808 self.readsock.setblocking(0)
@@ -627,18 +813,38 @@ class LoggingThread(threading.Thread):
627 self.connection_established.set() 813 self.connection_established.set()
628 814
629 # Actual data to be logged 815 # Actual data to be logged
630 elif self.readsock.fileno() == event[0]: 816 elif self.readsock and self.readsock.fileno() == fd:
631 data = self.recv(1024) 817 data = self.recv(1024, self.readsock)
632 self.logfunc(data) 818 self.logfunc(data)
819 elif self.qemuoutput.fileno() == fd:
820 data = self.qemuoutput.read()
821 self.logger.debug("Data received on qemu stdout %s" % data)
822 self.logfunc(data, ".stdout")
823 elif self.serialsock and self.serialsock.fileno() == fd:
824 if self.serial_lock.acquire(blocking=False):
825 data = self.recv(1024, self.serialsock)
826 self.logger.debug("Data received serial thread %s" % data.decode('utf-8', 'replace'))
827 self.logfunc(data, ".2")
828 self.serial_lock.release()
829 else:
830 serial_registered = False
831 poll.unregister(self.serialsock.fileno())
832
833 if not serial_registered and self.serialsock:
834 with nonblocking_lock(self.serial_lock) as l:
835 if l:
836 serial_registered = True
837 poll.register(self.serialsock.fileno(), event_read_mask)
838
633 839
634 # Since the socket is non-blocking make sure to honor EAGAIN 840 # Since the socket is non-blocking make sure to honor EAGAIN
635 # and EWOULDBLOCK. 841 # and EWOULDBLOCK.
636 def recv(self, count): 842 def recv(self, count, sock):
637 try: 843 try:
638 data = self.readsock.recv(count) 844 data = sock.recv(count)
639 except socket.error as e: 845 except socket.error as e:
640 if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK: 846 if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
641 return '' 847 return b''
642 else: 848 else:
643 raise 849 raise
644 850
@@ -649,7 +855,9 @@ class LoggingThread(threading.Thread):
649 # happened. But for this code it counts as an 855 # happened. But for this code it counts as an
650 # error since the connection shouldn't go away 856 # error since the connection shouldn't go away
651 # until qemu exits. 857 # until qemu exits.
652 raise Exception("Console connection closed unexpectedly") 858 if not self.canexit:
859 raise Exception("Console connection closed unexpectedly")
860 return b''
653 861
654 return data 862 return data
655 863
@@ -661,6 +869,9 @@ class LoggingThread(threading.Thread):
661 val = 'POLLHUP' 869 val = 'POLLHUP'
662 elif select.POLLNVAL == event: 870 elif select.POLLNVAL == event:
663 val = 'POLLNVAL' 871 val = 'POLLNVAL'
872 else:
873 val = "0x%x" % (event)
874
664 return val 875 return val
665 876
666 def close_socket(self, sock): 877 def close_socket(self, sock):