diff options
author | Richard Purdie <richard.purdie@linuxfoundation.org> | 2017-09-07 10:49:19 +0100 |
---|---|---|
committer | Richard Purdie <richard.purdie@linuxfoundation.org> | 2018-03-04 11:11:58 +0000 |
commit | 50750e15727f783c17df2b3377ba21880afe6a44 (patch) | |
tree | 04fba1b087367ef530f5a3af43dc594888cec6b1 | |
parent | 8f35c388b443d4d820af703d53269a81e11007a3 (diff) | |
download | poky-50750e15727f783c17df2b3377ba21880afe6a44.tar.gz |
oeqa/qemurunner: Improve logging
Python unittest intercepts stdout and stderr however qemurunner sets
up a streamhandler before that interception occurs, hence the messages
spam the unittest output.
By moving the logging init to the class init time, we use the unittest
stdout/stderr and this means unittest can only show the log output upon
failure. This cleans up the selftest and testimage output whilst still
showing logging upon failure.
(From OE-Core rev: 9099cecc727fe0ae5f1559582426d30ba7a9f4d3)
(From OE-Core rev: ee13216284c4d49b762eaab488f21de573d2079d)
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Signed-off-by: Armin Kuster <akuster808@gmail.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
-rw-r--r-- | meta/lib/oeqa/utils/qemurunner.py | 90 |
1 files changed, 45 insertions, 45 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index 1b8cbce477..3148d7ec22 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py | |||
@@ -17,11 +17,8 @@ import errno | |||
17 | import string | 17 | import string |
18 | import threading | 18 | import threading |
19 | import codecs | 19 | import codecs |
20 | from oeqa.utils.dump import HostDumper | ||
21 | |||
22 | import logging | 20 | import logging |
23 | logger = logging.getLogger("BitBake.QemuRunner") | 21 | from oeqa.utils.dump import HostDumper |
24 | logger.addHandler(logging.StreamHandler()) | ||
25 | 22 | ||
26 | # Get Unicode non printable control chars | 23 | # Get Unicode non printable control chars |
27 | control_range = list(range(0,32))+list(range(127,160)) | 24 | control_range = list(range(0,32))+list(range(127,160)) |
@@ -58,6 +55,9 @@ class QemuRunner: | |||
58 | self.runqemutime = 120 | 55 | self.runqemutime = 120 |
59 | self.host_dumper = HostDumper(dump_host_cmds, dump_dir) | 56 | self.host_dumper = HostDumper(dump_host_cmds, dump_dir) |
60 | 57 | ||
58 | self.logger = logging.getLogger("BitBake.QemuRunner") | ||
59 | self.logger.addHandler(logging.StreamHandler(sys.stdout)) | ||
60 | |||
61 | def create_socket(self): | 61 | def create_socket(self): |
62 | try: | 62 | try: |
63 | sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) | 63 | sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) |
@@ -65,7 +65,7 @@ class QemuRunner: | |||
65 | sock.bind(("127.0.0.1",0)) | 65 | sock.bind(("127.0.0.1",0)) |
66 | sock.listen(2) | 66 | sock.listen(2) |
67 | port = sock.getsockname()[1] | 67 | port = sock.getsockname()[1] |
68 | logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) | 68 | self.logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) |
69 | return (sock, port) | 69 | return (sock, port) |
70 | 70 | ||
71 | except socket.error: | 71 | except socket.error: |
@@ -91,8 +91,8 @@ class QemuRunner: | |||
91 | def handleSIGCHLD(self, signum, frame): | 91 | def handleSIGCHLD(self, signum, frame): |
92 | if self.runqemu and self.runqemu.poll(): | 92 | if self.runqemu and self.runqemu.poll(): |
93 | if self.runqemu.returncode: | 93 | if self.runqemu.returncode: |
94 | logger.info('runqemu exited with code %d' % self.runqemu.returncode) | 94 | self.logger.info('runqemu exited with code %d' % self.runqemu.returncode) |
95 | logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) | 95 | self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) |
96 | self.stop() | 96 | self.stop() |
97 | self._dump_host() | 97 | self._dump_host() |
98 | raise SystemExit | 98 | raise SystemExit |
@@ -104,15 +104,15 @@ class QemuRunner: | |||
104 | # interact badly with screensavers. | 104 | # interact badly with screensavers. |
105 | os.environ["QEMU_DONT_GRAB"] = "1" | 105 | os.environ["QEMU_DONT_GRAB"] = "1" |
106 | if not os.path.exists(self.rootfs): | 106 | if not os.path.exists(self.rootfs): |
107 | logger.error("Invalid rootfs %s" % self.rootfs) | 107 | self.logger.error("Invalid rootfs %s" % self.rootfs) |
108 | return False | 108 | return False |
109 | if not os.path.exists(self.tmpdir): | 109 | if not os.path.exists(self.tmpdir): |
110 | logger.error("Invalid TMPDIR path %s" % self.tmpdir) | 110 | self.logger.error("Invalid TMPDIR path %s" % self.tmpdir) |
111 | return False | 111 | return False |
112 | else: | 112 | else: |
113 | os.environ["OE_TMPDIR"] = self.tmpdir | 113 | os.environ["OE_TMPDIR"] = self.tmpdir |
114 | if not os.path.exists(self.deploy_dir_image): | 114 | if not os.path.exists(self.deploy_dir_image): |
115 | logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image) | 115 | self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image) |
116 | return False | 116 | return False |
117 | else: | 117 | else: |
118 | os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image | 118 | os.environ["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image |
@@ -120,10 +120,10 @@ class QemuRunner: | |||
120 | if not launch_cmd: | 120 | if not launch_cmd: |
121 | launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams) | 121 | launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams) |
122 | if self.use_kvm: | 122 | if self.use_kvm: |
123 | logger.info('Using kvm for runqemu') | 123 | self.logger.info('Using kvm for runqemu') |
124 | launch_cmd += ' kvm' | 124 | launch_cmd += ' kvm' |
125 | else: | 125 | else: |
126 | logger.info('Not using kvm for runqemu') | 126 | self.logger.info('Not using kvm for runqemu') |
127 | if not self.display: | 127 | if not self.display: |
128 | launch_cmd += ' nographic' | 128 | launch_cmd += ' nographic' |
129 | launch_cmd += ' %s %s' % (self.machine, self.rootfs) | 129 | launch_cmd += ' %s %s' % (self.machine, self.rootfs) |
@@ -135,7 +135,7 @@ class QemuRunner: | |||
135 | threadsock, threadport = self.create_socket() | 135 | threadsock, threadport = self.create_socket() |
136 | self.server_socket, self.serverport = self.create_socket() | 136 | self.server_socket, self.serverport = self.create_socket() |
137 | except socket.error as msg: | 137 | except socket.error as msg: |
138 | logger.error("Failed to create listening socket: %s" % msg[1]) | 138 | self.logger.error("Failed to create listening socket: %s" % msg[1]) |
139 | return False | 139 | return False |
140 | 140 | ||
141 | bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1' | 141 | bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1' |
@@ -151,7 +151,7 @@ class QemuRunner: | |||
151 | self.origchldhandler = signal.getsignal(signal.SIGCHLD) | 151 | self.origchldhandler = signal.getsignal(signal.SIGCHLD) |
152 | signal.signal(signal.SIGCHLD, self.handleSIGCHLD) | 152 | signal.signal(signal.SIGCHLD, self.handleSIGCHLD) |
153 | 153 | ||
154 | logger.info('launchcmd=%s'%(launch_cmd)) | 154 | self.logger.info('launchcmd=%s'%(launch_cmd)) |
155 | 155 | ||
156 | # FIXME: We pass in stdin=subprocess.PIPE here to work around stty | 156 | # FIXME: We pass in stdin=subprocess.PIPE here to work around stty |
157 | # blocking at the end of the runqemu script when using this within | 157 | # blocking at the end of the runqemu script when using this within |
@@ -186,24 +186,24 @@ class QemuRunner: | |||
186 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) | 186 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) |
187 | sys.exit(0) | 187 | sys.exit(0) |
188 | 188 | ||
189 | logger.info("runqemu started, pid is %s" % self.runqemu.pid) | 189 | self.logger.info("runqemu started, pid is %s" % self.runqemu.pid) |
190 | logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime) | 190 | self.logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime) |
191 | endtime = time.time() + self.runqemutime | 191 | endtime = time.time() + self.runqemutime |
192 | while not self.is_alive() and time.time() < endtime: | 192 | while not self.is_alive() and time.time() < endtime: |
193 | if self.runqemu.poll(): | 193 | if self.runqemu.poll(): |
194 | if self.runqemu.returncode: | 194 | if self.runqemu.returncode: |
195 | # No point waiting any longer | 195 | # No point waiting any longer |
196 | logger.info('runqemu exited with code %d' % self.runqemu.returncode) | 196 | self.logger.info('runqemu exited with code %d' % self.runqemu.returncode) |
197 | self._dump_host() | 197 | self._dump_host() |
198 | self.stop() | 198 | self.stop() |
199 | logger.info("Output from runqemu:\n%s" % self.getOutput(output)) | 199 | self.logger.info("Output from runqemu:\n%s" % self.getOutput(output)) |
200 | return False | 200 | return False |
201 | time.sleep(1) | 201 | time.sleep(1) |
202 | 202 | ||
203 | out = self.getOutput(output) | 203 | out = self.getOutput(output) |
204 | netconf = False # network configuration is not required by default | 204 | netconf = False # network configuration is not required by default |
205 | if self.is_alive(): | 205 | if self.is_alive(): |
206 | logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid)) | 206 | self.logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid)) |
207 | if get_ip: | 207 | if get_ip: |
208 | cmdline = '' | 208 | cmdline = '' |
209 | with open('/proc/%s/cmdline' % self.qemupid) as p: | 209 | with open('/proc/%s/cmdline' % self.qemupid) as p: |
@@ -215,7 +215,7 @@ class QemuRunner: | |||
215 | ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) | 215 | ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) |
216 | self.ip = ips[0] | 216 | self.ip = ips[0] |
217 | self.server_ip = ips[1] | 217 | self.server_ip = ips[1] |
218 | logger.info("qemu cmdline used:\n{}".format(cmdline)) | 218 | self.logger.info("qemu cmdline used:\n{}".format(cmdline)) |
219 | except (IndexError, ValueError): | 219 | except (IndexError, ValueError): |
220 | # Try to get network configuration from runqemu output | 220 | # Try to get network configuration from runqemu output |
221 | match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*', | 221 | match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*', |
@@ -227,27 +227,27 @@ class QemuRunner: | |||
227 | # and guest networking is not configured | 227 | # and guest networking is not configured |
228 | netconf = True | 228 | netconf = True |
229 | else: | 229 | else: |
230 | logger.error("Couldn't get ip from qemu command line and runqemu output! " | 230 | self.logger.error("Couldn't get ip from qemu command line and runqemu output! " |
231 | "Here is the qemu command line used:\n%s\n" | 231 | "Here is the qemu command line used:\n%s\n" |
232 | "and output from runqemu:\n%s" % (cmdline, out)) | 232 | "and output from runqemu:\n%s" % (cmdline, out)) |
233 | self._dump_host() | 233 | self._dump_host() |
234 | self.stop() | 234 | self.stop() |
235 | return False | 235 | return False |
236 | 236 | ||
237 | logger.info("Target IP: %s" % self.ip) | 237 | self.logger.info("Target IP: %s" % self.ip) |
238 | logger.info("Server IP: %s" % self.server_ip) | 238 | self.logger.info("Server IP: %s" % self.server_ip) |
239 | 239 | ||
240 | self.thread = LoggingThread(self.log, threadsock, logger) | 240 | self.thread = LoggingThread(self.log, threadsock, self.logger) |
241 | self.thread.start() | 241 | self.thread.start() |
242 | if not self.thread.connection_established.wait(self.boottime): | 242 | if not self.thread.connection_established.wait(self.boottime): |
243 | logger.error("Didn't receive a console connection from qemu. " | 243 | self.logger.error("Didn't receive a console connection from qemu. " |
244 | "Here is the qemu command line used:\n%s\nand " | 244 | "Here is the qemu command line used:\n%s\nand " |
245 | "output from runqemu:\n%s" % (cmdline, out)) | 245 | "output from runqemu:\n%s" % (cmdline, out)) |
246 | self.stop_thread() | 246 | self.stop_thread() |
247 | return False | 247 | return False |
248 | 248 | ||
249 | logger.info("Output from runqemu:\n%s", out) | 249 | self.logger.info("Output from runqemu:\n%s", out) |
250 | logger.info("Waiting at most %d seconds for login banner" % self.boottime) | 250 | self.logger.info("Waiting at most %d seconds for login banner" % self.boottime) |
251 | endtime = time.time() + self.boottime | 251 | endtime = time.time() + self.boottime |
252 | socklist = [self.server_socket] | 252 | socklist = [self.server_socket] |
253 | reachedlogin = False | 253 | reachedlogin = False |
@@ -266,7 +266,7 @@ class QemuRunner: | |||
266 | qemusock.setblocking(0) | 266 | qemusock.setblocking(0) |
267 | socklist.append(qemusock) | 267 | socklist.append(qemusock) |
268 | socklist.remove(self.server_socket) | 268 | socklist.remove(self.server_socket) |
269 | logger.info("Connection from %s:%s" % addr) | 269 | self.logger.info("Connection from %s:%s" % addr) |
270 | else: | 270 | else: |
271 | data = data + sock.recv(1024) | 271 | data = data + sock.recv(1024) |
272 | if data: | 272 | if data: |
@@ -278,7 +278,7 @@ class QemuRunner: | |||
278 | self.server_socket = qemusock | 278 | self.server_socket = qemusock |
279 | stopread = True | 279 | stopread = True |
280 | reachedlogin = True | 280 | reachedlogin = True |
281 | logger.info("Reached login banner") | 281 | self.logger.info("Reached login banner") |
282 | except UnicodeDecodeError: | 282 | except UnicodeDecodeError: |
283 | continue | 283 | continue |
284 | else: | 284 | else: |
@@ -287,10 +287,10 @@ class QemuRunner: | |||
287 | stopread = True | 287 | stopread = True |
288 | 288 | ||
289 | if not reachedlogin: | 289 | if not reachedlogin: |
290 | logger.info("Target didn't reached login boot in %d seconds" % self.boottime) | 290 | self.logger.info("Target didn't reached login boot in %d seconds" % self.boottime) |
291 | lines = "\n".join(bootlog.splitlines()[-25:]) | 291 | lines = "\n".join(bootlog.splitlines()[-25:]) |
292 | logger.info("Last 25 lines of text:\n%s" % lines) | 292 | self.logger.info("Last 25 lines of text:\n%s" % lines) |
293 | logger.info("Check full boot log: %s" % self.logfile) | 293 | self.logger.info("Check full boot log: %s" % self.logfile) |
294 | self._dump_host() | 294 | self._dump_host() |
295 | self.stop() | 295 | self.stop() |
296 | return False | 296 | return False |
@@ -300,30 +300,30 @@ class QemuRunner: | |||
300 | (status, output) = self.run_serial("root\n", raw=True) | 300 | (status, output) = self.run_serial("root\n", raw=True) |
301 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): | 301 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): |
302 | self.logged = True | 302 | self.logged = True |
303 | logger.info("Logged as root in serial console") | 303 | self.logger.info("Logged as root in serial console") |
304 | if netconf: | 304 | if netconf: |
305 | # configure guest networking | 305 | # configure guest networking |
306 | cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) | 306 | cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) |
307 | output = self.run_serial(cmd, raw=True)[1] | 307 | output = self.run_serial(cmd, raw=True)[1] |
308 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): | 308 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): |
309 | logger.info("configured ip address %s", self.ip) | 309 | self.logger.info("configured ip address %s", self.ip) |
310 | else: | 310 | else: |
311 | logger.info("Couldn't configure guest networking") | 311 | self.logger.info("Couldn't configure guest networking") |
312 | else: | 312 | else: |
313 | logger.info("Couldn't login into serial console" | 313 | self.logger.info("Couldn't login into serial console" |
314 | " as root using blank password") | 314 | " as root using blank password") |
315 | except: | 315 | except: |
316 | logger.info("Serial console failed while trying to login") | 316 | self.logger.info("Serial console failed while trying to login") |
317 | 317 | ||
318 | else: | 318 | else: |
319 | logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime) | 319 | self.logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime) |
320 | self._dump_host() | 320 | self._dump_host() |
321 | self.stop() | 321 | self.stop() |
322 | op = self.getOutput(output) | 322 | op = self.getOutput(output) |
323 | if op: | 323 | if op: |
324 | logger.error("Output from runqemu:\n%s" % op) | 324 | self.logger.error("Output from runqemu:\n%s" % op) |
325 | else: | 325 | else: |
326 | logger.error("No output from runqemu.\n") | 326 | self.logger.error("No output from runqemu.\n") |
327 | return False | 327 | return False |
328 | 328 | ||
329 | return self.is_alive() | 329 | return self.is_alive() |
@@ -336,7 +336,7 @@ class QemuRunner: | |||
336 | if self.runqemu: | 336 | if self.runqemu: |
337 | if hasattr(self, "monitorpid"): | 337 | if hasattr(self, "monitorpid"): |
338 | os.kill(self.monitorpid, signal.SIGKILL) | 338 | os.kill(self.monitorpid, signal.SIGKILL) |
339 | logger.info("Sending SIGTERM to runqemu") | 339 | self.logger.info("Sending SIGTERM to runqemu") |
340 | try: | 340 | try: |
341 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) | 341 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) |
342 | except OSError as e: | 342 | except OSError as e: |
@@ -346,7 +346,7 @@ class QemuRunner: | |||
346 | while self.runqemu.poll() is None and time.time() < endtime: | 346 | while self.runqemu.poll() is None and time.time() < endtime: |
347 | time.sleep(1) | 347 | time.sleep(1) |
348 | if self.runqemu.poll() is None: | 348 | if self.runqemu.poll() is None: |
349 | logger.info("Sending SIGKILL to runqemu") | 349 | self.logger.info("Sending SIGKILL to runqemu") |
350 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) | 350 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) |
351 | self.runqemu = None | 351 | self.runqemu = None |
352 | if hasattr(self, 'server_socket') and self.server_socket: | 352 | if hasattr(self, 'server_socket') and self.server_socket: |
@@ -361,7 +361,7 @@ class QemuRunner: | |||
361 | # qemu-system behaves well and a SIGTERM is enough | 361 | # qemu-system behaves well and a SIGTERM is enough |
362 | os.kill(self.qemupid, signal.SIGTERM) | 362 | os.kill(self.qemupid, signal.SIGTERM) |
363 | except ProcessLookupError as e: | 363 | except ProcessLookupError as e: |
364 | logger.warn('qemu-system ended unexpectedly') | 364 | self.logger.warn('qemu-system ended unexpectedly') |
365 | 365 | ||
366 | def stop_thread(self): | 366 | def stop_thread(self): |
367 | if self.thread and self.thread.is_alive(): | 367 | if self.thread and self.thread.is_alive(): |
@@ -369,7 +369,7 @@ class QemuRunner: | |||
369 | self.thread.join() | 369 | self.thread.join() |
370 | 370 | ||
371 | def restart(self, qemuparams = None): | 371 | def restart(self, qemuparams = None): |
372 | logger.info("Restarting qemu process") | 372 | self.logger.info("Restarting qemu process") |
373 | if self.runqemu.poll() is None: | 373 | if self.runqemu.poll() is None: |
374 | self.stop() | 374 | self.stop() |
375 | if self.start(qemuparams): | 375 | if self.start(qemuparams): |
@@ -478,7 +478,7 @@ class QemuRunner: | |||
478 | 478 | ||
479 | def _dump_host(self): | 479 | def _dump_host(self): |
480 | self.host_dumper.create_dir("qemu") | 480 | self.host_dumper.create_dir("qemu") |
481 | logger.warn("Qemu ended unexpectedly, dump data from host" | 481 | self.logger.warn("Qemu ended unexpectedly, dump data from host" |
482 | " is in %s" % self.host_dumper.dump_dir) | 482 | " is in %s" % self.host_dumper.dump_dir) |
483 | self.host_dumper.dump_host() | 483 | self.host_dumper.dump_host() |
484 | 484 | ||