diff options
author | Richard Purdie <richard.purdie@linuxfoundation.org> | 2023-12-18 12:18:45 +0000 |
---|---|---|
committer | Richard Purdie <richard.purdie@linuxfoundation.org> | 2023-12-20 07:47:00 +0000 |
commit | d921da782aed3fdf0b2c888751cc6e67618adc6a (patch) | |
tree | 393fd3fb956cb815c7bc16c073a7731b8ae0f963 /meta/lib/oeqa/utils/qemurunner.py | |
parent | 038d364992daa833bbf3eef14443a9e99211564e (diff) | |
download | poky-d921da782aed3fdf0b2c888751cc6e67618adc6a.tar.gz |
qemurunner: Improve stdout logging handling
We need to ensure we read from and log the output from qemu stdout
as otherwise the buffers can fill and block, leading qemu to hang.
Use our existing logging thread to do this.
Reviewed-by: Alex Bennée <alex.bennee@linaro.org>
(From OE-Core rev: a9c46ee014ef1e6436b39fdd4fd15d15388ea795)
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Diffstat (limited to 'meta/lib/oeqa/utils/qemurunner.py')
-rw-r--r-- | meta/lib/oeqa/utils/qemurunner.py | 54 |
1 files changed, 32 insertions, 22 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index ee36707800..cdd0db5877 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py | |||
@@ -29,6 +29,15 @@ control_chars = [chr(x) for x in control_range | |||
29 | if chr(x) not in string.printable] | 29 | if chr(x) not in string.printable] |
30 | re_control_char = re.compile('[%s]' % re.escape("".join(control_chars))) | 30 | re_control_char = re.compile('[%s]' % re.escape("".join(control_chars))) |
31 | 31 | ||
32 | def getOutput(o): | ||
33 | import fcntl | ||
34 | fl = fcntl.fcntl(o, fcntl.F_GETFL) | ||
35 | fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK) | ||
36 | try: | ||
37 | return os.read(o.fileno(), 1000000).decode("utf-8") | ||
38 | except BlockingIOError: | ||
39 | return "" | ||
40 | |||
32 | class QemuRunner: | 41 | class QemuRunner: |
33 | 42 | ||
34 | def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, use_kvm, logger, use_slirp=False, | 43 | def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, use_kvm, logger, use_slirp=False, |
@@ -55,6 +64,7 @@ class QemuRunner: | |||
55 | self.boottime = boottime | 64 | self.boottime = boottime |
56 | self.logged = False | 65 | self.logged = False |
57 | self.thread = None | 66 | self.thread = None |
67 | self.threadsock = None | ||
58 | self.use_kvm = use_kvm | 68 | self.use_kvm = use_kvm |
59 | self.use_ovmf = use_ovmf | 69 | self.use_ovmf = use_ovmf |
60 | self.use_slirp = use_slirp | 70 | self.use_slirp = use_slirp |
@@ -119,21 +129,11 @@ class QemuRunner: | |||
119 | f.write(msg) | 129 | f.write(msg) |
120 | self.msg += self.decode_qemulog(msg) | 130 | self.msg += self.decode_qemulog(msg) |
121 | 131 | ||
122 | def getOutput(self, o): | ||
123 | import fcntl | ||
124 | fl = fcntl.fcntl(o, fcntl.F_GETFL) | ||
125 | fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK) | ||
126 | try: | ||
127 | return os.read(o.fileno(), 1000000).decode("utf-8") | ||
128 | except BlockingIOError: | ||
129 | return "" | ||
130 | |||
131 | |||
132 | def handleSIGCHLD(self, signum, frame): | 132 | def handleSIGCHLD(self, signum, frame): |
133 | if self.runqemu and self.runqemu.poll(): | 133 | if self.runqemu and self.runqemu.poll(): |
134 | if self.runqemu.returncode: | 134 | if self.runqemu.returncode: |
135 | self.logger.error('runqemu exited with code %d' % self.runqemu.returncode) | 135 | self.logger.error('runqemu exited with code %d' % self.runqemu.returncode) |
136 | self.logger.error('Output from runqemu:\n%s' % self.getOutput(self.runqemu.stdout)) | 136 | self.logger.error('Output from runqemu:\n%s' % getOutput(self.runqemu.stdout)) |
137 | self.stop() | 137 | self.stop() |
138 | 138 | ||
139 | def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True): | 139 | def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True): |
@@ -282,7 +282,7 @@ class QemuRunner: | |||
282 | if self.runqemu.returncode: | 282 | if self.runqemu.returncode: |
283 | # No point waiting any longer | 283 | # No point waiting any longer |
284 | self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) | 284 | self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) |
285 | self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output)) | 285 | self.logger.warning("Output from runqemu:\n%s" % getOutput(output)) |
286 | self.stop() | 286 | self.stop() |
287 | return False | 287 | return False |
288 | time.sleep(0.5) | 288 | time.sleep(0.5) |
@@ -309,7 +309,7 @@ class QemuRunner: | |||
309 | ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0] | 309 | ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0] |
310 | processes = ps.decode("utf-8") | 310 | processes = ps.decode("utf-8") |
311 | self.logger.debug("Running processes:\n%s" % processes) | 311 | self.logger.debug("Running processes:\n%s" % processes) |
312 | op = self.getOutput(output) | 312 | op = getOutput(output) |
313 | self.stop() | 313 | self.stop() |
314 | if op: | 314 | if op: |
315 | self.logger.error("Output from runqemu:\n%s" % op) | 315 | self.logger.error("Output from runqemu:\n%s" % op) |
@@ -387,7 +387,7 @@ class QemuRunner: | |||
387 | time.time() - connect_time)) | 387 | time.time() - connect_time)) |
388 | 388 | ||
389 | # We are alive: qemu is running | 389 | # We are alive: qemu is running |
390 | out = self.getOutput(output) | 390 | out = getOutput(output) |
391 | netconf = False # network configuration is not required by default | 391 | netconf = False # network configuration is not required by default |
392 | self.logger.debug("qemu started in %.2f seconds - qemu procces pid is %s (%s)" % | 392 | self.logger.debug("qemu started in %.2f seconds - qemu procces pid is %s (%s)" % |
393 | (time.time() - (endtime - self.runqemutime), | 393 | (time.time() - (endtime - self.runqemutime), |
@@ -430,9 +430,10 @@ class QemuRunner: | |||
430 | self.logger.debug("Target IP: %s" % self.ip) | 430 | self.logger.debug("Target IP: %s" % self.ip) |
431 | self.logger.debug("Server IP: %s" % self.server_ip) | 431 | self.logger.debug("Server IP: %s" % self.server_ip) |
432 | 432 | ||
433 | self.thread = LoggingThread(self.log, self.threadsock, self.logger, self.runqemu.stdout) | ||
434 | self.thread.start() | ||
435 | |||
433 | if self.serial_ports >= 2: | 436 | if self.serial_ports >= 2: |
434 | self.thread = LoggingThread(self.log, self.threadsock, self.logger) | ||
435 | self.thread.start() | ||
436 | if not self.thread.connection_established.wait(self.boottime): | 437 | if not self.thread.connection_established.wait(self.boottime): |
437 | self.logger.error("Didn't receive a console connection from qemu. " | 438 | self.logger.error("Didn't receive a console connection from qemu. " |
438 | "Here is the qemu command line used:\n%s\nand " | 439 | "Here is the qemu command line used:\n%s\nand " |
@@ -444,7 +445,7 @@ class QemuRunner: | |||
444 | self.logger.debug("Waiting at most %d seconds for login banner (%s)" % | 445 | self.logger.debug("Waiting at most %d seconds for login banner (%s)" % |
445 | (self.boottime, time.strftime("%D %H:%M:%S"))) | 446 | (self.boottime, time.strftime("%D %H:%M:%S"))) |
446 | endtime = time.time() + self.boottime | 447 | endtime = time.time() + self.boottime |
447 | filelist = [self.server_socket, self.runqemu.stdout] | 448 | filelist = [self.server_socket] |
448 | reachedlogin = False | 449 | reachedlogin = False |
449 | stopread = False | 450 | stopread = False |
450 | qemusock = None | 451 | qemusock = None |
@@ -564,7 +565,7 @@ class QemuRunner: | |||
564 | self.logger.debug("Sending SIGKILL to runqemu") | 565 | self.logger.debug("Sending SIGKILL to runqemu") |
565 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) | 566 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) |
566 | if not self.runqemu.stdout.closed: | 567 | if not self.runqemu.stdout.closed: |
567 | self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) | 568 | self.logger.info("Output from runqemu:\n%s" % getOutput(self.runqemu.stdout)) |
568 | self.runqemu.stdin.close() | 569 | self.runqemu.stdin.close() |
569 | self.runqemu.stdout.close() | 570 | self.runqemu.stdout.close() |
570 | self.runqemu_exited = True | 571 | self.runqemu_exited = True |
@@ -700,9 +701,11 @@ class QemuRunner: | |||
700 | # event loop. The mechanism for stopping the thread is a simple pipe which | 701 | # event loop. The mechanism for stopping the thread is a simple pipe which |
701 | # will wake up the poll and allow for tearing everything down. | 702 | # will wake up the poll and allow for tearing everything down. |
702 | class LoggingThread(threading.Thread): | 703 | class LoggingThread(threading.Thread): |
703 | def __init__(self, logfunc, sock, logger): | 704 | def __init__(self, logfunc, sock, logger, qemuoutput): |
704 | self.connection_established = threading.Event() | 705 | self.connection_established = threading.Event() |
706 | |||
705 | self.serversock = sock | 707 | self.serversock = sock |
708 | self.qemuoutput = qemuoutput | ||
706 | self.logfunc = logfunc | 709 | self.logfunc = logfunc |
707 | self.logger = logger | 710 | self.logger = logger |
708 | self.readsock = None | 711 | self.readsock = None |
@@ -732,7 +735,8 @@ class LoggingThread(threading.Thread): | |||
732 | 735 | ||
733 | def teardown(self): | 736 | def teardown(self): |
734 | self.logger.debug("Tearing down logging thread") | 737 | self.logger.debug("Tearing down logging thread") |
735 | self.close_socket(self.serversock) | 738 | if self.serversock: |
739 | self.close_socket(self.serversock) | ||
736 | 740 | ||
737 | if self.readsock is not None: | 741 | if self.readsock is not None: |
738 | self.close_socket(self.readsock) | 742 | self.close_socket(self.readsock) |
@@ -747,7 +751,9 @@ class LoggingThread(threading.Thread): | |||
747 | def eventloop(self): | 751 | def eventloop(self): |
748 | poll = select.poll() | 752 | poll = select.poll() |
749 | event_read_mask = self.errorevents | self.readevents | 753 | event_read_mask = self.errorevents | self.readevents |
750 | poll.register(self.serversock.fileno()) | 754 | if self.serversock: |
755 | poll.register(self.serversock.fileno()) | ||
756 | poll.register(self.qemuoutput.fileno()) | ||
751 | poll.register(self.readpipe, event_read_mask) | 757 | poll.register(self.readpipe, event_read_mask) |
752 | 758 | ||
753 | breakout = False | 759 | breakout = False |
@@ -767,7 +773,7 @@ class LoggingThread(threading.Thread): | |||
767 | break | 773 | break |
768 | 774 | ||
769 | # A connection request was received | 775 | # A connection request was received |
770 | elif self.serversock.fileno() == event[0]: | 776 | elif self.serversock and self.serversock.fileno() == event[0]: |
771 | self.logger.debug("Connection request received") | 777 | self.logger.debug("Connection request received") |
772 | self.readsock, _ = self.serversock.accept() | 778 | self.readsock, _ = self.serversock.accept() |
773 | self.readsock.setblocking(0) | 779 | self.readsock.setblocking(0) |
@@ -781,6 +787,10 @@ class LoggingThread(threading.Thread): | |||
781 | elif self.readsock.fileno() == event[0]: | 787 | elif self.readsock.fileno() == event[0]: |
782 | data = self.recv(1024) | 788 | data = self.recv(1024) |
783 | self.logfunc(data) | 789 | self.logfunc(data) |
790 | elif self.qemuoutput.fileno() == event[0]: | ||
791 | data = self.qemuoutput.read() | ||
792 | self.logger.debug("Data received on qemu stdout %s" % data) | ||
793 | self.logfunc(data, ".stdout") | ||
784 | 794 | ||
785 | # Since the socket is non-blocking make sure to honor EAGAIN | 795 | # Since the socket is non-blocking make sure to honor EAGAIN |
786 | # and EWOULDBLOCK. | 796 | # and EWOULDBLOCK. |