1# 2# Copyright (C) 2013 Intel Corporation 3# 4# SPDX-License-Identifier: MIT 5# 6 7# This module provides a class for starting qemu images using runqemu. 8# It's used by testimage.bbclass. 9 10import subprocess 11import os 12import sys 13import time 14import signal 15import re 16import socket 17import select 18import errno 19import string 20import threading 21import codecs 22import tempfile 23from collections import defaultdict 24from contextlib import contextmanager 25import importlib 26import traceback 27 28# Get Unicode non printable control chars 29control_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] 32re_control_char = re.compile('[%s]' % re.escape("".join(control_chars))) 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 43class QemuRunner: 44 45 def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, use_kvm, logger, use_slirp=False, 46 serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None): 47 48 # Popen object for runqemu 49 self.runqemu = None 50 self.runqemu_exited = False 51 # pid of the qemu process that runqemu will start 52 self.qemupid = None 53 # target ip - from the command line or runqemu output 54 self.ip = None 55 # host ip - where qemu is running 56 self.server_ip = None 57 # target ip netmask 58 self.netmask = None 59 60 self.machine = machine 61 self.rootfs = rootfs 62 self.display = display 63 self.tmpdir = tmpdir 64 self.deploy_dir_image = deploy_dir_image 65 self.logfile = logfile 66 self.boottime = boottime 67 self.logged = False 68 self.thread = None 69 self.threadsock = None 70 self.use_kvm = use_kvm 71 self.use_ovmf = use_ovmf 72 self.use_slirp = use_slirp 73 self.serial_ports = serial_ports 74 self.msg = '' 75 self.boot_patterns = boot_patterns 76 self.tmpfsdir = tmpfsdir 77 78 self.runqemutime = 300 79 if not workdir: 80 workdir = os.getcwd() 81 self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid()) 82 self.monitorpipe = None 83 84 self.logger = logger 85 # Whether we're expecting an exit and should show related errors 86 self.canexit = False 87 88 # Enable testing other OS's 89 # Set commands for target communication, and default to Linux ALWAYS 90 # Other OS's or baremetal applications need to provide their 91 # own implementation passing it through QemuRunner's constructor 92 # or by passing them through TESTIMAGE_BOOT_PATTERNS[flag] 93 # provided variables, where <flag> is one of the mentioned below. 94 accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished'] 95 default_boot_patterns = defaultdict(str) 96 # Default to the usual paterns used to communicate with the target 97 default_boot_patterns['search_reached_prompt'] = ' login:' 98 default_boot_patterns['send_login_user'] = 'root\n' 99 default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#" 100 default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#" 101 102 # Only override patterns that were set e.g. login user TESTIMAGE_BOOT_PATTERNS[send_login_user] = "webserver\n" 103 for pattern in accepted_patterns: 104 if not self.boot_patterns[pattern]: 105 self.boot_patterns[pattern] = default_boot_patterns[pattern] 106 107 def create_socket(self): 108 try: 109 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) 110 sock.setblocking(0) 111 sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) 112 sock.bind(("127.0.0.1",0)) 113 sock.listen(2) 114 port = sock.getsockname()[1] 115 self.logger.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) 116 return (sock, port) 117 118 except socket.error: 119 sock.close() 120 raise 121 122 def decode_qemulog(self, todecode): 123 # Sanitize the data received from qemu as it may contain control characters 124 msg = todecode.decode("utf-8", errors='backslashreplace') 125 msg = re_control_char.sub('', msg) 126 return msg 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) 133 134 def handleSIGCHLD(self, signum, frame): 135 if self.runqemu and self.runqemu.poll(): 136 if self.runqemu.returncode: 137 self.logger.error('runqemu exited with code %d' % self.runqemu.returncode) 138 self.logger.error('Output from runqemu:\n%s' % getOutput(self.runqemu.stdout)) 139 self.stop() 140 141 def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True): 142 env = os.environ.copy() 143 if self.display: 144 env["DISPLAY"] = self.display 145 # Set this flag so that Qemu doesn't do any grabs as SDL grabs 146 # interact badly with screensavers. 147 env["QEMU_DONT_GRAB"] = "1" 148 if not os.path.exists(self.rootfs): 149 self.logger.error("Invalid rootfs %s" % self.rootfs) 150 return False 151 if not os.path.exists(self.tmpdir): 152 self.logger.error("Invalid TMPDIR path %s" % self.tmpdir) 153 return False 154 else: 155 env["OE_TMPDIR"] = self.tmpdir 156 if not os.path.exists(self.deploy_dir_image): 157 self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image) 158 return False 159 else: 160 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image 161 162 if self.tmpfsdir: 163 env["RUNQEMU_TMPFS_DIR"] = self.tmpfsdir 164 165 if not launch_cmd: 166 launch_cmd = 'runqemu %s' % ('snapshot' if discard_writes else '') 167 if self.use_kvm: 168 self.logger.debug('Using kvm for runqemu') 169 launch_cmd += ' kvm' 170 else: 171 self.logger.debug('Not using kvm for runqemu') 172 if not self.display: 173 launch_cmd += ' nographic' 174 if self.use_slirp: 175 launch_cmd += ' slirp' 176 if self.use_ovmf: 177 launch_cmd += ' ovmf' 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) 183 184 return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env) 185 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 210 try: 211 if self.serial_ports >= 2: 212 self.threadsock, threadport = self.create_socket() 213 self.server_socket, self.serverport = self.create_socket() 214 except socket.error as msg: 215 self.logger.error("Failed to create listening socket: %s" % msg[1]) 216 return False 217 218 bootparams = ' printk.time=1' 219 if extra_bootparams: 220 bootparams = bootparams + ' ' + extra_bootparams 221 222 # Ask QEMU to store the QEMU process PID in file, this way we don't have to parse running processes 223 # and analyze descendents in order to determine it. 224 if os.path.exists(self.qemu_pidfile): 225 os.remove(self.qemu_pidfile) 226 self.qemuparams = 'bootparams="{0}" qemuparams="-pidfile {1} {2}"'.format(bootparams, self.qemu_pidfile, qmp_param) 227 228 if qemuparams: 229 self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"' 230 231 if self.serial_ports >= 2: 232 launch_cmd += ' tcpserial=%s:%s %s' % (threadport, self.serverport, self.qemuparams) 233 else: 234 launch_cmd += ' tcpserial=%s %s' % (self.serverport, self.qemuparams) 235 236 self.origchldhandler = signal.getsignal(signal.SIGCHLD) 237 signal.signal(signal.SIGCHLD, self.handleSIGCHLD) 238 239 self.logger.debug('launchcmd=%s' % (launch_cmd)) 240 241 # FIXME: We pass in stdin=subprocess.PIPE here to work around stty 242 # blocking at the end of the runqemu script when using this within 243 # oe-selftest (this makes stty error out immediately). There ought 244 # to be a proper fix but this will suffice for now. 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) 246 output = self.runqemu.stdout 247 launch_time = time.time() 248 249 # 250 # We need the preexec_fn above so that all runqemu processes can easily be killed 251 # (by killing their process group). This presents a problem if this controlling 252 # process itself is killed however since those processes don't notice the death 253 # of the parent and merrily continue on. 254 # 255 # Rather than hack runqemu to deal with this, we add something here instead. 256 # Basically we fork off another process which holds an open pipe to the parent 257 # and also is setpgrp. If/when the pipe sees EOF from the parent dieing, it kills 258 # the process group. This is like pctrl's PDEATHSIG but for a process group 259 # rather than a single process. 260 # 261 r, w = os.pipe() 262 self.monitorpid = os.fork() 263 if self.monitorpid: 264 os.close(r) 265 self.monitorpipe = os.fdopen(w, "w") 266 else: 267 # child process 268 os.setpgrp() 269 os.close(w) 270 r = os.fdopen(r) 271 x = r.read() 272 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) 273 os._exit(0) 274 275 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid) 276 self.logger.debug("waiting at most %d seconds for qemu pid (%s)" % 277 (self.runqemutime, time.strftime("%D %H:%M:%S"))) 278 endtime = time.time() + self.runqemutime 279 while not self.is_alive() and time.time() < endtime: 280 if self.runqemu.poll(): 281 if self.runqemu_exited: 282 self.logger.warning("runqemu during is_alive() test") 283 return False 284 if self.runqemu.returncode: 285 # No point waiting any longer 286 self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) 287 self.logger.warning("Output from runqemu:\n%s" % getOutput(output)) 288 self.stop() 289 return False 290 time.sleep(0.5) 291 292 if self.runqemu_exited: 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) 297 298 if not self.is_alive(): 299 self.logger.error("Qemu pid didn't appear in %d seconds (%s)" % 300 (self.runqemutime, time.strftime("%D %H:%M:%S"))) 301 302 qemu_pid = None 303 if os.path.isfile(self.qemu_pidfile): 304 with open(self.qemu_pidfile, 'r') as f: 305 qemu_pid = f.read().strip() 306 307 self.logger.error("Status information, poll status: %s, pidfile exists: %s, pidfile contents %s, proc pid exists %s" 308 % (self.runqemu.poll(), os.path.isfile(self.qemu_pidfile), str(qemu_pid), os.path.exists("/proc/" + str(qemu_pid)))) 309 310 # Dump all processes to help us to figure out what is going on... 311 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0] 312 processes = ps.decode("utf-8") 313 self.logger.debug("Running processes:\n%s" % processes) 314 op = getOutput(output) 315 self.stop() 316 if op: 317 self.logger.error("Output from runqemu:\n%s" % op) 318 else: 319 self.logger.error("No output from runqemu.\n") 320 return False 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 391 # We are alive: qemu is running 392 out = getOutput(output) 393 netconf = False # network configuration is not required by default 394 self.logger.debug("qemu started in %.2f seconds - qemu procces pid is %s (%s)" % 395 (time.time() - (endtime - self.runqemutime), 396 self.qemupid, time.strftime("%D %H:%M:%S"))) 397 cmdline = '' 398 if get_ip: 399 with open('/proc/%s/cmdline' % self.qemupid) as p: 400 cmdline = p.read() 401 # It is needed to sanitize the data received 402 # because is possible to have control characters 403 cmdline = re_control_char.sub(' ', cmdline) 404 try: 405 if self.use_slirp: 406 tcp_ports = cmdline.split("hostfwd=tcp:")[1] 407 ip, tcp_ports = tcp_ports.split(":")[:2] 408 host_port = tcp_ports[:tcp_ports.find('-')] 409 self.ip = "%s:%s" % (ip, host_port) 410 else: 411 ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) 412 self.ip = ips[0] 413 self.server_ip = ips[1] 414 self.logger.debug("qemu cmdline used:\n{}".format(cmdline)) 415 except (IndexError, ValueError): 416 # Try to get network configuration from runqemu output 417 match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+).*', 418 out, re.MULTILINE | re.DOTALL) 419 if match: 420 self.ip, self.server_ip, self.netmask = match.groups() 421 # network configuration is required as we couldn't get it 422 # from the runqemu command line, so qemu doesn't run kernel 423 # and guest networking is not configured 424 netconf = True 425 else: 426 self.logger.error("Couldn't get ip from qemu command line and runqemu output! " 427 "Here is the qemu command line used:\n%s\n" 428 "and output from runqemu:\n%s" % (cmdline, out)) 429 self.stop() 430 return False 431 432 self.logger.debug("Target IP: %s" % self.ip) 433 self.logger.debug("Server IP: %s" % self.server_ip) 434 435 self.thread = LoggingThread(self.log, self.threadsock, self.logger, self.runqemu.stdout) 436 self.thread.start() 437 438 if self.serial_ports >= 2: 439 if not self.thread.connection_established.wait(self.boottime): 440 self.logger.error("Didn't receive a console connection from qemu. " 441 "Here is the qemu command line used:\n%s\nand " 442 "output from runqemu:\n%s" % (cmdline, out)) 443 self.stop_thread() 444 return False 445 446 self.logger.debug("Output from runqemu:\n%s", out) 447 self.logger.debug("Waiting at most %d seconds for login banner (%s)" % 448 (self.boottime, time.strftime("%D %H:%M:%S"))) 449 endtime = time.time() + self.boottime 450 filelist = [self.server_socket] 451 reachedlogin = False 452 stopread = False 453 qemusock = None 454 bootlog = b'' 455 data = b'' 456 while time.time() < endtime and not stopread: 457 try: 458 sread, swrite, serror = select.select(filelist, [], [], 5) 459 except InterruptedError: 460 continue 461 for file in sread: 462 if file is self.server_socket: 463 qemusock, addr = self.server_socket.accept() 464 qemusock.setblocking(False) 465 filelist.append(qemusock) 466 filelist.remove(self.server_socket) 467 self.logger.debug("Connection from %s:%s" % addr) 468 else: 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 481 if data: 482 bootlog += data 483 self.log(data, extension = ".2") 484 data = b'' 485 486 if bytes(self.boot_patterns['search_reached_prompt'], 'utf-8') in bootlog: 487 self.server_socket.close() 488 self.server_socket = qemusock 489 stopread = True 490 reachedlogin = True 491 self.logger.debug("Reached login banner in %.2f seconds (%s)" % 492 (time.time() - (endtime - self.boottime), 493 time.strftime("%D %H:%M:%S"))) 494 else: 495 # no need to check if reachedlogin unless we support multiple connections 496 self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" % 497 time.strftime("%D %H:%M:%S")) 498 filelist.remove(file) 499 file.close() 500 stopread = True 501 502 if not reachedlogin: 503 if time.time() >= endtime: 504 self.logger.warning("Target didn't reach login banner in %d seconds (%s)" % 505 (self.boottime, time.strftime("%D %H:%M:%S"))) 506 tail = lambda l: "\n".join(l.splitlines()[-25:]) 507 bootlog = self.decode_qemulog(bootlog) 508 self.logger.warning("Last 25 lines of login console (%d):\n%s" % (len(bootlog), tail(bootlog))) 509 self.logger.warning("Last 25 lines of all logging (%d):\n%s" % (len(self.msg), tail(self.msg))) 510 self.logger.warning("Check full boot log: %s" % self.logfile) 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() 523 return False 524 525 with self.thread.serial_lock: 526 self.thread.set_serialsock(self.server_socket) 527 528 # If we are not able to login the tests can continue 529 try: 530 (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120) 531 if re.search(self.boot_patterns['search_login_succeeded'], output): 532 self.logged = True 533 self.logger.debug("Logged in as %s in serial console" % self.boot_patterns['send_login_user'].replace("\n", "")) 534 if netconf: 535 # configure guest networking 536 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) 537 output = self.run_serial(cmd, raw=True)[1] 538 if re.search(r"root@[a-zA-Z0-9\-]+:~#", output): 539 self.logger.debug("configured ip address %s", self.ip) 540 else: 541 self.logger.debug("Couldn't configure guest networking") 542 else: 543 self.logger.warning("Couldn't login into serial console" 544 " as %s using blank password" % self.boot_patterns['send_login_user'].replace("\n", "")) 545 self.logger.warning("The output:\n%s" % output) 546 except: 547 self.logger.warning("Serial console failed while trying to login") 548 return True 549 550 def stop(self): 551 if hasattr(self, "origchldhandler"): 552 signal.signal(signal.SIGCHLD, self.origchldhandler) 553 self.stop_thread() 554 self.stop_qemu_system() 555 if self.runqemu: 556 if hasattr(self, "monitorpid"): 557 os.kill(self.monitorpid, signal.SIGKILL) 558 self.logger.debug("Sending SIGTERM to runqemu") 559 try: 560 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) 561 except OSError as e: 562 if e.errno != errno.ESRCH: 563 raise 564 try: 565 outs, errs = self.runqemu.communicate(timeout=self.runqemutime) 566 if outs: 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: 571 self.logger.debug("Sending SIGKILL to runqemu") 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)) 575 self.runqemu.stdin.close() 576 self.runqemu.stdout.close() 577 self.runqemu_exited = True 578 579 if hasattr(self, 'qmp') and self.qmp: 580 self.qmp.close() 581 self.qmp = None 582 if hasattr(self, 'server_socket') and self.server_socket: 583 self.server_socket.close() 584 self.server_socket = None 585 if hasattr(self, 'threadsock') and self.threadsock: 586 self.threadsock.close() 587 self.threadsock = None 588 self.qemupid = None 589 self.ip = None 590 if os.path.exists(self.qemu_pidfile): 591 try: 592 os.remove(self.qemu_pidfile) 593 except FileNotFoundError as e: 594 # We raced, ignore 595 pass 596 if self.monitorpipe: 597 self.monitorpipe.close() 598 599 def stop_qemu_system(self): 600 if self.qemupid: 601 try: 602 # qemu-system behaves well and a SIGTERM is enough 603 os.kill(self.qemupid, signal.SIGTERM) 604 except ProcessLookupError as e: 605 self.logger.warning('qemu-system ended unexpectedly') 606 607 def stop_thread(self): 608 if self.thread and self.thread.is_alive(): 609 self.thread.stop() 610 self.thread.join() 611 612 def allowexit(self): 613 self.canexit = True 614 if self.thread: 615 self.thread.allowexit() 616 617 def restart(self, qemuparams = None): 618 self.logger.warning("Restarting qemu process") 619 if self.runqemu.poll() is None: 620 self.stop() 621 if self.start(qemuparams): 622 return True 623 return False 624 625 def is_alive(self): 626 if not self.runqemu or self.runqemu.poll() is not None or self.runqemu_exited: 627 return False 628 if os.path.isfile(self.qemu_pidfile): 629 # when handling pidfile, qemu creates the file, stat it, lock it and then write to it 630 # so it's possible that the file has been created but the content is empty 631 pidfile_timeout = time.time() + 3 632 while time.time() < pidfile_timeout: 633 try: 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 639 # file created but not yet written contents 640 if not qemu_pid: 641 time.sleep(0.5) 642 continue 643 else: 644 if os.path.exists("/proc/" + qemu_pid): 645 self.qemupid = int(qemu_pid) 646 return True 647 return False 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 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 660 # We assume target system have echo to get command status 661 if not raw: 662 command = "%s; echo $?\n" % command 663 664 data = '' 665 status = 0 666 with self.thread.serial_lock: 667 self.server_socket.sendall(command.encode('utf-8')) 668 start = time.time() 669 end = start + timeout 670 while True: 671 now = time.time() 672 if now >= end: 673 data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout 674 break 675 try: 676 sread, _, _ = select.select([self.server_socket],[],[], end - now) 677 except InterruptedError: 678 continue 679 if sread: 680 # try to avoid reading single character at a time 681 time.sleep(0.1) 682 answer = self.server_socket.recv(1024) 683 if answer: 684 data += answer.decode('utf-8') 685 # Search the prompt to stop 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?") 692 693 if data: 694 if raw: 695 status = 1 696 else: 697 # Remove first line (command line) and last line (prompt) 698 data = data[data.find('$?\r\n')+4:data.rfind('\r\n')] 699 index = data.rfind('\r\n') 700 if index == -1: 701 status_cmd = data 702 data = "" 703 else: 704 status_cmd = data[index+2:] 705 data = data[:index] 706 if (status_cmd == "0"): 707 status = 1 708 return (status, str(data)) 709 710@contextmanager 711def nonblocking_lock(lock): 712 locked = lock.acquire(False) 713 try: 714 yield locked 715 finally: 716 if locked: 717 lock.release() 718 719# This class is for reading data from a socket and passing it to logfunc 720# to be processed. It's completely event driven and has a straightforward 721# event loop. The mechanism for stopping the thread is a simple pipe which 722# will wake up the poll and allow for tearing everything down. 723class LoggingThread(threading.Thread): 724 def __init__(self, logfunc, sock, logger, qemuoutput): 725 self.connection_established = threading.Event() 726 self.serial_lock = threading.Lock() 727 728 self.serversock = sock 729 self.serialsock = None 730 self.qemuoutput = qemuoutput 731 self.logfunc = logfunc 732 self.logger = logger 733 self.readsock = None 734 self.running = False 735 self.canexit = False 736 737 self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL 738 self.readevents = select.POLLIN | select.POLLPRI 739 740 threading.Thread.__init__(self, target=self.threadtarget) 741 742 def set_serialsock(self, serialsock): 743 self.serialsock = serialsock 744 745 def threadtarget(self): 746 try: 747 self.eventloop() 748 except Exception as e: 749 self.logger.warning("Exception %s in logging thread" % traceback.format_exception(e)) 750 finally: 751 self.teardown() 752 753 def run(self): 754 self.logger.debug("Starting logging thread") 755 self.readpipe, self.writepipe = os.pipe() 756 threading.Thread.run(self) 757 758 def stop(self): 759 self.logger.debug("Stopping logging thread") 760 if self.running: 761 os.write(self.writepipe, bytes("stop", "utf-8")) 762 763 def teardown(self): 764 self.logger.debug("Tearing down logging thread") 765 if self.serversock: 766 self.close_socket(self.serversock) 767 768 if self.readsock is not None: 769 self.close_socket(self.readsock) 770 771 self.close_ignore_error(self.readpipe) 772 self.close_ignore_error(self.writepipe) 773 self.running = False 774 775 def allowexit(self): 776 self.canexit = True 777 778 def eventloop(self): 779 poll = select.poll() 780 event_read_mask = self.errorevents | self.readevents 781 if self.serversock: 782 poll.register(self.serversock.fileno()) 783 serial_registered = False 784 poll.register(self.qemuoutput.fileno()) 785 poll.register(self.readpipe, event_read_mask) 786 787 breakout = False 788 self.running = True 789 self.logger.debug("Starting thread event loop") 790 while not breakout: 791 events = poll.poll(2) 792 for fd, event in events: 793 794 # An error occurred, bail out 795 if event & self.errorevents: 796 raise Exception(self.stringify_event(event)) 797 798 # Event to stop the thread 799 if self.readpipe == fd: 800 self.logger.debug("Stop event received") 801 breakout = True 802 break 803 804 # A connection request was received 805 elif self.serversock and self.serversock.fileno() == fd: 806 self.logger.debug("Connection request received") 807 self.readsock, _ = self.serversock.accept() 808 self.readsock.setblocking(0) 809 poll.unregister(self.serversock.fileno()) 810 poll.register(self.readsock.fileno(), event_read_mask) 811 812 self.logger.debug("Setting connection established event") 813 self.connection_established.set() 814 815 # Actual data to be logged 816 elif self.readsock and self.readsock.fileno() == fd: 817 data = self.recv(1024, self.readsock) 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 839 840 # Since the socket is non-blocking make sure to honor EAGAIN 841 # and EWOULDBLOCK. 842 def recv(self, count, sock): 843 try: 844 data = sock.recv(count) 845 except socket.error as e: 846 if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK: 847 return b'' 848 else: 849 raise 850 851 if data is None: 852 raise Exception("No data on read ready socket") 853 elif not data: 854 # This actually means an orderly shutdown 855 # happened. But for this code it counts as an 856 # error since the connection shouldn't go away 857 # until qemu exits. 858 if not self.canexit: 859 raise Exception("Console connection closed unexpectedly") 860 return b'' 861 862 return data 863 864 def stringify_event(self, event): 865 val = '' 866 if select.POLLERR == event: 867 val = 'POLLER' 868 elif select.POLLHUP == event: 869 val = 'POLLHUP' 870 elif select.POLLNVAL == event: 871 val = 'POLLNVAL' 872 else: 873 val = "0x%x" % (event) 874 875 return val 876 877 def close_socket(self, sock): 878 sock.shutdown(socket.SHUT_RDWR) 879 sock.close() 880 881 def close_ignore_error(self, fd): 882 try: 883 os.close(fd) 884 except OSError: 885 pass 886