* Try to fix qemu freezing due to full socket buffers
@ 2015-08-20 22:24 Randy Witt
2015-08-20 22:24 ` [PATCH 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt
` (4 more replies)
0 siblings, 5 replies; 11+ messages in thread
From: Randy Witt @ 2015-08-20 22:24 UTC (permalink / raw)
To: openembedded-core
The following changes since commit a3d228a484cf471e999b6537987e2897d8a7bd4e:
bitbake: main: Handle RuntimeError exception in list_extension_modules (2015-08-20 22:04:43 +0100)
are available in the git repository at:
git://git.yoctoproject.org/poky-contrib rewitt/logthread
for you to fetch changes up to c0f8b3c28c4410031dc763e714bc2ad0f87171d6:
qemurunner: Use two serial ports and log console with a thread (2015-08-20 14:16:29 -0700)
----------------------------------------------------------------
Randy Witt (3):
qemurunner.py: Move some class variables that should only be local
qemurunner: Make create_socket() return data and use exceptions
qemurunner: Use two serial ports and log console with a thread
meta/conf/machine/qemuarm.conf | 2 +-
meta/conf/machine/qemuarm64.conf | 2 +-
meta/conf/machine/qemumips.conf | 2 +-
meta/conf/machine/qemumips64.conf | 2 +-
meta/conf/machine/qemuppc.conf | 2 +-
meta/conf/machine/qemux86-64.conf | 2 +-
meta/conf/machine/qemux86.conf | 2 +-
meta/lib/oeqa/utils/qemurunner.py | 174 ++++++++++++++++++++++++++++++++------
8 files changed, 155 insertions(+), 33 deletions(-)
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 1/3] qemurunner.py: Move some class variables that should only be local 2015-08-20 22:24 Try to fix qemu freezing due to full socket buffers Randy Witt @ 2015-08-20 22:24 ` Randy Witt 2015-08-20 22:24 ` [PATCH 2/3] qemurunner: Make create_socket() return data and use exceptions Randy Witt ` (3 subsequent siblings) 4 siblings, 0 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 22:24 UTC (permalink / raw) To: openembedded-core The bootlog and qemusock variables were set in the class as part of the create_socket() routine. However those variables are never used outside of the same function and thus serve no purpose as class variables. This initializes those variables near where they are used. Signed-off-by: Randy Witt <randy.e.witt@linux.intel.com> --- meta/lib/oeqa/utils/qemurunner.py | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index 0458447..c5bb13c 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -43,9 +43,6 @@ class QemuRunner: def create_socket(self): - self.bootlog = '' - self.qemusock = None - try: self.server_socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM) self.server_socket.setblocking(0) @@ -145,22 +142,24 @@ class QemuRunner: socklist = [self.server_socket] reachedlogin = False stopread = False + qemusock = None + bootlog = '' while time.time() < endtime and not stopread: sread, swrite, serror = select.select(socklist, [], [], 5) for sock in sread: if sock is self.server_socket: - self.qemusock, addr = self.server_socket.accept() - self.qemusock.setblocking(0) - socklist.append(self.qemusock) + qemusock, addr = self.server_socket.accept() + qemusock.setblocking(0) + socklist.append(qemusock) socklist.remove(self.server_socket) logger.info("Connection from %s:%s" % addr) else: data = sock.recv(1024) if data: self.log(data) - self.bootlog += data - if re.search(".* login:", self.bootlog): - self.server_socket = self.qemusock + bootlog += data + if re.search(".* login:", bootlog): + self.server_socket = qemusock stopread = True reachedlogin = True logger.info("Reached login banner") @@ -171,7 +170,7 @@ class QemuRunner: if not reachedlogin: logger.info("Target didn't reached login boot in %d seconds" % self.boottime) - lines = "\n".join(self.bootlog.splitlines()[-25:]) + lines = "\n".join(bootlog.splitlines()[-25:]) logger.info("Last 25 lines of text:\n%s" % lines) logger.info("Check full boot log: %s" % self.logfile) self.stop() -- 2.4.3 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 2/3] qemurunner: Make create_socket() return data and use exceptions 2015-08-20 22:24 Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-20 22:24 ` [PATCH 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt @ 2015-08-20 22:24 ` Randy Witt 2015-08-20 22:24 ` [PATCH 3/3] qemurunner: Use two serial ports and log console with a thread Randy Witt ` (2 subsequent siblings) 4 siblings, 0 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 22:24 UTC (permalink / raw) To: openembedded-core So that create_socket() can be called more than once to create sockets, it now returns the socket and port rather than setting class variables directly. create_socket() now only uses exceptions for errors, not the return value from the function. Signed-off-by: Randy Witt <randy.e.witt@linux.intel.com> --- meta/lib/oeqa/utils/qemurunner.py | 29 +++++++++++++++-------------- 1 file changed, 15 insertions(+), 14 deletions(-) diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index c5bb13c..c8d6899 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -42,20 +42,18 @@ class QemuRunner: self.runqemutime = 60 def create_socket(self): - try: - self.server_socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM) - self.server_socket.setblocking(0) - self.server_socket.bind(("127.0.0.1",0)) - self.server_socket.listen(2) - self.serverport = self.server_socket.getsockname()[1] - logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % self.serverport) - return True - except socket.error, msg: - self.server_socket.close() - logger.error("Failed to create listening socket: %s" % msg[1]) - return False - + sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + sock.setblocking(0) + sock.bind(("127.0.0.1",0)) + sock.listen(2) + port = sock.getsockname()[1] + logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) + return (sock, port) + + except socket.error: + sock.close() + raise def log(self, msg): if self.logfile: @@ -82,7 +80,10 @@ class QemuRunner: else: os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image - if not self.create_socket(): + try: + self.server_socket, self.serverport = self.create_socket() + except socket.error, msg: + logger.error("Failed to create listening socket: %s" % msg[1]) return False # Set this flag so that Qemu doesn't do any grabs as SDL grabs interact -- 2.4.3 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 3/3] qemurunner: Use two serial ports and log console with a thread 2015-08-20 22:24 Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-20 22:24 ` [PATCH 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt 2015-08-20 22:24 ` [PATCH 2/3] qemurunner: Make create_socket() return data and use exceptions Randy Witt @ 2015-08-20 22:24 ` Randy Witt 2015-08-20 23:46 ` [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-21 13:36 ` Try to fix qemu freezing due to full socket buffers Burton, Ross 4 siblings, 0 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 22:24 UTC (permalink / raw) To: openembedded-core qemu can freeze and stop responding if the socket buffer connected to a tcp serial connection fills up. This happens of course when the reader of the serial data doesn't actually read it. This happened in the qemurunner code, because after checking for the "login:" sentinel, data was never again read from the serial connection. This patch solves the potential freeze by adding a thread to continuously read the data from the console and log it. So it also will give a full log of the console, rather than just up to the login prompt. To simplify this patch, another serial port was also added to use for the sole purpose of watching for the sentinel as well as being the interactive serial port. This will also prevent the possibility of lots of debug data on the console preventing the sentinel value from being seen due to interleaved text. Signed-off-by: Randy Witt <randy.e.witt@linux.intel.com> --- meta/conf/machine/qemuarm.conf | 2 +- meta/conf/machine/qemuarm64.conf | 2 +- meta/conf/machine/qemumips.conf | 2 +- meta/conf/machine/qemumips64.conf | 2 +- meta/conf/machine/qemuppc.conf | 2 +- meta/conf/machine/qemux86-64.conf | 2 +- meta/conf/machine/qemux86.conf | 2 +- meta/lib/oeqa/utils/qemurunner.py | 126 +++++++++++++++++++++++++++++++++++++- 8 files changed, 131 insertions(+), 9 deletions(-) diff --git a/meta/conf/machine/qemuarm.conf b/meta/conf/machine/qemuarm.conf index d07084b..cdad03f 100644 --- a/meta/conf/machine/qemuarm.conf +++ b/meta/conf/machine/qemuarm.conf @@ -8,5 +8,5 @@ require conf/machine/include/tune-arm926ejs.inc KERNEL_IMAGETYPE = "zImage" -SERIAL_CONSOLE = "115200 ttyAMA0" +SERIAL_CONSOLES = "115200;ttyAMA0 115200;ttyAMA1" diff --git a/meta/conf/machine/qemuarm64.conf b/meta/conf/machine/qemuarm64.conf index 20bcfba..7bbdad7 100644 --- a/meta/conf/machine/qemuarm64.conf +++ b/meta/conf/machine/qemuarm64.conf @@ -9,4 +9,4 @@ MACHINE_FEATURES = "" KERNEL_IMAGETYPE = "Image" -SERIAL_CONSOLE = "38400 ttyAMA0" +SERIAL_CONSOLES = "38400;ttyAMA0 38400;ttyAMA1" diff --git a/meta/conf/machine/qemumips.conf b/meta/conf/machine/qemumips.conf index d9d2421..fbf8137 100644 --- a/meta/conf/machine/qemumips.conf +++ b/meta/conf/machine/qemumips.conf @@ -8,6 +8,6 @@ require conf/machine/include/tune-mips32r2.inc KERNEL_IMAGETYPE = "vmlinux" KERNEL_ALT_IMAGETYPE = "vmlinux.bin" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" MACHINE_EXTRA_RRECOMMENDS = " kernel-modules" diff --git a/meta/conf/machine/qemumips64.conf b/meta/conf/machine/qemumips64.conf index b2c7998..8c3f1fe 100644 --- a/meta/conf/machine/qemumips64.conf +++ b/meta/conf/machine/qemumips64.conf @@ -8,6 +8,6 @@ require conf/machine/include/tune-mips64.inc KERNEL_IMAGETYPE = "vmlinux" KERNEL_ALT_IMAGETYPE = "vmlinux.bin" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" MACHINE_EXTRA_RRECOMMENDS = " kernel-modules" diff --git a/meta/conf/machine/qemuppc.conf b/meta/conf/machine/qemuppc.conf index 93145a1..85cbbf7 100644 --- a/meta/conf/machine/qemuppc.conf +++ b/meta/conf/machine/qemuppc.conf @@ -7,5 +7,5 @@ require conf/machine/include/tune-ppc7400.inc KERNEL_IMAGETYPE = "vmlinux" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" diff --git a/meta/conf/machine/qemux86-64.conf b/meta/conf/machine/qemux86-64.conf index 837f9f4..a4fd43c 100644 --- a/meta/conf/machine/qemux86-64.conf +++ b/meta/conf/machine/qemux86-64.conf @@ -13,7 +13,7 @@ require conf/machine/include/tune-core2.inc KERNEL_IMAGETYPE = "bzImage" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" XSERVER = "xserver-xorg \ ${@bb.utils.contains('DISTRO_FEATURES', 'opengl', 'mesa-driver-swrast', '', d)} \ diff --git a/meta/conf/machine/qemux86.conf b/meta/conf/machine/qemux86.conf index 3562276..96cea66 100644 --- a/meta/conf/machine/qemux86.conf +++ b/meta/conf/machine/qemux86.conf @@ -12,7 +12,7 @@ require conf/machine/include/tune-i586.inc KERNEL_IMAGETYPE = "bzImage" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" XSERVER = "xserver-xorg \ ${@bb.utils.contains('DISTRO_FEATURES', 'opengl', 'mesa-driver-swrast', '', d)} \ diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index c8d6899..b50b6ea 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -13,6 +13,7 @@ import re import socket import select import errno +import threading import logging logger = logging.getLogger("BitBake.QemuRunner") @@ -38,6 +39,7 @@ class QemuRunner: self.logfile = logfile self.boottime = boottime self.logged = False + self.thread = None self.runqemutime = 60 @@ -81,6 +83,7 @@ class QemuRunner: os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image try: + threadsock, threadport = self.create_socket() self.server_socket, self.serverport = self.create_socket() except socket.error, msg: logger.error("Failed to create listening socket: %s" % msg[1]) @@ -89,7 +92,7 @@ class QemuRunner: # Set this flag so that Qemu doesn't do any grabs as SDL grabs interact # badly with screensavers. os.environ["QEMU_DONT_GRAB"] = "1" - self.qemuparams = 'bootparams="console=tty1 console=ttyS0,115200n8" qemuparams="-serial tcp:127.0.0.1:%s"' % self.serverport + self.qemuparams = 'bootparams="console=tty1 console=ttyS0,115200n8" qemuparams="-serial tcp:127.0.0.1:{} -serial tcp:127.0.0.1:{}"'.format(threadport, self.serverport) if qemuparams: self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"' @@ -138,6 +141,16 @@ class QemuRunner: return False logger.info("Target IP: %s" % self.ip) logger.info("Server IP: %s" % self.server_ip) + + logger.info("Starting logging thread") + self.thread = LoggingThread(self.log, threadsock, logger) + self.thread.start() + if not self.thread.connection_established.wait(self.boottime): + logger.error("Didn't receive a console connection from qemu") + logger.info("Couldn't get ip from qemu process arguments! Here is the qemu command line used:\n%s\nand output from runqemu:\n%s" % (cmdline, getOutput(output))) + self.stop_thread() + return False + logger.info("Waiting at most %d seconds for login banner" % self.boottime) endtime = time.time() + self.boottime socklist = [self.server_socket] @@ -157,7 +170,6 @@ class QemuRunner: else: data = sock.recv(1024) if data: - self.log(data) bootlog += data if re.search(".* login:", bootlog): self.server_socket = qemusock @@ -214,6 +226,12 @@ class QemuRunner: self.server_socket = None self.qemupid = None self.ip = None + self.stop_thread() + + def stop_thread(self): + if self.thread and self.thread.is_alive(): + self.thread.stop() + self.thread.join() def restart(self, qemuparams = None): logger.info("Restarting qemu process") @@ -312,3 +330,107 @@ class QemuRunner: if (status_cmd == "0"): status = 1 return (status, str(data)) + +# This class is for reading data from a socket and passing it to logfunc +# to be processed. It's completely event driven and has a straightforward +# event loop. The mechanism for stopping the thread is a simple pipe which +# will wake up the poll and allow for tearing everything down. +class LoggingThread(threading.Thread): + def __init__(self, logfunc, sock, logger): + self.connection_established = threading.Event() + self.serversock = sock + self.logfunc = logfunc + self.logger = logger + self.readsock = None + self.running = False + + self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL + self.readevents = select.POLLIN | select.POLLPRI + + threading.Thread.__init__(self, target=self.threadtarget) + + def threadtarget(self): + try: + self.eventloop() + finally: + self.teardown() + + def run(self): + self.logger.info("Starting logging thread") + self.readpipe, self.writepipe = os.pipe() + threading.Thread.run(self) + + def stop(self): + self.logger.info("Stopping logging thread") + if self.running: + os.write(self.writepipe, "stop") + + def teardown(self): + self.close_socket(self.serversock) + + if self.readsock is not None: + self.close_socket(self.readsock) + + self.close_ignore_error(self.readpipe) + self.close_ignore_error(self.writepipe) + self.running = False + + def eventloop(self): + poll = select.poll() + eventmask = self.errorevents | self.readevents + poll.register(self.serversock.fileno()) + poll.register(self.readpipe, eventmask) + + breakout = False + self.running = True + self.logger.info("Starting thread event loop") + while not breakout: + events = poll.poll() + for event in events: + # An error occurred, bail out + if event[1] & self.errorevents: + raise Exception(self.stringify_event(event[1])) + + # Event to stop the thread + if self.readpipe == event[0]: + self.logger.info("Stop event received") + breakout = True + break + + # A connection request was received + elif self.serversock.fileno() == event[0]: + self.logger.info("Connection request received") + self.readsock, _ = self.serversock.accept() + poll.unregister(self.serversock.fileno()) + poll.register(self.readsock.fileno()) + + self.logger.info("Setting connection established event") + self.connection_established.set() + + # Actual data to be logged + elif self.readsock.fileno() == event[0]: + data = self.readsock.recv(1024) + if not data: + raise Exception("No data on read ready socket") + + self.logfunc(data) + + def stringify_event(self, event): + val = '' + if select.POLLERR == event: + val = 'POLLER' + elif select.POLLHUP == event: + val = 'POLLHUP' + elif select.POLLNVAL == event: + val = 'POLLNVAL' + return val + + def close_socket(self, sock): + sock.shutdown(socket.SHUT_RDWR) + sock.close() + + def close_ignore_error(self, fd): + try: + os.close(fd) + except OSError: + pass -- 2.4.3 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers 2015-08-20 22:24 Try to fix qemu freezing due to full socket buffers Randy Witt ` (2 preceding siblings ...) 2015-08-20 22:24 ` [PATCH 3/3] qemurunner: Use two serial ports and log console with a thread Randy Witt @ 2015-08-20 23:46 ` Randy Witt 2015-08-20 23:46 ` [PATCH V2 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt ` (2 more replies) 2015-08-21 13:36 ` Try to fix qemu freezing due to full socket buffers Burton, Ross 4 siblings, 3 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 23:46 UTC (permalink / raw) To: openembedded-core Fix copy and pasted error message that had no meaning to the actual timeout. ^ permalink raw reply [flat|nested] 11+ messages in thread
* [PATCH V2 1/3] qemurunner.py: Move some class variables that should only be local 2015-08-20 23:46 ` [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers Randy Witt @ 2015-08-20 23:46 ` Randy Witt 2015-08-20 23:46 ` [PATCH V2 2/3] qemurunner: Make create_socket() return data and use exceptions Randy Witt 2015-08-20 23:46 ` [PATCH V2 3/3] qemurunner: Use two serial ports and log console with a thread Randy Witt 2 siblings, 0 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 23:46 UTC (permalink / raw) To: openembedded-core The bootlog and qemusock variables were set in the class as part of the create_socket() routine. However those variables are never used outside of the same function and thus serve no purpose as class variables. This initializes those variables near where they are used. Signed-off-by: Randy Witt <randy.e.witt@linux.intel.com> --- meta/lib/oeqa/utils/qemurunner.py | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index 0458447..c5bb13c 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -43,9 +43,6 @@ class QemuRunner: def create_socket(self): - self.bootlog = '' - self.qemusock = None - try: self.server_socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM) self.server_socket.setblocking(0) @@ -145,22 +142,24 @@ class QemuRunner: socklist = [self.server_socket] reachedlogin = False stopread = False + qemusock = None + bootlog = '' while time.time() < endtime and not stopread: sread, swrite, serror = select.select(socklist, [], [], 5) for sock in sread: if sock is self.server_socket: - self.qemusock, addr = self.server_socket.accept() - self.qemusock.setblocking(0) - socklist.append(self.qemusock) + qemusock, addr = self.server_socket.accept() + qemusock.setblocking(0) + socklist.append(qemusock) socklist.remove(self.server_socket) logger.info("Connection from %s:%s" % addr) else: data = sock.recv(1024) if data: self.log(data) - self.bootlog += data - if re.search(".* login:", self.bootlog): - self.server_socket = self.qemusock + bootlog += data + if re.search(".* login:", bootlog): + self.server_socket = qemusock stopread = True reachedlogin = True logger.info("Reached login banner") @@ -171,7 +170,7 @@ class QemuRunner: if not reachedlogin: logger.info("Target didn't reached login boot in %d seconds" % self.boottime) - lines = "\n".join(self.bootlog.splitlines()[-25:]) + lines = "\n".join(bootlog.splitlines()[-25:]) logger.info("Last 25 lines of text:\n%s" % lines) logger.info("Check full boot log: %s" % self.logfile) self.stop() -- 2.4.3 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH V2 2/3] qemurunner: Make create_socket() return data and use exceptions 2015-08-20 23:46 ` [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-20 23:46 ` [PATCH V2 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt @ 2015-08-20 23:46 ` Randy Witt 2015-08-20 23:46 ` [PATCH V2 3/3] qemurunner: Use two serial ports and log console with a thread Randy Witt 2 siblings, 0 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 23:46 UTC (permalink / raw) To: openembedded-core So that create_socket() can be called more than once to create sockets, it now returns the socket and port rather than setting class variables directly. create_socket() now only uses exceptions for errors, not the return value from the function. Signed-off-by: Randy Witt <randy.e.witt@linux.intel.com> --- meta/lib/oeqa/utils/qemurunner.py | 29 +++++++++++++++-------------- 1 file changed, 15 insertions(+), 14 deletions(-) diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index c5bb13c..c8d6899 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -42,20 +42,18 @@ class QemuRunner: self.runqemutime = 60 def create_socket(self): - try: - self.server_socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM) - self.server_socket.setblocking(0) - self.server_socket.bind(("127.0.0.1",0)) - self.server_socket.listen(2) - self.serverport = self.server_socket.getsockname()[1] - logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % self.serverport) - return True - except socket.error, msg: - self.server_socket.close() - logger.error("Failed to create listening socket: %s" % msg[1]) - return False - + sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + sock.setblocking(0) + sock.bind(("127.0.0.1",0)) + sock.listen(2) + port = sock.getsockname()[1] + logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) + return (sock, port) + + except socket.error: + sock.close() + raise def log(self, msg): if self.logfile: @@ -82,7 +80,10 @@ class QemuRunner: else: os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image - if not self.create_socket(): + try: + self.server_socket, self.serverport = self.create_socket() + except socket.error, msg: + logger.error("Failed to create listening socket: %s" % msg[1]) return False # Set this flag so that Qemu doesn't do any grabs as SDL grabs interact -- 2.4.3 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH V2 3/3] qemurunner: Use two serial ports and log console with a thread 2015-08-20 23:46 ` [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-20 23:46 ` [PATCH V2 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt 2015-08-20 23:46 ` [PATCH V2 2/3] qemurunner: Make create_socket() return data and use exceptions Randy Witt @ 2015-08-20 23:46 ` Randy Witt 2 siblings, 0 replies; 11+ messages in thread From: Randy Witt @ 2015-08-20 23:46 UTC (permalink / raw) To: openembedded-core qemu can freeze and stop responding if the socket buffer connected to a tcp serial connection fills up. This happens of course when the reader of the serial data doesn't actually read it. This happened in the qemurunner code, because after checking for the "login:" sentinel, data was never again read from the serial connection. This patch solves the potential freeze by adding a thread to continuously read the data from the console and log it. So it also will give a full log of the console, rather than just up to the login prompt. To simplify this patch, another serial port was also added to use for the sole purpose of watching for the sentinel as well as being the interactive serial port. This will also prevent the possibility of lots of debug data on the console preventing the sentinel value from being seen due to interleaved text. Signed-off-by: Randy Witt <randy.e.witt@linux.intel.com> --- meta/conf/machine/qemuarm.conf | 2 +- meta/conf/machine/qemuarm64.conf | 2 +- meta/conf/machine/qemumips.conf | 2 +- meta/conf/machine/qemumips64.conf | 2 +- meta/conf/machine/qemuppc.conf | 2 +- meta/conf/machine/qemux86-64.conf | 2 +- meta/conf/machine/qemux86.conf | 2 +- meta/lib/oeqa/utils/qemurunner.py | 128 +++++++++++++++++++++++++++++++++++++- 8 files changed, 133 insertions(+), 9 deletions(-) diff --git a/meta/conf/machine/qemuarm.conf b/meta/conf/machine/qemuarm.conf index d07084b..cdad03f 100644 --- a/meta/conf/machine/qemuarm.conf +++ b/meta/conf/machine/qemuarm.conf @@ -8,5 +8,5 @@ require conf/machine/include/tune-arm926ejs.inc KERNEL_IMAGETYPE = "zImage" -SERIAL_CONSOLE = "115200 ttyAMA0" +SERIAL_CONSOLES = "115200;ttyAMA0 115200;ttyAMA1" diff --git a/meta/conf/machine/qemuarm64.conf b/meta/conf/machine/qemuarm64.conf index 20bcfba..7bbdad7 100644 --- a/meta/conf/machine/qemuarm64.conf +++ b/meta/conf/machine/qemuarm64.conf @@ -9,4 +9,4 @@ MACHINE_FEATURES = "" KERNEL_IMAGETYPE = "Image" -SERIAL_CONSOLE = "38400 ttyAMA0" +SERIAL_CONSOLES = "38400;ttyAMA0 38400;ttyAMA1" diff --git a/meta/conf/machine/qemumips.conf b/meta/conf/machine/qemumips.conf index d9d2421..fbf8137 100644 --- a/meta/conf/machine/qemumips.conf +++ b/meta/conf/machine/qemumips.conf @@ -8,6 +8,6 @@ require conf/machine/include/tune-mips32r2.inc KERNEL_IMAGETYPE = "vmlinux" KERNEL_ALT_IMAGETYPE = "vmlinux.bin" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" MACHINE_EXTRA_RRECOMMENDS = " kernel-modules" diff --git a/meta/conf/machine/qemumips64.conf b/meta/conf/machine/qemumips64.conf index b2c7998..8c3f1fe 100644 --- a/meta/conf/machine/qemumips64.conf +++ b/meta/conf/machine/qemumips64.conf @@ -8,6 +8,6 @@ require conf/machine/include/tune-mips64.inc KERNEL_IMAGETYPE = "vmlinux" KERNEL_ALT_IMAGETYPE = "vmlinux.bin" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" MACHINE_EXTRA_RRECOMMENDS = " kernel-modules" diff --git a/meta/conf/machine/qemuppc.conf b/meta/conf/machine/qemuppc.conf index 93145a1..85cbbf7 100644 --- a/meta/conf/machine/qemuppc.conf +++ b/meta/conf/machine/qemuppc.conf @@ -7,5 +7,5 @@ require conf/machine/include/tune-ppc7400.inc KERNEL_IMAGETYPE = "vmlinux" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" diff --git a/meta/conf/machine/qemux86-64.conf b/meta/conf/machine/qemux86-64.conf index 837f9f4..a4fd43c 100644 --- a/meta/conf/machine/qemux86-64.conf +++ b/meta/conf/machine/qemux86-64.conf @@ -13,7 +13,7 @@ require conf/machine/include/tune-core2.inc KERNEL_IMAGETYPE = "bzImage" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" XSERVER = "xserver-xorg \ ${@bb.utils.contains('DISTRO_FEATURES', 'opengl', 'mesa-driver-swrast', '', d)} \ diff --git a/meta/conf/machine/qemux86.conf b/meta/conf/machine/qemux86.conf index 3562276..96cea66 100644 --- a/meta/conf/machine/qemux86.conf +++ b/meta/conf/machine/qemux86.conf @@ -12,7 +12,7 @@ require conf/machine/include/tune-i586.inc KERNEL_IMAGETYPE = "bzImage" -SERIAL_CONSOLE = "115200 ttyS0" +SERIAL_CONSOLES = "115200;ttyS0 115200;ttyS1" XSERVER = "xserver-xorg \ ${@bb.utils.contains('DISTRO_FEATURES', 'opengl', 'mesa-driver-swrast', '', d)} \ diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index c8d6899..e976fd0 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -13,6 +13,7 @@ import re import socket import select import errno +import threading import logging logger = logging.getLogger("BitBake.QemuRunner") @@ -38,6 +39,7 @@ class QemuRunner: self.logfile = logfile self.boottime = boottime self.logged = False + self.thread = None self.runqemutime = 60 @@ -81,6 +83,7 @@ class QemuRunner: os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image try: + threadsock, threadport = self.create_socket() self.server_socket, self.serverport = self.create_socket() except socket.error, msg: logger.error("Failed to create listening socket: %s" % msg[1]) @@ -89,7 +92,7 @@ class QemuRunner: # Set this flag so that Qemu doesn't do any grabs as SDL grabs interact # badly with screensavers. os.environ["QEMU_DONT_GRAB"] = "1" - self.qemuparams = 'bootparams="console=tty1 console=ttyS0,115200n8" qemuparams="-serial tcp:127.0.0.1:%s"' % self.serverport + self.qemuparams = 'bootparams="console=tty1 console=ttyS0,115200n8" qemuparams="-serial tcp:127.0.0.1:{} -serial tcp:127.0.0.1:{}"'.format(threadport, self.serverport) if qemuparams: self.qemuparams = self.qemuparams[:-1] + " " + qemuparams + " " + '\"' @@ -138,6 +141,18 @@ class QemuRunner: return False logger.info("Target IP: %s" % self.ip) logger.info("Server IP: %s" % self.server_ip) + + logger.info("Starting logging thread") + self.thread = LoggingThread(self.log, threadsock, logger) + self.thread.start() + if not self.thread.connection_established.wait(self.boottime): + logger.error("Didn't receive a console connection from qemu. " + "Here is the qemu command line used:\n%s\nand " + "output from runqemu:\n%s" % (cmdline, + getOutput(output))) + self.stop_thread() + return False + logger.info("Waiting at most %d seconds for login banner" % self.boottime) endtime = time.time() + self.boottime socklist = [self.server_socket] @@ -157,7 +172,6 @@ class QemuRunner: else: data = sock.recv(1024) if data: - self.log(data) bootlog += data if re.search(".* login:", bootlog): self.server_socket = qemusock @@ -214,6 +228,12 @@ class QemuRunner: self.server_socket = None self.qemupid = None self.ip = None + self.stop_thread() + + def stop_thread(self): + if self.thread and self.thread.is_alive(): + self.thread.stop() + self.thread.join() def restart(self, qemuparams = None): logger.info("Restarting qemu process") @@ -312,3 +332,107 @@ class QemuRunner: if (status_cmd == "0"): status = 1 return (status, str(data)) + +# This class is for reading data from a socket and passing it to logfunc +# to be processed. It's completely event driven and has a straightforward +# event loop. The mechanism for stopping the thread is a simple pipe which +# will wake up the poll and allow for tearing everything down. +class LoggingThread(threading.Thread): + def __init__(self, logfunc, sock, logger): + self.connection_established = threading.Event() + self.serversock = sock + self.logfunc = logfunc + self.logger = logger + self.readsock = None + self.running = False + + self.errorevents = select.POLLERR | select.POLLHUP | select.POLLNVAL + self.readevents = select.POLLIN | select.POLLPRI + + threading.Thread.__init__(self, target=self.threadtarget) + + def threadtarget(self): + try: + self.eventloop() + finally: + self.teardown() + + def run(self): + self.logger.info("Starting logging thread") + self.readpipe, self.writepipe = os.pipe() + threading.Thread.run(self) + + def stop(self): + self.logger.info("Stopping logging thread") + if self.running: + os.write(self.writepipe, "stop") + + def teardown(self): + self.close_socket(self.serversock) + + if self.readsock is not None: + self.close_socket(self.readsock) + + self.close_ignore_error(self.readpipe) + self.close_ignore_error(self.writepipe) + self.running = False + + def eventloop(self): + poll = select.poll() + eventmask = self.errorevents | self.readevents + poll.register(self.serversock.fileno()) + poll.register(self.readpipe, eventmask) + + breakout = False + self.running = True + self.logger.info("Starting thread event loop") + while not breakout: + events = poll.poll() + for event in events: + # An error occurred, bail out + if event[1] & self.errorevents: + raise Exception(self.stringify_event(event[1])) + + # Event to stop the thread + if self.readpipe == event[0]: + self.logger.info("Stop event received") + breakout = True + break + + # A connection request was received + elif self.serversock.fileno() == event[0]: + self.logger.info("Connection request received") + self.readsock, _ = self.serversock.accept() + poll.unregister(self.serversock.fileno()) + poll.register(self.readsock.fileno()) + + self.logger.info("Setting connection established event") + self.connection_established.set() + + # Actual data to be logged + elif self.readsock.fileno() == event[0]: + data = self.readsock.recv(1024) + if not data: + raise Exception("No data on read ready socket") + + self.logfunc(data) + + def stringify_event(self, event): + val = '' + if select.POLLERR == event: + val = 'POLLER' + elif select.POLLHUP == event: + val = 'POLLHUP' + elif select.POLLNVAL == event: + val = 'POLLNVAL' + return val + + def close_socket(self, sock): + sock.shutdown(socket.SHUT_RDWR) + sock.close() + + def close_ignore_error(self, fd): + try: + os.close(fd) + except OSError: + pass -- 2.4.3 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: Try to fix qemu freezing due to full socket buffers 2015-08-20 22:24 Try to fix qemu freezing due to full socket buffers Randy Witt ` (3 preceding siblings ...) 2015-08-20 23:46 ` [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers Randy Witt @ 2015-08-21 13:36 ` Burton, Ross 2015-08-21 13:41 ` Richard Purdie 4 siblings, 1 reply; 11+ messages in thread From: Burton, Ross @ 2015-08-21 13:36 UTC (permalink / raw) To: Randy Witt; +Cc: OE-core [-- Attachment #1: Type: text/plain, Size: 516 bytes --] On 20 August 2015 at 23:24, Randy Witt <randy.e.witt@linux.intel.com> wrote: > Randy Witt (3): > qemurunner.py: Move some class variables that should only be local > qemurunner: Make create_socket() return data and use exceptions > qemurunner: Use two serial ports and log console with a thread https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/450/steps/Running%20Sanity%20Tests_2/logs/stdio If this was meant to fix the ttyS1 hangs, I'm sorry :( Ross [-- Attachment #2: Type: text/html, Size: 1119 bytes --] ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Try to fix qemu freezing due to full socket buffers 2015-08-21 13:36 ` Try to fix qemu freezing due to full socket buffers Burton, Ross @ 2015-08-21 13:41 ` Richard Purdie 2015-08-21 14:23 ` Burton, Ross 0 siblings, 1 reply; 11+ messages in thread From: Richard Purdie @ 2015-08-21 13:41 UTC (permalink / raw) To: Burton, Ross; +Cc: OE-core On Fri, 2015-08-21 at 14:36 +0100, Burton, Ross wrote: > > On 20 August 2015 at 23:24, Randy Witt <randy.e.witt@linux.intel.com> > wrote: > Randy Witt (3): > qemurunner.py: Move some class variables that should > only be local > qemurunner: Make create_socket() return data and use > exceptions > qemurunner: Use two serial ports and log console with a > thread > > https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/450/steps/Running%20Sanity%20Tests_2/logs/stdio > > > If this was meant to fix the ttyS1 hangs, I'm sorry :( > It was meant to fix the issue where qemu hangs and stops responding to network requests. Its a useful datapoint that the systemd issues remain though. Was there a systemd upgrade in mut out of interest (as another data point)? Cheers, Richard ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Try to fix qemu freezing due to full socket buffers 2015-08-21 13:41 ` Richard Purdie @ 2015-08-21 14:23 ` Burton, Ross 0 siblings, 0 replies; 11+ messages in thread From: Burton, Ross @ 2015-08-21 14:23 UTC (permalink / raw) To: Richard Purdie; +Cc: OE-core [-- Attachment #1: Type: text/plain, Size: 447 bytes --] On 21 August 2015 at 14:41, Richard Purdie < richard.purdie@linuxfoundation.org> wrote: > It was meant to fix the issue where qemu hangs and stops responding to > network requests. Its a useful datapoint that the systemd issues remain > though. Was there a systemd upgrade in mut out of interest (as another > data point)? > There's still plenty of builds so lets see what happens... There wasn't a systemd in that MUT, no. Ross [-- Attachment #2: Type: text/html, Size: 938 bytes --] ^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2015-08-21 14:23 UTC | newest] Thread overview: 11+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2015-08-20 22:24 Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-20 22:24 ` [PATCH 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt 2015-08-20 22:24 ` [PATCH 2/3] qemurunner: Make create_socket() return data and use exceptions Randy Witt 2015-08-20 22:24 ` [PATCH 3/3] qemurunner: Use two serial ports and log console with a thread Randy Witt 2015-08-20 23:46 ` [PATCH V2 0/3] Try to fix qemu freezing due to full socket buffers Randy Witt 2015-08-20 23:46 ` [PATCH V2 1/3] qemurunner.py: Move some class variables that should only be local Randy Witt 2015-08-20 23:46 ` [PATCH V2 2/3] qemurunner: Make create_socket() return data and use exceptions Randy Witt 2015-08-20 23:46 ` [PATCH V2 3/3] qemurunner: Use two serial ports and log console with a thread Randy Witt 2015-08-21 13:36 ` Try to fix qemu freezing due to full socket buffers Burton, Ross 2015-08-21 13:41 ` Richard Purdie 2015-08-21 14:23 ` Burton, Ross
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox