1# Copyright (C) 2013 Intel Corporation
2#
3# Released under the MIT license (see COPYING.MIT)
4
5# This module provides a class for starting qemu images using runqemu.
6# It's used by testimage.bbclass.
7
8import subprocess
9import os
10import sys
11import time
12import signal
13import re
14import socket
15import select
16import errno
17import string
18import threading
19import codecs
20import logging
21from oeqa.utils.dump import HostDumper
22
23# Get Unicode non printable control chars
24control_range = list(range(0,32))+list(range(127,160))
25control_chars = [chr(x) for x in control_range
26                if chr(x) not in string.printable]
27re_control_char = re.compile('[%s]' % re.escape("".join(control_chars)))
28
29class QemuRunner:
30
31    def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds, use_kvm, logger):
32
33        # Popen object for runqemu
34        self.runqemu = None
35        # pid of the qemu process that runqemu will start
36        self.qemupid = None
37        # target ip - from the command line or runqemu output
38        self.ip = None
39        # host ip - where qemu is running
40        self.server_ip = None
41        # target ip netmask
42        self.netmask = None
43
44        self.machine = machine
45        self.rootfs = rootfs
46        self.display = display
47        self.tmpdir = tmpdir
48        self.deploy_dir_image = deploy_dir_image
49        self.logfile = logfile
50        self.boottime = boottime
51        self.logged = False
52        self.thread = None
53        self.use_kvm = use_kvm
54        self.msg = ''
55
56        self.runqemutime = 120
57        self.qemu_pidfile = 'pidfile_'+str(os.getpid())
58        self.host_dumper = HostDumper(dump_host_cmds, dump_dir)
59
60        self.logger = logger
61
62    def create_socket(self):
63        try:
64            sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
65            sock.setblocking(0)
66            sock.bind(("127.0.0.1",0))
67            sock.listen(2)
68            port = sock.getsockname()[1]
69            self.logger.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port)
70            return (sock, port)
71
72        except socket.error:
73            sock.close()
74            raise
75
76    def log(self, msg):
77        if self.logfile:
78            # It is needed to sanitize the data received from qemu
79            # because is possible to have control characters
80            msg = msg.decode("utf-8", errors='ignore')
81            msg = re_control_char.sub('', msg)
82            self.msg += msg
83            with codecs.open(self.logfile, "a", encoding="utf-8") as f:
84                f.write("%s" % msg)
85
86    def getOutput(self, o):
87        import fcntl
88        fl = fcntl.fcntl(o, fcntl.F_GETFL)
89        fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK)
90        return os.read(o.fileno(), 1000000).decode("utf-8")
91
92
93    def handleSIGCHLD(self, signum, frame):
94        if self.runqemu and self.runqemu.poll():
95            if self.runqemu.returncode:
96                self.logger.debug('runqemu exited with code %d' % self.runqemu.returncode)
97                self.logger.debug("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout))
98                self.stop()
99                self._dump_host()
100                raise SystemExit
101
102    def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True):
103        env = os.environ.copy()
104        if self.display:
105            env["DISPLAY"] = self.display
106            # Set this flag so that Qemu doesn't do any grabs as SDL grabs
107            # interact badly with screensavers.
108            env["QEMU_DONT_GRAB"] = "1"
109        if not os.path.exists(self.rootfs):
110            self.logger.error("Invalid rootfs %s" % self.rootfs)
111            return False
112        if not os.path.exists(self.tmpdir):
113            self.logger.error("Invalid TMPDIR path %s" % self.tmpdir)
114            return False
115        else:
116            env["OE_TMPDIR"] = self.tmpdir
117        if not os.path.exists(self.deploy_dir_image):
118            self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
119            return False
120        else:
121            env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
122
123        if not launch_cmd:
124            launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams)
125            if self.use_kvm:
126                self.logger.debug('Using kvm for runqemu')
127                launch_cmd += ' kvm'
128            else:
129                self.logger.debug('Not using kvm for runqemu')
130            if not self.display:
131                launch_cmd += ' nographic'
132            launch_cmd += ' %s %s' % (self.machine, self.rootfs)
133
134        return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env)
135
136    def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None):
137        try:
138            self.threadsock, threadport = self.create_socket()
139            self.server_socket, self.serverport = self.create_socket()
140        except socket.error as msg:
141            self.logger.error("Failed to create listening socket: %s" % msg[1])
142            return False
143
144        bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1'
145        if extra_bootparams:
146            bootparams = bootparams + ' ' + extra_bootparams
147
148        # Ask QEMU to store the QEMU process PID in file, this way we don't have to parse running processes
149        # and analyze descendents in order to determine it.
150        if os.path.exists(self.qemu_pidfile):
151            os.remove(self.qemu_pidfile)
152        self.qemuparams = 'bootparams="{0}" qemuparams="-serial tcp:127.0.0.1:{1} -pidfile {2}"'.format(bootparams, threadport, self.qemu_pidfile)
153        if qemuparams:
154            self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"'
155
156        launch_cmd += ' tcpserial=%s %s' % (self.serverport, self.qemuparams)
157
158        self.origchldhandler = signal.getsignal(signal.SIGCHLD)
159        signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
160
161        self.logger.debug('launchcmd=%s'%(launch_cmd))
162
163        # FIXME: We pass in stdin=subprocess.PIPE here to work around stty
164        # blocking at the end of the runqemu script when using this within
165        # oe-selftest (this makes stty error out immediately). There ought
166        # to be a proper fix but this will suffice for now.
167        self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env)
168        output = self.runqemu.stdout
169
170        #
171        # We need the preexec_fn above so that all runqemu processes can easily be killed
172        # (by killing their process group). This presents a problem if this controlling
173        # process itself is killed however since those processes don't notice the death
174        # of the parent and merrily continue on.
175        #
176        # Rather than hack runqemu to deal with this, we add something here instead.
177        # Basically we fork off another process which holds an open pipe to the parent
178        # and also is setpgrp. If/when the pipe sees EOF from the parent dieing, it kills
179        # the process group. This is like pctrl's PDEATHSIG but for a process group
180        # rather than a single process.
181        #
182        r, w = os.pipe()
183        self.monitorpid = os.fork()
184        if self.monitorpid:
185            os.close(r)
186            self.monitorpipe = os.fdopen(w, "w")
187        else:
188            # child process
189            os.setpgrp()
190            os.close(w)
191            r = os.fdopen(r)
192            x = r.read()
193            os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
194            sys.exit(0)
195
196        self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
197        self.logger.debug("waiting at most %s seconds for qemu pid (%s)" %
198                          (self.runqemutime, time.strftime("%D %H:%M:%S")))
199        endtime = time.time() + self.runqemutime
200        while not self.is_alive() and time.time() < endtime:
201            if self.runqemu.poll():
202                if self.runqemu.returncode:
203                    # No point waiting any longer
204                    self.logger.debug('runqemu exited with code %d' % self.runqemu.returncode)
205                    self._dump_host()
206                    self.logger.debug("Output from runqemu:\n%s" % self.getOutput(output))
207                    self.stop()
208                    return False
209            time.sleep(0.5)
210
211        if not self.is_alive():
212            self.logger.error("Qemu pid didn't appear in %s seconds (%s)" %
213                              (self.runqemutime, time.strftime("%D %H:%M:%S")))
214            # Dump all processes to help us to figure out what is going on...
215            ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0]
216            processes = ps.decode("utf-8")
217            self.logger.debug("Running processes:\n%s" % processes)
218            self._dump_host()
219            op = self.getOutput(output)
220            self.stop()
221            if op:
222                self.logger.error("Output from runqemu:\n%s" % op)
223            else:
224                self.logger.error("No output from runqemu.\n")
225            return False
226
227        # We are alive: qemu is running
228        out = self.getOutput(output)
229        netconf = False # network configuration is not required by default
230        self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" %
231                          (time.time() - (endtime - self.runqemutime),
232                           self.qemupid, time.strftime("%D %H:%M:%S")))
233        if get_ip:
234            cmdline = ''
235            with open('/proc/%s/cmdline' % self.qemupid) as p:
236                cmdline = p.read()
237                # It is needed to sanitize the data received
238                # because is possible to have control characters
239                cmdline = re_control_char.sub(' ', cmdline)
240            try:
241                ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
242                self.ip = ips[0]
243                self.server_ip = ips[1]
244                self.logger.debug("qemu cmdline used:\n{}".format(cmdline))
245            except (IndexError, ValueError):
246                # Try to get network configuration from runqemu output
247                match = re.match(r'.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*',
248                                 out, re.MULTILINE|re.DOTALL)
249                if match:
250                    self.ip, self.server_ip, self.netmask = match.groups()
251                    # network configuration is required as we couldn't get it
252                    # from the runqemu command line, so qemu doesn't run kernel
253                    # and guest networking is not configured
254                    netconf = True
255                else:
256                    self.logger.error("Couldn't get ip from qemu command line and runqemu output! "
257                                 "Here is the qemu command line used:\n%s\n"
258                                 "and output from runqemu:\n%s" % (cmdline, out))
259                    self._dump_host()
260                    self.stop()
261                    return False
262
263        self.logger.debug("Target IP: %s" % self.ip)
264        self.logger.debug("Server IP: %s" % self.server_ip)
265
266        self.thread = LoggingThread(self.log, self.threadsock, self.logger)
267        self.thread.start()
268        if not self.thread.connection_established.wait(self.boottime):
269            self.logger.error("Didn't receive a console connection from qemu. "
270                         "Here is the qemu command line used:\n%s\nand "
271                         "output from runqemu:\n%s" % (cmdline, out))
272            self.stop_thread()
273            return False
274
275        self.logger.debug("Output from runqemu:\n%s", out)
276        self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
277                          (self.boottime, time.strftime("%D %H:%M:%S")))
278        endtime = time.time() + self.boottime
279        socklist = [self.server_socket]
280        reachedlogin = False
281        stopread = False
282        qemusock = None
283        bootlog = b''
284        data = b''
285        while time.time() < endtime and not stopread:
286            try:
287                sread, swrite, serror = select.select(socklist, [], [], 5)
288            except InterruptedError:
289                continue
290            for sock in sread:
291                if sock is self.server_socket:
292                    qemusock, addr = self.server_socket.accept()
293                    qemusock.setblocking(0)
294                    socklist.append(qemusock)
295                    socklist.remove(self.server_socket)
296                    self.logger.debug("Connection from %s:%s" % addr)
297                else:
298                    data = data + sock.recv(1024)
299                    if data:
300                        bootlog += data
301                        data = b''
302                        if b' login:' in bootlog:
303                            self.server_socket = qemusock
304                            stopread = True
305                            reachedlogin = True
306                            self.logger.debug("Reached login banner in %s seconds (%s)" %
307                                              (time.time() - (endtime - self.boottime),
308                                              time.strftime("%D %H:%M:%S")))
309                    else:
310                        # no need to check if reachedlogin unless we support multiple connections
311                        self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" %
312                                          time.strftime("%D %H:%M:%S"))
313                        socklist.remove(sock)
314                        sock.close()
315                        stopread = True
316
317
318        if not reachedlogin:
319            if time.time() >= endtime:
320                self.logger.debug("Target didn't reach login banner in %d seconds (%s)" %
321                                  (self.boottime, time.strftime("%D %H:%M:%S")))
322            tail = lambda l: "\n".join(l.splitlines()[-25:])
323            # in case bootlog is empty, use tail qemu log store at self.msg
324            lines = tail(bootlog if bootlog else self.msg)
325            self.logger.debug("Last 25 lines of text:\n%s" % lines)
326            self.logger.debug("Check full boot log: %s" % self.logfile)
327            self._dump_host()
328            self.stop()
329            return False
330
331        # If we are not able to login the tests can continue
332        try:
333            (status, output) = self.run_serial("root\n", raw=True)
334            if re.search(r"root@[a-zA-Z0-9\-]+:~#", output):
335                self.logged = True
336                self.logger.debug("Logged as root in serial console")
337                if netconf:
338                    # configure guest networking
339                    cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
340                    output = self.run_serial(cmd, raw=True)[1]
341                    if re.search(r"root@[a-zA-Z0-9\-]+:~#", output):
342                        self.logger.debug("configured ip address %s", self.ip)
343                    else:
344                        self.logger.debug("Couldn't configure guest networking")
345            else:
346                self.logger.debug("Couldn't login into serial console"
347                            " as root using blank password")
348        except:
349            self.logger.debug("Serial console failed while trying to login")
350        return True
351
352    def stop(self):
353        if hasattr(self, "origchldhandler"):
354            signal.signal(signal.SIGCHLD, self.origchldhandler)
355        self.stop_thread()
356        self.stop_qemu_system()
357        if self.runqemu:
358            if hasattr(self, "monitorpid"):
359                os.kill(self.monitorpid, signal.SIGKILL)
360                self.logger.debug("Sending SIGTERM to runqemu")
361                try:
362                    os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
363                except OSError as e:
364                    if e.errno != errno.ESRCH:
365                        raise
366            endtime = time.time() + self.runqemutime
367            while self.runqemu.poll() is None and time.time() < endtime:
368                time.sleep(1)
369            if self.runqemu.poll() is None:
370                self.logger.debug("Sending SIGKILL to runqemu")
371                os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
372            self.runqemu.stdin.close()
373            self.runqemu.stdout.close()
374            self.runqemu = None
375
376        if hasattr(self, 'server_socket') and self.server_socket:
377            self.server_socket.close()
378            self.server_socket = None
379        if hasattr(self, 'threadsock') and self.threadsock:
380            self.threadsock.close()
381            self.threadsock = None
382        self.qemupid = None
383        self.ip = None
384        if os.path.exists(self.qemu_pidfile):
385            os.remove(self.qemu_pidfile)
386        if self.monitorpipe:
387            self.monitorpipe.close()
388
389    def stop_qemu_system(self):
390        if self.qemupid:
391            try:
392                # qemu-system behaves well and a SIGTERM is enough
393                os.kill(self.qemupid, signal.SIGTERM)
394            except ProcessLookupError as e:
395                self.logger.warning('qemu-system ended unexpectedly')
396
397    def stop_thread(self):
398        if self.thread and self.thread.is_alive():
399            self.thread.stop()
400            self.thread.join()
401
402    def restart(self, qemuparams = None):
403        self.logger.debug("Restarting qemu process")
404        if self.runqemu.poll() is None:
405            self.stop()
406        if self.start(qemuparams):
407            return True
408        return False
409
410    def is_alive(self):
411        if not self.runqemu or self.runqemu.poll() is not None:
412            return False
413        if os.path.isfile(self.qemu_pidfile):
414            f = open(self.qemu_pidfile, 'r')
415            qemu_pid = f.read()
416            f.close()
417            qemupid = int(qemu_pid)
418            if os.path.exists("/proc/" + str(qemupid)):
419                self.qemupid = qemupid
420                return True
421        return False
422
423    def run_serial(self, command, raw=False, timeout=5):
424        # We assume target system have echo to get command status
425        if not raw:
426            command = "%s; echo $?\n" % command
427
428        data = ''
429        status = 0
430        self.server_socket.sendall(command.encode('utf-8'))
431        start = time.time()
432        end = start + timeout
433        while True:
434            now = time.time()
435            if now >= end:
436                data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
437                break
438            try:
439                sread, _, _ = select.select([self.server_socket],[],[], end - now)
440            except InterruptedError:
441                continue
442            if sread:
443                answer = self.server_socket.recv(1024)
444                if answer:
445                    data += answer.decode('utf-8')
446                    # Search the prompt to stop
447                    if re.search(r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#", data):
448                        break
449                else:
450                    raise Exception("No data on serial console socket")
451
452        if data:
453            if raw:
454                status = 1
455            else:
456                # Remove first line (command line) and last line (prompt)
457                data = data[data.find('$?\r\n')+4:data.rfind('\r\n')]
458                index = data.rfind('\r\n')
459                if index == -1:
460                    status_cmd = data
461                    data = ""
462                else:
463                    status_cmd = data[index+2:]
464                    data = data[:index]
465                if (status_cmd == "0"):
466                    status = 1
467        return (status, str(data))
468
469
470    def _dump_host(self):
471        self.host_dumper.create_dir("qemu")
472        self.logger.warning("Qemu ended unexpectedly, dump data from host"
473                " is in %s" % self.host_dumper.dump_dir)
474        self.host_dumper.dump_host()
475
476# This class is for reading data from a socket and passing it to logfunc
477# to be processed. It's completely event driven and has a straightforward
478# event loop. The mechanism for stopping the thread is a simple pipe which
479# will wake up the poll and allow for tearing everything down.
480class LoggingThread(threading.Thread):
481    def __init__(self, logfunc, sock, logger):
482        self.connection_established = threading.Event()
483        self.serversock = sock
484        self.logfunc = logfunc
485        self.logger = logger
486        self.readsock = None
487        self.running = False
488
489        self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
490        self.readevents = select.POLLIN | select.POLLPRI
491
492        threading.Thread.__init__(self, target=self.threadtarget)
493
494    def threadtarget(self):
495        try:
496            self.eventloop()
497        finally:
498            self.teardown()
499
500    def run(self):
501        self.logger.debug("Starting logging thread")
502        self.readpipe, self.writepipe = os.pipe()
503        threading.Thread.run(self)
504
505    def stop(self):
506        self.logger.debug("Stopping logging thread")
507        if self.running:
508            os.write(self.writepipe, bytes("stop", "utf-8"))
509
510    def teardown(self):
511        self.logger.debug("Tearing down logging thread")
512        self.close_socket(self.serversock)
513
514        if self.readsock is not None:
515            self.close_socket(self.readsock)
516
517        self.close_ignore_error(self.readpipe)
518        self.close_ignore_error(self.writepipe)
519        self.running = False
520
521    def eventloop(self):
522        poll = select.poll()
523        event_read_mask = self.errorevents | self.readevents
524        poll.register(self.serversock.fileno())
525        poll.register(self.readpipe, event_read_mask)
526
527        breakout = False
528        self.running = True
529        self.logger.debug("Starting thread event loop")
530        while not breakout:
531            events = poll.poll()
532            for event in events:
533                # An error occurred, bail out
534                if event[1] & self.errorevents:
535                    raise Exception(self.stringify_event(event[1]))
536
537                # Event to stop the thread
538                if self.readpipe == event[0]:
539                    self.logger.debug("Stop event received")
540                    breakout = True
541                    break
542
543                # A connection request was received
544                elif self.serversock.fileno() == event[0]:
545                    self.logger.debug("Connection request received")
546                    self.readsock, _ = self.serversock.accept()
547                    self.readsock.setblocking(0)
548                    poll.unregister(self.serversock.fileno())
549                    poll.register(self.readsock.fileno(), event_read_mask)
550
551                    self.logger.debug("Setting connection established event")
552                    self.connection_established.set()
553
554                # Actual data to be logged
555                elif self.readsock.fileno() == event[0]:
556                    data = self.recv(1024)
557                    self.logfunc(data)
558
559    # Since the socket is non-blocking make sure to honor EAGAIN
560    # and EWOULDBLOCK.
561    def recv(self, count):
562        try:
563            data = self.readsock.recv(count)
564        except socket.error as e:
565            if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
566                return ''
567            else:
568                raise
569
570        if data is None:
571            raise Exception("No data on read ready socket")
572        elif not data:
573            # This actually means an orderly shutdown
574            # happened. But for this code it counts as an
575            # error since the connection shouldn't go away
576            # until qemu exits.
577            raise Exception("Console connection closed unexpectedly")
578
579        return data
580
581    def stringify_event(self, event):
582        val = ''
583        if select.POLLERR == event:
584            val = 'POLLER'
585        elif select.POLLHUP == event:
586            val = 'POLLHUP'
587        elif select.POLLNVAL == event:
588            val = 'POLLNVAL'
589        return val
590
591    def close_socket(self, sock):
592        sock.shutdown(socket.SHUT_RDWR)
593        sock.close()
594
595    def close_ignore_error(self, fd):
596        try:
597            os.close(fd)
598        except OSError:
599            pass
600