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