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