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