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