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