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