diff options
author | Richard Purdie <richard.purdie@linuxfoundation.org> | 2017-11-08 18:13:24 +0000 |
---|---|---|
committer | Richard Purdie <richard.purdie@linuxfoundation.org> | 2017-11-09 12:24:24 +0000 |
commit | 07cddf76a2b4e6ab3cdfe9cea2e69566070f7c88 (patch) | |
tree | 4c9273a2feeece1bded7fd3dc0857033b3125a59 | |
parent | 77239864f465adbb6a589d1952bcfd43df5712bd (diff) | |
download | poky-07cddf76a2b4e6ab3cdfe9cea2e69566070f7c88.tar.gz |
oeqa/qemurunner: Use logger.debug, not logger.info
Bitbake logs info messages to the console. These messages are really
there as debugging information. At the debug level, they will be shown
in failure logs and in the task logs but not on the console which
is what we want in this case.
(From OE-Core rev: e05b14ad5a3c5ac1656b6fffdcf7e58250638e96)
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
-rw-r--r-- | meta/lib/oeqa/utils/qemurunner.py | 74 |
1 files changed, 37 insertions, 37 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index aa2600b827..32148871ff 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py | |||
@@ -68,7 +68,7 @@ class QemuRunner: | |||
68 | sock.bind(("127.0.0.1",0)) | 68 | sock.bind(("127.0.0.1",0)) |
69 | sock.listen(2) | 69 | sock.listen(2) |
70 | port = sock.getsockname()[1] | 70 | port = sock.getsockname()[1] |
71 | self.logger.info("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) | 71 | self.logger.debug("Created listening socket for qemu serial console on: 127.0.0.1:%s" % port) |
72 | return (sock, port) | 72 | return (sock, port) |
73 | 73 | ||
74 | except socket.error: | 74 | except socket.error: |
@@ -95,8 +95,8 @@ class QemuRunner: | |||
95 | def handleSIGCHLD(self, signum, frame): | 95 | def handleSIGCHLD(self, signum, frame): |
96 | if self.runqemu and self.runqemu.poll(): | 96 | if self.runqemu and self.runqemu.poll(): |
97 | if self.runqemu.returncode: | 97 | if self.runqemu.returncode: |
98 | self.logger.info('runqemu exited with code %d' % self.runqemu.returncode) | 98 | self.logger.debug('runqemu exited with code %d' % self.runqemu.returncode) |
99 | self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) | 99 | self.logger.debug("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) |
100 | self.stop() | 100 | self.stop() |
101 | self._dump_host() | 101 | self._dump_host() |
102 | raise SystemExit | 102 | raise SystemExit |
@@ -125,10 +125,10 @@ class QemuRunner: | |||
125 | if not launch_cmd: | 125 | if not launch_cmd: |
126 | launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams) | 126 | launch_cmd = 'runqemu %s %s ' % ('snapshot' if discard_writes else '', runqemuparams) |
127 | if self.use_kvm: | 127 | if self.use_kvm: |
128 | self.logger.info('Using kvm for runqemu') | 128 | self.logger.debug('Using kvm for runqemu') |
129 | launch_cmd += ' kvm' | 129 | launch_cmd += ' kvm' |
130 | else: | 130 | else: |
131 | self.logger.info('Not using kvm for runqemu') | 131 | self.logger.debug('Not using kvm for runqemu') |
132 | if not self.display: | 132 | if not self.display: |
133 | launch_cmd += ' nographic' | 133 | launch_cmd += ' nographic' |
134 | launch_cmd += ' %s %s' % (self.machine, self.rootfs) | 134 | launch_cmd += ' %s %s' % (self.machine, self.rootfs) |
@@ -160,7 +160,7 @@ class QemuRunner: | |||
160 | self.origchldhandler = signal.getsignal(signal.SIGCHLD) | 160 | self.origchldhandler = signal.getsignal(signal.SIGCHLD) |
161 | signal.signal(signal.SIGCHLD, self.handleSIGCHLD) | 161 | signal.signal(signal.SIGCHLD, self.handleSIGCHLD) |
162 | 162 | ||
163 | self.logger.info('launchcmd=%s'%(launch_cmd)) | 163 | self.logger.debug('launchcmd=%s'%(launch_cmd)) |
164 | 164 | ||
165 | # FIXME: We pass in stdin=subprocess.PIPE here to work around stty | 165 | # FIXME: We pass in stdin=subprocess.PIPE here to work around stty |
166 | # blocking at the end of the runqemu script when using this within | 166 | # blocking at the end of the runqemu script when using this within |
@@ -195,17 +195,17 @@ class QemuRunner: | |||
195 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) | 195 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) |
196 | sys.exit(0) | 196 | sys.exit(0) |
197 | 197 | ||
198 | self.logger.info("runqemu started, pid is %s" % self.runqemu.pid) | 198 | self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid) |
199 | self.logger.info("waiting at most %s seconds for qemu pid" % self.runqemutime) | 199 | self.logger.debug("waiting at most %s seconds for qemu pid" % self.runqemutime) |
200 | endtime = time.time() + self.runqemutime | 200 | endtime = time.time() + self.runqemutime |
201 | while not self.is_alive() and time.time() < endtime: | 201 | while not self.is_alive() and time.time() < endtime: |
202 | if self.runqemu.poll(): | 202 | if self.runqemu.poll(): |
203 | if self.runqemu.returncode: | 203 | if self.runqemu.returncode: |
204 | # No point waiting any longer | 204 | # No point waiting any longer |
205 | self.logger.info('runqemu exited with code %d' % self.runqemu.returncode) | 205 | self.logger.debug('runqemu exited with code %d' % self.runqemu.returncode) |
206 | self._dump_host() | 206 | self._dump_host() |
207 | self.stop() | 207 | self.stop() |
208 | self.logger.info("Output from runqemu:\n%s" % self.getOutput(output)) | 208 | self.logger.debug("Output from runqemu:\n%s" % self.getOutput(output)) |
209 | return False | 209 | return False |
210 | time.sleep(0.5) | 210 | time.sleep(0.5) |
211 | 211 | ||
@@ -214,7 +214,7 @@ class QemuRunner: | |||
214 | # Dump all processes to help us to figure out what is going on... | 214 | # Dump all processes to help us to figure out what is going on... |
215 | ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0] | 215 | ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0] |
216 | processes = ps.decode("utf-8") | 216 | processes = ps.decode("utf-8") |
217 | self.logger.info("Running processes:\n%s" % processes) | 217 | self.logger.debug("Running processes:\n%s" % processes) |
218 | self._dump_host() | 218 | self._dump_host() |
219 | self.stop() | 219 | self.stop() |
220 | op = self.getOutput(output) | 220 | op = self.getOutput(output) |
@@ -227,7 +227,7 @@ class QemuRunner: | |||
227 | # We are alive: qemu is running | 227 | # We are alive: qemu is running |
228 | out = self.getOutput(output) | 228 | out = self.getOutput(output) |
229 | netconf = False # network configuration is not required by default | 229 | netconf = False # network configuration is not required by default |
230 | self.logger.info("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid)) | 230 | self.logger.debug("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid)) |
231 | if get_ip: | 231 | if get_ip: |
232 | cmdline = '' | 232 | cmdline = '' |
233 | with open('/proc/%s/cmdline' % self.qemupid) as p: | 233 | with open('/proc/%s/cmdline' % self.qemupid) as p: |
@@ -239,7 +239,7 @@ class QemuRunner: | |||
239 | ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) | 239 | ips = re.findall("((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) |
240 | self.ip = ips[0] | 240 | self.ip = ips[0] |
241 | self.server_ip = ips[1] | 241 | self.server_ip = ips[1] |
242 | self.logger.info("qemu cmdline used:\n{}".format(cmdline)) | 242 | self.logger.debug("qemu cmdline used:\n{}".format(cmdline)) |
243 | except (IndexError, ValueError): | 243 | except (IndexError, ValueError): |
244 | # Try to get network configuration from runqemu output | 244 | # Try to get network configuration from runqemu output |
245 | match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*', | 245 | match = re.match('.*Network configuration: ([0-9.]+)::([0-9.]+):([0-9.]+)$.*', |
@@ -258,8 +258,8 @@ class QemuRunner: | |||
258 | self.stop() | 258 | self.stop() |
259 | return False | 259 | return False |
260 | 260 | ||
261 | self.logger.info("Target IP: %s" % self.ip) | 261 | self.logger.debug("Target IP: %s" % self.ip) |
262 | self.logger.info("Server IP: %s" % self.server_ip) | 262 | self.logger.debug("Server IP: %s" % self.server_ip) |
263 | 263 | ||
264 | self.thread = LoggingThread(self.log, threadsock, self.logger) | 264 | self.thread = LoggingThread(self.log, threadsock, self.logger) |
265 | self.thread.start() | 265 | self.thread.start() |
@@ -270,8 +270,8 @@ class QemuRunner: | |||
270 | self.stop_thread() | 270 | self.stop_thread() |
271 | return False | 271 | return False |
272 | 272 | ||
273 | self.logger.info("Output from runqemu:\n%s", out) | 273 | self.logger.debug("Output from runqemu:\n%s", out) |
274 | self.logger.info("Waiting at most %d seconds for login banner" % self.boottime) | 274 | self.logger.debug("Waiting at most %d seconds for login banner" % self.boottime) |
275 | endtime = time.time() + self.boottime | 275 | endtime = time.time() + self.boottime |
276 | socklist = [self.server_socket] | 276 | socklist = [self.server_socket] |
277 | reachedlogin = False | 277 | reachedlogin = False |
@@ -290,7 +290,7 @@ class QemuRunner: | |||
290 | qemusock.setblocking(0) | 290 | qemusock.setblocking(0) |
291 | socklist.append(qemusock) | 291 | socklist.append(qemusock) |
292 | socklist.remove(self.server_socket) | 292 | socklist.remove(self.server_socket) |
293 | self.logger.info("Connection from %s:%s" % addr) | 293 | self.logger.debug("Connection from %s:%s" % addr) |
294 | else: | 294 | else: |
295 | data = data + sock.recv(1024) | 295 | data = data + sock.recv(1024) |
296 | if data: | 296 | if data: |
@@ -302,7 +302,7 @@ class QemuRunner: | |||
302 | self.server_socket = qemusock | 302 | self.server_socket = qemusock |
303 | stopread = True | 303 | stopread = True |
304 | reachedlogin = True | 304 | reachedlogin = True |
305 | self.logger.info("Reached login banner") | 305 | self.logger.debug("Reached login banner") |
306 | except UnicodeDecodeError: | 306 | except UnicodeDecodeError: |
307 | continue | 307 | continue |
308 | else: | 308 | else: |
@@ -312,12 +312,12 @@ class QemuRunner: | |||
312 | 312 | ||
313 | 313 | ||
314 | if not reachedlogin: | 314 | if not reachedlogin: |
315 | self.logger.info("Target didn't reached login boot in %d seconds" % self.boottime) | 315 | self.logger.debug("Target didn't reached login boot in %d seconds" % self.boottime) |
316 | tail = lambda l: "\n".join(l.splitlines()[-25:]) | 316 | tail = lambda l: "\n".join(l.splitlines()[-25:]) |
317 | # in case bootlog is empty, use tail qemu log store at self.msg | 317 | # in case bootlog is empty, use tail qemu log store at self.msg |
318 | lines = tail(bootlog if bootlog else self.msg) | 318 | lines = tail(bootlog if bootlog else self.msg) |
319 | self.logger.info("Last 25 lines of text:\n%s" % lines) | 319 | self.logger.debug("Last 25 lines of text:\n%s" % lines) |
320 | self.logger.info("Check full boot log: %s" % self.logfile) | 320 | self.logger.debug("Check full boot log: %s" % self.logfile) |
321 | self._dump_host() | 321 | self._dump_host() |
322 | self.stop() | 322 | self.stop() |
323 | return False | 323 | return False |
@@ -327,20 +327,20 @@ class QemuRunner: | |||
327 | (status, output) = self.run_serial("root\n", raw=True) | 327 | (status, output) = self.run_serial("root\n", raw=True) |
328 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): | 328 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): |
329 | self.logged = True | 329 | self.logged = True |
330 | self.logger.info("Logged as root in serial console") | 330 | self.logger.debug("Logged as root in serial console") |
331 | if netconf: | 331 | if netconf: |
332 | # configure guest networking | 332 | # configure guest networking |
333 | cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) | 333 | cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) |
334 | output = self.run_serial(cmd, raw=True)[1] | 334 | output = self.run_serial(cmd, raw=True)[1] |
335 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): | 335 | if re.search("root@[a-zA-Z0-9\-]+:~#", output): |
336 | self.logger.info("configured ip address %s", self.ip) | 336 | self.logger.debug("configured ip address %s", self.ip) |
337 | else: | 337 | else: |
338 | self.logger.info("Couldn't configure guest networking") | 338 | self.logger.debug("Couldn't configure guest networking") |
339 | else: | 339 | else: |
340 | self.logger.info("Couldn't login into serial console" | 340 | self.logger.debug("Couldn't login into serial console" |
341 | " as root using blank password") | 341 | " as root using blank password") |
342 | except: | 342 | except: |
343 | self.logger.info("Serial console failed while trying to login") | 343 | self.logger.debug("Serial console failed while trying to login") |
344 | return True | 344 | return True |
345 | 345 | ||
346 | def stop(self): | 346 | def stop(self): |
@@ -351,7 +351,7 @@ class QemuRunner: | |||
351 | if self.runqemu: | 351 | if self.runqemu: |
352 | if hasattr(self, "monitorpid"): | 352 | if hasattr(self, "monitorpid"): |
353 | os.kill(self.monitorpid, signal.SIGKILL) | 353 | os.kill(self.monitorpid, signal.SIGKILL) |
354 | self.logger.info("Sending SIGTERM to runqemu") | 354 | self.logger.debug("Sending SIGTERM to runqemu") |
355 | try: | 355 | try: |
356 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) | 356 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGTERM) |
357 | except OSError as e: | 357 | except OSError as e: |
@@ -361,7 +361,7 @@ class QemuRunner: | |||
361 | while self.runqemu.poll() is None and time.time() < endtime: | 361 | while self.runqemu.poll() is None and time.time() < endtime: |
362 | time.sleep(1) | 362 | time.sleep(1) |
363 | if self.runqemu.poll() is None: | 363 | if self.runqemu.poll() is None: |
364 | self.logger.info("Sending SIGKILL to runqemu") | 364 | self.logger.debug("Sending SIGKILL to runqemu") |
365 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) | 365 | os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) |
366 | self.runqemu = None | 366 | self.runqemu = None |
367 | if hasattr(self, 'server_socket') and self.server_socket: | 367 | if hasattr(self, 'server_socket') and self.server_socket: |
@@ -387,7 +387,7 @@ class QemuRunner: | |||
387 | self.thread.join() | 387 | self.thread.join() |
388 | 388 | ||
389 | def restart(self, qemuparams = None): | 389 | def restart(self, qemuparams = None): |
390 | self.logger.info("Restarting qemu process") | 390 | self.logger.debug("Restarting qemu process") |
391 | if self.runqemu.poll() is None: | 391 | if self.runqemu.poll() is None: |
392 | self.stop() | 392 | self.stop() |
393 | if self.start(qemuparams): | 393 | if self.start(qemuparams): |
@@ -485,17 +485,17 @@ class LoggingThread(threading.Thread): | |||
485 | self.teardown() | 485 | self.teardown() |
486 | 486 | ||
487 | def run(self): | 487 | def run(self): |
488 | self.logger.info("Starting logging thread") | 488 | self.logger.debug("Starting logging thread") |
489 | self.readpipe, self.writepipe = os.pipe() | 489 | self.readpipe, self.writepipe = os.pipe() |
490 | threading.Thread.run(self) | 490 | threading.Thread.run(self) |
491 | 491 | ||
492 | def stop(self): | 492 | def stop(self): |
493 | self.logger.info("Stopping logging thread") | 493 | self.logger.debug("Stopping logging thread") |
494 | if self.running: | 494 | if self.running: |
495 | os.write(self.writepipe, bytes("stop", "utf-8")) | 495 | os.write(self.writepipe, bytes("stop", "utf-8")) |
496 | 496 | ||
497 | def teardown(self): | 497 | def teardown(self): |
498 | self.logger.info("Tearing down logging thread") | 498 | self.logger.debug("Tearing down logging thread") |
499 | self.close_socket(self.serversock) | 499 | self.close_socket(self.serversock) |
500 | 500 | ||
501 | if self.readsock is not None: | 501 | if self.readsock is not None: |
@@ -513,7 +513,7 @@ class LoggingThread(threading.Thread): | |||
513 | 513 | ||
514 | breakout = False | 514 | breakout = False |
515 | self.running = True | 515 | self.running = True |
516 | self.logger.info("Starting thread event loop") | 516 | self.logger.debug("Starting thread event loop") |
517 | while not breakout: | 517 | while not breakout: |
518 | events = poll.poll() | 518 | events = poll.poll() |
519 | for event in events: | 519 | for event in events: |
@@ -523,19 +523,19 @@ class LoggingThread(threading.Thread): | |||
523 | 523 | ||
524 | # Event to stop the thread | 524 | # Event to stop the thread |
525 | if self.readpipe == event[0]: | 525 | if self.readpipe == event[0]: |
526 | self.logger.info("Stop event received") | 526 | self.logger.debug("Stop event received") |
527 | breakout = True | 527 | breakout = True |
528 | break | 528 | break |
529 | 529 | ||
530 | # A connection request was received | 530 | # A connection request was received |
531 | elif self.serversock.fileno() == event[0]: | 531 | elif self.serversock.fileno() == event[0]: |
532 | self.logger.info("Connection request received") | 532 | self.logger.debug("Connection request received") |
533 | self.readsock, _ = self.serversock.accept() | 533 | self.readsock, _ = self.serversock.accept() |
534 | self.readsock.setblocking(0) | 534 | self.readsock.setblocking(0) |
535 | poll.unregister(self.serversock.fileno()) | 535 | poll.unregister(self.serversock.fileno()) |
536 | poll.register(self.readsock.fileno(), event_read_mask) | 536 | poll.register(self.readsock.fileno(), event_read_mask) |
537 | 537 | ||
538 | self.logger.info("Setting connection established event") | 538 | self.logger.debug("Setting connection established event") |
539 | self.connection_established.set() | 539 | self.connection_established.set() |
540 | 540 | ||
541 | # Actual data to be logged | 541 | # Actual data to be logged |