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            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.stop()
207                    self.logger.debug("Output from runqemu:\n%s" % self.getOutput(output))
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            self.stop()
220            op = self.getOutput(output)
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("((?:[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('.*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, 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("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("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        self.stop_thread()
354        self.stop_qemu_system()
355        if hasattr(self, "origchldhandler"):
356            signal.signal(signal.SIGCHLD, self.origchldhandler)
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 = None
373        if hasattr(self, 'server_socket') and self.server_socket:
374            self.server_socket.close()
375            self.server_socket = None
376        self.qemupid = None
377        self.ip = None
378        if os.path.exists(self.qemu_pidfile):
379            os.remove(self.qemu_pidfile)
380
381    def stop_qemu_system(self):
382        if self.qemupid:
383            try:
384                # qemu-system behaves well and a SIGTERM is enough
385                os.kill(self.qemupid, signal.SIGTERM)
386            except ProcessLookupError as e:
387                self.logger.warn('qemu-system ended unexpectedly')
388
389    def stop_thread(self):
390        if self.thread and self.thread.is_alive():
391            self.thread.stop()
392            self.thread.join()
393
394    def restart(self, qemuparams = None):
395        self.logger.debug("Restarting qemu process")
396        if self.runqemu.poll() is None:
397            self.stop()
398        if self.start(qemuparams):
399            return True
400        return False
401
402    def is_alive(self):
403        if not self.runqemu:
404            return False
405        if os.path.isfile(self.qemu_pidfile):
406            f = open(self.qemu_pidfile, 'r')
407            qemu_pid = f.read()
408            f.close()
409            qemupid = int(qemu_pid)
410            if os.path.exists("/proc/" + str(qemupid)):
411                self.qemupid = qemupid
412                return True
413        return False
414
415    def run_serial(self, command, raw=False, timeout=5):
416        # We assume target system have echo to get command status
417        if not raw:
418            command = "%s; echo $?\n" % command
419
420        data = ''
421        status = 0
422        self.server_socket.sendall(command.encode('utf-8'))
423        start = time.time()
424        end = start + timeout
425        while True:
426            now = time.time()
427            if now >= end:
428                data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout
429                break
430            try:
431                sread, _, _ = select.select([self.server_socket],[],[], end - now)
432            except InterruptedError:
433                continue
434            if sread:
435                answer = self.server_socket.recv(1024)
436                if answer:
437                    data += answer.decode('utf-8')
438                    # Search the prompt to stop
439                    if re.search("[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#", data):
440                        break
441                else:
442                    raise Exception("No data on serial console socket")
443
444        if data:
445            if raw:
446                status = 1
447            else:
448                # Remove first line (command line) and last line (prompt)
449                data = data[data.find('$?\r\n')+4:data.rfind('\r\n')]
450                index = data.rfind('\r\n')
451                if index == -1:
452                    status_cmd = data
453                    data = ""
454                else:
455                    status_cmd = data[index+2:]
456                    data = data[:index]
457                if (status_cmd == "0"):
458                    status = 1
459        return (status, str(data))
460
461
462    def _dump_host(self):
463        self.host_dumper.create_dir("qemu")
464        self.logger.warn("Qemu ended unexpectedly, dump data from host"
465                " is in %s" % self.host_dumper.dump_dir)
466        self.host_dumper.dump_host()
467
468# This class is for reading data from a socket and passing it to logfunc
469# to be processed. It's completely event driven and has a straightforward
470# event loop. The mechanism for stopping the thread is a simple pipe which
471# will wake up the poll and allow for tearing everything down.
472class LoggingThread(threading.Thread):
473    def __init__(self, logfunc, sock, logger):
474        self.connection_established = threading.Event()
475        self.serversock = sock
476        self.logfunc = logfunc
477        self.logger = logger
478        self.readsock = None
479        self.running = False
480
481        self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL
482        self.readevents = select.POLLIN | select.POLLPRI
483
484        threading.Thread.__init__(self, target=self.threadtarget)
485
486    def threadtarget(self):
487        try:
488            self.eventloop()
489        finally:
490            self.teardown()
491
492    def run(self):
493        self.logger.debug("Starting logging thread")
494        self.readpipe, self.writepipe = os.pipe()
495        threading.Thread.run(self)
496
497    def stop(self):
498        self.logger.debug("Stopping logging thread")
499        if self.running:
500            os.write(self.writepipe, bytes("stop", "utf-8"))
501
502    def teardown(self):
503        self.logger.debug("Tearing down logging thread")
504        self.close_socket(self.serversock)
505
506        if self.readsock is not None:
507            self.close_socket(self.readsock)
508
509        self.close_ignore_error(self.readpipe)
510        self.close_ignore_error(self.writepipe)
511        self.running = False
512
513    def eventloop(self):
514        poll = select.poll()
515        event_read_mask = self.errorevents | self.readevents
516        poll.register(self.serversock.fileno())
517        poll.register(self.readpipe, event_read_mask)
518
519        breakout = False
520        self.running = True
521        self.logger.debug("Starting thread event loop")
522        while not breakout:
523            events = poll.poll()
524            for event in events:
525                # An error occurred, bail out
526                if event[1] & self.errorevents:
527                    raise Exception(self.stringify_event(event[1]))
528
529                # Event to stop the thread
530                if self.readpipe == event[0]:
531                    self.logger.debug("Stop event received")
532                    breakout = True
533                    break
534
535                # A connection request was received
536                elif self.serversock.fileno() == event[0]:
537                    self.logger.debug("Connection request received")
538                    self.readsock, _ = self.serversock.accept()
539                    self.readsock.setblocking(0)
540                    poll.unregister(self.serversock.fileno())
541                    poll.register(self.readsock.fileno(), event_read_mask)
542
543                    self.logger.debug("Setting connection established event")
544                    self.connection_established.set()
545
546                # Actual data to be logged
547                elif self.readsock.fileno() == event[0]:
548                    data = self.recv(1024)
549                    self.logfunc(data)
550
551    # Since the socket is non-blocking make sure to honor EAGAIN
552    # and EWOULDBLOCK.
553    def recv(self, count):
554        try:
555            data = self.readsock.recv(count)
556        except socket.error as e:
557            if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK:
558                return ''
559            else:
560                raise
561
562        if data is None:
563            raise Exception("No data on read ready socket")
564        elif not data:
565            # This actually means an orderly shutdown
566            # happened. But for this code it counts as an
567            # error since the connection shouldn't go away
568            # until qemu exits.
569            raise Exception("Console connection closed unexpectedly")
570
571        return data
572
573    def stringify_event(self, event):
574        val = ''
575        if select.POLLERR == event:
576            val = 'POLLER'
577        elif select.POLLHUP == event:
578            val = 'POLLHUP'
579        elif select.POLLNVAL == event:
580            val = 'POLLNVAL'
581        return val
582
583    def close_socket(self, sock):
584        sock.shutdown(socket.SHUT_RDWR)
585        sock.close()
586
587    def close_ignore_error(self, fd):
588        try:
589            os.close(fd)
590        except OSError:
591            pass
592