summaryrefslogtreecommitdiffstats
path: root/meta/lib/oeqa
diff options
context:
space:
mode:
authorRichard Purdie <richard.purdie@linuxfoundation.org>2017-09-07 10:49:19 +0100
committerRichard Purdie <richard.purdie@linuxfoundation.org>2017-09-11 17:30:27 +0100
commitf981059be1572d4f3322e30c8ff98d7447c7daa6 (patch)
tree0504382f65238511fc8c03058c0965ad763897ee /meta/lib/oeqa
parent2e8256d0c75aaf66f88ccc18084187ab16aec17e (diff)
downloadpoky-f981059be1572d4f3322e30c8ff98d7447c7daa6.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) Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Diffstat (limited to 'meta/lib/oeqa')
-rw-r--r--meta/lib/oeqa/utils/qemurunner.py90
1 files changed, 45 insertions, 45 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py
index 54312fb94c..6ee52a2f1e 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -17,11 +17,8 @@ import errno
17import string 17import string
18import threading 18import threading
19import codecs 19import codecs
20from oeqa.utils.dump import HostDumper
21
22import logging 20import logging
23logger = logging.getLogger("BitBake.QemuRunner") 21from oeqa.utils.dump import HostDumper
24logger.addHandler(logging.StreamHandler())
25 22
26# Get Unicode non printable control chars 23# Get Unicode non printable control chars
27control_range = list(range(0,32))+list(range(127,160)) 24control_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
@@ -105,15 +105,15 @@ class QemuRunner:
105 # interact badly with screensavers. 105 # interact badly with screensavers.
106 env["QEMU_DONT_GRAB"] = "1" 106 env["QEMU_DONT_GRAB"] = "1"
107 if not os.path.exists(self.rootfs): 107 if not os.path.exists(self.rootfs):
108 logger.error("Invalid rootfs %s" % self.rootfs) 108 self.logger.error("Invalid rootfs %s" % self.rootfs)
109 return False 109 return False
110 if not os.path.exists(self.tmpdir): 110 if not os.path.exists(self.tmpdir):
111 logger.error("Invalid TMPDIR path %s" % self.tmpdir) 111 self.logger.error("Invalid TMPDIR path %s" % self.tmpdir)
112 return False 112 return False
113 else: 113 else:
114 env["OE_TMPDIR"] = self.tmpdir 114 env["OE_TMPDIR"] = self.tmpdir
115 if not os.path.exists(self.deploy_dir_image): 115 if not os.path.exists(self.deploy_dir_image):
116 logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image) 116 self.logger.error("Invalid DEPLOY_DIR_IMAGE path %s" % self.deploy_dir_image)
117 return False 117 return False
118 else: 118 else:
119 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image 119 env["DEPLOY_DIR_IMAGE"] = self.deploy_dir_image
@@ -121,10 +121,10 @@ class QemuRunner:
121 if not launch_cmd: 121 if not launch_cmd:
122 launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams) 122 launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams)
123 if self.use_kvm: 123 if self.use_kvm:
124 logger.info('Using kvm for runqemu') 124 self.logger.info('Using kvm for runqemu')
125 launch_cmd += ' kvm' 125 launch_cmd += ' kvm'
126 else: 126 else:
127 logger.info('Not using kvm for runqemu') 127 self.logger.info('Not using kvm for runqemu')
128 if not self.display: 128 if not self.display:
129 launch_cmd += ' nographic' 129 launch_cmd += ' nographic'
130 launch_cmd += ' %s %s' % (self.machine, self.rootfs) 130 launch_cmd += ' %s %s' % (self.machine, self.rootfs)
@@ -136,7 +136,7 @@ class QemuRunner:
136 threadsock, threadport = self.create_socket() 136 threadsock, threadport = self.create_socket()
137 self.server_socket, self.serverport = self.create_socket() 137 self.server_socket, self.serverport = self.create_socket()
138 except socket.error as msg: 138 except socket.error as msg:
139 logger.error("Failed to create listening socket: %s" % msg[1]) 139 self.logger.error("Failed to create listening socket: %s" % msg[1])
140 return False 140 return False
141 141
142 bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1' 142 bootparams = 'console=tty1 console=ttyS0,115200n8 printk.time=1'
@@ -152,7 +152,7 @@ class QemuRunner:
152 self.origchldhandler = signal.getsignal(signal.SIGCHLD) 152 self.origchldhandler = signal.getsignal(signal.SIGCHLD)
153 signal.signal(signal.SIGCHLD, self.handleSIGCHLD) 153 signal.signal(signal.SIGCHLD, self.handleSIGCHLD)
154 154
155 logger.info('launchcmd=%s'%(launch_cmd)) 155 self.logger.info('launchcmd=%s'%(launch_cmd))
156 156
157 # FIXME: We pass in stdin=subprocess.PIPE here to work around stty 157 # FIXME: We pass in stdin=subprocess.PIPE here to work around stty
158 # blocking at the end of the runqemu script when using this within 158 # blocking at the end of the runqemu script when using this within
@@ -187,24 +187,24 @@ class QemuRunner:
187 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) 187 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
188 sys.exit(0) 188 sys.exit(0)
189 189
190 logger.info("runqemu started, pid is %s" % self.runqemu.pid) 190 self.logger.info("runqemu started, pid is %s" % self.runqemu.pid)
191 logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime) 191 self.logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime)
192 endtime = time.time() + self.runqemutime 192 endtime = time.time() + self.runqemutime
193 while not self.is_alive() and time.time() < endtime: 193 while not self.is_alive() and time.time() < endtime:
194 if self.runqemu.poll(): 194 if self.runqemu.poll():
195 if self.runqemu.returncode: 195 if self.runqemu.returncode:
196 # No point waiting any longer 196 # No point waiting any longer
197 logger.info('runqemu exited with code %d' % self.runqemu.returncode) 197 self.logger.info('runqemu exited with code %d' % self.runqemu.returncode)
198 self._dump_host() 198 self._dump_host()
199 self.stop() 199 self.stop()
200 logger.info("Output from runqemu:\n%s" % self.getOutput(output)) 200 self.logger.info("Output from runqemu:\n%s" % self.getOutput(output))
201 return False 201 return False
202 time.sleep(1) 202 time.sleep(1)
203 203
204 out = self.getOutput(output) 204 out = self.getOutput(output)
205 netconf = False # network configuration is not required by default 205 netconf = False # network configuration is not required by default
206 if self.is_alive(): 206 if self.is_alive():
207 logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid)) 207 self.logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid))
208 if get_ip: 208 if get_ip:
209 cmdline = '' 209 cmdline = ''
210 with open('/proc/%s/cmdline' % self.qemupid) as p: 210 with open('/proc/%s/cmdline' % self.qemupid) as p:
@@ -216,7 +216,7 @@ class QemuRunner:
216 ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) 216 ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1])
217 self.ip = ips[0] 217 self.ip = ips[0]
218 self.server_ip = ips[1] 218 self.server_ip = ips[1]
219 logger.info("qemu cmdline used:\n{}".format(cmdline)) 219 self.logger.info("qemu cmdline used:\n{}".format(cmdline))
220 except (IndexError, ValueError): 220 except (IndexError, ValueError):
221 # Try to get network configuration from runqemu output 221 # Try to get network configuration from runqemu output
222 match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*', 222 match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*',
@@ -228,27 +228,27 @@ class QemuRunner:
228 # and guest networking is not configured 228 # and guest networking is not configured
229 netconf = True 229 netconf = True
230 else: 230 else:
231 logger.error("Couldn't get ip from qemu command line and runqemu output! " 231 self.logger.error("Couldn't get ip from qemu command line and runqemu output! "
232 "Here is the qemu command line used:\n%s\n" 232 "Here is the qemu command line used:\n%s\n"
233 "and output from runqemu:\n%s" % (cmdline, out)) 233 "and output from runqemu:\n%s" % (cmdline, out))
234 self._dump_host() 234 self._dump_host()
235 self.stop() 235 self.stop()
236 return False 236 return False
237 237
238 logger.info("Target IP: %s" % self.ip) 238 self.logger.info("Target IP: %s" % self.ip)
239 logger.info("Server IP: %s" % self.server_ip) 239 self.logger.info("Server IP: %s" % self.server_ip)
240 240
241 self.thread = LoggingThread(self.log, threadsock, logger) 241 self.thread = LoggingThread(self.log, threadsock, self.logger)
242 self.thread.start() 242 self.thread.start()
243 if not self.thread.connection_established.wait(self.boottime): 243 if not self.thread.connection_established.wait(self.boottime):
244 logger.error("Didn't receive a console connection from qemu. " 244 self.logger.error("Didn't receive a console connection from qemu. "
245 "Here is the qemu command line used:\n%s\nand " 245 "Here is the qemu command line used:\n%s\nand "
246 "output from runqemu:\n%s" % (cmdline, out)) 246 "output from runqemu:\n%s" % (cmdline, out))
247 self.stop_thread() 247 self.stop_thread()
248 return False 248 return False
249 249
250 logger.info("Output from runqemu:\n%s", out) 250 self.logger.info("Output from runqemu:\n%s", out)
251 logger.info("Waiting at most %d seconds for login banner" % self.boottime) 251 self.logger.info("Waiting at most %d seconds for login banner" % self.boottime)
252 endtime = time.time() + self.boottime 252 endtime = time.time() + self.boottime
253 socklist = [self.server_socket] 253 socklist = [self.server_socket]
254 reachedlogin = False 254 reachedlogin = False
@@ -267,7 +267,7 @@ class QemuRunner:
267 qemusock.setblocking(0) 267 qemusock.setblocking(0)
268 socklist.append(qemusock) 268 socklist.append(qemusock)
269 socklist.remove(self.server_socket) 269 socklist.remove(self.server_socket)
270 logger.info("Connection from %s:%s" % addr) 270 self.logger.info("Connection from %s:%s" % addr)
271 else: 271 else:
272 data = data + sock.recv(1024) 272 data = data + sock.recv(1024)
273 if data: 273 if data:
@@ -279,7 +279,7 @@ class QemuRunner:
279 self.server_socket = qemusock 279 self.server_socket = qemusock
280 stopread = True 280 stopread = True
281 reachedlogin = True 281 reachedlogin = True
282 logger.info("Reached login banner") 282 self.logger.info("Reached login banner")
283 except UnicodeDecodeError: 283 except UnicodeDecodeError:
284 continue 284 continue
285 else: 285 else:
@@ -288,10 +288,10 @@ class QemuRunner:
288 stopread = True 288 stopread = True
289 289
290 if not reachedlogin: 290 if not reachedlogin:
291 logger.info("Target didn't reached login boot in %d seconds" % self.boottime) 291 self.logger.info("Target didn't reached login boot in %d seconds" % self.boottime)
292 lines = "\n".join(bootlog.splitlines()[-25:]) 292 lines = "\n".join(bootlog.splitlines()[-25:])
293 logger.info("Last 25 lines of text:\n%s" % lines) 293 self.logger.info("Last 25 lines of text:\n%s" % lines)
294 logger.info("Check full boot log: %s" % self.logfile) 294 self.logger.info("Check full boot log: %s" % self.logfile)
295 self._dump_host() 295 self._dump_host()
296 self.stop() 296 self.stop()
297 return False 297 return False
@@ -301,30 +301,30 @@ class QemuRunner:
301 (status, output) = self.run_serial("root\n", raw=True) 301 (status, output) = self.run_serial("root\n", raw=True)
302 if re.search("root@[a-zA-Z0-9\-]+:~#", output): 302 if re.search("root@[a-zA-Z0-9\-]+:~#", output):
303 self.logged = True 303 self.logged = True
304 logger.info("Logged as root in serial console") 304 self.logger.info("Logged as root in serial console")
305 if netconf: 305 if netconf:
306 # configure guest networking 306 # configure guest networking
307 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) 307 cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask)
308 output = self.run_serial(cmd, raw=True)[1] 308 output = self.run_serial(cmd, raw=True)[1]
309 if re.search("root@[a-zA-Z0-9\-]+:~#", output): 309 if re.search("root@[a-zA-Z0-9\-]+:~#", output):
310 logger.info("configured ip address %s", self.ip) 310 self.logger.info("configured ip address %s", self.ip)
311 else: 311 else:
312 logger.info("Couldn't configure guest networking") 312 self.logger.info("Couldn't configure guest networking")
313 else: 313 else:
314 logger.info("Couldn't login into serial console" 314 self.logger.info("Couldn't login into serial console"
315 " as root using blank password") 315 " as root using blank password")
316 except: 316 except:
317 logger.info("Serial console failed while trying to login") 317 self.logger.info("Serial console failed while trying to login")
318 318
319 else: 319 else:
320 logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime) 320 self.logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime)
321 self._dump_host() 321 self._dump_host()
322 self.stop() 322 self.stop()
323 op = self.getOutput(output) 323 op = self.getOutput(output)
324 if op: 324 if op:
325 logger.error("Output from runqemu:\n%s" % op) 325 self.logger.error("Output from runqemu:\n%s" % op)
326 else: 326 else:
327 logger.error("No output from runqemu.\n") 327 self.logger.error("No output from runqemu.\n")
328 return False 328 return False
329 329
330 return self.is_alive() 330 return self.is_alive()
@@ -337,7 +337,7 @@ class QemuRunner:
337 if self.runqemu: 337 if self.runqemu:
338 if hasattr(self, "monitorpid"): 338 if hasattr(self, "monitorpid"):
339 os.kill(self.monitorpid, signal.SIGKILL) 339 os.kill(self.monitorpid, signal.SIGKILL)
340 logger.info("Sending SIGTERM to runqemu") 340 self.logger.info("Sending SIGTERM to runqemu")
341 try: 341 try:
342 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) 342 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM)
343 except OSError as e: 343 except OSError as e:
@@ -347,7 +347,7 @@ class QemuRunner:
347 while self.runqemu.poll() is None and time.time() < endtime: 347 while self.runqemu.poll() is None and time.time() < endtime:
348 time.sleep(1) 348 time.sleep(1)
349 if self.runqemu.poll() is None: 349 if self.runqemu.poll() is None:
350 logger.info("Sending SIGKILL to runqemu") 350 self.logger.info("Sending SIGKILL to runqemu")
351 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) 351 os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL)
352 self.runqemu = None 352 self.runqemu = None
353 if hasattr(self, 'server_socket') and self.server_socket: 353 if hasattr(self, 'server_socket') and self.server_socket:
@@ -362,7 +362,7 @@ class QemuRunner:
362 # qemu-system behaves well and a SIGTERM is enough 362 # qemu-system behaves well and a SIGTERM is enough
363 os.kill(self.qemupid, signal.SIGTERM) 363 os.kill(self.qemupid, signal.SIGTERM)
364 except ProcessLookupError as e: 364 except ProcessLookupError as e:
365 logger.warn('qemu-system ended unexpectedly') 365 self.logger.warn('qemu-system ended unexpectedly')
366 366
367 def stop_thread(self): 367 def stop_thread(self):
368 if self.thread and self.thread.is_alive(): 368 if self.thread and self.thread.is_alive():
@@ -370,7 +370,7 @@ class QemuRunner:
370 self.thread.join() 370 self.thread.join()
371 371
372 def restart(self, qemuparams = None): 372 def restart(self, qemuparams = None):
373 logger.info("Restarting qemu process") 373 self.logger.info("Restarting qemu process")
374 if self.runqemu.poll() is None: 374 if self.runqemu.poll() is None:
375 self.stop() 375 self.stop()
376 if self.start(qemuparams): 376 if self.start(qemuparams):
@@ -479,7 +479,7 @@ class QemuRunner:
479 479
480 def _dump_host(self): 480 def _dump_host(self):
481 self.host_dumper.create_dir("qemu") 481 self.host_dumper.create_dir("qemu")
482 logger.warn("Qemu ended unexpectedly, dump data from host" 482 self.logger.warn("Qemu ended unexpectedly, dump data from host"
483 " is in %s" % self.host_dumper.dump_dir) 483 " is in %s" % self.host_dumper.dump_dir)
484 self.host_dumper.dump_host() 484 self.host_dumper.dump_host()
485 485