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                with open(self.qemu_pidfile, 'r') as f:
634                    qemu_pid = f.read().strip()
635                # file created but not yet written contents
636                if not qemu_pid:
637                    time.sleep(0.5)
638                    continue
639                else:
640                    if os.path.exists("/proc/" + qemu_pid):
641                        self.qemupid = int(qemu_pid)
642                        return True
643        return False
644
645    def run_monitor(self, command, args=None, timeout=60):
646        if hasattr(self, 'qmp') and self.qmp:
647            self.qmp.settimeout(timeout)
648            if args is not None:
649                return self.qmp.cmd(command, args)
650            else:
651                return self.qmp.cmd(command)
652
653    def run_serial(self, command, raw=False, timeout=60):
654        # Returns (status, output) where status is 1 on success and 0 on error
655
656        # We assume target system have echo to get command status
657        if not raw:
658            command = "%s; echo $?\n" % command
659
660        data = ''
661        status = 0
662        with self.thread.serial_lock:
663            self.server_socket.sendall(command.encode('utf-8'))
664            start = time.time()
665            end = start + timeout
666            while True:
667                now = time.time()
668                if now >= end:
669                    data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
670                    break
671                try:
672                    sread, _, _ = select.select([self.server_socket],[],[], end - now)
673                except InterruptedError:
674                    continue
675                if sread:
676                    # try to avoid reading single character at a time
677                    time.sleep(0.1)
678                    answer = self.server_socket.recv(1024)
679                    if answer:
680                        data += answer.decode('utf-8')
681                        # Search the prompt to stop
682                        if re.search(self.boot_patterns['search_cmd_finished'], data):
683                            break
684                    else:
685                        if self.canexit:
686                            return (1, "")
687                        raise Exception("No data on serial console socket, connection closed?")
688
689        if data:
690            if raw:
691                status = 1
692            else:
693                # Remove first line (command line) and last line (prompt)
694                data = data[data.find('$?\r\n')+4:data.rfind('\r\n')]
695                index = data.rfind('\r\n')
696                if index == -1:
697                    status_cmd = data
698                    data = ""
699                else:
700                    status_cmd = data[index+2:]
701                    data = data[:index]
702                if (status_cmd == "0"):
703                    status = 1
704        return (status, str(data))
705
706@contextmanager
707def nonblocking_lock(lock):
708    locked = lock.acquire(False)
709    try:
710        yield locked
711    finally:
712        if locked:
713            lock.release()
714
715# This class is for reading data from a socket and passing it to logfunc
716# to be processed. It's completely event driven and has a straightforward
717# event loop. The mechanism for stopping the thread is a simple pipe which
718# will wake up the poll and allow for tearing everything down.
719class LoggingThread(threading.Thread):
720    def __init__(self, logfunc, sock, logger, qemuoutput):
721        self.connection_established = threading.Event()
722        self.serial_lock = threading.Lock()
723
724        self.serversock = sock
725        self.serialsock = None
726        self.qemuoutput = qemuoutput
727        self.logfunc = logfunc
728        self.logger = logger
729        self.readsock = None
730        self.running = False
731        self.canexit = False
732
733        self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
734        self.readevents = select.POLLIN | select.POLLPRI
735
736        threading.Thread.__init__(self, target=self.threadtarget)
737
738    def set_serialsock(self, serialsock):
739        self.serialsock = serialsock
740
741    def threadtarget(self):
742        try:
743            self.eventloop()
744        except Exception as e:
745            self.logger.warning("Exception %s in logging thread" % traceback.format_exception(e))
746        finally:
747            self.teardown()
748
749    def run(self):
750        self.logger.debug("Starting logging thread")
751        self.readpipe, self.writepipe = os.pipe()
752        threading.Thread.run(self)
753
754    def stop(self):
755        self.logger.debug("Stopping logging thread")
756        if self.running:
757            os.write(self.writepipe, bytes("stop", "utf-8"))
758
759    def teardown(self):
760        self.logger.debug("Tearing down logging thread")
761        if self.serversock:
762            self.close_socket(self.serversock)
763
764        if self.readsock is not None:
765            self.close_socket(self.readsock)
766
767        self.close_ignore_error(self.readpipe)
768        self.close_ignore_error(self.writepipe)
769        self.running = False
770
771    def allowexit(self):
772        self.canexit = True
773
774    def eventloop(self):
775        poll = select.poll()
776        event_read_mask = self.errorevents | self.readevents
777        if self.serversock:
778            poll.register(self.serversock.fileno())
779        serial_registered = False
780        poll.register(self.qemuoutput.fileno())
781        poll.register(self.readpipe, event_read_mask)
782
783        breakout = False
784        self.running = True
785        self.logger.debug("Starting thread event loop")
786        while not breakout:
787            events = poll.poll(2)
788            for fd, event in events:
789
790                # An error occurred, bail out
791                if event & self.errorevents:
792                    raise Exception(self.stringify_event(event))
793
794                # Event to stop the thread
795                if self.readpipe == fd:
796                    self.logger.debug("Stop event received")
797                    breakout = True
798                    break
799
800                # A connection request was received
801                elif self.serversock and self.serversock.fileno() == fd:
802                    self.logger.debug("Connection request received")
803                    self.readsock, _ = self.serversock.accept()
804                    self.readsock.setblocking(0)
805                    poll.unregister(self.serversock.fileno())
806                    poll.register(self.readsock.fileno(), event_read_mask)
807
808                    self.logger.debug("Setting connection established event")
809                    self.connection_established.set()
810
811                # Actual data to be logged
812                elif self.readsock and self.readsock.fileno() == fd:
813                    data = self.recv(1024, self.readsock)
814                    self.logfunc(data)
815                elif self.qemuoutput.fileno() == fd:
816                    data = self.qemuoutput.read()
817                    self.logger.debug("Data received on qemu stdout %s" % data)
818                    self.logfunc(data, ".stdout")
819                elif self.serialsock and self.serialsock.fileno() == fd:
820                    if self.serial_lock.acquire(blocking=False):
821                        data = self.recv(1024, self.serialsock)
822                        self.logger.debug("Data received serial thread %s" % data.decode('utf-8', 'replace'))
823                        self.logfunc(data, ".2")
824                        self.serial_lock.release()
825                    else:
826                        serial_registered = False
827                        poll.unregister(self.serialsock.fileno())
828
829            if not serial_registered and self.serialsock:
830                with nonblocking_lock(self.serial_lock) as l:
831                    if l:
832                        serial_registered = True
833                        poll.register(self.serialsock.fileno(), event_read_mask)
834
835
836    # Since the socket is non-blocking make sure to honor EAGAIN
837    # and EWOULDBLOCK.
838    def recv(self, count, sock):
839        try:
840            data = sock.recv(count)
841        except socket.error as e:
842            if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
843                return b''
844            else:
845                raise
846
847        if data is None:
848            raise Exception("No data on read ready socket")
849        elif not data:
850            # This actually means an orderly shutdown
851            # happened. But for this code it counts as an
852            # error since the connection shouldn't go away
853            # until qemu exits.
854            if not self.canexit:
855                raise Exception("Console connection closed unexpectedly")
856            return b''
857
858        return data
859
860    def stringify_event(self, event):
861        val = ''
862        if select.POLLERR == event:
863            val = 'POLLER'
864        elif select.POLLHUP == event:
865            val = 'POLLHUP'
866        elif select.POLLNVAL == event:
867            val = 'POLLNVAL'
868        else:
869            val = "0x%x" % (event)
870
871        return val
872
873    def close_socket(self, sock):
874        sock.shutdown(socket.SHUT_RDWR)
875        sock.close()
876
877    def close_ignore_error(self, fd):
878        try:
879            os.close(fd)
880        except OSError:
881            pass
882